823090 - Reduce redundant Marionette failure lines marked as log level ERROR (and thus shown in TBPL annotated summary)

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[Ed Morley [:emorley]]

A fairly typical Marionette failure shows in TBPL's annotated summary as:
{
08:02:51    ERROR -  Traceback (most recent call last):
08:02:51     INFO -  TEST-UNEXPECTED-FAIL | test_specialpowers.py TestSpecialPowersContent.test_prefs | EOFError: telnet connection closed
08:02:51    ERROR -  Traceback (most recent call last):
08:02:51     INFO -  TEST-UNEXPECTED-FAIL | test_specialpowers.py TestSpecialPowersContent.test_prefs_after_navigate | error: [Errno 111] Connection refused
08:02:51    ERROR -  FAILED (errors=2)
08:02:51    ERROR -  Traceback (most recent call last):
08:02:51     INFO -  TEST-UNEXPECTED-FAIL | test_appcache.py AppCacheTests.testWeCanGetTheStatusOfTheAppCache | error: [Errno 111] Connection refused
08:02:51    ERROR -  FAILED (errors=1)
08:02:51    ERROR -  Traceback (most recent call last):
08:02:51     INFO -  TEST-UNEXPECTED-FAIL | test_screenshot.py ScreenshotTests.testWeCanTakeAScreenShotEntireCanvas | error: [Errno 111] Connection refused
08:02:51    ERROR -  Traceback (most recent call last):
08:02:51     INFO -  TEST-UNEXPECTED-FAIL | test_screenshot.py ScreenshotTests.testWeCanTakeAScreenShotOfAnElement | error: [Errno 111] Connection refused
08:02:51    ERROR -  FAILED (errors=2)
08:02:52    ERROR - Return code: 10
}

For cases where only one or two tests fail, this is already pretty verbose; for those where we carry on through the testsuite failing every test (eg due to bug  813292), it's even harder to skim read and work out what has gone wrong when sheriffing. (And if I find it hard, the devs who only look at TBPL are going to find it even harder, which from my experience leads to things like them ignoring oranges on Try, and breaking the tree when they land).

The above output ideally would have been something like:
{
08:02:51     INFO -  TEST-UNEXPECTED-FAIL | test_specialpowers.py TestSpecialPowersContent.test_prefs | EOFError: telnet connection closed
08:02:51     INFO -  TEST-UNEXPECTED-FAIL | test_specialpowers.py TestSpecialPowersContent.test_prefs_after_navigate | error: [Errno 111] Connection refused
08:02:51     INFO -  TEST-UNEXPECTED-FAIL | test_appcache.py AppCacheTests.testWeCanGetTheStatusOfTheAppCache | error: [Errno 111] Connection refused
08:02:51     INFO -  TEST-UNEXPECTED-FAIL | test_screenshot.py ScreenshotTests.testWeCanTakeAScreenShotEntireCanvas | error: [Errno 111] Connection refused
08:02:51     INFO -  TEST-UNEXPECTED-FAIL | test_screenshot.py ScreenshotTests.testWeCanTakeAScreenShotOfAnElement | error: [Errno 111] Connection refused
}

For reference, TBPL's parser is matching against the "<datetime>   ERROR - " or else the "TEST-UNEXPECTED-FAIL":
https://hg.mozilla.org/webtools/tbpl/file/tip/php/inc/GeneralErrorFilter.php#l25

If you didn't want some of these lines marked as INFO, we could instead decide which of "ERROR|CRITICAL|FATAL" counted as a line that we want to display in TBPL, adjust TBPLs regexes and switch things around in mozharness/marionette appropriately.

Thank you :-)

Comment 1

[Ed Morley [:emorley]]

This contributed to sheriffs mistaking one failure mode as another last night, which combined with coalescing, meant permaorange was left in for hours unnoticed :-(

Comment 2

[Ed Morley [:emorley]]

Please may someone take a look at this? :-)

Comment 3

[Aki Sasaki (not active)]

This is desktop marionette, not b2g emulator marionette-webapi?

Comment 4

[Ed Morley [:emorley]]

eg:
b2g_ics_armv7a_gecko_emulator_vm mozilla-central opt test marionette-webapi
https://tbpl.mozilla.org/php/getParsedLog.php?id=20646184&tree=Firefox

{
07:07:27    ERROR -  Traceback (most recent call last):
07:07:27    ERROR -      raise TimeoutException(message='socket.timeout', status=ErrorCodes.TIMEOUT, stacktrace=None)
07:07:27    ERROR -  errors.TimeoutException: socket.timeout
07:07:28    ERROR - Return code: 1
07:07:28    ERROR - Marionette exited with return code 1: harness failures
07:07:28    ERROR - # TBPL FAILURE #
}

Should be something like:
{
07:07:27    ERROR -  errors.TimeoutException: socket.timeout
}

Comment 5

[Aki Sasaki (not active)]

Attachment: reduce marionette errors

This will get rid of the Traceback and FAILED tbpl matches.

Comment 6

[Jonathan Griffin (:jgriffin)]

Comment on attachment 724979 [details] [diff] [review]
reduce marionette errors

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

lgtm

Comment 7

[Aki Sasaki (not active)]

Comment on attachment 724979 [details] [diff] [review]
reduce marionette errors

http://hg.mozilla.org/build/mozharness/rev/eb53ac7a8bc0

Comment 8

[Aki Sasaki (not active)]

Merged to production.  This should be fixed.

Comment 9

[Ed Morley [:emorley]]

Thank you :-)