1006511 - Marionette timeouts shouldn't print the ScriptTimeoutException traceback to the log

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[Ed Morley [:emorley]]

eg:
https://tbpl.mozilla.org/php/getParsedLog.php?id=39122484&tree=Mozilla-Inbound
{
04:16:29     INFO -  ======================================================================
04:16:29     INFO -  ERROR: None
04:16:29     INFO -  ----------------------------------------------------------------------
04:16:29     INFO -  Traceback (most recent call last):
04:16:29     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 170, in run
04:16:29     INFO -      testMethod()
04:16:29     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 497, in runTest
04:16:29     INFO -      filename=os.path.basename(self.jsFile))
04:16:29     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 1057, in execute_js_script
04:16:29     INFO -      line=None)
04:16:29     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/decorators.py", line 35, in _
04:16:29     INFO -      return func(*args, **kwargs)
04:16:29     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 631, in _send_message
04:16:29     INFO -      self._handle_error(response)
04:16:29     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 690, in _handle_error
04:16:29    ERROR -      raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
04:16:29    ERROR -  TEST-UNEXPECTED-FAIL | test_emergency_label.js | ScriptTimeoutException: ScriptTimeoutException: timed out
04:16:29     INFO -  ----------------------------------------------------------------------
04:16:29     INFO -  Ran 1 test in 61.776s
04:16:29  WARNING -  FAILED (errors=1)
}

The ScriptTimeoutException is just a Pythonic way to handle the timeout internally - we shouldn't print the traceback to the log, since it's going to confuse parsers.

We're handling the exception by printing the timeout line, and so the traceback is both unnecessarily worrying to the lay-person reading the logs - and doesn't really add any content.

Comment 1

[Ryan VanderMeulen [:RyanVM]]

Excellent, Dave and I were just discussing this yesterday.

Comment 2

[David Burns :automatedtester]

Attachment: Do not print script timeout messages to tbpl for marionette tests

Comment 3

[David Burns :automatedtester]

landed in https://hg.mozilla.org/integration/mozilla-inbound/rev/57cb8275056b

Comment 4

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/57cb8275056b

Comment 5

[Ed Morley [:emorley]]

Looking good - eg:
https://tbpl.mozilla.org/php/getParsedLog.php?id=39624242&tree=Mozilla-Inbound

Thank you :-)

Comment 6

[Zac C (:zac)]

Can we back this out?

On Gu this has caused the whole Traceback to disappear:


06:40:17     INFO -  TEST-START test_homescreen_edit_mode.py
06:41:10     INFO -  test_access_and_leave_edit_mode (test_homescreen_edit_mode.TestEditMode) ... ERROR
06:41:11     INFO -  ======================================================================
06:41:11     INFO -  ERROR: None
06:41:11     INFO -  ----------------------------------------------------------------------
06:41:11    ERROR -  TEST-UNEXPECTED-FAIL | test_homescreen_edit_mode.py test_homescreen_edit_mode.TestEditMode.test_access_and_leave_edit_mode | ScriptTimeoutException: ScriptTimeoutException: timed out
06:41:11     INFO -  ----------------------------------------------------------------------
06:41:11     INFO -  Ran 1 test in 54.008s
06:41:11  WARNING -  FAILED (errors=1)

Comment 7

[Ed Morley [:emorley]]

I'm happy to back this out temporarily, but we shouldn't be outputting a stacktrace anywhere IMO.

We should improve the content of the TEST-UNEXPECTED-FAIL line to include whatever line numbers amongst the rest of the stack that was useful for you - that way the info is more visible, since it will be in the log excerpt.

Comment 8

[Zac C (:zac)]

Thanks Ed.
We definitely need some information in there, we can't just have nothing!

Comment 9

[Jonathan Griffin (:jgriffin)]

In the case in the original description, the entire stack trace is useless, since JS files are executed using a single execute_async_script statement, and nothing in the traceback yields useful additional information.

In the case of Python tests, like gaia-ui-tests, the traceback points to which execute call is timing out, which is really important.

Comment 10

[David Burns :automatedtester]

What I can do is have a it print the stack if it is a python test and ignore it if it is a JS test.

Is that a good compromise?

I do wonder if we should be better to raise a different exception for the JS tests

Comment 11

[Ed Morley [:emorley]]

wfm for now :-)

Comment 12

[David Burns :automatedtester]

try 

https://tbpl.mozilla.org/?tree=Try&rev=41911879599d
https://tbpl.mozilla.org/?tree=Try&rev=fe4d37b34d12

Comment 13

[Ryan VanderMeulen [:RyanVM]]

We also need to do the same for "TimeoutException: TimeoutException: Connection timed out"

Comment 14

[Ed Morley [:emorley]]

I'm starring all Mnw "TimeoutException: TimeoutException: Connection timed out" failures generically (and have been since bug 948895 was resolved incomplete) due to this bug btw - since the bug suggestions list is too spammy to use in a timely manner. The try runs in comment 12 look good - let's get this landed! :-)

Comment 15

[David Burns :automatedtester]

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #13)
> We also need to do the same for "TimeoutException: TimeoutException:
> Connection timed out"

Timeout is actually useful since its a specific operation like loading a page. Script is overloaded since it can be run this arbitary bit of code or run this entire test.

Comment 16

[David Burns :automatedtester]

(In reply to Ed Morley [:edmorley UTC+0] from comment #14)
> I'm starring all Mnw "TimeoutException: TimeoutException: Connection timed
> out" failures generically (and have been since bug 948895 was resolved
> incomplete) due to this bug btw - since the bug suggestions list is too
> spammy to use in a timely manner. The try runs in comment 12 look good -
> let's get this landed! :-)

While this looks good for a sheriff it doesnt look good for anyone else and doesnt meet the compromise in comment 10. 

New try 

https://tbpl.mozilla.org/?tree=Try&rev=e7b98f18835e
https://tbpl.mozilla.org/?tree=Try&rev=50fc89334c88

Comment 17

[Ed Morley [:emorley]]

(In reply to David Burns :automatedtester from comment #16)
> While this looks good for a sheriff it doesnt look good for anyone else and
> doesnt meet the compromise in comment 10. 

Oh I thought I saw the tail end of a stack in the excerpt for gaia-ui tests; clearly not.

Comment 18

[Ed Morley [:emorley]]

The try runs in comment 16 look better - is this ready to land now? :-)

Comment 19

[David Burns :automatedtester]

Attachment: Print script timeout stacks if they came from a python test

Comment 20

[Jonathan Griffin (:jgriffin)]

Comment on attachment 8429612 [details] [diff] [review]
Print script timeout stacks if they came from a python test

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

::: testing/marionette/client/marionette/runner/base.py
@@ +230,5 @@
>                  if 'TEST-UNEXPECTED-FAIL' in line:
>                      fail_present = True
>              for line in err:
>                  if line != lastline or fail_present:
> +                    if re.match('.*\.js', test_name):

or just test_name.endswith('.js')?

Comment 21

[David Burns :automatedtester]

Discussed with jgriffin on irc. We can have situations where it can be testFile.js testClass.testName which the regex would handle. The Python tests report like that so if we make them the same we dont need to worry

Comment 22

[David Burns :automatedtester]

landed in https://hg.mozilla.org/integration/mozilla-inbound/rev/af55ccf5219b

Comment 23

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/af55ccf5219b

Comment 24

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/87a1b92e83dc
https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/43c35a6eddd1

https://hg.mozilla.org/releases/mozilla-b2g28_v1_3/rev/b9a78eeaa4fb
https://hg.mozilla.org/releases/mozilla-b2g28_v1_3/rev/a55e22f592ac