809529 - Ensure B2G failures are printed as ERRORS so TBPL can parse them

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Comment 1

[Andrew Halberstadt [:ahal]]

Attachment: Patch 1.0 - Add error messages

Comment 2

[Andrew Halberstadt [:ahal]]

https://hg.mozilla.org/build/mozharness/rev/e32ed3d9681f

Comment 3

[Ed Morley [:emorley]]

If I'm reading the attached patch correctly, it should catch errors of the form:
"03:22:54     INFO -  : Timeout waiting for marionette on port '40169'"

but we're unfortunately not, eg: 
https://tbpl.mozilla.org/php/getParsedLog.php?id=16986938&tree=Mozilla-Inbound

Comment 4

[Ed Morley [:emorley]]

(Also, what's with the leading colon?)

Comment 5

[Andrew Halberstadt [:ahal]]

Weird, it's thrown here: http://mxr.mozilla.org/mozilla-central/source/testing/marionette/client/marionette/emulator.py#415

Mozharness must be munging the error message and the colon is probably why it isn't getting caught.

Comment 6

[Ed Morley [:emorley]]

Is there a bug filed for making sure the last line of a traceback is always printed on an ERROR line?

Comment 7

[Ed Morley [:emorley]]

(Seeing as it would stop us having to hardcode these)

Comment 8

[Ed Morley [:emorley]]

Also:
23:16:13     INFO -  MarionetteException: Could not successfully complete transport of message to Gecko, socket closed?
https://tbpl.mozilla.org/php/getParsedLog.php?id=17057752&tree=Mozilla-Inbound#error0

Comment 9

[Andrew Halberstadt [:ahal]]

So to recap, we have two exceptions (though we should hunt down the others while we are at it):
MarionetteException: Could not successfully complete transport of message to Gecko, socket closed?
Timeout waiting for marionette on port 'nnnnn'

Also the latter should read "TimeoutException: Timeout waiting for marionette on port 'nnnnn'" but for some reason mozharness is only dumping out  ": Timeout waiting for..."

:aki, would you be able to look into this? I'll do it otherwise.

Comment 10

[Ed Morley [:emorley]]

And also:
23:33:46     INFO -  : Timeout waiting for the b2g process to start

But the v4 patch in bug 809437 removes some of the strings iirc?

Comment 11

[Andrew Halberstadt [:ahal]]

(In reply to Ed Morley [:edmorley UTC+0] from comment #10)
> But the v4 patch in bug 809437 removes some of the strings iirc?

Yep, it removes the "Timeout waiting for the B2G process to terminate" string. So we should remove that while we are at it. The other string is still possible and the "Could not successfully complete transport of message to Gecko" one is a generic error that can happen anywhere we use marionette when the server hasn't started up, so it should be added.

Comment 12

[Aki Sasaki (not active)]

(In reply to Ed Morley [:edmorley UTC+0] from comment #6)
> Is there a bug filed for making sure the last line of a traceback is always
> printed on an ERROR line?

bug 688338 would allow us to easily.

Comment 13

[Aki Sasaki (not active)]

Or less difficult, at least.

(In reply to Andrew Halberstadt [:ahal] from comment #5)
> Weird, it's thrown here:
> http://mxr.mozilla.org/mozilla-central/source/testing/marionette/client/
> marionette/emulator.py#415
> 
> Mozharness must be munging the error message and the colon is probably why
> it isn't getting caught.

substr shouldn't care where in the string it is...
I should be able to add TimeoutException and MarionetteException pretty easily.

Comment 14

[Andrew Halberstadt [:ahal]]

Theoretically any of these exceptions can be thrown: http://mxr.mozilla.org/mozilla-central/source/testing/marionette/client/marionette/errors.py

Though in practice I'm not sure how many of them are actually used.

Comment 15

[Aki Sasaki (not active)]

Attachment: all emulator exceptions in a regex

Comment 16

[Andrew Halberstadt [:ahal]]

Comment on attachment 682057 [details] [diff] [review]
all emulator exceptions in a regex

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

So this patch looks good, but I don't think it will work. The problem we are seeing is despite these messages being here they are still being printed at the INFO level. I have no idea why. (see https://tbpl.mozilla.org/php/getParsedLog.php?id=17071920&tree=Mozilla-Inbound). Instead all errors are just "Error: Return code 1"

Also could you remove the 'Timeout waiting for the b2g process to terminate' message? That is no longer being raised.

Comment 17

[Aki Sasaki (not active)]

Attachment: with a couple more tweaks

[11:03]	<aki>	ahal: i'm not sure why the line that starts with the : doesn't get caught, but it would catch this line above: 09:44:43 INFO - raise TimeoutException("Timeout waiting for marionette on port '%s'" % self.marionette_port)

My current guess is this error is eating the TimeoutException: "BaseException.message has been deprecated as of Python 2.6"

09:44:43     INFO -      raise TimeoutException("Timeout waiting for marionette on port '%s'" % self.marionette_port)
09:44:43     INFO -  marionette.errors.TimeoutException/home/cltbld/talos-slave/test/build/venv/lib/python2.6/site-packages/marionette/errors.py:18: DeprecationWarning: BaseException.message has been deprecated as of Python 2.6
09:44:43     INFO -    return str(self.message)

Comment 18

[Andrew Halberstadt [:ahal]]

Comment on attachment 682087 [details] [diff] [review]
with a couple more tweaks

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

Ok, let's land. I'll file a bug to get rid of the deprecation warning and we'll see what happens. Thanks! r+ with one nit.

::: scripts/marionette.py
@@ +79,5 @@
>  
>      error_list = [
>          {'substr': 'FAILED (errors=', 'level': ERROR},
>          {'substr': r'''Could not successfully complete transport of message to Gecko, socket closed''', 'level': ERROR},
>          {'substr': 'Timeout waiting for the b2g process to terminate', 'level': ERROR},

Forgot to remove this here

Comment 19

[Aki Sasaki (not active)]

Comment on attachment 682087 [details] [diff] [review]
with a couple more tweaks

Also added a missing 'import re' that I found while running unit.sh.
http://hg.mozilla.org/build/mozharness/rev/817d3b48fefc

We should be able to see its effect on any job starting after that.

Comment 20

[Aki Sasaki (not active)]

And, as :ahal expected, not fixed:
http://buildbot-master24.build.scl1.mozilla.com:8201/builders/b2g_ics_armv7a_gecko_emulator%20mozilla-inbound%20opt%20test%20reftest-2/builds/83/steps/run_script/logs/stdio

Comment 21

[Aki Sasaki (not active)]

Attachment: duh

Comment 22

[Andrew Halberstadt [:ahal]]

Comment on attachment 682307 [details] [diff] [review]
duh

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

Heh

Comment 23

[Aki Sasaki (not active)]

Comment on attachment 682307 [details] [diff] [review]
duh

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