1403616 - Consumers of Marionette have to handle exceptions in start_session()

Status: RESOLVED FIXED

(Testing :: General, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

As we got informed by Greg today, there were crashes for mochitests in all builds. See bug 1403220 for details. Sadly for those test harnesses which use Marionette, the crashes are not getting reported. Instead we only see application disconnects for Marionette like in bug 1352671 and bug 1261598.

The problem here is that if a crash occurs Marionette driver still tries to connect to the application, and then after a timeout raises an exception. But this exception is not handled, and as such any clean-up and crash analysis is getting skipped. Here an example for Mochitests:

https://dxr.mozilla.org/mozilla-central/source/testing/mochitest/runtests.py#2156

Reftests should also be affected, maybe others too. I will have to check that.

To fix this, we should update the code so it uses a try/catch block for all Marionette code. If an error occurs it should be logged as an error, but the runner should continue to cleanup all state.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I got this reproduced by manually injecting a call to execute_script which crashes the browser right after `start_session`.

To fix that we have to put a try/finally block around all the Marionette code, and not try/except as mentioned above. As result we see the following:

Application command: /Volumes/data/code/gecko/obj/debug/dist/NightlyDebug.app/Contents/MacOS/firefox -marionette -foreground -profile /var/folders/4k/sf4gz5fn3kl9hr3nd7pzbvhc0000gn/T/tmpSFFvTV.mozrunner
runtests.py | Application pid: 50519
[..]
TEST-INFO | Main app process: exit 1
Buffered messages finished
0 ERROR TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code 1
runtests.py | Application ran for: 0:00:04.938802
zombiecheck | Reading PID log: /var/folders/4k/sf4gz5fn3kl9hr3nd7pzbvhc0000gn/T/tmpZ70EeFpidlog
mozcrash Copy/paste: /data/mozilla/macosx64-minidump_stackwalk /var/folders/4k/sf4gz5fn3kl9hr3nd7pzbvhc0000gn/T/tmpSFFvTV.mozrunner/minidumps/435EF165-A52E-4F45-9977-B137B6DCFDA9.dmp /Volumes/data/code/gecko/obj/debug/dist/crashreporter-symbols
PROCESS-CRASH | automation.py | application crashed [@ XUL + 0x4a09b0c]
[..]
Traceback (most recent call last):
[..]
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/transport.py", line 245, in send
    self.connect()
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/transport.py", line 223, in connect
    self.sock.connect((self.addr, self.port))
  File "/usr/local/Cellar/python/2.7.12_2/Frameworks/Python.framework/Versions/2.7/lib/python2.7/socket.py", line 228, in meth
    return getattr(self._sock,name)(*args)
error: [Errno 61] Connection refused
1 ERROR Automation Error: Received unexpected exception while running application

This will put the Marionette exception after the PROCESS_CRASH and leak log lines, which should be what we want to avoid mis-filing of bugs from Treeherder.

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The last comment was wrong in assuming that we can always defer re-raising the Marionette exception later. Given that we run all the tests through a script as executed via Marionette other exceptions could appear, which should not be deferred. As such we should use try/catch, but only defer IOError exceptions to after the post-test checks.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: Bug 1403616 - Defer logging of Marionette IOError to after post-test checks.

If Firefox crashes while mochitests or reftests are running, Marionette
will trigger an IOError exception which currently gets logged immediately,
and causes no post-test checks to be performed. This results in missing
crash and leak checks, and an unclear failure message on Treeherder.

With this change only the IOError from Marionette gets deferred until
all post-test checks are done. This fixes the failure messages, and will
put PROCESS_CRASH or leak log output first.

Review commit: https://reviewboard.mozilla.org/r/184184/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/184184/

Comment 4

[Geoff Brown [:gbrown]]

Comment on attachment 8912846 [details]
Bug 1403616 - Defer logging of Marionette IOError to after post-test checks.

https://reviewboard.mozilla.org/r/184184/#review189404

::: layout/tools/reftest/runreftest.py:737
(Diff revision 1)
> -                addons.install(options.specialPowersExtensionPath, temp=True)
> +                    addons.install(options.specialPowersExtensionPath, temp=True)
>  
> -            addons.install(options.reftestExtensionPath, temp=True)
> +                addons.install(options.reftestExtensionPath, temp=True)
>  
> -            marionette.delete_session()
> +                marionette.delete_session()
> +            except IOError:

Please add a comment here, and in runtests.py, explaining why the exception is being deferred, and why only IOError is being handled.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 8912846 [details]
Bug 1403616 - Defer logging of Marionette IOError to after post-test checks.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/184184/diff/1-2/

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Please see the following try job which shows the new way of reporting this failure:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=d0929f4e28f0&selectedJob=133746048

It's all fine now! \o/

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/82c2eecf82ba
Defer logging of Marionette IOError to after post-test checks. r=gbrown

Comment 8

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/82c2eecf82ba

Comment 9

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/2fbad6a28964