13:27:43 INFO - 147 INFO TEST-START | dom/workers/test/serviceworkers/test_workerupdatefoundevent.html 13:27:43 INFO - 148 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_workerupdatefoundevent.html | Test timed out. - expected PASS 13:27:43 INFO - 149 INFO TEST-OK | dom/workers/test/serviceworkers/test_workerupdatefoundevent.html | took 327099ms

:nsm -- These failures seem quite frequent today. Are you investigating?

Failures on Windows are an exciting twist to this.

Bisection range: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=mozilla-inbound%20opt%20test%20mochitest-13&fromchange=2274f5b28b31&tochange=83c9e4db68b3 There's a bunch of other unfiled serviceworker-related orange floating about today as well; seems like a decent chance it's related.

I backed out bug 1154494 for said other orange, but I think this is separate.

I pushed a debugging patch for this: https://hg.mozilla.org/integration/mozilla-inbound/rev/5ce83454a0e4

(In reply to Treeherder Robot from comment #144) > log: > https://treeherder.mozilla.org/logviewer.html#?repo=b2g-inbound&job_id=1838304 > repository: b2g-inbound > start_time: 2015-05-01T18:25:15 > who: philringnalda[at]gmail[dot]com > machine: t-w732-ix-075 > buildname: Windows 7 32-bit b2g-inbound pgo test mochitest-4 > revision: c59fc5403728 18:32:10 INFO - 527 INFO TEST-START | dom/workers/test/serviceworkers/test_workerupdatefoundevent.html 18:32:10 INFO - 528 INFO start got called 18:32:10 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:10 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:10 INFO - ###!!! [Parent][MessageChannel] Error: (msgtype=0x140001,name=PBackgroundTest::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 18:32:10 INFO - IPDL protocol error: Handler for PBackgroundTest returned error code 18:32:10 INFO - ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x120001,name=PBackground::Msg_PBackgroundTestConstructor) Processing error: message was deserialized, but the handler returned false (indicating failure) 18:32:10 INFO - 529 INFO startWaitForUpdateFound got called 18:32:10 INFO - 530 INFO registerNext got called 18:32:10 INFO - 531 INFO onupdatefound 18:32:11 INFO - worker_updatefoundevent2.js loaded 18:32:11 INFO - 532 INFO waitForUpdateFound got called 18:32:11 INFO - 533 INFO onupdatefound 18:32:12 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:15 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:15 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:15 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:15 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:15 INFO - ###!!! [Parent][MessageChannel] Error: (msgtype=0x140001,name=PBackgroundTest::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 18:32:15 INFO - IPDL protocol error: Handler for PBackgroundTest returned error code 18:32:15 INFO - ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x120001,name=PBackground::Msg_PBackgroundTestConstructor) Processing error: message was deserialized, but the handler returned false (indicating failure) 18:32:15 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:15 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:15 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:15 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:15 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:22 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:22 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:22 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:22 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:22 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:22 INFO - ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 18:32:31 INFO - [NPAPI 2852] WARNING: pipe error: 109: file c:/builds/moz2_slave/b2g-in-w32-pgo-000000000000000/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 333 18:37:28 INFO - 1430530648185 Browser.Experiments.Experiments TRACE Experiments #0::updateManifest() 18:37:28 INFO - 1430530648185 Browser.Experiments.Experiments TRACE Experiments #0::_run 18:37:28 INFO - 1430530648185 Browser.Experiments.Experiments TRACE Experiments #0::_main iteration 18:37:28 INFO - 1430530648186 Browser.Experiments.Experiments TRACE Experiments #0::_loadManifest 18:37:28 INFO - 1430530648186 Browser.Experiments.Experiments TRACE Experiments #0::httpGetRequest(http://127.0.0.1:8888/experiments-dummy/manifest) 18:37:28 INFO - 1430530648193 Browser.Experiments.Experiments ERROR Experiments #0::httpGetRequest::onLoad() - Request to http://127.0.0.1:8888/experiments-dummy/manifest returned status 404 18:37:28 INFO - 1430530648193 Browser.Experiments.Experiments ERROR Experiments #0::_loadManifest - failure to fetch/parse manifest (continuing anyway): Error: Experiments - XHR status for http://127.0.0.1:8888/experiments-dummy/manifest is 404 18:37:28 INFO - 1430530648193 Browser.Experiments.Experiments TRACE Experiments #0::_evaluateExperiments 18:37:28 INFO - 1430530648194 Browser.Experiments.Experiments TRACE Experiments #0::_main finished, scheduling next run 18:37:36 INFO - TEST-INFO | screenshot: exit status 0 18:37:36 INFO - 534 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_workerupdatefoundevent.html | Test timed out. - expected PASS 18:37:36 INFO - MEMORY STAT vsize after test: 644751360 18:37:36 INFO - MEMORY STAT vsizeMaxContiguous after test: 621215744 18:37:36 INFO - MEMORY STAT residentFast after test: 65941504 18:37:36 INFO - MEMORY STAT heapAllocated after test: 52769996 18:37:36 INFO - 535 INFO TEST-OK | dom/workers/test/serviceworkers/test_workerupdatefoundevent.html | took 326879ms

I think this was caused by the same underlying issue that was causing bug 1134841 (the worker going away before the activate event's waitUntil promise was resolved.) Thanks, Ben!