#[markdown(off)]
Filed by: aciure [at] mozilla.com

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

https://queue.taskcluster.net/v1/task/b4eUua9WS3-nejAyOQEklw/runs/0/artifacts/public/logs/live_backing.log

[task 2019-03-17T11:14:13.214Z] 11:14:13 INFO - PID 10472 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpbykZb7.mozrunner/runtests_leaks_841_tab_pid14120.log
[task 2019-03-17T11:14:13.315Z] 11:14:13 INFO - PID 10472 | ++DOMWINDOW == 3 (0x7fb8ca64a000) [pid = 14086] [serial = 3] [outer = 0x7fb8c9661d40]
[task 2019-03-17T11:14:13.352Z] 11:14:13 INFO - PID 10472 | [Parent 10472, Main Thread] WARNING: '!parent', file /builds/worker/workspace/build/src/netwerk/ipc/NeckoParent.cpp, line 954
[task 2019-03-17T11:14:13.400Z] 11:14:13 INFO - PID 10472 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-03-17T11:14:13.401Z] 11:14:13 INFO - PID 10472 | [Child 14120, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/netwerk/base/nsIOService.cpp, line 941
[task 2019-03-17T11:14:13.530Z] 11:14:13 INFO - PID 10472 | [Parent 10472, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/netwerk/url-classifier/UrlClassifierCommon.cpp, line 117
[task 2019-03-17T11:14:13.598Z] 11:14:13 INFO - PID 10472 | ++DOMWINDOW == 4 (0x7fb8c961ec00) [pid = 14086] [serial = 4] [outer = 0x7fb8c9661d40]
[task 2019-03-17T11:14:13.599Z] 11:14:13 INFO - PID 10472 | [Parent 10472, Main Thread] WARNING: '!window', file /builds/worker/workspace/build/src/dom/cache/CacheStorage.cpp, line 572
[task 2019-03-17T11:14:13.841Z] 11:14:13 INFO - PID 10472 | [Parent 10472, Main Thread] WARNING: '!window', file /builds/worker/workspace/build/src/dom/cache/CacheStorage.cpp, line 572
[task 2019-03-17T11:14:13.918Z] 11:14:13 INFO - PID 10472 | [Parent 10472, Main Thread] WARNING: '!window', file /builds/worker/workspace/build/src/dom/cache/CacheStorage.cpp, line 572
[task 2019-03-17T11:14:13.954Z] 11:14:13 INFO - PID 10472 | [Parent 10472, Main Thread] WARNING: '!window', file /builds/worker/workspace/build/src/dom/cache/CacheStorage.cpp, line 572
[task 2019-03-17T11:14:13.976Z] 11:14:13 INFO - PID 10472 | [Parent 10472, Main Thread] WARNING: '!window', file /builds/worker/workspace/build/src/dom/cache/CacheStorage.cpp, line 572
[task 2019-03-17T11:14:14.032Z] 11:14:14 INFO - PID 10472 | [Parent 10472, Main Thread] WARNING: '!window', file /builds/worker/workspace/build/src/dom/cache/CacheStorage.cpp, line 572
[task 2019-03-17T11:14:14.052Z] 11:14:14 INFO - PID 10472 | [Parent 10472, Main Thread] WARNING: '!window', file /builds/worker/workspace/build/src/dom/cache/CacheStorage.cpp, line 572
[task 2019-03-17T11:14:29.888Z] 11:14:29 INFO - PID 10472 | --DOMWINDOW == 3 (0x7fb8ca64a000) [pid = 14086] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2019-03-17T11:14:29.888Z] 11:14:29 INFO - PID 10472 | --DOMWINDOW == 2 (0x7fb8ca63c400) [pid = 14086] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-03-17T11:14:43.802Z] 11:14:43 INFO -
[task 2019-03-17T11:14:43.802Z] 11:14:43 INFO - TEST-UNEXPECTED-TIMEOUT | /service-workers/service-worker/multiple-update.https.html | Trigger multiple updates. - Test timed out
[task 2019-03-17T11:14:43.802Z] 11:14:43 INFO - TEST-UNEXPECTED-TIMEOUT | /service-workers/service-worker/multiple-update.https.html | expected OK
[task 2019-03-17T11:14:43.802Z] 11:14:43 INFO - TEST-INFO took 31055ms
[task 2019-03-17T11:14:43.839Z] 11:14:43 INFO - PID 10472 | 1552821283829 Marionette INFO Stopped listening on port 2828
[task 2019-03-17T11:14:44.122Z] 11:14:44 INFO - PID 10472 | Assertion failure: (mProxy->mDelayedUpdate == this), at /builds/worker/workspace/build/src/dom/serviceworkers/ServiceWorkerRegistrationProxy.cpp:285
[task 2019-03-17T11:15:33.755Z] 11:15:33 INFO - PID 10472 | #01: nsTimerImpl::Fire(int) [xpcom/threads/nsTimerImpl.cpp:0]
[task 2019-03-17T11:15:33.755Z] 11:15:33 INFO -
[task 2019-03-17T11:15:33.755Z] 11:15:33 INFO - PID 10472 | #02: nsTimerEvent::Run() [xpcom/threads/TimerThread.cpp:260]
[task 2019-03-17T11:15:33.755Z] 11:15:33 INFO -
[task 2019-03-17T11:15:33.756Z] 11:15:33 INFO - PID 10472 | #03: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1166]
[task 2019-03-17T11:15:33.756Z] 11:15:33 INFO -
[task 2019-03-17T11:15:33.756Z] 11:15:33 INFO - PID 10472 | #04: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:482]
[task 2019-03-17T11:15:33.756Z] 11:15:33 INFO -
[task 2019-03-17T11:15:33.757Z] 11:15:33 INFO - PID 10472 | #05: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:88]
[task 2019-03-17T11:15:33.757Z] 11:15:33 INFO -
[task 2019-03-17T11:15:33.757Z] 11:15:33 INFO - PID 10472 | #06: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:315]
[task 2019-03-17T11:15:33.757Z] 11:15:33 INFO -
[task 2019-03-17T11:15:33.758Z] 11:15:33 INFO - PID 10472 | #07: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:584]
[task 2019-03-17T11:15:33.758Z] 11:15:33 INFO -
[task 2019-03-17T11:15:33.758Z] 11:15:33 INFO - PID 10472 | #08: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:139]
[task 2019-03-17T11:15:33.758Z] 11:15:33 INFO -
[task 2019-03-17T11:15:33.759Z] 11:15:33 INFO - PID 10472 | #09: nsAppStartup::Run() [toolkit/components/startup/nsAppStartup.cpp:272]
[task 2019-03-17T11:15:33.759Z] 11:15:33 INFO -
[task 2019-03-17T11:15:33.759Z] 11:15:33 INFO - PID 10472 | #10: XREMain::XRE_mainRun() [toolkit/xre/nsAppRunner.cpp:4589]

I'm pretty sure this timeout is because the update code is adding additional delays with each subsequent update (see: https://searchfox.org/mozilla-central/source/dom/serviceworkers/ServiceWorkerRegistrationInfo.cpp#699).

Fixing/fixed this as part of making the tests for bug 1231213 pass.

There are 42 total failures in the last 7 days on linux64 debug

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=239571514&repo=mozilla-central&lineNumber=47378

[task 2019-04-11T05:49:58.488Z] 05:49:58 INFO - TEST-START | /service-workers/service-worker/multiple-update.https.html
[task 2019-04-11T05:49:58.488Z] 05:49:58 INFO - Closing window 212600881153
[task 2019-04-11T05:49:58.585Z] 05:49:58 INFO - PID 9022 | ++DOCSHELL 0x7fa8ffb8d000 == 1 [pid = 12620] [id = {0db4acdd-a824-4187-ad45-3c7a1de7ccf9}]
[task 2019-04-11T05:49:58.586Z] 05:49:58 INFO - PID 9022 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-04-11T05:49:58.594Z] 05:49:58 INFO - PID 9022 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-04-11T05:49:58.596Z] 05:49:58 INFO - PID 9022 | [Child 12589, Main Thread] WARNING: NS_ENSURE_TRUE(!mHasOrHasHadOwnerWindow || mOwnerWindow) failed: file /builds/worker/workspace/build/src/dom/events/DOMEventTargetHelper.cpp, line 318
[task 2019-04-11T05:49:58.599Z] 05:49:58 INFO - PID 9022 | [Child 12589, Main Thread] WARNING: Finishing incremental GC in progress during CC: file /builds/worker/workspace/build/src/xpcom/base/nsCycleCollector.cpp, line 3300
[task 2019-04-11T05:49:58.656Z] 05:49:58 INFO - PID 9022 | ++DOMWINDOW == 1 (0x7fa8ffbc2d40) [pid = 12620] [serial = 1] [outer = (nil)]

[task 2019-04-11T05:50:18.120Z] 05:50:18 INFO - PID 9022 | --DOMWINDOW == 2 (0x7fa9175ccc00) [pid = 12620] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2019-04-11T05:50:29.350Z] 05:50:29 INFO -
[task 2019-04-11T05:50:29.350Z] 05:50:29 INFO - TEST-UNEXPECTED-TIMEOUT | /service-workers/service-worker/multiple-update.https.html | Trigger multiple updates. - Test timed out
[task 2019-04-11T05:50:29.351Z] 05:50:29 INFO - TEST-UNEXPECTED-TIMEOUT | /service-workers/service-worker/multiple-update.https.html | expected OK
[task 2019-04-11T05:50:29.351Z] 05:50:29 INFO - TEST-INFO took 30867ms
[task 2019-04-11T05:50:29.387Z] 05:50:29 INFO - PID 9022 | 1554961829374 Marionette INFO Stopped listening on port 2828
[task 2019-04-11T05:50:29.590Z] 05:50:29 INFO - PID 9022 | Assertion failure: (mProxy->mDelayedUpdate == this), at /builds/worker/workspace/build/src/dom/serviceworkers/ServiceWorkerRegistrationProxy.cpp:280
[task 2019-04-11T05:50:50.999Z] 05:50:50 INFO - PID 9022 | #01: nsTimerImpl::Fire(int) [xpcom/threads/nsTimerImpl.cpp:0]
[task 2019-04-11T05:50:50.999Z] 05:50:50 INFO -
[task 2019-04-11T05:50:51.001Z] 05:50:51 INFO - PID 9022 | #02: nsTimerEvent::Run() [xpcom/threads/TimerThread.cpp:260]
[task 2019-04-11T05:50:51.001Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.002Z] 05:50:51 INFO - PID 9022 | #03: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1167]
[task 2019-04-11T05:50:51.002Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.002Z] 05:50:51 INFO - PID 9022 | #04: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:486]
[task 2019-04-11T05:50:51.002Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.002Z] 05:50:51 INFO - PID 9022 | #05: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:88]
[task 2019-04-11T05:50:51.002Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.002Z] 05:50:51 INFO - PID 9022 | #06: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:315]
[task 2019-04-11T05:50:51.002Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.003Z] 05:50:51 INFO - PID 9022 | #07: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:291]
[task 2019-04-11T05:50:51.003Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.003Z] 05:50:51 INFO - PID 9022 | #08: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:139]
[task 2019-04-11T05:50:51.003Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.003Z] 05:50:51 INFO - PID 9022 | #09: nsAppStartup::Run() [toolkit/components/startup/nsAppStartup.cpp:271]
[task 2019-04-11T05:50:51.003Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.004Z] 05:50:51 INFO - PID 9022 | #10: XREMain::XRE_mainRun() [toolkit/xre/nsAppRunner.cpp:4572]
[task 2019-04-11T05:50:51.004Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.004Z] 05:50:51 INFO - PID 9022 | #11: XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/nsAppRunner.cpp:4710]
[task 2019-04-11T05:50:51.004Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.004Z] 05:50:51 INFO - PID 9022 | #12: XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/nsAppRunner.cpp:4791]
[task 2019-04-11T05:50:51.004Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.005Z] 05:50:51 INFO - PID 9022 | #13: _fini
[task 2019-04-11T05:50:51.005Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.005Z] 05:50:51 INFO - PID 9022 | #14: libc.so.6 + 0x20830
[task 2019-04-11T05:50:51.005Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.005Z] 05:50:51 INFO - PID 9022 | #15: _fini
[task 2019-04-11T05:50:51.005Z] 05:50:51 INFO -
[task 2019-04-11T05:50:51.006Z] 05:50:51 INFO - PID 9022 | ExceptionHandler::GenerateDump cloned child 12684
[task 2019-04-11T05:50:51.006Z] 05:50:51 INFO - PID 9022 | ExceptionHandler::SendContinueSignalToChild sent continue signal to child

Waiting on bug 1231213 to be fixed.

Started to perma fail with this merge:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=e0861be8d6c0fff8066fc5fe39e720dc55524122&searchStr=linux%2Cx64%2Cdebug%2Cweb%2Cplatform%2Ctests%2Cwith%2Cserviceworker%2Credesign%2Cand%2Ce10s%2Ctest-linux64%2Fdebug-web-platform-tests-sw-e10s-14%2Cw-sw-e10s%28wpt14%29&selectedJob=234398565

https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=e0861be8d6c0fff8066fc5fe39e720dc55524122

This occurs on central as beta simulations as well: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed%2Cbusted%2Cexception&revision=95c973c0a332b2f647495ee55e0b20161042100b&selectedJob=242045326

Waiting on bug 1231213 to be fixed.

Failure is hidden now due to update of the test expectation to TIMEOUT: https://hg.mozilla.org/mozilla-central/rev/a9e8bb1d8a16#l86.1

In the last 7 days this has 96 failures

autoland: 54
mozilla-inbound: 12
mozilla-central: 12
try: 18

Should be resolved by bug 1231213.