Closed Bug 1338397 Opened 7 years ago Closed 7 years ago

Web platform test runner fails repeatedly to connect to marionette

Categories

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

Product:
Testing
Component:
web-platform-tests
Version:
Version 3
Platform:
x86
Windows 10
Type:
defect

Tracking

(firefox55 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla55
Tracking Flags:
Tracking Status
firefox55 --- fixed

People

(Reporter: birtles, Unassigned)

Details

Attachments

(3 files, 1 obsolete file)

Log after applying patch from bug 1315611
92.31 KB, text/plain
Details
bug.diff
13.68 KB, patch
birtles
: feedback+
Details | Diff | Splinter Review
Bug 1338397 - Use timeout multipler to adjust browser startup timeout in wpt,
59 bytes, text/x-review-board-request
impossibus
: review+
Details 
Yesterday I was experiencing the looping forever but failing to run web-platform-tests problem described in bug 1219467. It turned out that the problem was just that my machine was under load since I was building Firefox in another terminal. As soon as I finished building the test runner began working again. This was on a very high-end Windows machine.

Today, I am working on a very slightly less powerful Windows machine (top of the line Surface Book Pro) and I simply cannot get the test runner to succeed at all. It gets to the point where a Firefox window opens but it is soon closed. It seems like it gives up waiting just moments too soon.

My log is as follows:

$ mach web-platform-tests web-animations/interfaces/KeyframeEffect/processing-a-keyframes-argument.html
 0:00.26 LOG: Thread-Log INFO STDERR: Opening manifest at c:\moz\src\testing\web-platform\meta\MANIFEST.json
 0:01.13 LOG: Thread-Log INFO STDERR: Opening manifest at c:\moz\src\testing\web-platform\mozilla\meta\MANIFEST.json
 0:01.30 LOG: MainThread INFO Using 1 client processes
 0:03.91 SUITE_START: MainThread 1
 0:03.91 LOG: MainThread INFO Running reftest tests
 0:03.92 LOG: MainThread INFO No reftest tests to run
 0:03.92 LOG: MainThread INFO Running wdspec tests
 0:03.92 LOG: MainThread INFO No wdspec tests to run
 0:03.92 LOG: MainThread INFO Running testharness tests
 0:04.06 LOG: Thread-TestrunnerManager-1 INFO Setting up ssl
 0:04.12 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) Full command: c:/moz/src/obj-debug\dist\bin\certutil.exe -N -d c:\users\brian\appdata\local\temp\tmpner1kl.mozrunner -f c:\users\brian\appdata\local\temp\tmpner1kl.mozrunner\.crtdbpw
(pid:certutil) ""
 0:04.14 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) ""
 0:04.16 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) "
Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

web-platform-tests                                           CT,,
"
 0:04.16 LOG: Thread-TestrunnerManager-1 INFO Application command: c:/moz/src/obj-debug\dist\bin\firefox.exe -marionette about:blank -profile c:\users\brian\appdata\local\temp\tmpner1kl.mozrunner
 0:04.17 LOG: Thread-TestrunnerManager-1 INFO Starting runner
 0:05.48 PROCESS_OUTPUT: ProcessReader (pid:4564) Full command: c:/moz/src/obj-debug\dist\bin\firefox.exe -marionette about:blank -profile c:\users\brian\appdata\local\temp\tmpner1kl.mozrunner
(pid:4564) "[4564] WARNING: Failed to load startupcache file correctly, removing!: file c:/moz/src/startupcache/StartupCache.cpp, line 219"
 0:06.59 PROCESS_OUTPUT: ProcessReader (pid:4564) "[4564] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src/xpcom/base/nsSystemInfo.cpp, line 118"
 0:10.01 PROCESS_OUTPUT: ProcessReader (pid:4564) "[4564] WARNING: This method is lossy. Use GetCanonicalPath !: file c:/moz/src/xpcom/io/nsLocalFileWin.cpp, line 3573"
 0:22.95 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOCSHELL 09612400 == 1 [pid = 4564] [id = {5831b688-49b0-4696-9c99-7c9116ecde4a}]"
 0:22.95 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 1 (09612800) [pid = 4564] [serial = 1] [outer = 00000000]"
 0:22.95 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 2 (09613000) [pid = 4564] [serial = 2] [outer = 09612800]"
 0:23.77 PROCESS_OUTPUT: ProcessReader (pid:4564) "[GPU 10000] WARNING: '!compMgr', file c:/moz/src/xpcom/components/nsComponentManagerUtils.cpp, line 63"
 0:23.77 PROCESS_OUTPUT: ProcessReader (pid:4564) "[GPU 10000] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file c:/moz/src/modules/libpref/Preferences.cpp, line 1637"
 0:23.77 PROCESS_OUTPUT: ProcessReader (pid:4564) "[GPU 10000] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file c:\moz\src\obj-debug\dist\include\mozilla/Preferences.h, line 104"
 0:23.78 PROCESS_OUTPUT: ProcessReader (pid:4564) "[GPU 10000] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file c:/moz/src/modules/libpref/Preferences.cpp, line 1405"
 0:23.78 PROCESS_OUTPUT: ProcessReader (pid:4564) "[GPU 10000] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file c:/moz/src/modules/libpref/Preferences.cpp, line 1414"
 0:24.54 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOCSHELL 0BE66400 == 2 [pid = 4564] [id = {b3e953a2-659c-4314-819f-73b21fb8fe8a}]"
 0:24.54 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 3 (0BE66800) [pid = 4564] [serial = 3] [outer = 00000000]"
 0:24.55 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 4 (0BE67000) [pid = 4564] [serial = 4] [outer = 0BE66800]"
 0:27.19 PROCESS_OUTPUT: ProcessReader (pid:4564) "1486693312163        Marionette      INFO    Listening on port 2828"
 0:30.83 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOCSHELL 0E80F400 == 3 [pid = 4564] [id = {8866e6da-94dc-4ef0-8120-a4798d3a8c20}]"
 0:30.83 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 5 (0E80F800) [pid = 4564] [serial = 5] [outer = 00000000]"
 0:30.83 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 6 (0E810000) [pid = 4564] [serial = 6] [outer = 0E80F800]"
 0:32.80 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 7 (0ED26000) [pid = 4564] [serial = 7] [outer = 0BE66800]"
 0:35.61 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Child 9532] WARNING: '!compMgr', file c:/moz/src/xpcom/components/nsComponentManagerUtils.cpp, line 63"
 0:37.22 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Child 9532] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src/toolkit/xre/nsXREDirProvider.cpp, line 1699"
 0:37.23 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Child 9532] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src/xpcom/base/nsSystemInfo.cpp, line 118"
 0:38.82 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Parent 4564] WARNING: attempt to modify an immutable nsStandardURL: file c:/moz/src/netwerk/base/nsStandardURL.cpp, line 1639"
 0:39.26 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Parent 4564] WARNING: attempt to modify an immutable nsStandardURL: file c:/moz/src/netwerk/base/nsStandardURL.cpp, line 1639"
 0:39.38 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOCSHELL 05208400 == 1 [pid = 9532] [id = {2f0fc27b-19e4-463c-9361-8185e133ffe4}]"
 0:39.38 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 1 (05208800) [pid = 9532] [serial = 1] [outer = 00000000]"
 0:39.44 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Parent 4564] WARNING: Failed to retarget HTML data delivery to the parser thread.: file c:/moz/src/parser/html/nsHtml5StreamParser.cpp, line 984"
 0:40.21 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 2 (016C7000) [pid = 9532] [serial = 2] [outer = 05208800]"
 0:41.09 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 3 (05210C00) [pid = 9532] [serial = 3] [outer = 05208800]"
 0:42.55 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Parent 4564] WARNING: getting z level of unregistered window: file c:/moz/src/xpfe/appshell/nsWindowMediator.cpp, line 623"
 0:42.55 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Parent 4564] WARNING: getting z level of unregistered window: file c:/moz/src/xpfe/appshell/nsWindowMediator.cpp, line 623"
 0:42.59 PROCESS_OUTPUT: ProcessReader (pid:4564) "--DOCSHELL 09612400 == 2 [pid = 4564] [id = {5831b688-49b0-4696-9c99-7c9116ecde4a}]"
 0:42.92 PROCESS_OUTPUT: ProcessReader (pid:4564) "[GPU 10000] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:43.62 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Child 9532] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:43.62 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Child 9532] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:44.72 PROCESS_OUTPUT: ProcessReader (pid:4564) "[GPU 10000] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:44.72 PROCESS_OUTPUT: ProcessReader (pid:4564) "[GPU 10000] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:44.72 PROCESS_OUTPUT: ProcessReader (pid:4564) "[GPU 10000] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:44.72 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Child 9532] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file c:/moz/src/xpcom/threads/nsThread.cpp, line 1008"
 0:44.72 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Parent 4564] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:45.28 PROCESS_OUTPUT: ProcessReader (pid:4564) "--DOCSHELL 05208400 == 0 [pid = 9532] [id = {2f0fc27b-19e4-463c-9361-8185e133ffe4}]"
 0:45.28 PROCESS_OUTPUT: ProcessReader (pid:4564) "--DOMWINDOW == 2 (05208800) [pid = 9532] [serial = 1] [outer = 00000000] [url = chrome://gfxsanity/content/sanitytest.html]"
 0:45.29 PROCESS_OUTPUT: ProcessReader (pid:4564) "--DOMWINDOW == 1 (016C7000) [pid = 9532] [serial = 2] [outer = 00000000] [url = about:blank]"
 0:45.29 PROCESS_OUTPUT: ProcessReader (pid:4564) "--DOMWINDOW == 0 (05210C00) [pid = 9532] [serial = 3] [outer = 00000000] [url = chrome://gfxsanity/content/sanitytest.html]"
 0:45.39 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Child 9532] WARNING: '!compMgr', file c:/moz/src/xpcom/components/nsComponentManagerUtils.cpp, line 63"
 0:45.40 PROCESS_OUTPUT: ProcessReader (pid:4564) "nsStringStats"
 0:45.40 PROCESS_OUTPUT: ProcessReader (pid:4564) " => mAllocCount:          14620"
 0:45.40 PROCESS_OUTPUT: ProcessReader (pid:4564) " => mReallocCount:          301"
 0:45.40 PROCESS_OUTPUT: ProcessReader (pid:4564) " => mFreeCount:           14620"
 0:45.40 PROCESS_OUTPUT: ProcessReader (pid:4564) " => mShareCount:          11429"
 0:45.41 PROCESS_OUTPUT: ProcessReader (pid:4564) " => mAdoptCount:           1206"
 0:45.41 PROCESS_OUTPUT: ProcessReader (pid:4564) " => mAdoptFreeCount:       1206"
 0:45.41 PROCESS_OUTPUT: ProcessReader (pid:4564) " => Process ID: 9532, Thread ID: 1036"
 0:52.46 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOCSHELL 0FB76800 == 3 [pid = 4564] [id = {55ee0abe-e3f4-4208-8f47-212feb00e70f}]"
 0:52.47 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 8 (0FB77000) [pid = 4564] [serial = 8] [outer = 00000000]"
 0:52.51 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOCSHELL 0FB7F000 == 4 [pid = 4564] [id = {14b43f87-3ab2-4594-8ae1-b76e385884d7}]"
 0:52.51 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 9 (0FF86C00) [pid = 4564] [serial = 9] [outer = 00000000]"
 0:54.61 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOCSHELL 0DCECC00 == 5 [pid = 4564] [id = {e6a01526-c58d-47ed-8084-a13986146859}]"
 0:54.61 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 10 (0DCED000) [pid = 4564] [serial = 10] [outer = 00000000]"
 0:55.32 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 11 (0DCF6C00) [pid = 4564] [serial = 11] [outer = 0DCED000]"
 0:56.94 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 12 (0A628400) [pid = 4564] [serial = 12] [outer = 0FB77000]"
 0:57.04 PROCESS_OUTPUT: ProcessReader (pid:4564) "++DOMWINDOW == 13 (0A62A800) [pid = 4564] [serial = 13] [outer = 0FF86C00]"
 0:57.26 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Child 10592] WARNING: '!compMgr', file c:/moz/src/xpcom/components/nsComponentManagerUtils.cpp, line 63"
 0:58.90 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Child 10592] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src/toolkit/xre/nsXREDirProvider.cpp, line 1699"
 0:58.92 PROCESS_OUTPUT: ProcessReader (pid:4564) "[Child 10592] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src/xpcom/base/nsSystemInfo.cpp, line 118"
 1:03.95 LOG: Thread-TestrunnerManager-1 WARNING Init failed 1
 1:04.03 LOG: Thread-TestrunnerManager-1 WARNING u'log' (u'warning', {'message': 'Starting marionette session failed: [Errno 10054] \x8a\xf9\x91\xb6\x82\xcc\x90\xda\x91\xb1\x82\xcd\x83\x8a\x83\x82\x81[\x83g \x83z\x83X\x83g\x82\xc9\x8b\xad\x90\xa7\x93I\x82\xc9\x90\xd8\x92f\x82\xb3\x82\xea\x82\xdc\x82\xb5\x82\xbd\x81B'})
 1:04.03 LOG: Thread-TestrunnerManager-1 WARNING u'log' (u'warning', {'message': 'Failed to connect to Marionette'})
 1:04.03 LOG: Thread-TestrunnerManager-1 WARNING 'init_failed' ()
 1:04.03 LOG: Thread-TestrunnerManager-1 WARNING u'runner_teardown' ()
 1:04.19 LOG: Thread-TestrunnerManager-1 INFO Setting up ssl
 1:04.25 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) ""
 1:04.27 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) ""
 1:04.28 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) "
Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

web-platform-tests                                           CT,,
"
 1:04.35 LOG: Thread-TestrunnerManager-1 INFO Application command: c:/moz/src/obj-debug\dist\bin\firefox.exe -marionette about:blank -profile c:\users\brian\appdata\local\temp\tmpeuvmx6.mozrunner
 1:04.36 LOG: Thread-TestrunnerManager-1 INFO Starting runner
(and so on...)


Translating that error message:

$ python
>>> message = "\x8a\xf9\x91\xb6\x82\xcc\x90\xda\x91\xb1\x82\xcd\x83\x8a\x83\x82\x81[\x83g \x83z\x83X\x83g\x82\xc9\x8b\xad\x90\xa7\x93I\x82\xc9\x90\xd8\x92f\x82\xb3\x82\xea\x82\xdc\x82\xb5\x82\xbd\x81B"
>>> print message.decode('sjis')
既存の接続はリモート ホストに強制的に切断されました。

i.e. The existing connection was forcibly disconnected by the remote host.

So basically it seems my situation is: can't run wpt from anything but the most powerful computer and can't run it while compiling.

It would be nice to get a few more people running wpt on Windows. I seem to be hitting all the issues.
Actually, maybe it's not dependent on the power of the machine. Now even on my powerful machine I can't run web-platform-tests and get a similar error to the above:

$ mach test web-animations/interfaces
 0:00.76 LOG: Thread-Log INFO STDERR: Opening manifest at c:\moz\src\testing\web-platform\meta\MANIFEST.json
 0:01.66 LOG: Thread-Log INFO STDERR: Opening manifest at c:\moz\src\testing\web-platform\mozilla\meta\MANIFEST.json
 0:01.82 LOG: MainThread INFO Using 1 client processes
 0:04.49 SUITE_START: MainThread 41
 0:04.49 LOG: MainThread INFO Running reftest tests
 0:04.52 LOG: MainThread INFO No reftest tests to run
 0:04.52 LOG: MainThread INFO Running wdspec tests
 0:04.52 LOG: MainThread INFO No wdspec tests to run
 0:04.52 LOG: MainThread INFO Running testharness tests
 0:04.61 LOG: Thread-TestrunnerManager-1 INFO Setting up ssl
 0:04.64 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) Full command: c:/moz/src/obj-debug\dist\bin\certutil.exe -N -d c:\users\brian\appdata\local\temp\tmp8bdmnu.mozrunner -f c:\users\brian\appdata\local\temp\tmp8bdmnu.mozrunner\.crtdbpw
(pid:certutil) ""
 0:04.66 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) ""
 0:04.67 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) "
Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

web-platform-tests                                           CT,,
"
 0:04.67 LOG: Thread-TestrunnerManager-1 INFO Application command: c:/moz/src/obj-debug\dist\bin\firefox.exe -marionette about:blank -profile c:\users\brian\appdata\local\temp\tmp8bdmnu.mozrunner
 0:04.68 LOG: Thread-TestrunnerManager-1 INFO Starting runner
 0:05.32 PROCESS_OUTPUT: ProcessReader (pid:13764) Full command: c:/moz/src/obj-debug\dist\bin\firefox.exe -marionette about:blank -profile c:\users\brian\appdata\local\temp\tmp8bdmnu.mozrunner
(pid:13764) "[13764] WARNING: Failed to load startupcache file correctly, removing!: file c:/moz/src/startupcache/StartupCache.cpp, line 219"
 0:06.26 PROCESS_OUTPUT: ProcessReader (pid:13764) "[13764] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src/xpcom/base/nsSystemInfo.cpp, line 118"
 0:09.23 PROCESS_OUTPUT: ProcessReader (pid:13764) "[13764] WARNING: This method is lossy. Use GetCanonicalPath !: file c:/moz/src/xpcom/io/nsLocalFileWin.cpp, line 3573"
 0:20.10 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOCSHELL 17B66C00 == 1 [pid = 13764] [id = {5eaae348-b11d-4ea3-a7a2-4d117c337f45}]"
 0:20.10 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 1 (17B67000) [pid = 13764] [serial = 1] [outer = 00000000]"
 0:20.10 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 2 (17B67800) [pid = 13764] [serial = 2] [outer = 17B67000]"
 0:20.84 PROCESS_OUTPUT: ProcessReader (pid:13764) "[GPU 24544] WARNING: '!compMgr', file c:/moz/src/xpcom/components/nsComponentManagerUtils.cpp, line 63"
 0:20.84 PROCESS_OUTPUT: ProcessReader (pid:13764) "[GPU 24544] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file c:/moz/src/modules/libpref/Preferences.cpp, line 1637"
 0:20.84 PROCESS_OUTPUT: ProcessReader (pid:13764) "[GPU 24544] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file c:\moz\src\obj-debug\dist\include\mozilla/Preferences.h, line 104"
 0:20.84 PROCESS_OUTPUT: ProcessReader (pid:13764) "[GPU 24544] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file c:/moz/src/modules/libpref/Preferences.cpp, line 1405"
 0:20.85 PROCESS_OUTPUT: ProcessReader (pid:13764) "[GPU 24544] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file c:/moz/src/modules/libpref/Preferences.cpp, line 1414"
 0:21.44 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOCSHELL 158A3400 == 2 [pid = 13764] [id = {d63a8c12-5b90-47b3-8b5f-1bbd9d1d72af}]"
 0:21.44 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 3 (158A3800) [pid = 13764] [serial = 3] [outer = 00000000]"
 0:21.44 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 4 (158A4000) [pid = 13764] [serial = 4] [outer = 158A3800]"
 0:23.77 PROCESS_OUTPUT: ProcessReader (pid:13764) "1486707287463       Marionette      INFO    Listening on port 2828"
 0:26.85 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOCSHELL 1AFC2400 == 3 [pid = 13764] [id = {c052abeb-a001-4ac6-8147-fef8ff472563}]"
 0:26.85 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 5 (1AFC2800) [pid = 13764] [serial = 5] [outer = 00000000]"
 0:26.85 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 6 (1AFC3000) [pid = 13764] [serial = 6] [outer = 1AFC2800]"
 0:28.85 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 7 (1B691800) [pid = 13764] [serial = 7] [outer = 158A3800]"
 0:30.86 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Child 26732] WARNING: '!compMgr', file c:/moz/src/xpcom/components/nsComponentManagerUtils.cpp, line 63"
 0:32.08 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Child 26732] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src/toolkit/xre/nsXREDirProvider.cpp, line 1699"
 0:32.08 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Child 26732] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src/xpcom/base/nsSystemInfo.cpp, line 118"
 0:33.16 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Parent 13764] WARNING: attempt to modify an immutable nsStandardURL: file c:/moz/src/netwerk/base/nsStandardURL.cpp, line 1639"
 0:33.54 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Parent 13764] WARNING: attempt to modify an immutable nsStandardURL: file c:/moz/src/netwerk/base/nsStandardURL.cpp, line 1639"
 0:33.59 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOCSHELL 1140AC00 == 1 [pid = 26732] [id = {7546280f-b4ad-45d5-b464-af4e8334cd3a}]"
 0:33.59 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 1 (1140B000) [pid = 26732] [serial = 1] [outer = 00000000]"
 0:33.65 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Parent 13764] WARNING: Failed to retarget HTML data delivery to the parser thread.: file c:/moz/src/parser/html/nsHtml5StreamParser.cpp, line 984"
 0:34.22 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 2 (016BA800) [pid = 26732] [serial = 2] [outer = 1140B000]"
 0:34.99 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 3 (17B1F400) [pid = 26732] [serial = 3] [outer = 1140B000]"
 0:36.11 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Parent 13764] WARNING: getting z level of unregistered window: file c:/moz/src/xpfe/appshell/nsWindowMediator.cpp, line 623"
 0:36.11 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Parent 13764] WARNING: getting z level of unregistered window: file c:/moz/src/xpfe/appshell/nsWindowMediator.cpp, line 623"
 0:36.13 PROCESS_OUTPUT: ProcessReader (pid:13764) "--DOCSHELL 17B66C00 == 2 [pid = 13764] [id = {5eaae348-b11d-4ea3-a7a2-4d117c337f45}]"
 0:36.42 PROCESS_OUTPUT: ProcessReader (pid:13764) "[GPU 24544] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:37.01 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Child 26732] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:37.01 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Child 26732] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:37.34 PROCESS_OUTPUT: ProcessReader (pid:13764) "[GPU 24544] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:37.34 PROCESS_OUTPUT: ProcessReader (pid:13764) "[GPU 24544] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:37.34 PROCESS_OUTPUT: ProcessReader (pid:13764) "[GPU 24544] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:37.34 PROCESS_OUTPUT: ProcessReader (pid:13764) "[GPU 24544] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:37.34 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Child 26732] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file c:/moz/src/xpcom/threads/nsThread.cpp, line 1008"
 0:37.34 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Parent 13764] WARNING: pipe error: 109: file c:/moz/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
 0:37.78 PROCESS_OUTPUT: ProcessReader (pid:13764) "--DOCSHELL 1140AC00 == 0 [pid = 26732] [id = {7546280f-b4ad-45d5-b464-af4e8334cd3a}]"
 0:37.78 PROCESS_OUTPUT: ProcessReader (pid:13764) "--DOMWINDOW == 2 (1140B000) [pid = 26732] [serial = 1] [outer = 00000000] [url = chrome://gfxsanity/content/sanitytest.html]"
 0:37.79 PROCESS_OUTPUT: ProcessReader (pid:13764) "--DOMWINDOW == 1 (016BA800) [pid = 26732] [serial = 2] [outer = 00000000] [url = about:blank]"
 0:37.79 PROCESS_OUTPUT: ProcessReader (pid:13764) "--DOMWINDOW == 0 (17B1F400) [pid = 26732] [serial = 3] [outer = 00000000] [url = chrome://gfxsanity/content/sanitytest.html]"
 0:37.87 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Child 26732] WARNING: '!compMgr', file c:/moz/src/xpcom/components/nsComponentManagerUtils.cpp, line 63"
 0:37.87 PROCESS_OUTPUT: ProcessReader (pid:13764) "nsStringStats"
 0:37.87 PROCESS_OUTPUT: ProcessReader (pid:13764) " => mAllocCount:          14233"
 0:37.87 PROCESS_OUTPUT: ProcessReader (pid:13764) " => mReallocCount:          299"
 0:37.87 PROCESS_OUTPUT: ProcessReader (pid:13764) " => mFreeCount:           14233"
 0:37.87 PROCESS_OUTPUT: ProcessReader (pid:13764) " => mShareCount:          11369"
 0:37.87 PROCESS_OUTPUT: ProcessReader (pid:13764) " => mAdoptCount:           1206"
 0:37.87 PROCESS_OUTPUT: ProcessReader (pid:13764) " => mAdoptFreeCount:       1206"
 0:37.87 PROCESS_OUTPUT: ProcessReader (pid:13764) " => Process ID: 26732, Thread ID: 26808"
 0:44.47 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOCSHELL 1C1A2400 == 3 [pid = 13764] [id = {1bd76ccf-6d54-4ed8-aea7-0efe21f406bc}]"
 0:44.47 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 8 (1C1A2800) [pid = 13764] [serial = 8] [outer = 00000000]"
 0:44.49 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOCSHELL 1C1A4800 == 4 [pid = 13764] [id = {c021a63b-037e-40ee-8ed1-fd245c4da0fd}]"
 0:44.49 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 9 (1C1A8C00) [pid = 13764] [serial = 9] [outer = 00000000]"
 0:46.22 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOCSHELL 1A621000 == 5 [pid = 13764] [id = {394ae271-6550-4435-902a-fce4b09f5819}]"
 0:46.22 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 10 (1A621400) [pid = 13764] [serial = 10] [outer = 00000000]"
 0:46.80 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 11 (1A62B000) [pid = 13764] [serial = 11] [outer = 1A621400]"
 0:48.02 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 12 (1AFC3C00) [pid = 13764] [serial = 12] [outer = 1C1A2800]"
 0:48.10 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 13 (16F01400) [pid = 13764] [serial = 13] [outer = 1C1A8C00]"
 0:48.28 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Child 16632] WARNING: '!compMgr', file c:/moz/src/xpcom/components/nsComponentManagerUtils.cpp, line 63"
 0:49.53 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Child 16632] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src/toolkit/xre/nsXREDirProvider.cpp, line 1699"
 0:49.54 PROCESS_OUTPUT: ProcessReader (pid:13764) "[Child 16632] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src/xpcom/base/nsSystemInfo.cpp, line 118"
 0:56.28 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOCSHELL 10CD7800 == 1 [pid = 16632] [id = {517166b9-e57b-4200-a4f4-37cae4de559d}]"
 0:56.28 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 1 (10CD7C00) [pid = 16632] [serial = 1] [outer = 00000000]"
 0:56.92 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 2 (012B7800) [pid = 16632] [serial = 2] [outer = 10CD7C00]"
 1:00.83 PROCESS_OUTPUT: ProcessReader (pid:13764) "--DOCSHELL 1A621000 == 4 [pid = 13764] [id = {394ae271-6550-4435-902a-fce4b09f5819}]"
 1:02.28 PROCESS_OUTPUT: ProcessReader (pid:13764) "--DOMWINDOW == 12 (17B67000) [pid = 13764] [serial = 1] [outer = 00000000] [url = chrome://gfxsanity/content/sanityparent.html]"
 1:02.28 PROCESS_OUTPUT: ProcessReader (pid:13764) "--DOMWINDOW == 11 (1A621400) [pid = 13764] [serial = 10] [outer = 00000000] [url = about:blank]"
 1:03.48 PROCESS_OUTPUT: ProcessReader (pid:13764) "++DOMWINDOW == 3 (181E3800) [pid = 16632] [serial = 3] [outer = 10CD7C00]"
 1:04.53 LOG: Thread-TestrunnerManager-1 WARNING Init failed 1
 1:05.58 LOG: Thread-TestrunnerManager-1 WARNING u'log' (u'warning', {'message': 'Post-connection steps failed'})
 1:05.58 LOG: Thread-TestrunnerManager-1 WARNING u'log' (u'error', {'message': 'Traceback (most recent call last):\n  File "c:\\moz\\src\\testing/web-platform/harness\\wptrunner\\executors\\executormarionette.py", line 98, in setup\n    self.after_connect()\n  File "c:\\moz\\src\\testing/web-platform/harness\\wptrunner\\executors\\executormarionette.py", line 124, in after_connect\n    self.load_runner("http")\n  File "c:\\moz\\src\\testing/web-platform/harness\\wptrunner\\executors\\executormarionette.py", line 137, in load_runner\n    self.marionette.execute_script("if (window.wrappedJSObject.win) {window.wrappedJSObject.win.close()}")\n  File "c:\\moz\\src\\testing/marionette/client\\marionette_driver\\marionette.py", line 1797, in execute_script\n    rv = self._send_message("executeScript", body, key="value")\n  File "c:\\moz\\src\\testing/marionette/client\\marionette_driver\\decorators.py", line 28, in _\n    m._handle_socket_failure()\n  File "c:\\moz\\src\\testing/marionette/client\\marionette_driver\\decorators.py", line 23, in _\n    return func(*args, **kwargs)\n  File "c:\\moz\\src\\testing/marionette/client\\marionette_driver\\marionette.py", line 721, in _send_message\n    msg = self.client.request(name, params)\n  File "c:\\moz\\src\\testing/marionette/client\\marionette_driver\\transport.py", line 284, in request\n    return self.receive()\n  File "c:\\moz\\src\\testing/marionette/client\\marionette_driver\\transport.py", line 178, in receive\n    chunk = self.sock.recv(bytes_to_recv)\nerror: [Errno 10054] \x8a\xf9\x91\xb6\x82\xcc\x90\xda\x91\xb1\x82\xcd\x83\x8a\x83\x82\x81[\x83g \x83z\x83X\x83g\x82\xc9\x8b\xad\x90\xa7\x93I\x82\xc9\x90\xd8\x92f\x82\xb3\x82\xea\x82\xdc\x82\xb5\x82\xbd\x81B\n'})
 1:05.58 LOG: Thread-TestrunnerManager-1 WARNING 'init_failed' ()
 1:05.58 LOG: Thread-TestrunnerManager-1 WARNING u'runner_teardown' ()
 1:05.69 LOG: Thread-TestrunnerManager-1 INFO Setting up ssl
 1:05.74 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) ""
 1:05.79 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) ""
 1:05.82 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) "
Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

web-platform-tests                                           CT,,
"
 1:05.88 LOG: Thread-TestrunnerManager-1 INFO Application command: c:/moz/src/obj-debug\dist\bin\firefox.exe -marionette about:blank -profile c:\users\brian\appdata\local\temp\tmp3ylxx7.mozrunner
 1:05.89 LOG: Thread-TestrunnerManager-1 INFO Starting runner
Summary: Web platform test runner does not wait long enough on windows → Web platform test runner fails repeatedly to connect to marionette
It turns out this is a timeout issue after all. Or at least for the machine in comment 1. By overriding the timeout in transport.py[1] (setting it to None) I can get it to run.

[1] http://searchfox.org/mozilla-central/source/testing/marionette/client/marionette_driver/transport.py#128
Or maybe not. Even with said fix applied, it still mostly fails. I think I was just lucky that time.
Henrik, is this a fallout from the recent modifications to socket timeouts done for the Android tests?
Flags: needinfo?(hskupin)
I don't think so. My patch increased the timeout from 65s to 300s so it should be better now. Brian can you try to run the Marionette unit tests and see if those work for you? It might give better error details if something is plainly wrong with your machine. Thanks.
Flags: needinfo?(hskupin)
Sure, how do I do that? What command do you want me to run?

This is happening on multiple (Windows) machines so it's not a particular machine to blame.
Flags: needinfo?(hskupin)
You can use `./mach marionette-test` to run the full suite of Marionette tests:
https://developer.mozilla.org/en-US/docs/Mozilla/QA/Marionette/Running_Tests
Flags: needinfo?(hskupin)
Marionette tests seem to run. web-platform-tests continue to fail however.

(I hope you don't mind me setting this to P1 since this is blocking large parts of my work as we rely of web-platform-tests heavily for animation work. I expect it affects other on Windows too since I am see the same symptoms on both my Windows machines.)
Priority: -- → P1
Would you mind doing a regression test on mozilla-central? You can use mozregression for it. It should help to find a possible cause of this problem.
I'm not aware of any setting on mozregression that let's you run 'mach test web-animations/interfaces' ? Last I recall it was just downloading binaries whereas it's the test infrastructure we want to bisect here.

I'm bisecting this the slow way (40 minutes per test) and it's difficult because sometimes the tests will work intermittently, but I'll let you know if manage to narrow it down at all.
Even a larger range might be helpful. So don't hesitate to update the bug earlier. There might be obvious changes to find which could explain it.

mozregression can run a custom command which is not only firefox itself. So if you have a script which can download and extract the appropriate tests, you can easily pass it along.
I'll investigate this.
|mach wpt testing/web-platform/tests/dom/| works for me with a fresh artifact build on Windows 10. I did get a popup about giving python access to the firewall, so I wonder if you have some firewall rules that are interfering with the connections here?
I'm pretty sure it's not firewall rules since it does (very) occasionally work and it used to work. Furthermore a build from 2017-01-01 works.

Was the artifact build a debug build? I wouldn't be surprised if opt builds work since it does seem like a timeout issue.

I'll see how far I can get with bisecting today.
I haven't had much luck bisecting this. It's just so intermittent. I somehow found myself bisecting changesets from 2017-02-10 and got the following results:

 -100 d295888faea0 First time ok, second time ok, third time ok, fourth time ok
  -69 84b84e7610ee First time ok, second time bad
  -50 f35a21d38a23 (Build broken)
  -49 34521aa2e278 First time ok, second time bad, third time ok, fourth time ok
    0 2e61f82dd80d First time bad

But then there's not even anything vaguely suspicious in that range. Mostly just graphics merges. The closest WPT-related change I can see is 2e544c9e2fdc (bug 1338180) which is just outside that range.
Just got a new even more powerful laptop. Everything is newly installed. I haven't touched a single line in my fresh checkout of mozilla-central and still I hit this same problem.

Note that this is a debug build, i.e. has the following .mozconfig:

. $topsrcdir/browser/config/mozconfig
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/obj-debug
mk_add_options AUTOCLOBBER=1
ac_add_options --disable-optimize
ac_add_options --enable-debug
ac_add_options --enable-tests
ac_add_options --target=x86_64-pc-mingw32
ac_add_options --host=x86_64-pc-mingw32
Hm, in the log you showed above in comment 1 I don't see any Gecko log message from Marionette that the server socket has been started and that it is listening on port 2828. But WPT still tries to use execute_script() to close a window. Btw what does the error message mean you are pointing out in comment 0? I'm not that familiar with Chinese. :)
"The existing connection was forcibly disconnected by the remote host."
Which versions of Windows have you used so far for testing? Do you see the same failure for local opt builds?
The message “Starting marionette session failed” originates from
wptrunner, and is logged whenever calling self.marionette.start_session
fails:

	https://github.com/w3c/wptrunner/blob/a48459321f4a26a954059a2c5dc1590dca3181b5/wptrunner/executors/executormarionette.py#L87

Marionette starts listening at 0:27.19 but the connection isn’t dropped until 1:04.03, roughly 30 seconds later:

> 0:27.19 PROCESS_OUTPUT: ProcessReader (pid:4564) "1486693312163        Marionette      INFO    Listening on port 2828"
> …
> 1:04.03 LOG: Thread-TestrunnerManager-1 WARNING u'log' (u'warning', {'message': 'Starting marionette session failed: [Errno 10054] \x8a\xf9\x91\xb6\x82\xcc\x90\xda\x91\xb1\x82\xcd\x83\x8a\x83\x82\x81[\x83g \x83z\x83X\x83g\x82\xc9\x8b\xad\x90\xa7\x93I\x82\xc9\x90\xd8\x92f\x82\xb3\x82\xea\x82\xdc\x82\xb5\x82\xbd\x81B'})

According to MSDN, errno 10054 WSAECONNRESET:

> Connection reset by peer.
>
> An existing connection was forcibly closed by the remote host. This
> normally results if the peer application on the remote host is
> suddenly stopped, the host is rebooted, the host or remote network
> interface is disabled, or the remote host uses a hard close (see
> setsockopt for more information on the SO_LINGER option on the remote
> socket). This error may also result if a connection was broken
> due to keep-alive activity detecting a failure while one or more
> operations are in progress. Operations that were in progress fail with
> WSAENETRESET. Subsequent operations fail with WSAECONNRESET.

wptrunner configures the Marionette Python client to have a
socket_timeout of None:

	https://github.com/w3c/wptrunner/blob/a48459321f4a26a954059a2c5dc1590dca3181b5/wptrunner/executors/executormarionette.py#L69

This gets passed to Marionette.start_session, overriding the default
Marionette.socket_timeout of 360 seconds:

	http://searchfox.org/mozilla-central/source/testing/marionette/client/marionette_driver/marionette.py#1255

This value ends up being used on socket.settimeout when the TCP
connection attempt is made:

	http://searchfox.org/mozilla-central/source/testing/marionette/client/marionette_driver/transport.py#221

According to the Python documentation, socket.settimeout(None) is
equivalent to socket.setblocking(1), effectively disabling timeouts on
socket operations:

	https://docs.python.org/2/library/socket.html#socket.socket.settimeout

In the log, I don’t see any successful connection attempts to
Marionette.  We would expect to see an “Accepted connection conn0”
message in the Gecko log when a socket connection is accepted by
Marionette:

	http://searchfox.org/mozilla-central/source/testing/marionette/server.js#131

It would be useful to see the exact stacktrace of the raised exception
when Marionette.start_session throws. wptrunner logs a warning, but
because it uses string concatentation, only the e variable’s string
representation is printed.

You could add this line to wptrunner/executors/executormarionette.py:87
to get the full stacktrace:

> self.logger.error(traceback.format_exc())

As one can tell from the marionette.transprt.TcpTransport.connect
method, there are a few places it can go wrong:

	http://searchfox.org/mozilla-central/source/testing/marionette/client/marionette_driver/transport.py#213-236

Although I do suspect the offending line is

> self.sock.connect(self.addr, self.port))

That a connection is reset by peer tells us one side times out and
aborts the connection, but it’s unclear to me which side causes this
given we don’t seem to accept the connection in Marionette.  A likely
suspect would be firewall settings or packet filtering.

I think the next step is to use tcpdump(8), Wireshark, or an equivalent
tool to inspect what passes under our noses.  It might also help to add
some more logging to testing/marionette/server.js and transport.py.
I've used three different machines but they are all Windows 10. I'll kick off an opt build and see how it goes.
I'll try to produce the stacktrace mentioned in comment 20 too.
Another thing to try would be `./mach marionette-test --gecko-log - -vv` on the same build, to see if the same error manifests with the Mn harness.  It uses slightly different socket configurations.
(In reply to Andreas Tolfsen from comment #23)
> Another thing to try would be `./mach marionette-test --gecko-log - -vv` on
> the same build, to see if the same error manifests with the Mn harness.  It
> uses slightly different socket configurations.

That's what I asked already above. Marionette tests themselves work fine.

(In reply to Andreas Tolfsen from comment #20)
> In the log, I don’t see any successful connection attempts to
> Marionette.  We would expect to see an “Accepted connection conn0”
> message in the Gecko log when a socket connection is accepted by
> Marionette:
> 
> 	http://searchfox.org/mozilla-central/source/testing/marionette/server.js#131

This is debug and not info, so you don't see it by default. How can debug or even tracing be enabled for WPT tests?
I tried with an opt build but it just failed with:

PROCESS_OUTPUT: ProcessReader (pid:996) "FATAL ERROR: Non-local network connections are disabled and a connection attempt to tiles.services.mozilla.com (52.40.13.190) was made."
Log from debug build with the stack requested in comment 20:

> $ mach test web-animations/interfaces
> Build configuration changed. Regenerating backend.
>  0:00.53 LOG: Thread-Log INFO STDOUT: DEBUG:manifest:Opening manifest at c:\moz\src1\testing\web-platform\meta\MANIFEST.json
>  0:01.44 LOG: Thread-Log INFO STDOUT: DEBUG:manifest:Opening manifest at c:\moz\src1\testing\web-platform\mozilla\meta\MANIFEST.json
>  0:01.63 LOG: MainThread INFO Using 1 client processes
>  0:04.19 SUITE_START: MainThread 42
>  0:04.19 LOG: MainThread INFO Running reftest tests
>  0:04.22 LOG: MainThread INFO No reftest tests to run
>  0:04.22 LOG: MainThread INFO Running wdspec tests
>  0:04.22 LOG: MainThread INFO No wdspec tests to run
>  0:04.22 LOG: MainThread INFO Running testharness tests
>  0:04.45 LOG: Thread-TestrunnerManager-1 INFO Setting up ssl
>  0:04.57 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) Full command: c:/moz/src1/obj-debug\dist\bin\certutil.exe -N -d c:\users\brian\appdata\local\temp\tmp_mod_d.mozrunner -f c:\users\brian\appdata\local\temp\tmp_mod_d.mozrunner\.crtdbpw
> (pid:certutil) ""
>  0:04.63 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) ""
>  0:04.67 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) "
> Certificate Nickname                                         Trust Attributes
>                                                              SSL,S/MIME,JAR/XPI
> 
> web-platform-tests                                           CT,,
> "
>  0:04.67 LOG: Thread-TestrunnerManager-1 INFO Application command: c:/moz/src1/obj-debug\dist\bin\firefox.exe -marionette about:blank -profile c:\users\brian\appdata\local\temp\tmp_mod_d.mozrunner
>  0:04.69 LOG: Thread-TestrunnerManager-1 INFO Starting runner
>  0:05.62 PROCESS_OUTPUT: ProcessReader (pid:12992) Full command: c:/moz/src1/obj-debug\dist\bin\firefox.exe -marionette about:blank -profile c:\users\brian\appdata\local\temp\tmp_mod_d.mozrunner
> (pid:12992) "[12992] WARNING: Failed to load startupcache file correctly, removing!: file c:/moz/src1/startupcache/StartupCache.cpp, line 219"
>  0:06.95 PROCESS_OUTPUT: ProcessReader (pid:12992) "[12992] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src1/xpcom/base/nsSystemInfo.cpp, line 117"
>  0:11.26 PROCESS_OUTPUT: ProcessReader (pid:12992) "[12992] WARNING: This method is lossy. Use GetCanonicalPath !: file c:/moz/src1/xpcom/io/nsLocalFileWin.cpp, line 3572"
>  0:25.61 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOCSHELL 0000017D9E51B000 == 1 [pid = 12992] [id = {bff46a3f-af2d-4f3c-aedb-23b58303577a}]"
>  0:25.61 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOMWINDOW == 1 (0000017D9E51B800) [pid = 12992] [serial = 1] [outer = 0000000000000000]"
>  0:25.61 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOMWINDOW == 2 (0000017D9E51C800) [pid = 12992] [serial = 2] [outer = 0000017D9E51B800]"
>  0:26.61 PROCESS_OUTPUT: ProcessReader (pid:12992) "[GPU 2640] WARNING: '!compMgr', file c:/moz/src1/xpcom/components/nsComponentManagerUtils.cpp, line 63"
>  0:26.61 PROCESS_OUTPUT: ProcessReader (pid:12992) "[GPU 2640] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file c:/moz/src1/modules/libpref/Preferences.cpp, line 1648"
>  0:26.61 PROCESS_OUTPUT: ProcessReader (pid:12992) "[GPU 2640] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file c:\moz\src1\obj-debug\dist\include\mozilla/Preferences.h, line 104"
>  0:26.62 PROCESS_OUTPUT: ProcessReader (pid:12992) "[GPU 2640] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file c:/moz/src1/modules/libpref/Preferences.cpp, line 1416"
>  0:26.62 PROCESS_OUTPUT: ProcessReader (pid:12992) "[GPU 2640] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file c:/moz/src1/modules/libpref/Preferences.cpp, line 1425"
>  0:27.50 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOCSHELL 0000017DA03D5800 == 2 [pid = 12992] [id = {cc90ed7d-fdd1-4889-81c1-e7834c45d7c1}]"
>  0:27.50 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOMWINDOW == 3 (0000017DA03D6000) [pid = 12992] [serial = 3] [outer = 0000000000000000]"
>  0:27.50 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOMWINDOW == 4 (0000017DA03D7000) [pid = 12992] [serial = 4] [outer = 0000017DA03D6000]"
>  0:30.80 PROCESS_OUTPUT: ProcessReader (pid:12992) "1488356509881       Marionette      INFO    Listening on port 2828"
>  0:35.39 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOCSHELL 0000017DA136C800 == 3 [pid = 12992] [id = {8a1be455-f4be-454d-8dd1-26c08145455d}]"
>  0:35.39 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOMWINDOW == 5 (0000017DA136D000) [pid = 12992] [serial = 5] [outer = 0000000000000000]"
>  0:35.39 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOMWINDOW == 6 (0000017DA136E000) [pid = 12992] [serial = 6] [outer = 0000017DA136D000]"
>  0:37.40 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOMWINDOW == 7 (0000017DA187C800) [pid = 12992] [serial = 7] [outer = 0000017DA03D6000]"
>  0:40.82 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!compMgr', file c:/moz/src1/xpcom/components/nsComponentManagerUtils.cpp, line 63"
>  0:41.18 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!compMgr', file c:/moz/src1/xpcom/components/nsComponentManagerUtils.cpp, line 63"
>  0:42.77 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src1/toolkit/xre/nsXREDirProvider.cpp, line 1699"
>  0:42.77 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src1/xpcom/base/nsSystemInfo.cpp, line 117"
>  0:43.93 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Parent 12992] WARNING: attempt to modify an immutable nsStandardURL: file c:/moz/src1/netwerk/base/nsStandardURL.cpp, line 1641"
>  0:44.37 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Parent 12992] WARNING: attempt to modify an immutable nsStandardURL: file c:/moz/src1/netwerk/base/nsStandardURL.cpp, line 1641"
>  0:44.50 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Parent 12992] WARNING: Failed to retarget HTML data delivery to the parser thread.: file c:/moz/src1/parser/html/nsHtml5StreamParser.cpp, line 988"
>  0:44.80 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOCSHELL 0000026596FA7000 == 1 [pid = 5944] [id = {8d9b990c-4ce9-459d-b9d8-63887f92d224}]"
>  0:44.80 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOMWINDOW == 1 (0000026596FA7800) [pid = 5944] [serial = 1] [outer = 0000000000000000]"
>  0:45.80 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOMWINDOW == 2 (000002659F518000) [pid = 5944] [serial = 2] [outer = 0000026596FA7800]"
>  0:46.54 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Parent 12992] WARNING: getting z level of unregistered window: file c:/moz/src1/xpfe/appshell/nsWindowMediator.cpp, line 623"
>  0:46.54 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Parent 12992] WARNING: getting z level of unregistered window: file c:/moz/src1/xpfe/appshell/nsWindowMediator.cpp, line 623"
>  0:46.58 PROCESS_OUTPUT: ProcessReader (pid:12992) "++DOMWINDOW == 3 (000002659F529000) [pid = 5944] [serial = 3] [outer = 0000026596FA7800]"
>  0:46.60 PROCESS_OUTPUT: ProcessReader (pid:12992) "--DOCSHELL 0000017D9E51B000 == 2 [pid = 12992] [id = {bff46a3f-af2d-4f3c-aedb-23b58303577a}]"
>  0:46.77 PROCESS_OUTPUT: ProcessReader (pid:12992) "IPDL protocol error: Handler returned error code!"
>  0:46.77 PROCESS_OUTPUT: ProcessReader (pid:12992) ""
>  0:46.77 PROCESS_OUTPUT: ProcessReader (pid:12992) "###!!! [Parent][DispatchAsyncMessage] Error: PLayerTransaction::Msg_ReleaseLayer Processing error: message was deserialized, but the handler returned false (indicating failure)"
>  0:46.77 PROCESS_OUTPUT: ProcessReader (pid:12992) ""
>  0:47.23 PROCESS_OUTPUT: ProcessReader (pid:12992) "[GPU 2640] WARNING: pipe error: 109: file c:/moz/src1/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
>  0:48.00 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: pipe error: 109: file c:/moz/src1/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
>  0:48.00 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: pipe error: 109: file c:/moz/src1/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
>  0:48.12 PROCESS_OUTPUT: ProcessReader (pid:12992) "[GPU 2640] WARNING: pipe error: 109: file c:/moz/src1/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
>  0:48.12 PROCESS_OUTPUT: ProcessReader (pid:12992) "[GPU 2640] WARNING: pipe error: 109: file c:/moz/src1/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
>  0:48.12 PROCESS_OUTPUT: ProcessReader (pid:12992) "[GPU 2640] WARNING: pipe error: 109: file c:/moz/src1/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
>  0:48.12 PROCESS_OUTPUT: ProcessReader (pid:12992) "[GPU 2640] WARNING: pipe error: 109: file c:/moz/src1/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
>  0:48.12 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file c:/moz/src1/xpcom/threads/nsThread.cpp, line 1009"
>  0:48.12 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Parent 12992] WARNING: pipe error: 109: file c:/moz/src1/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"
>  0:48.39 PROCESS_OUTPUT: ProcessReader (pid:12992) "--DOCSHELL 0000026596FA7000 == 0 [pid = 5944] [id = {8d9b990c-4ce9-459d-b9d8-63887f92d224}]"
>  0:48.78 PROCESS_OUTPUT: ProcessReader (pid:12992) "--DOMWINDOW == 2 (0000026596FA7800) [pid = 5944] [serial = 1] [outer = 0000000000000000] [url = chrome://gfxsanity/content/sanitytest.html]"
>  0:48.78 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.78 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.78 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.78 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.78 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.78 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.78 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.78 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.78 PROCESS_OUTPUT: ProcessReader (pid:12992) "--DOMWINDOW == 1 (000002659F518000) [pid = 5944] [serial = 2] [outer = 0000000000000000] [url = about:blank]"
>  0:48.78 PROCESS_OUTPUT: ProcessReader (pid:12992) "--DOMWINDOW == 0 (000002659F529000) [pid = 5944] [serial = 3] [outer = 0000000000000000] [url = chrome://gfxsanity/content/sanitytest.html]"
>  0:48.92 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!compMgr', file c:/moz/src1/xpcom/components/nsComponentManagerUtils.cpp, line 63"
>  0:48.92 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.92 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.92 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.92 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.92 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.92 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.92 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.92 PROCESS_OUTPUT: ProcessReader (pid:12992) "[Child 5944] WARNING: '!mMainThread', file c:/moz/src1/xpcom/threads/nsThreadManager.cpp, line 314"
>  0:48.93 PROCESS_OUTPUT: ProcessReader (pid:12992) "nsStringStats"
>  0:48.93 PROCESS_OUTPUT: ProcessReader (pid:12992) " => mAllocCount:          13763"
>  0:48.93 PROCESS_OUTPUT: ProcessReader (pid:12992) " => mReallocCount:          312"
>  0:48.93 PROCESS_OUTPUT: ProcessReader (pid:12992) " => mFreeCount:           13763"
>  0:48.93 PROCESS_OUTPUT: ProcessReader (pid:12992) " => mShareCount:          10487"
>  0:48.94 PROCESS_OUTPUT: ProcessReader (pid:12992) " => mAdoptCount:           1143"
>  0:48.94 PROCESS_OUTPUT: ProcessReader (pid:12992) " => mAdoptFreeCount:       1143"
>  0:48.94 PROCESS_OUTPUT: ProcessReader (pid:12992) " => Process ID: 5944, Thread ID: 14780"
>  1:04.24 LOG: Thread-TestrunnerManager-1 WARNING Init failed 1
>  1:04.32 LOG: Thread-TestrunnerManager-1 WARNING u'log' (u'error', {'message': 'Traceback (most recent call last):\n  File "c:\\moz\\src1\\testing/web-platform/harness\\wptrunner\\executors\\executormarionette.py", line 86, in setup\n    self.marionette.start_session()\n  File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\decorators.py", line 28, in _\n    m._handle_socket_failure()\n  File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\decorators.py", line 23, in _\n    return func(*args, **kwargs)\n  File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\marionette.py", line 1287, in start_session\n    resp = self._send_message("newSession", body)\n  File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\decorators.py", line 28, in _\n    m._handle_socket_failure()\n  File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\decorators.py", line 23, in _\n    return func(*args, **kwargs)\n  File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\marionette.py", line 721, in _send_message\n    msg = self.client.request(name, params)\n  File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\transport.py", line 284, in request\n    return self.receive()\n  File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\transport.py", line 178, in receive\n    chunk = self.sock.recv(bytes_to_recv)\nerror: [Errno 10054] \x8a\xf9\x91\xb6\x82\xcc\x90\xda\x91\xb1\x82\xcd\x83\x8a\x83\x82\x81[\x83g \x83z\x83X\x83g\x82\xc9\x8b\xad\x90\xa7\x93I\x82\xc9\x90\xd8\x92f\x82\xb3\x82\xea\x82\xdc\x82\xb5\x82\xbd\x81B\n'})
>  1:04.32 LOG: Thread-TestrunnerManager-1 WARNING u'log' (u'warning', {'message': 'Starting marionette session failed: [Errno 10054] \x8a\xf9\x91\xb6\x82\xcc\x90\xda\x91\xb1\x82\xcd\x83\x8a\x83\x82\x81[\x83g \x83z\x83X\x83g\x82\xc9\x8b\xad\x90\xa7\x93I\x82\xc9\x90\xd8\x92f\x82\xb3\x82\xea\x82\xdc\x82\xb5\x82\xbd\x81B'})
>  1:04.32 LOG: Thread-TestrunnerManager-1 WARNING u'log' (u'warning', {'message': 'Failed to connect to Marionette'})
>  1:04.32 LOG: Thread-TestrunnerManager-1 WARNING 'init_failed' ()
>  1:04.32 LOG: Thread-TestrunnerManager-1 WARNING u'runner_teardown' ()
>  1:04.46 LOG: Thread-TestrunnerManager-1 INFO Setting up ssl
>  1:04.52 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) ""
>  1:04.55 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) ""
>  1:04.57 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:certutil) "
> Certificate Nickname                                         Trust Attributes
>                                                              SSL,S/MIME,JAR/XPI
> 
> web-platform-tests                                           CT,,
> "
>  1:04.68 LOG: Thread-TestrunnerManager-1 INFO Application command: c:/moz/src1/obj-debug\dist\bin\firefox.exe -marionette about:blank -profile c:\users\brian\appdata\local\temp\tmpbo_msh.mozrunner
>  1:04.68 LOG: Thread-TestrunnerManager-1 INFO Starting runner
>  1:05.45 PROCESS_OUTPUT: ProcessReader (pid:5124) Full command: c:/moz/src1/obj-debug\dist\bin\firefox.exe -marionette about:blank -profile c:\users\brian\appdata\local\temp\tmpbo_msh.mozrunner
> (pid:5124) "[5124] WARNING: Failed to load startupcache file correctly, removing!: file c:/moz/src1/startupcache/StartupCache.cpp, line 219"
>  1:06.71 PROCESS_OUTPUT: ProcessReader (pid:5124) "[5124] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src1/xpcom/base/nsSystemInfo.cpp, line 117"
>  1:10.83 PROCESS_OUTPUT: ProcessReader (pid:5124) "[5124] WARNING: This method is lossy. Use GetCanonicalPath !: file c:/moz/src1/xpcom/io/nsLocalFileWin.cpp, line 3572"
Fixing the formatting of the stack:

> File "c:\\moz\\src1\\testing/web-platform/harness\\wptrunner\\executors\\executormarionette.py", line 86, in setup
>     self.marionette.start_session()
>   File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\decorators.py", line 28, in _
>     m._handle_socket_failure()
>   File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\decorators.py", line 23, in _
>     return func(*args, **kwargs)
>   File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\marionette.py", line 1287, in start_session
>     resp = self._send_message("newSession", body)
>   File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\decorators.py", line 28, in _
>     m._handle_socket_failure()
>   File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\decorators.py", line 23, in _
>     return func(*args, **kwargs)
>   File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\marionette.py", line 721, in _send_message
>     msg = self.client.request(name, params)
>   File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\transport.py", line 284, in request
>     return self.receive()
>   File "c:\\moz\\src1\\testing/marionette/client\\marionette_driver\\transport.py", line 178, in receive
>     chunk = self.sock.recv(bytes_to_recv)
> error: [Errno 10054] \x8a\xf9\x91\xb6\x82\xcc\x90\xda\x91\xb1\x82\xcd\x83\x8a\x83\x82\x81[\x83g \x83z\x83X\x83g\x82\xc9\x8b\xad\x90\xa7\x93I\x82\xc9\x90\xd8\x92f\x82\xb3\x82\xea\x82\xdc\x82\xb5\x82\xbd\x81B
> '})
> "FATAL ERROR: Non-local network connections are disabled and a connection attempt to tiles.services.mozilla.com (52.40.13.190) was made."

By default any of our test suites as reporting as Tier-1 to Treeherder do not allow outbound connections due to risk of intermittent failures. As result we crash Firefox. As it looks like we have a service in Firefox enabled for WPT tests which still wants to connect. I wonder why we do not see this for our per commit WPT jobs on Treeherder.

Do you maybe see the same for debug builds too? 

Something I would suggest for the WPT testrunner and specifically for the Marionette executor, that it should check for crash reports. Marionette is not doing that itself when it doesn't have a reference to the running instance of the application.

Btw. it would be better if you could add logs as attachment. Having those as comments make the bug a bit hard to follow. Thanks.
wptrunner uses MOZ_DISABLE_NONLOCAL_CONNECTIONS to cause Firefox to assert-crash when accessing external resources.  This is to ensure test runs are hermetic and not influenced by any external factors.

I am somewhat surprised that happens when you run WPT tests.  Are you executing `mach web-platform-tests web-animations/interfaces/KeyframeEffect/processing-a-keyframes-argument.html`?  I am guessing “tiles” has something to do with about:newtab or some such?
I will examine the logs above in detail later when I have more time.
Yes, it's for new tabs. Doesn't WPT turn off "browser.newtabpage.enabled"? I guess not, cause it's trying to contact the server.

Otherwise the following URLs would have to be changed to a faked local end point:
https://dxr.mozilla.org/mozilla-central/source/browser/app/profile/firefox.js#1193-1196
(In reply to Henrik Skupin (:whimboo) from comment #28)
> > "FATAL ERROR: Non-local network connections are disabled and a connection attempt to tiles.services.mozilla.com (52.40.13.190) was made."
> Do you maybe see the same for debug builds too? 

No.

(In reply to Andreas Tolfsen ‹:ato› from comment #29)
> I am somewhat surprised that happens when you run WPT tests.  Are you
> executing `mach web-platform-tests
> web-animations/interfaces/KeyframeEffect/processing-a-keyframes-argument.
> html`?

Yes.
Anything I can do help to fix this?

This is really impeding my work and one of my team yesterday told me he is also completely unable to run wpt on Windows. Please let me know what I can do to help debug this.
Sorry for the slow reply.

I spent Friday afternoon failing to reproduce this. I was using a Windows 10 preview VM from [1], with Mozilla-Build and MSVC 2015 Community edition. I tried installing cygwin to reproduce the mingw builds in your configuration but I couldn't work out how to make that work and ended up breaking my build environment in some way I didn't understand. So at this point I sort of suspect either

a) Something weird in mingw builds
b) Some setup in Japanese Windows that isn't in those VMs.

Both of those things would explain why it's so reliable in CI but apparently very unreliable for you. Based on the logging, it really looks like there's a firewall or something that's blocking off the marionette connection.

Are you able to try installing one of those VMs and/or see if you can reproduce with a MSVC build (or an artifact build)?


[1] https://developer.microsoft.com/en-us/microsoft-edge/tools/vms/
Thanks for looking into this. You shouldn't need to install cygwin (I haven't). Just vanilla MozillaBuild is enough. The only settings I have different beyond that are:

* MOZ_NO_RESET_PATH=1 (i.e. I have a few more things in my path than the default MSVC batch files add)
* XPCOM_DEBUG_BREAK=warn
* Japanese Windows
* Up-to-date Windows 10 Home

I can install one of those VMs but even if it works it doesn't really tell us what the problem is so I'm probably better off to just try and debug the error myself.

Note that, at least on some of my machines, the test runner *sometimes* works and previously it used to nearly always work (>90% of the time), so if it's a firewall getting in the way, it's not doing it very reliably!
(In reply to Brian Birtles (:birtles) from comment #35)
> * MOZ_NO_RESET_PATH=1 (i.e. I have a few more things in my path than the
> default MSVC batch files add)
> * XPCOM_DEBUG_BREAK=warn

Just tried running the tests without these environment variables set and the problem persists so they appear to be unrelated.
Tried turning off Windows firewall altogether but the problem persists.
Kato-san is able to run these tests on a fresh install of Japanese Windows with a debug-opt build.
Just rebuilt debug and opt builds on latest m-c. The debug build continues to fail but the opt build runs without problem.

(The issue in comment 25 is likely because I built at that time with --disable-test and just ran 'mach web-platform-tests' directly.)

Comparing the two configurations:

$ diff .mozconfig .mozconfig-opt
2c2
< mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/obj-debug
---
> mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/obj-opt
4,6c4,6
< ac_add_options --disable-optimize
< ac_add_options --enable-debug
< ac_add_options --enable-tests
---
> ac_add_options --enable-optimize
> ac_add_options --enable-debug-symbols
> ac_add_options --enable-profiling
The curious thing is that in a debug build it looks like Firefox starts, gets killed, and then restarts and we give up running the test in between.

So the log initially looks like the following:
> ...
> 0:29.96 PROCESS_OUTPUT: ProcessReader (pid:10736) "++DOMWINDOW == 3 (000001AB6F987000) [pid = 10736] [serial = 3] [outer = 0000000000000000]"
> 0:29.96 PROCESS_OUTPUT: ProcessReader (pid:10736) "++DOMWINDOW == 4 (000001AB6F988000) [pid = 10736] [serial = 4] [outer = 000001AB6F987000]"
> 0:33.56 PROCESS_OUTPUT: ProcessReader (pid:10736) "1488873178733       Marionette      INFO    Listening on port 2828"
> 0:38.48 PROCESS_OUTPUT: ProcessReader (pid:10736) "++DOCSHELL 000001AB719BF000 == 3 [pid = 10736] [id = {5e673458-2a9c-4ed5-9e20-686f7b32464a}]"
> 0:38.48 PROCESS_OUTPUT: ProcessReader (pid:10736) "++DOMWINDOW == 5 (000001AB719BF800) [pid = 10736] [serial = 5] [outer = 0000000000000000]"
> 0:38.48 PROCESS_OUTPUT: ProcessReader (pid:10736) "++DOMWINDOW == 6 (000001AB719C0800) [pid = 10736] [serial = 6] [outer = 000001AB719BF800]"
> 0:40.74 PROCESS_OUTPUT: ProcessReader (pid:10736) "++DOMWINDOW == 7 (000001AB71D6B000) [pid = 10736] [serial = 7] [outer = 000001AB6F987000]"

Then at about this point the Firefox logo appears in the task bar:

> 0:45.04 PROCESS_OUTPUT: ProcessReader (pid:10736) "[Child 18264] WARNING: '!compMgr', file c:/moz/src3/xpcom/components/nsComponentManagerUtils.cpp, line 63"
> 0:45.68 PROCESS_OUTPUT: ProcessReader (pid:10736) "[Child 18264] WARNING: '!compMgr', file c:/moz/src3/xpcom/components/nsComponentManagerUtils.cpp, line 63"

Then somewhere in the following few lines it disappears:

> 0:47.64 PROCESS_OUTPUT: ProcessReader (pid:10736) "[Child 18264] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src3/toolkit/xre/nsXREDirProvider.cpp, line 1699"
> 0:47.64 PROCESS_OUTPUT: ProcessReader (pid:10736) "[Child 18264] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file c:/moz/src3/xpcom/base/nsSystemInfo.cpp, line 117"
> 0:48.29 PROCESS_OUTPUT: ProcessReader (pid:10736) "[Parent 10736] WARNING: getting z level of unregistered window: file c:/moz/src3/xpfe/appshell/nsWindowMediator.cpp, line 616"
> 0:48.29 PROCESS_OUTPUT: ProcessReader (pid:10736) "[Parent 10736] WARNING: getting z level of unregistered window: file c:/moz/src3/xpfe/appshell/nsWindowMediator.cpp, line 616"
> 0:48.35 PROCESS_OUTPUT: ProcessReader (pid:10736) "--DOCSHELL 000001AB6E6EA800 == 2 [pid = 10736] [id = {5a12d329-19f6-44f6-a555-1b048746dccd}]"
> 0:48.39 PROCESS_OUTPUT: ProcessReader (pid:10736) "[GPU 19956] WARNING: pipe error: 109: file c:/moz/src3/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346"

The final line, I suppose, is the GPU process failing to communicate with the parent process.

If I hit Ctrl+C at that point, sometime later Firefox will show up again. I'm not sure if this initial window is the graphics driver check we do. Perhaps Marionette is failing to wait for us to restart or failing to wait long enough such that it works on opt builds but not debug builds. Just guessing here. When I run the opt build, the second Firefox icon appears before the first one disappears.
Oh, and I suspect this worked for Kato-san because he is using a debug-opt build which was quite fast.
Speaking with Kato-san, the initial window is probably not the graphics driver check but the profile manager being initially loaded. Apparently this typically runs, stops, and then Firefox is started again (presumably with the correct profile).

In either case, I wonder if this is a timing issue where, with a debug build, the initial Firefox instance is still running when Marionette starts and it is trying to communicate with this initial process only for it to be terminated, causing Marionette to fail. On an opt build, however, Marionette is successfully finding the correct instance of Firefox.

I guess one way to test that would be to pass -no-remote along.
Regarding the gfx sanity test window I have a patch on bug 1322383 which implements the correct handling for it. Right now Marionette doesn't wait for it to disappear which can cause a race condition in our tests. But that shouldn't cause the problem you are seeing here.

Btw how long does it take for you once wpt tests are started until it fails with the not being able to connect to Marionette message?
OK, I can reproduce with a --disable-optimize build. I think that explains why we can't reproduce on CI either, since afaik those builds have optimisation enabled. I increased the marionette connection timeout, but it didn't help; it looked like marionette was terminating the connection, so more investigation is needed.
(In reply to Henrik Skupin (:whimboo) from comment #43)
> Regarding the gfx sanity test window I have a patch on bug 1322383 which
> implements the correct handling for it. Right now Marionette doesn't wait
> for it to disappear which can cause a race condition in our tests. But that
> shouldn't cause the problem you are seeing here.

I tried applying the patch from bug 1315611 but it doesn't seem to fix this. Instead I get a different error (see attached log)--it seems like the Marionette session doesn't even start.

> Btw how long does it take for you once wpt tests are started until it fails
> with the not being able to connect to Marionette message?

I'm not sure what you mean by wpt tests starting but the time from when the mach command is executed until the connection failure message appears is about 1min per the timings in comment 0.
Replacing some of the debug log statements in executormarionette.py with warnings, I can see that (with the patch from bug 1315611 applied) it gives up exactly 60s after waiting for the marionette connection so clearly the following line is timing out:

  success = self.marionette.wait_for_port(60)

If I extend that to, say, 180 instead I find the runner gets forcibly terminated due to the init_timeout of 60s specified in testing/web-platform/harness/wptrunner/browsers/firefox.py. If I change that to 180s the tests run!

So my theory is:

* The rather quick failures I was seeing yesterday were due to a bug that is fixed by bug 131561
* The original issue is, as originally suggested, an overly zealous timeout
* Presumably, over time, either startup time for debug builds of Firefox on Windows or startup time for the test runner infrastructure itself has regressed such that 60s is no longer enough in a lot of cases.
* The test runner works under opt builds because startup time is fast enough (hence why there are no failures of this sort under CI or for debug-opt builds)
* The symptoms I originally reported where the tests would run on a faster machine when not compiling are consistent with the timeout *sometimes* being sufficient when the system is not under load. The fact that I have a nearly 100% failure rate on a new faster machine suggests there has been a significant regression over the last month or that there is something about this new machine that exacerbates the problem (different graphics driver / higher DPI display etc.).
Attached patch bug.diff (obsolete) — — Splinter Review 
Does the attached diff help? With the changes to detect the graphics check window and this patch to increase the timeout, the problem seems fixed to me.
Attachment #8844884 - Flags: feedback?(bbirtles)
Comment on attachment 8844884 [details] [diff] [review]
bug.diff

I'm afraid not. I tried running with the patch applied but I got the usual "Failed to connect to Marionette. Init failed" messages.
Attachment #8844884 - Flags: feedback?(bbirtles) → feedback-
(In reply to Brian Birtles (:birtles) from comment #48)
> Comment on attachment 8844884 [details] [diff] [review]
> bug.diff
> 
> I'm afraid not. I tried running with the patch applied but I got the usual
> "Failed to connect to Marionette. Init failed" messages.

You also had the patch from bug 1315611 applied?
(In reply to James Graham [:jgraham] from comment #49)
> (In reply to Brian Birtles (:birtles) from comment #48)
> > Comment on attachment 8844884 [details] [diff] [review]
> > bug.diff
> > 
> > I'm afraid not. I tried running with the patch applied but I got the usual
> > "Failed to connect to Marionette. Init failed" messages.
> 
> You also had the patch from bug 1315611 applied?

Yes. I pulled again from m-c after it was merged there and I've double checked it is applied.
Running the tests now I see it is killing Firefox after 60s while it is still loading. If I get a chance, I'll try to debug it later today.
I had a look into this and confirmed that with attachment 8844884 [details] [diff] [review] we are successfully increasing the timeout defined for firefox (in firefox.py) to 180, but we're not changing the timeout used in executormarionette.py. Specifically we're timing out here:

  http://searchfox.org/mozilla-central/rev/7cb75d87753de9103253e34bc85592e26378f506/testing/web-platform/harness/wptrunner/executors/executormarionette.py#77

We need to adjust both timeouts (or get rid of one, I guess).
FYI web-platform-tests are starting Firefox themselves. So having a timeout error for Marionette when it is set to 60s is kinda weird! I still think something else goes badly wrong, and bumping up the timeout here will not fix the underlying issue.

Recently I had a similar thing to fix for our Linux hosts in automation. See bug 1345105 for details.
(In reply to Brian Birtles (:birtles) from comment #52)

> http://searchfox.org/mozilla-central/rev/
> 7cb75d87753de9103253e34bc85592e26378f506/testing/web-platform/harness/
> wptrunner/executors/executormarionette.py#77
> 
> We need to adjust both timeouts (or get rid of one, I guess).

Hmm, I thought I fixed that. Obviously not, or I failed to make the right patch.

> FYI web-platform-tests are starting Firefox themselves. So having a timeout error for Marionette when it is set to 60s is kinda weird!

That doesn't seem weird? These builds are really slow to start so it's easy to imagine that marionette isn't ready 60s after we get to here.
Attached patch bug.diff — — Splinter Review 
Any better with this one?
Attachment #8844884 - Attachment is obsolete: true
Attachment #8846674 - Flags: feedback?(bbirtles)
Comment on attachment 8846674 [details] [diff] [review]
bug.diff

Fixes it for me. Thank you!
Attachment #8846674 - Flags: feedback?(bbirtles) → feedback+
Comment on attachment 8850618 [details]
Bug 1338397 - Use timeout multipler to adjust browser startup timeout in wpt,

https://reviewboard.mozilla.org/r/123162/#review125982

::: commit-message-439ee:1
(Diff revision 1)
> +Bug 1338397 - Use timeout multipler to adjust browser statup timeout in wpt, r=maja_zf

Typo: statup
Attachment #8850618 - Flags: review?(mjzffr) → review+
Pushed by james@hoppipolla.co.uk:
https://hg.mozilla.org/integration/autoland/rev/df7bd26e69b6
Use timeout multipler to adjust browser startup timeout in wpt, r=maja_zf
Backed out for wpt failing, at least on Windows opt:

https://hg.mozilla.org/integration/autoland/rev/b9c1c731bf45255f01e82242854f36544fba3cb4

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=df7bd26e69b68470ce6733b958b59e881efbbc6c&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=86395985&repo=autoland

02:08:08     INFO - TEST-START | /websockets/interfaces/WebSocket/protocol/protocol-initial.html?wss
02:08:08     INFO - TEST-SKIP | /websockets/interfaces/WebSocket/protocol/protocol-initial.html?wss | took 1ms
02:08:08     INFO - Setting up ssl
02:08:08     INFO - certutil | 
02:08:08     INFO - certutil | 
02:08:08     INFO - certutil | 
02:08:08     INFO - Certificate Nickname                                         Trust Attributes
02:08:08     INFO -                                                              SSL,S/MIME,JAR/XPI
02:08:08     INFO - 
02:08:08     INFO - web-platform-tests                                           CT,, 
02:08:08     INFO - 
02:08:08     INFO - Application command: c:\slave\test\build\application\firefox\firefox.exe -marionette about:blank -profile c:\users\cltbld\appdata\local\temp\tmp2epyjo.mozrunner
02:08:08     INFO - Starting runner
02:08:09 CRITICAL - Test harness output was not a valid structured log message: 
02:08:09 CRITICAL - Traceback (most recent call last):
02:08:09 CRITICAL - Test harness output was not a valid structured log message: 
02:08:09 CRITICAL -   File "c:\slave\test\build\tests\web-platform\harness\wptrunner\testrunner.py", line 132, in start_runner
02:08:09 CRITICAL - Test harness output was not a valid structured log message: 
02:08:09 CRITICAL -     runner.run()
02:08:09 CRITICAL - Test harness output was not a valid structured log message: 
02:08:09 CRITICAL -   File "c:\slave\test\build\tests\web-platform\harness\wptrunner\testrunner.py", line 88, in run
02:08:09 CRITICAL - Test harness output was not a valid structured log message: 
02:08:09 CRITICAL -     self.setup()
02:08:09 CRITICAL - Test harness output was not a valid structured log message: 
02:08:09 CRITICAL -   File "c:\slave\test\build\tests\web-platform\harness\wptrunner\testrunner.py", line 75, in setup
02:08:09 CRITICAL - Test harness output was not a valid structured log message: 
02:08:09 CRITICAL -     self.executor.setup(self)
02:08:09 CRITICAL - Test harness output was not a valid structured log message: 
02:08:09 CRITICAL -   File "c:\slave\test\build\tests\web-platform\harness\wptrunner\executors\base.py", line 134, in setup
02:08:09 CRITICAL - Test harness output was not a valid structured log message: 
02:08:09 CRITICAL -     self.protocol.setup(runner)
02:08:09 CRITICAL - Test harness output was not a valid structured log message: 
02:08:09 CRITICAL -   File "c:\slave\test\build\tests\web-platform\harness\wptrunner\executors\executormarionette.py", line 70, in setup
02:08:09 CRITICAL - Test harness output was not a valid structured log message: 
02:08:09 CRITICAL -     startup_timeout = marionette.Marionette.DEFAULT_STARTUP_TIMEOUT * self.timeout_multiplier
02:08:09 CRITICAL - Test harness output was not a valid structured log message: 
02:08:09 CRITICAL - TypeError: unsupported operand type(s) for *: 'int' and 'NoneType'
02:08:09     INFO - Browser exited with return code 572
Flags: needinfo?(james)
Pushed by james@hoppipolla.co.uk:
https://hg.mozilla.org/integration/autoland/rev/e93b7a9b7786
Use timeout multipler to adjust browser startup timeout in wpt, r=maja_zf
https://hg.mozilla.org/mozilla-central/rev/e93b7a9b7786
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Flags: needinfo?(james)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: