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

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Ting-Yu Lin [:TYLin] (UTC+8) (Traveling Nov 23 - Dec 15)]

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

Comment 1

[Ed Morley [:emorley]]

Thank you for filing :-)
TBPL only displays the results and logs generated elsewhere - moving to mochitest.

Comment 2

[Ed Morley [:emorley]]

Good:
https://tbpl.mozilla.org/php/getParsedLog.php?id=44896337&full=1&branch=mozilla-inbound

Bad:
https://tbpl.mozilla.org/php/getParsedLog.php?id=44895449&full=1&branch=mozilla-inbound

Caused by:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&rev=327f8728d818
Bug 1044206 - Revert the global logger in mochitest's runtests to use python stdlib logging for compatibility with mozharness regex.;r=ahal

Comment 3

[Ahmed Kachkach [:akachkach]]

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)?

Comment 4

[James Graham [:jgraham]]

Yes, all loggers with the same name share the same handlers.

Comment 5

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1046566-avoid-instantiating-multiple-structured-.patch

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

Comment 6

[Andrew Halberstadt [:ahal]]

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.

Comment 7

[Ting-Yu Lin [:TYLin] (UTC+8) (Traveling Nov 23 - Dec 15)]

I notice that B2G Desktop Linux Opt had an exception.

UnboundLocalError: local variable 'structured_log' referenced before assignment

Comment 8

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1046566-avoid-instantiating-multiple-structured-.patch

carry r+ forward

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

https://tbpl.mozilla.org/?rev=b2186e7af31b&tree=Try

Comment 9

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/fx-team/rev/4c8452cc4511

Comment 10

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/4c8452cc4511