Anytime you click on a b2g emulator job, the blue suggestions box (and log annotations) have each test failure listed twice. This is because the TEST-UNEXPECTED- messages appear in both the normal logs, and the logcat which gets dumped at the end.

I think this might fix it. I'm not at all familiar with tbpl though, and I don't know how to test this.. so please be extra careful! :)

For some reason it looks like the Gecko logcat messages are now interleaved with the normal ones, while only the other stuff is dumped at the end. I'm not sure when this changed or whether it was intentional. Shouldn't need a change to the above patch though.

Example log output: https://tbpl.mozilla.org/php/getParsedLog.php?id=40455736&tree=Mozilla-Inbound 06:21:18 INFO - I/GeckoDump( 730): 110 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_bug1013809.html | pc_local: ICE failed to switch to 'connected' state: failed 06:21:18 INFO - 110 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_bug1013809.html | pc_local: ICE failed to switch to 'connected' state: failed and: https://tbpl.mozilla.org/php/getParsedLog.php?id=40429690&tree=Mozilla-Inbound I/Gecko ( 703): REFTEST TEST-UNEXPECTED-FAIL | http://10.0.2.2:8888/tests/layout/reftests/bugs/404553-1.html | image comparison (==), max difference: 255, number of differing pixels: 384 REFTEST TEST-UNEXPECTED-FAIL | http://10.0.2.2:8888/tests/layout/reftests/bugs/404553-1.html | image comparison (==), max difference: 255, number of differing pixels: 384 Also for Android robocop: https://tbpl.mozilla.org/php/getParsedLog.php?id=40420163&tree=Mozilla-Inbound 9 INFO TEST-UNEXPECTED-FAIL | testNewTab | Number of tabs increased - got 1, expected 2 junit.framework.AssertionFailedError: 9 INFO TEST-UNEXPECTED-FAIL | testNewTab | Number of tabs increased - got 1, expected 2 10 INFO TEST-UNEXPECTED-FAIL | testNewTab | Exception caught - junit.framework.AssertionFailedError: 9 INFO TEST-UNEXPECTED-FAIL | testNewTab | Number of tabs increased - got 1, expected 2 05-26 11:10:48.632 I/Robocop ( 2544): 9 INFO TEST-UNEXPECTED-FAIL | testNewTab | Number of tabs increased - got 1, expected 2 05-26 11:10:48.828 I/Robocop ( 2544): junit.framework.AssertionFailedError: 9 INFO TEST-UNEXPECTED-FAIL | testNewTab | Number of tabs increased - got 1, expected 2 05-26 11:10:48.828 I/Robocop ( 2544): 10 INFO TEST-UNEXPECTED-FAIL | testNewTab | Exception caught - junit.framework.AssertionFailedError: 9 INFO TEST-UNEXPECTED-FAIL | testNewTab | Number of tabs increased - got 1, expected 2 Thinking we can fix both at once.

Thank you for filing this - it's been bugging me for a while! :-)

Comment on attachment 8429288 [details] [diff] [review] logcat_summary_print Review of attachment 8429288 [details] [diff] [review]: ----------------------------------------------------------------- Thank you for the patch! :-) Unfortunately the fullLine variable doesn't start with the logcat prefix, so the start of line anchor won't match. Was thinking making this change as part of the main TEST-UNEXPECTED- line might be the best way of doing this (using a negative lookahead) - since the entries at the top are either temporary exceptions, or else perf optimisations. eg something like: (?<!I\/(Gecko|Robocop).*)TEST-UNEXPECTED- That regexp doesn't quite work, have been testing with: Should match: 06:21:18 INFO - 110 INFO TEST-UNEXPECTED-FAIL | testname | message 14:43:45 INFO - REFTEST TEST-UNEXPECTED-FAIL | testname | message 11:10:53 INFO - 9 INFO TEST-UNEXPECTED-FAIL | testname | message 11:10:53 INFO - junit.framework.AssertionFailedError: 9 INFO TEST-UNEXPECTED-FAIL | testname | message 11:10:53 INFO - 10 INFO TEST-UNEXPECTED-FAIL | testname | Exception caught - junit.framework.AssertionFailedError: 9 INFO TEST-UNEXPECTED-FAIL | testname | message Should not match: 06:21:18 INFO - I/GeckoDump( 730): 110 INFO TEST-UNEXPECTED-FAIL | testname | message 14:43:45 INFO - I/Gecko ( 703): REFTEST TEST-UNEXPECTED-FAIL | testname | message 11:10:55 INFO - 05-26 11:10:48.632 I/Robocop ( 2544): 9 INFO TEST-UNEXPECTED-FAIL | testname | message 11:10:55 INFO - 05-26 11:10:48.828 I/Robocop ( 2544): junit.framework.AssertionFailedError: message 11:10:55 INFO - 05-26 11:10:48.828 I/Robocop ( 2544): 10 INFO TEST-UNEXPECTED-FAIL | testname | Exception caught - junit.framework.AssertionFailedError: message Using: http://www.phpliveregex.com/p/5oo

I mean lookbehind, not lookahead. Anyway, I'll play around with this more tomorrow :-)

So after playing around, I've decided that using lookbehind is too messy, so I'm going with your approach of exclusion. However we'll need to support robocop, and use $line rather than $fullLine. eg something like: + // Exclude TEST-UNEXPECTED- messages that appear in Android & B2G logcats since + // they are already printed in the main part of the log. + if (preg_match("/^I\/(Gecko|Robocop).*TEST-UNEXPECTED-/", $line)) + return false; However, I've also spotted instances like: https://tbpl.mozilla.org/php/getParsedLog.php?id=41039512&tree=Mozilla-Central (b2g_emulator_vm mozilla-central debug test mochitest-debug-1) 09:30:36 INFO - 06-04 15:53:23.878 751 751 I GeckoDump: 201 INFO TEST-UNEXPECTED-FAIL | /tests/content/base/test/csp/test_bug836922_npolicies.html | Received (0/1) enforced-policy reports for css_examplecom ...where we prefix the logcat with a timestamp, as well as strip the forward slashes after the "I" - helpful! So I guess we'll either need to cleanup the logcat dump (and make it more consistent across all the places we print it to the log) or use something like: if (preg_match("/^(I\/(Gecko|Robocop)|.* I GeckoDump:).*TEST-UNEXPECTED-/", $line)) Do you know where the prefixed logcat dump comes from?

(In reply to Ed Morley [:edmorley UTC+0] from comment #7) > or use something like: > > if (preg_match("/^(I\/(Gecko|Robocop)|.* I GeckoDump:).*TEST-UNEXPECTED-/", > $line)) Actually that wouldn't match some of the Robocop examples in comment 5, which are also prefixed, but don't have the slashes removed. Something like this might work: if (preg_match("/I[ \/](Gecko|Robocop).*TEST-UNEXPECTED-/", $line)) ...though the change of false positives is not insignificant now :-/

s/change/chance/

(In reply to Ed Morley [:edmorley UTC+0] from comment #7) > However, I've also spotted instances like: > https://tbpl.mozilla.org/php/getParsedLog.php?id=41039512&tree=Mozilla- > Central > (b2g_emulator_vm mozilla-central debug test mochitest-debug-1) > 09:30:36 INFO - 06-04 15:53:23.878 751 751 I GeckoDump: 201 INFO > TEST-UNEXPECTED-FAIL | > /tests/content/base/test/csp/test_bug836922_npolicies.html | Received (0/1) > enforced-policy reports for css_examplecom > > ...where we prefix the logcat with a timestamp, as well as strip the forward > slashes after the "I" - helpful! > > So I guess we'll either need to cleanup the logcat dump (and make it more > consistent across all the places we print it to the log) or use something > like: > > if (preg_match("/^(I\/(Gecko|Robocop)|.* I GeckoDump:).*TEST-UNEXPECTED-/", > $line)) Geoff, do you know where the prefixed logcat dump (quoted) comes from?

No, not really. "GeckoDump" usually indicates a dump() call in js. For Android, I expect: 00:53:36 INFO - 06-12 00:09:35.600 I/GeckoDump( 647): Robocop:Quit received -- requesting quit ^^^^^^^^^^^^^^^^^^^^ ^^^^^^^^^^^^^^^^^^ ^^^^^^^^^^^^^^^^^^^ mozharness logger logcat timestamp logcat level/component(pid) I'm not familiar with the b2g logs though.

Ok thank you - I think this is B2G specific with the handling of the logcats by the harnesses after the run. Andrew, do you know why some of the B2G logcat dumps have different formatting / have been sanitised? eg "I GeckoDump" instead of the usual "I/GeckoDump" ? Normal format: https://tbpl.mozilla.org/php/getParsedLog.php?id=40429690&full=1&branch=mozilla-inbound#error0 b2g_emulator_vm mozilla-inbound opt test reftest-4 on 2014-05-26 13:48:30 PDT for push 779f6c203c03 { 14:43:45 INFO - E/GeckoConsole( 777): [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://10.0.2.2:8888/tests/layout/reftests/bugs/404553-1-ref.html" line: 0}] 14:43:45 INFO - E/GeckoConsole( 777): [JavaScript Warning: "No meta-viewport tag found. Please explicitly specify one to prevent unexpected behavioural changes in future versions. For more help https://developer.mozilla.org/en/docs/Mozilla/Mobile/Viewport_meta_tag" {file: "http://10.0.2.2:8888/tests/layout/reftests/bugs/404553-1-ref.html" line: 0}] 14:43:45 INFO - I/Gecko ( 703): REFTEST TEST-UNEXPECTED-FAIL | http://10.0.2.2:8888/tests/layout/reftests/bugs/404553-1.html | image comparison (==), max difference: 255, number of differing pixels: 384 } The other variant: https://tbpl.mozilla.org/php/getParsedLog.php?id=41039512&full=1&branch=mozilla-central#error1 b2g_emulator_vm mozilla-central debug test mochitest-debug-1 on 2014-06-04 08:25:35 PDT for push c7fdd7e755cd { 09:30:30 INFO - Mochitest INFO | runtestsb2g.py | Running tests: end. 09:30:34 INFO - Return code: 0 09:30:34 INFO - dumping logcat 09:30:34 INFO - Running command: ['cat', '/builds/slave/test/build/emulator-5554.log'] 09:30:34 INFO - Copy/paste: cat /builds/slave/test/build/emulator-5554.log 09:30:34 INFO - 06-04 15:29:18.648 35 35 I qemu-props: connected to 'boot-properties' qemud service. 09:30:34 INFO - 06-04 15:29:18.648 35 35 I qemu-props: receiving.. } Searching for "dumping logcat" implies the mangled format comes from: http://mxr.mozilla.org/build-central/source/mozharness/scripts/b2g_emulator_unittest.py#396 http://mxr.mozilla.org/build-central/source/mozharness/scripts/marionette.py#486 Whereas I think expected-format Android output comes from: http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/runtestsremote.py#497 http://mxr.mozilla.org/mozilla-central/source/layout/tools/reftest/remotereftest.py#403 Though I'm not sure where this expected-format B2G reftest output comes from: https://tbpl.mozilla.org/php/getParsedLog.php?id=40429690&tree=Mozilla-Inbound It would just help for this bug if the logcat format were consistent everywhere.

Oh, I think I answered my own question - the Android instances use: http://mxr.mozilla.org/mozilla-central/source/testing/mozbase/mozdevice/mozdevice/devicemanager.py#127 ...which uses (amongst other things): 135 cmdline = ["/system/bin/logcat", "-v", format, "-d"] + filterSpecs And the non-mangled B2G instances use also use device manager: http://mxr.mozilla.org/mozilla-central/source/testing/marionette/client/marionette/runner/mixins/b2g.py#76 And http://developer.android.com/tools/debugging/debugging-log.html#outputFormat says the default format is "brief", whereas when going via device manager's getLogcat() we set it to "time". Compare this to: http://mxr.mozilla.org/build-central/source/mozharness/scripts/marionette.py#486 http://mxr.mozilla.org/build-central/source/mozharness/scripts/b2g_emulator_unittest.py#396 Where we don't pass any params. I'll file another bug.

Hope you don't mind me taking this - thought you would have your hands full with bug 997244 :-) This patch: * Uses $line rather than $fullLine (the former has the mozharness log level and datetime stripped off for us already). * Doesn't use the start of line anchor, since anything that has come via the logcat.py wrapper has a time prefix. * Caters for the different process name during robocop runs. * Works with the 'threadtime' logcat format from B2G, that has a space instead of the forward slash before the process name (at least until bug 1027574 is fixed, at which point we can simplify this). * Adds the same check to ReftestFailureFilter.php, since that is what generates the log lines for the reftest analyser (and thus will help with bug 1016251). I'll test this in the VM locally to check for false positives/negatives :-)

Comment on attachment 8442928 [details] [diff] [review] Don't match against TEST-UNEXPECTED- logcat lines Review of attachment 8442928 [details] [diff] [review]: ----------------------------------------------------------------- Thanks!

Np; this bug has been annoying me for a while - I should have filed it sooner! I noticed I didn't add the same comment in ReftestFailureFilter.php as GeneralErrorFilter.php, so have added that locally.

Tested locally and check it allowed non TEST-EXPECTED logcat through & blocked the ones we were after + worked for reftest excerpts too. remote: https://hg.mozilla.org/webtools/tbpl/rev/1b41e6b5b765