Closed Bug 1046566 Opened 5 years ago Closed 5 years ago

Almost every line is printed twice in B2G Desktop Linux Opt Full Log

Categories

(Testing :: Mochitest, defect)

defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED
mozilla34

People

(Reporter: TYLin, Assigned: akachkach)

References

Details

(Keywords: regression)

Attachments

(1 file, 1 obsolete file)

See the BAD log. For example:
16:13:36     INFO -  43346 INFO TEST-START | Shutdown
16:13:36     INFO -  43347 INFO TEST-START | Shutdown
16:13:36     INFO -  43348 INFO Passed:  391711
16:13:36     INFO -  43349 INFO Passed:  391711
16:13:36     INFO -  43350 INFO Failed:  0
16:13:36     INFO -  43351 INFO Failed:  0
16:13:36     INFO -  43352 INFO Todo:    8737
16:13:36     INFO -  43353 INFO Todo:    8737
16:13:36     INFO -  43354 INFO Slowest: 36175ms - /tests/image/test/mochitest/test_bug733553.html
16:13:36     INFO -  43355 INFO Slowest: 36175ms - /tests/image/test/mochitest/test_bug733553.html
16:13:36     INFO -  43356 INFO SimpleTest FINISHED
16:13:36     INFO -  43357 INFO SimpleTest FINISHED
16:13:36     INFO -  43358 INFO TEST-INFO | Ran 1 Loops
16:13:36     INFO -  43359 INFO TEST-INFO | Ran 1 Loops
16:13:36     INFO -  43360 INFO SimpleTest FINISHED
16:13:36     INFO -  43361 INFO SimpleTest FINISHED
16:13:36     INFO -  43362 INFO SUITE-END | took 1097s
16:13:36     INFO -  43363 INFO SUITE-END | took 1097s

BAD @ 2014-07-30 15:53:38 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=44928000&tree=Mozilla-Central&full=1

Good @ 2014-07-30 15:09:49 PDT
https://tbpl.mozilla.org/php/getParsedLog.php?id=44924888&tree=Mozilla-Central&full=1
Thank you for filing :-)
TBPL only displays the results and logs generated elsewhere - moving to mochitest.
Component: Tinderboxpushlog → Mochitest
Keywords: regression
Product: Webtools → Testing
Looks like we're attaching two handlers to the same logger? Still, this is pretty unlikely because the StructuredLogger in that patch is instantiated directly before we attach the StreamHandler.

Are messages passed to the handlers of loggers that have the same name (even if it's two different instances)?
Flags: needinfo?(james)
Yes, all loggers with the same name share the same handlers.
Flags: needinfo?(james)
Assignee: nobody → akachkach
A quick fix for this would be to make sure we don't instantiate multiple structured loggers.

Just did a try push to see if it's enough: https://tbpl.mozilla.org/?tree=Try&rev=1bee4ba52f4d
Attachment #8465979 - Flags: review?(ahalberstadt)
Comment on attachment 8465979 [details] [diff] [review]
0001-Bug-1046566-avoid-instantiating-multiple-structured-.patch

Review of attachment 8465979 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks, probably the easiest solution for now.
Attachment #8465979 - Flags: review?(ahalberstadt) → review+
I notice that B2G Desktop Linux Opt had an exception.

UnboundLocalError: local variable 'structured_log' referenced before assignment
carry r+ forward

Thanks TYLin, fixed that bug and looks like it eliminates the duplicated output.

https://tbpl.mozilla.org/?rev=b2186e7af31b&tree=Try
Attachment #8465979 - Attachment is obsolete: true
Attachment #8466376 - Flags: review+
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/4c8452cc4511
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → mozilla34
You need to log in before you can comment on or make changes to this bug.