1016371 - Annotated summaries & reftest excerpts should not include redundant TEST-UNEXPECTED- lines from Android/B2G logcats

Status: RESOLVED FIXED

(Tree Management Graveyard :: TBPL, defect)

Description

[Andrew Halberstadt [:ahal]]

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.

Comment 1

[Andrew Halberstadt [:ahal]]

Attachment: logcat_summary_print

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! :)

Comment 2

[Andrew Halberstadt [:ahal]]

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.

Comment 3

[Ed Morley [:emorley]]

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.

Comment 4

[Ed Morley [:emorley]]

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

Comment 5

[Ed Morley [:emorley]]

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

Comment 6

[Ed Morley [:emorley]]

I mean lookbehind, not lookahead.

Anyway, I'll play around with this more tomorrow :-)

Comment 7

[Ed Morley [:emorley]]

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?

Comment 8

[Ed Morley [:emorley]]

(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 :-/

Comment 9

[Ed Morley [:emorley]]

s/change/chance/

Comment 10

[Ed Morley [:emorley]]

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

Comment 11

[Geoff Brown [:gbrown]]

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.

Comment 12

[Ed Morley [:emorley]]

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.

Comment 13

[Ed Morley [:emorley]]

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.

Comment 14

[Ed Morley [:emorley]]

Attachment: Don't match against TEST-UNEXPECTED- logcat lines

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 15

[Andrew Halberstadt [:ahal]]

Comment on attachment 8442928 [details] [diff] [review]
Don't match against TEST-UNEXPECTED- logcat lines

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

Thanks!

Comment 16

[Ed Morley [:emorley]]

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.

Comment 17

[Ed Morley [:emorley]]

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