1219467 - ./mach web-platform-tests --e10s doesn't work

Status: RESOLVED WORKSFORME

(Testing :: web-platform-tests, defect)

Description

[(no longer active)]

We open the Firefox window and die shortly after for some reason, and then we fall into a loop until the test runner gives up.  This is on OSX on a debug build.

$ ./mach web-platform-tests --e10s _mozilla
 0:01.71 LOG: MainThread INFO Using 1 client processes
 0:03.15 LOG: MainThread wptserve INFO Starting http server on 127.0.0.1:8000
 0:03.15 LOG: MainThread wptserve INFO Starting http server on 127.0.0.1:8001
 0:03.15 LOG: MainThread wptserve INFO Starting http server on 127.0.0.1:8443
 0:03.79 SUITE_START: MainThread 89
 0:03.79 LOG: MainThread INFO Running testharness tests
 0:03.79 TEST_START: MainThread /_mozilla/service-workers/service-worker/resource-timing.https.html
 0:03.79 TEST_END: MainThread SKIP
 0:03.87 LOG: Thread-TestrunnerManager-1 INFO Setting up ssl
 0:03.91 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) Full command: /Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/certutil -N -d /var/folders/ry/m4kkhrl17c76cqyfd5qv5sph0000gn/T/tmpIW3b7p.mozrunner -f /var/folders/ry/m4kkhrl17c76cqyfd5qv5sph0000gn/T/tmpIW3b7p.mozrunner/.crtdbpw
(pid:certutil) ""
 0:03.95 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) ""
 0:04.14 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) "
Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

web-platform-tests                                           CT,,
"
 0:04.17 LOG: Thread-TestrunnerManager-1 INFO Starting runner
 0:08.93 PROCESS_OUTPUT: ProcessReader (pid:60434) Full command: /Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/firefox --marionette about:blank -foreground -profile /var/folders/ry/m4kkhrl17c76cqyfd5qv5sph0000gn/T/tmpIW3b7p.mozrunner
(pid:60434) "1446071355558	Marionette	INFO	Marionette enabled via build flag and pref"
 0:09.64 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOCSHELL 0x120424f00 == 1 [pid = 60434] [id = 1]"
 0:09.64 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOMWINDOW == 1 (0x12043fc00) [pid = 60434] [serial = 1] [outer = 0x0]"
 0:09.70 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOMWINDOW == 2 (0x120527800) [pid = 60434] [serial = 2] [outer = 0x12043fc00]"
 0:11.13 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071357755	Marionette	INFO	Listening on port 2828"
 0:17.23 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071363859	Marionette	INFO	Marionette enabled via command-line flag"
 0:17.27 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOCSHELL 0x12b310100 == 2 [pid = 60434] [id = 2]"
 0:17.28 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOMWINDOW == 3 (0x12b8ae000) [pid = 60434] [serial = 3] [outer = 0x0]"
 0:17.28 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOMWINDOW == 4 (0x12b8ae400) [pid = 60434] [serial = 4] [outer = 0x12b8ae000]"
 0:17.99 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071364625	Marionette	INFO	Accepted connection conn0 from 127.0.0.1:50839"
 0:17.99 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071364627	Marionette	DEBUG	conn0 client <- {"applicationType":"gecko","marionetteProtocol":2}"
 0:18.62 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071365249	Marionette	INFO	Closed connection conn0"
 0:18.66 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071365282	Marionette	INFO	Accepted connection conn1 from 127.0.0.1:50841"
 0:18.66 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071365284	Marionette	DEBUG	conn1 client <- {"applicationType":"gecko","marionetteProtocol":2}"
 0:18.73 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: Loaded script chrome://global/content/printUtils.js twice (bug 392650): file /Users/ehsan/moz/src/dom/xul/nsXULPrototypeCache.cpp, line 219"
 0:18.74 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: Loaded script chrome://global/content/viewZoomOverlay.js twice (bug 392650): file /Users/ehsan/moz/src/dom/xul/nsXULPrototypeCache.cpp, line 219"
 0:18.77 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071365399	Marionette	INFO	Accepted connection conn2 from 127.0.0.1:50842"
 0:18.77 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071365406	Marionette	DEBUG	conn2 client <- {"applicationType":"gecko","marionetteProtocol":2}"
 0:18.81 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071365436	Marionette	INFO	Closed connection conn2"
 0:18.82 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071365451	Marionette	DEBUG	conn1 -> {"name":"newSession","parameters":{"sessionId":null,"capabilities":null}}"
 0:18.96 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: Loaded script chrome://browser/content/places/browserPlacesViews.js twice (bug 392650): file /Users/ehsan/moz/src/dom/xul/nsXULPrototypeCache.cpp, line 219"
 0:22.57 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: Loaded script chrome://browser/content/browser.js twice (bug 392650): file /Users/ehsan/moz/src/dom/xul/nsXULPrototypeCache.cpp, line 219"
 0:22.88 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: Loaded script chrome://browser/content/downloads/downloads.js twice (bug 392650): file /Users/ehsan/moz/src/dom/xul/nsXULPrototypeCache.cpp, line 219"
 0:22.97 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: Loaded script chrome://browser/content/downloads/indicator.js twice (bug 392650): file /Users/ehsan/moz/src/dom/xul/nsXULPrototypeCache.cpp, line 219"
 0:23.06 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: Loaded script chrome://browser/content/customizableui/panelUI.js twice (bug 392650): file /Users/ehsan/moz/src/dom/xul/nsXULPrototypeCache.cpp, line 219"
 0:23.18 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: Loaded script chrome://global/content/viewSourceUtils.js twice (bug 392650): file /Users/ehsan/moz/src/dom/xul/nsXULPrototypeCache.cpp, line 219"
 0:23.20 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /Users/ehsan/moz/src/parser/html/nsHtml5StreamParser.cpp, line 966"
 0:24.32 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOCSHELL 0x12a776500 == 3 [pid = 60434] [id = 3]"
 0:24.32 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOMWINDOW == 5 (0x12d797800) [pid = 60434] [serial = 5] [outer = 0x0]"
 0:24.32 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOCSHELL 0x12a776a00 == 4 [pid = 60434] [id = 4]"
 0:24.32 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOMWINDOW == 6 (0x12ea8d400) [pid = 60434] [serial = 6] [outer = 0x0]"
 0:26.04 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /Users/ehsan/moz/src/dom/base/nsFrameLoader.cpp, line 272"
 0:26.52 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOCSHELL 0x12d6d7c00 == 5 [pid = 60434] [id = 5]"
 0:26.52 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOMWINDOW == 7 (0x12c360000) [pid = 60434] [serial = 7] [outer = 0x0]"
 0:26.56 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /Users/ehsan/moz/src/dom/base/nsFrameLoader.cpp, line 272"
 0:26.87 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOMWINDOW == 8 (0x130bdd400) [pid = 60434] [serial = 8] [outer = 0x12c360000]"
 0:27.39 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: NS_ENSURE_TRUE(mTextInputHandler) failed: file /Users/ehsan/moz/src/widget/cocoa/nsChildView.mm, line 5375"
 0:27.51 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOMWINDOW == 9 (0x13093e800) [pid = 60434] [serial = 9] [outer = 0x12d797800]"
 0:27.54 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOMWINDOW == 10 (0x13093ec00) [pid = 60434] [serial = 10] [outer = 0x12ea8d400]"
 0:27.58 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOMWINDOW == 11 (0x130940800) [pid = 60434] [serial = 11] [outer = 0x12c360000]"
 0:27.89 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: NS_ENSURE_TRUE(mTextInputHandler) failed: file /Users/ehsan/moz/src/widget/cocoa/nsChildView.mm, line 5375"
 0:31.12 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071377748	Marionette	INFO	loaded listener.js"
 0:31.24 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071377878	Marionette	INFO	loaded listener.js"
 0:32.24 PROCESS_OUTPUT: ProcessReader (pid:60434) "++DOMWINDOW == 12 (0x12ea3c400) [pid = 60434] [serial = 12] [outer = 0x12c360000]"
 0:32.55 PROCESS_OUTPUT: ProcessReader (pid:60434) "1446071379182	Marionette	DEBUG	conn1 client <- {"sessionId":"66e9c9ac-07d7-954a-82aa-7d6e2d5a75b4","capabilities":{"browserName":"Firefox","browserVersion":"44.0a1","platformName":"DARWIN","platformVersion":"44.0a1","specificationLevel":"1","raisesAccessibilityExceptions":false,"rotatable":false,"acceptSslCerts":false,"takesElementScreenshot":true,"takesScreenshot":true,"proxy":{},"platform":"DARWIN","XULappId":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","appBuildId":"20151028174147","device":"desktop","version":"44.0a1"}}"
 0:33.31 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: NS_ENSURE_TRUE(window) failed: file /Users/ehsan/moz/src/dom/base/nsFocusManager.cpp, line 566"
 0:33.31 PROCESS_OUTPUT: ProcessReader (pid:60434) "[60434] WARNING: NS_ENSURE_TRUE(windowToFocus) failed: file /Users/ehsan/moz/src/dom/base/nsFocusManager.cpp, line 397"
 0:33.84 LOG: Thread-TestrunnerManager-1 WARNING Init failed 1
 0:33.98 LOG: Thread-TestrunnerManager-1 WARNING u'log' (u'warning', {'message': 'Starting marionette session failed: Connection to Marionette server is lost. Check gecko.log (desktop firefox) or logcat (b2g) for errors.'})
 0:33.98 LOG: Thread-TestrunnerManager-1 WARNING u'log' (u'warning', {'message': 'Failed to connect to Marionette'})
 0:33.98 LOG: Thread-TestrunnerManager-1 WARNING 'init_failed' ()
 0:33.98 LOG: Thread-TestrunnerManager-1 WARNING u'runner_teardown' ()
 0:34.02 LOG: Thread-TestrunnerManager-1 INFO Setting up ssl
 0:34.06 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) ""
 0:34.10 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) ""
 0:34.13 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) "
Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

web-platform-tests                                           CT,,
"
 0:34.17 LOG: Thread-TestrunnerManager-1 INFO Starting runner
(looping...)

Comment 1

[James Graham [:jgraham]]

Looks like something is going wrong establishing the marionette connection, but I'm not sure. I can make a linux debug build and see if I can reproduce.

Comment 2

[(no longer active)]

Please do.  Also let me know if there is something I can do to work around this and/or get more info.

Comment 3

[James Graham [:jgraham]]

Hmm, I rather misread the log yesterday; the browser at least gets as far as trying to send a response when trying to establish the connection, but the start_session call must nevertheless be throwing an exception for some reason.

You could try editing testing/web-platform/harness/wptrunner/executors/executormarionette.py:74 s/self.logger.warning("Starting marionette session failed: %s" % e)/self.logger.warning("Starting marionette session failed: %s" % traceback.format_exc(e))/ to give you a better idea of what's going wrong. Also, is this reproducible? I saw an error once, but not after that, when I tried with a Linux debug build and e10s.

Comment 4

[(no longer active)]

I tried your suggestion, but realized that I can't reproduce any more...  :/