1455530 - Intermittent Marionette error: raise socket.error("No data received over socket")

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

Filed by: ncsoregi [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=174704412&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/UsrCIFQeQTuIN84WfkO-3w/runs/0/artifacts/public/logs/live_backing.log

https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/UsrCIFQeQTuIN84WfkO-3w/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2018-04-20T05:38:27.224Z] 05:38:27     INFO - PID 6851 | Assertion failed at /builds/worker/workspace/build/src/gfx/cairo/cairo/src/cairo-array.c:339: array->num_elements + num_elements <= array->size
[task 2018-04-20T05:38:27.241Z] 05:38:27     INFO - PID 6851 | ExceptionHandler::GenerateDump cloned child 6995
[task 2018-04-20T05:38:27.241Z] 05:38:27     INFO - PID 6851 | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2018-04-20T05:38:27.249Z] 05:38:27     INFO - PID 6851 | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2018-04-20T05:38:27.440Z] 05:38:27  WARNING - Post-connection steps failed
[task 2018-04-20T05:38:27.447Z] 05:38:27    ERROR - Traceback (most recent call last):
[task 2018-04-20T05:38:27.447Z] 05:38:27    ERROR -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/protocol.py", line 55, in setup
[task 2018-04-20T05:38:27.447Z] 05:38:27    ERROR -     self.after_connect()
[task 2018-04-20T05:38:27.447Z] 05:38:27    ERROR -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 375, in after_connect
[task 2018-04-20T05:38:27.448Z] 05:38:27    ERROR -     self.testharness.load_runner(self.executor.last_environment["protocol"])
[task 2018-04-20T05:38:27.448Z] 05:38:27    ERROR -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 137, in load_runner
[task 2018-04-20T05:38:27.448Z] 05:38:27    ERROR -     "document.title = '%s'" % threading.current_thread().name.replace("'", '"'))
[task 2018-04-20T05:38:27.448Z] 05:38:27    ERROR -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1717, in execute_script
[task 2018-04-20T05:38:27.448Z] 05:38:27    ERROR -     rv = self._send_message("WebDriver:ExecuteScript", body, key="value")
[task 2018-04-20T05:38:27.448Z] 05:38:27    ERROR -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 31, in _
[task 2018-04-20T05:38:27.448Z] 05:38:27    ERROR -     m._handle_socket_failure()
[task 2018-04-20T05:38:27.448Z] 05:38:27    ERROR -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 797, in _handle_socket_failure
[task 2018-04-20T05:38:27.448Z] 05:38:27    ERROR -     reraise(exc, val, tb)
[task 2018-04-20T05:38:27.449Z] 05:38:27    ERROR -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2018-04-20T05:38:27.449Z] 05:38:27    ERROR -     return func(*args, **kwargs)
[task 2018-04-20T05:38:27.449Z] 05:38:27    ERROR -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 733, in _send_message
[task 2018-04-20T05:38:27.449Z] 05:38:27    ERROR -     msg = self.client.request(name, params)
[task 2018-04-20T05:38:27.450Z] 05:38:27    ERROR -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 273, in request
[task 2018-04-20T05:38:27.450Z] 05:38:27    ERROR -     return self.receive()
[task 2018-04-20T05:38:27.451Z] 05:38:27    ERROR -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 159, in receive
[task 2018-04-20T05:38:27.451Z] 05:38:27    ERROR -     raise socket.error("No data received over socket")
[task 2018-04-20T05:38:27.452Z] 05:38:27    ERROR - error: No data received over socket
[task 2018-04-20T05:38:27.452Z] 05:38:27    ERROR -

Comment 1

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

This is just an assertion which triggers a MOZ_CRASH:

[task 2018-04-20T05:38:27.224Z] 05:38:27     INFO - PID 6851 | Assertion failed at /builds/worker/workspace/build/src/gfx/cairo/cairo/src/cairo-array.c:339: array->num_elements + num_elements <= array->size
[task 2018-04-20T05:38:27.241Z] 05:38:27     INFO - PID 6851 | ExceptionHandler::GenerateDump cloned child 6995
[task 2018-04-20T05:38:27.241Z] 05:38:27     INFO - PID 6851 | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2018-04-20T05:38:27.249Z] 05:38:27     INFO - PID 6851 | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[..]
[task 2018-04-20T05:38:27.454Z] 05:38:27     INFO - PID 6851 | Hit MOZ_CRASH(Aborting on channel error.) at /builds/worker/workspace/build/src/ipc/glue/MessageChannel.cpp:2553
[task 2018-04-20T05:38:27.550Z] 05:38:27     INFO - PID 6851 | #01: mozilla::ipc::ProcessLink::OnChannelError() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:27.552Z] 05:38:27     INFO - PID 6851 | #02: event_process_active_single_queue (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:27.560Z] 05:38:27     INFO - PID 6851 | #03: event_base_loop (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:27.561Z] 05:38:27     INFO - PID 6851 | #04: base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:27.570Z] 05:38:27     INFO - PID 6851 | #05: MessageLoop::RunInternal() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:27.571Z] 05:38:27     INFO - PID 6851 | #06: MessageLoop::Run() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:27.579Z] 05:38:27     INFO - PID 6851 | #07: base::Thread::ThreadMain() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:27.583Z] 05:38:27     INFO - PID 6851 | #08: ThreadFunc(void*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:27.631Z] 05:38:27     INFO - PID 6851 | #09: start_thread (/build/glibc-Cl5G7W/glibc-2.23/nptl/pthread_create.c:333)
[task 2018-04-20T05:38:29.566Z] 05:38:29     INFO - PID 6851 | #10: __clone (/build/glibc-Cl5G7W/glibc-2.23/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:111)
[task 2018-04-20T05:38:29.567Z] 05:38:29     INFO - PID 6851 | #11: ??? (???:???)
[task 2018-04-20T05:38:29.569Z] 05:38:29     INFO - PID 6851 | [Child 6918, Chrome_ChildThread] WARNING: pipe error (3): Connection reset by peer: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353
[task 2018-04-20T05:38:29.569Z] 05:38:29     INFO - PID 6851 | Hit MOZ_CRASH(Aborting on channel error.) at /builds/worker/workspace/build/src/ipc/glue/MessageChannel.cpp:2553
[task 2018-04-20T05:38:29.569Z] 05:38:29     INFO - PID 6851 | #01: mozilla::ipc::ProcessLink::OnChannelError() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:29.570Z] 05:38:29     INFO - PID 6851 | #02: event_process_active_single_queue (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:29.570Z] 05:38:29     INFO - PID 6851 | #03: event_base_loop (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:29.571Z] 05:38:29     INFO - PID 6851 | #04: base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:29.571Z] 05:38:29     INFO - PID 6851 | #05: MessageLoop::RunInternal() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:29.571Z] 05:38:29     INFO - PID 6851 | #06: MessageLoop::Run() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:29.572Z] 05:38:29     INFO - PID 6851 | #07: base::Thread::ThreadMain() (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:29.573Z] 05:38:29     INFO - PID 6851 | #08: ThreadFunc(void*) (/builds/worker/workspace/build/application/firefox/libxul.so)
[task 2018-04-20T05:38:29.573Z] 05:38:29     INFO - PID 6851 | #09: start_thread (/build/glibc-Cl5G7W/glibc-2.23/nptl/pthread_create.c:333)
[task 2018-04-20T05:38:29.574Z] 05:38:29     INFO - PID 6851 | #10: __clone (/build/glibc-Cl5G7W/glibc-2.23/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:111)
[task 2018-04-20T05:38:29.574Z] 05:38:29     INFO - PID 6851 | #11: ??? (???:???)

The wptrunner doesn't seem to handle such a situation very well, and the reporting is kinda bad in this case too. Not sure why we don't report a crash. James any feedback?

Comment 2

[James Graham [:jgraham]]

Looks like we get a crash during startup for some reason. Then we try to recover and try again, but the teardown method for the reftest executor is trying to use a marionette connection that doesn't exist and do that fails, and we don't recover from that. We should definitely ensure that teardown can fail gracefully.

Comment 3

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

Btw. the assertion and crash are covered by bug 1290339.

(In reply to James Graham [:jgraham] from comment #2)
> and we don't recover from that. We should definitely ensure that teardown
> can fail gracefully.

We would then correctly report the assertion and crash?

Comment 4

[Intermittent Failures Robot]

1 failures in 782 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* linux64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1455530&startday=2018-04-16&endday=2018-04-22&tree=trunk

Comment 5

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 6

[Arthur Iakab [arthur_iakab]]

Here is a push where the failure appeared https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=94415f8067eca69a78ef2d630068f254aedf1f27&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=pending&filter-resultStatus=running&filter-resultStatus=success&filter-classifiedState=unclassified

Link to a recent log https://treeherder.mozilla.org/logviewer.html#?job_id=179114803&repo=mozilla-inbound

Part of that log: 
02:37:02     INFO - web-platform-tests                                           CT,, 
02:37:02     INFO - 
02:37:02     INFO - Application command: Z:\task_1526607357\build\application\firefox\firefox.exe -marionette about:blank -profile c:\users\task_1526607357\appdata\local\temp\tmpxrmlb5.mozrunner
02:37:02     INFO - Starting runner
02:37:03     INFO - PID 5048 | [5048, Main Thread] WARNING: Failed to load startupcache file correctly, removing!: file z:/build/build/src/startupcache/StartupCache.cpp, line 217
02:37:03     INFO - PID 5048 | 1526611023263	addons.xpi-utils	WARN	Error: Synchronously loading the add-ons database (resource://gre/modules/addons/XPIDatabase.jsm:1392:17) JS Stack trace: [e-mail]:1392:17
02:37:03     INFO - PID 5048 | [e-mail]:2376:9
02:37:03     INFO - PID 5048 | [e-mail]:1909:25
02:37:03     INFO - PID 5048 | [e-mail]:205:12
02:37:03     INFO - PID 5048 | [e-mail]:653:5
02:37:03     INFO - PID 5048 | [e-mail]:812:9
02:37:03     INFO - PID 5048 | [e-mail]:2864:5
02:37:03     INFO - PID 5048 | [e-mail]:66:9
02:37:04     INFO - PID 5048 | [5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/extensions/cookie/nsPermissionManager.cpp, line 2910
02:37:04     INFO - PID 5048 | ++DOCSHELL 0E8B2800 == 1 [pid = 5048] [id = {bea287e7-c1e2-485f-8722-1e3992561461}]
02:37:04     INFO - PID 5048 | ++DOMWINDOW == 1 (0DB942E0) [pid = 5048] [serial = 1] [outer = 00000000]
02:37:04     INFO - PID 5048 | [5048, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/widget/windows/nsLookAndFeel.cpp, line 847
02:37:04     INFO - PID 5048 | ++DOMWINDOW == 2 (0E8B3800) [pid = 5048] [serial = 2] [outer = 0DB942E0]
02:37:04     INFO - PID 5048 | [5048, Main Thread] WARNING: DWM not enabled, falling back to software vsync: file z:/build/build/src/gfx/thebes/gfxWindowsPlatform.cpp, line 1975
02:37:04     INFO - PID 5048 | ++DOCSHELL 0E8BE400 == 2 [pid = 5048] [id = {098feb14-d4fc-4699-9f51-edcc4ddd9f32}]
02:37:04     INFO - PID 5048 | ++DOMWINDOW == 3 (0DB94540) [pid = 5048] [serial = 3] [outer = 00000000]
02:37:04     INFO - PID 5048 | ++DOMWINDOW == 4 (0E8BF000) [pid = 5048] [serial = 4] [outer = 0DB94540]
02:37:04     INFO - PID 5048 | ++DOCSHELL 0F519000 == 3 [pid = 5048] [id = {9084c21f-fda7-4797-9a2a-cb1d2725f134}]
02:37:04     INFO - PID 5048 | ++DOMWINDOW == 5 (0DB947A0) [pid = 5048] [serial = 5] [outer = 00000000]
02:37:04     INFO - PID 5048 | ++DOMWINDOW == 6 (0F520000) [pid = 5048] [serial = 6] [outer = 0DB947A0]
02:37:04     INFO - PID 5048 | [5048, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file z:/build/build/src/widget/windows/nsLookAndFeel.cpp, line 473
02:37:04     INFO - PID 5048 | ++DOMWINDOW == 7 (0FA10800) [pid = 5048] [serial = 7] [outer = 0DB94540]
02:37:05     INFO - PID 5048 | ++DOCSHELL 0EE1BC00 == 4 [pid = 5048] [id = {4f9d4608-28af-4f38-b986-164efc60f341}]
02:37:05     INFO - PID 5048 | ++DOMWINDOW == 8 (0DB94C60) [pid = 5048] [serial = 8] [outer = 00000000]
02:37:05     INFO - PID 5048 | ++DOCSHELL 0EE1C000 == 5 [pid = 5048] [id = {58aed7f6-95c7-407f-9886-14abfa155e50}]
02:37:05     INFO - PID 5048 | ++DOMWINDOW == 9 (0DB94D90) [pid = 5048] [serial = 9] [outer = 00000000]
02:37:05     INFO - PID 5048 | [Child 3076, Main Thread] WARNING: No CID found when attempting to map contract ID: file z:/build/build/src/xpcom/components/nsComponentManager.cpp, line 505
02:37:05     INFO - PID 5048 | [Child 3076, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file z:/build/build/src/xpcom/base/nsSystemInfo.cpp, line 119
02:37:05     INFO - PID 5048 | ++DOCSHELL 05D3B000 == 1 [pid = 3076] [id = {37d2f6b4-ad59-433e-bc38-317b3177b09a}]
02:37:05     INFO - PID 5048 | [Child 3076, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/widget/windows/nsLookAndFeel.cpp, line 847
02:37:05     INFO - PID 5048 | ++DOMWINDOW == 1 (05DB11B0) [pid = 3076] [serial = 1] [outer = 00000000]
02:37:05     INFO - PID 5048 | ++DOMWINDOW == 2 (05D3C800) [pid = 3076] [serial = 2] [outer = 05DB11B0]
02:37:05     INFO - PID 5048 | [Child 3076, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file z:/build/build/src/widget/windows/nsLookAndFeel.cpp, line 473
02:37:05     INFO - PID 5048 | ++DOMWINDOW == 10 (14B50C00) [pid = 5048] [serial = 10] [outer = 0DB94D90]
02:37:05     INFO - PID 5048 | ++DOMWINDOW == 3 (0AFB0000) [pid = 3076] [serial = 3] [outer = 05DB11B0]
02:37:05     INFO - PID 5048 | [Child 3076, MediaPlayback #1] WARNING: NS_ENSURE_TRUE(SUCCEEDED(hr)) failed: file z:/build/build/src/dom/media/platforms/wmf/WMFUtils.cpp, line 74
02:37:05     INFO - PID 5048 | [Child 3076, MediaPDecoder #1] WARNING: NS_ENSURE_TRUE(SUCCEEDED(hr)) failed: file z:/build/build/src/dom/media/platforms/wmf/WMFUtils.cpp, line 74
02:37:05     INFO - PID 5048 | ++DOMWINDOW == 11 (14B56000) [pid = 5048] [serial = 11] [outer = 0DB94C60]
02:37:05     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: No CID found when attempting to map contract ID: file z:/build/build/src/xpcom/components/nsComponentManager.cpp, line 505
02:37:05     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file z:/build/build/src/xpcom/base/nsSystemInfo.cpp, line 119
02:37:05     INFO - PID 5048 | ++DOCSHELL 05F3A000 == 1 [pid = 5648] [id = {2311eeb7-8ddc-409c-84d8-340c293736c4}]
02:37:05     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/widget/windows/nsLookAndFeel.cpp, line 847
02:37:05     INFO - PID 5048 | ++DOMWINDOW == 1 (05FC11B0) [pid = 5648] [serial = 1] [outer = 00000000]
02:37:05     INFO - PID 5048 | ++DOMWINDOW == 2 (05F3B800) [pid = 5648] [serial = 2] [outer = 05FC11B0]
02:37:05     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file z:/build/build/src/widget/windows/nsLookAndFeel.cpp, line 473
02:37:05     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 342
02:37:05     INFO - PID 5048 | ++DOMWINDOW == 3 (0ADC0400) [pid = 5648] [serial = 3] [outer = 05FC11B0]
02:37:06     INFO - PID 5048 | ++DOCSHELL 1580FC00 == 6 [pid = 5048] [id = {1983af5f-0773-4d32-b709-cf354547d13a}]
02:37:06     INFO - PID 5048 | ++DOMWINDOW == 12 (0DB95D00) [pid = 5048] [serial = 12] [outer = 00000000]
02:37:06     INFO - PID 5048 | ++DOMWINDOW == 13 (0E721400) [pid = 5048] [serial = 13] [outer = 0DB95D00]
02:37:06     INFO - PID 5048 | ++DOMWINDOW == 14 (0E722C00) [pid = 5048] [serial = 14] [outer = 0DB95D00]
02:37:06     INFO - PID 5048 | ++DOMWINDOW == 15 (0E725000) [pid = 5048] [serial = 15] [outer = 0DB95D00]
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: Need TabChild to get the nativeWindow from!: file z:/build/build/src/widget/PuppetWidget.cpp, line 1220
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file z:/build/build/src/parser/html/nsHtml5StreamParser.cpp, line 1003
02:37:06     INFO - PID 5048 | [Parent 5048, Gecko_IOThread] WARNING: pipe error: 232: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 513
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x2D0020,name=PContent::Msg_PreferenceUpdate) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x16008D,name=PBrowser::Msg_UpdateNativeWindowHandle) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | ###!!! [Parent][MessageChannel] Error: (msgtype=0x160080,name=PBrowser::Msg_Destroy) Channel error: cannot send/recv
02:37:06     INFO - PID 5048 | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
02:37:06     INFO - PID 5048 | 1526611026428	addons.xpi	WARN	Exception running bootstrap method shutdown on [e-mail]: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource://activity-stream/lib/TelemetryFeed.jsm :: uninit :: line 493"  data: no] Stack trace: uninit()@resource://activity-stream/lib/TelemetryFeed.jsm:493
02:37:06     INFO - PID 5048 | onAction()@resource://activity-stream/lib/TelemetryFeed.jsm:451
02:37:06     INFO - PID 5048 | _middleware/</<()@resource://activity-stream/lib/Store.jsm:51
02:37:06     INFO - PID 5048 | Store/this[method]()@resource://activity-stream/lib/Store.jsm:29
02:37:06     INFO - PID 5048 | uninit()@resource://activity-stream/lib/Store.jsm:166
02:37:06     INFO - PID 5048 | uninit()@resource://activity-stream/lib/ActivityStream.jsm:314
02:37:06     INFO - PID 5048 | uninit()@resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///Z:/task_1526607357/build/application/firefox/browser/features/[e-mail]!/bootstrap.js:79
02:37:06     INFO - PID 5048 | shutdown()@resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///Z:/task_1526607357/build/application/firefox/browser/features/[e-mail]!/bootstrap.js:187
02:37:06     INFO - PID 5048 | callBootstrapMethod()@resource://gre/modules/addons/XPIProvider.jsm:1385
02:37:06     INFO - PID 5048 | shutdown()@resource://gre/modules/addons/XPIProvider.jsm:1527
02:37:06     INFO - PID 5048 | observer()@resource://gre/modules/addons/XPIProvider.jsm:1982
02:37:06     INFO - PID 5048 | observe()@resource:///modules/ContentCrashHandlers.jsm:152
02:37:06     INFO - PID 5048 | [Parent 5048, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 188
02:37:06     INFO - PID 5048 | [Parent 5048, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 259
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/dom/fetch/FetchDriver.cpp, line 554
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 259
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/dom/fetch/FetchDriver.cpp, line 554
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 259
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/dom/fetch/FetchDriver.cpp, line 554
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 259
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/dom/fetch/FetchDriver.cpp, line 554
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 259
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/dom/fetch/FetchDriver.cpp, line 554
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 259
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/dom/fetch/FetchDriver.cpp, line 554
02:37:06     INFO - PID 5048 | [Child 5648, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
02:37:06     INFO - PID 5048 | [Child 5648, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
02:37:06     INFO - PID 5048 | [Parent 5048, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
02:37:06     INFO - PID 5048 | [Parent 5048, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
02:37:06     INFO - PID 5048 | [Parent 5048, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
02:37:06     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file z:/build/build/src/xpcom/threads/nsThread.cpp, line 805
02:37:06     INFO - PID 5048 | [Parent 5048, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
02:37:06     INFO - PID 5048 | JavaScript error: resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///Z:/task_1526607357/build/application/firefox/browser/features/[e-mail]!/bootstrap.js, line 33: TypeError: NetworkError when attempting to fetch resource.
02:37:06     INFO - PID 5048 | JavaScript error: resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///Z:/task_1526607357/build/application/firefox/browser/features/[e-mail]!/bootstrap.js, line 33: TypeError: NetworkError when attempting to fetch resource.
02:37:06     INFO - PID 5048 | JavaScript error: resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///Z:/task_1526607357/build/application/firefox/browser/features/[e-mail]!/bootstrap.js, line 33: TypeError: NetworkError when attempting to fetch resource.
02:37:06     INFO - PID 5048 | JavaScript error: resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///Z:/task_1526607357/build/application/firefox/browser/features/[e-mail]!/bootstrap.js, line 33: TypeError: NetworkError when attempting to fetch resource.
02:37:06     INFO - PID 5048 | JavaScript error: resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///Z:/task_1526607357/build/application/firefox/browser/features/[e-mail]!/bootstrap.js, line 33: TypeError: NetworkError when attempting to fetch resource.
02:37:06     INFO - PID 5048 | JavaScript error: resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///Z:/task_1526607357/build/application/firefox/browser/features/[e-mail]!/bootstrap.js, line 33: TypeError: NetworkError when attempting to fetch resource.
02:37:06     INFO - PID 5048 | [Parent 5048, LoadRoots] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3378
02:37:06     INFO - PID 5048 | [Parent 5048, LoadRoots] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3378
02:37:06     INFO - PID 5048 | [Parent 5048, LoadRoots] WARNING: This method is lossy. Use GetCanonicalPath !: file z:/build/build/src/xpcom/io/nsLocalFileWin.cpp, line 3378
02:37:06     INFO - PID 5048 | --DOCSHELL 05F3A000 == 0 [pid = 5648] [id = {2311eeb7-8ddc-409c-84d8-340c293736c4}]
02:37:06     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: '!gThread', file z:/build/build/src/xpcom/threads/nsTimerImpl.cpp, line 399
02:37:06     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/startupcache/StartupCacheUtils.cpp, line 171
02:37:06     INFO - PID 5048 | --DOMWINDOW == 2 (0ADC0400) [pid = 5648] [serial = 3] [outer = 00000000] [url = about:blank]
02:37:06     INFO - PID 5048 | --DOMWINDOW == 1 (05FC11B0) [pid = 5648] [serial = 1] [outer = 00000000] [url = about:blank]
02:37:06     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 517
02:37:06     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 517
02:37:06     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 517
02:37:06     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 517
02:37:06     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 517
02:37:06     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 517
02:37:06     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 517
02:37:06     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 517
02:37:06     INFO - PID 5048 | [Child 5648, Main Thread] WARNING: '!mMainThread', file z:/build/build/src/xpcom/threads/nsThreadManager.cpp, line 517
02:37:06     INFO - PID 5048 | --DOMWINDOW == 0 (05F3B800) [pid = 5648] [serial = 2] [outer = 00000000] [url = about:blank]
02:37:06     INFO - PID 5048 | nsStringStats
02:37:06     INFO - PID 5048 |  => mAllocCount:           7912
02:37:06     INFO - PID 5048 |  => mReallocCount:          138
02:37:06     INFO - PID 5048 |  => mFreeCount:            7912
02:37:06     INFO - PID 5048 |  => mShareCount:           6643
02:37:06     INFO - PID 5048 |  => mAdoptCount:            528
02:37:06     INFO - PID 5048 |  => mAdoptFreeCount:        528
02:37:06     INFO - PID 5048 |  => Process ID: 5648, Thread ID: 6072
02:37:06     INFO - PID 5048 | 1526611026957	Marionette	INFO	Listening on port 2828
02:37:07     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_TRUE(service) failed: file z:/build/build/src/netwerk/cache2/CacheObserver.cpp, line 347
02:37:07     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file z:/build/build/src/netwerk/cache2/CacheObserver.cpp, line 370
02:37:07     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file z:/build/build/src/netwerk/cache2/CacheObserver.cpp, line 487
02:37:07     INFO - PID 5048 | [Parent 5048, Main Thread] WARNING: unable to post continuation event: file z:/build/build/src/xpcom/io/nsStreamUtils.cpp, line 490
02:37:07  WARNING - Failed to start protocol connection
02:37:07    ERROR - Traceback (most recent call last):
02:37:07    ERROR -   File "Z:\task_1526607357\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\protocol.py", line 47, in setup
02:37:07    ERROR -     self.connect()
02:37:07    ERROR -   File "Z:\task_1526607357\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 371, in connect
02:37:07    ERROR -     self.marionette.start_session()
02:37:07    ERROR -   File "Z:\task_1526607357\build\venv\lib\site-packages\marionette_driver\decorators.py", line 31, in _
02:37:07    ERROR -     m._handle_socket_failure()
02:37:07    ERROR -   File "Z:\task_1526607357\build\venv\lib\site-packages\marionette_driver\marionette.py", line 797, in _handle_socket_failure
02:37:07    ERROR -     reraise(exc, val, tb)
02:37:07    ERROR -   File "Z:\task_1526607357\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
02:37:07    ERROR -     return func(*args, **kwargs)
02:37:07    ERROR -   File "Z:\task_1526607357\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1243, in start_session
02:37:07    ERROR -     body)
02:37:07    ERROR -   File "Z:\task_1526607357\build\venv\lib\site-packages\marionette_driver\decorators.py", line 31, in _
02:37:07    ERROR -     m._handle_socket_failure()
02:37:07    ERROR -   File "Z:\task_1526607357\build\venv\lib\site-packages\marionette_driver\marionette.py", line 797, in _handle_socket_failure
02:37:07    ERROR -     reraise(exc, val, tb)
02:37:07    ERROR -   File "Z:\task_1526607357\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
02:37:07    ERROR -     return func(*args, **kwargs)
02:37:07    ERROR -   File "Z:\task_1526607357\build\venv\lib\site-packages\marionette_driver\marionette.py", line 733, in _send_message
02:37:07    ERROR -     msg = self.client.request(name, params)
02:37:07    ERROR -   File "Z:\task_1526607357\build\venv\lib\site-packages\marionette_driver\transport.py", line 273, in request
02:37:07    ERROR -     return self.receive()
02:37:07    ERROR -   File "Z:\task_1526607357\build\venv\lib\site-packages\marionette_driver\transport.py", line 159, in receive
02:37:07    ERROR -     raise socket.error("No data received over socket")
02:37:07    ERROR - error: No data received over socket
02:37:07    ERROR - 
02:37:07     INFO - Browser exited with return code 259
02:37:07  WARNING - u'runner_teardown': ()
02:37:07     INFO - Setting up ssl
02:37:07     INFO - certutil | 
02:37:07     INFO - certutil | 
02:37:07     INFO - certutil | 
02:37:07     INFO - Certificate Nickname                                         Trust Attributes
02:37:07     INFO -                                                              SSL,S/MIME,JAR/XPI
02:37:07     INFO - 
02:37:07     INFO - web-platform-tests                                           CT,,

Comment 7

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

As you can see in the log there is a content process crash, and as such Firefox has been shutdown:

> 02:37:06     INFO - PID 5048 | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
0

I don't know what the Marionette executor is doing here, but at least mozcrash is not run to analyze and print the crash report. If it would check the reports the failure message would look totally different.

James is that a known missing feature?

Comment 8

[James Graham [:jgraham]]

It looks like we don't handle a crash during start_session well, which is probably a startup crash. Not sure what we should do in that case, really.

Comment 9

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

Given that the executor handles the binary itself it will have to take care of possible crashes, which also applies to start-up. When `start_session()` raises an exception this would give an indication, and the executor should check for a possible crash. How is the crash check done once the tests are executed, and one of them crashes Firefox?

Comment 10

[Intermittent Failures Robot]

1 failures in 639 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1455530&startday=2018-05-14&endday=2018-05-20&tree=trunk

Comment 11

[James Graham [:jgraham]]

When a test executes we look for crashes by examining any protocol errors and/or using mozcrash to look for crash dump files. We certainly could handle this error explicitly and try to get the crash details which might help with debugging, but given the very low frequency of intermittents, and the fact that it's hard to work out the details of how to handle this, I don't think the work is going to be high priority.

Comment 12

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup