Filed by: csabou [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=172444730&repo=mozilla-inbound https://queue.taskcluster.net/v1/task/Zapfd5BoRzmJyDtS52ZJ8Q/runs/0/artifacts/public/logs/live_backing.log 09:37:37 INFO - 145 INFO TEST-START | browser/components/contextualidentity/test/browser/browser_windowOpen.js 09:37:37 INFO - GECKO(4608) | MEMORY STAT | vsize 796MB | vsizeMaxContiguous 460MB | residentFast 267MB | heapAllocated 113MB 09:37:37 INFO - 146 INFO TEST-OK | browser/components/contextualidentity/test/browser/browser_windowOpen.js | took 309ms 09:37:37 INFO - 147 INFO checking window state 09:37:39 INFO - GECKO(4608) | Completed ShutdownLeaks collections in process 604 09:37:39 INFO - GECKO(4608) | Completed ShutdownLeaks collections in process 5432 09:37:39 INFO - GECKO(4608) | Completed ShutdownLeaks collections in process 6096 09:37:39 INFO - GECKO(4608) | Completed ShutdownLeaks collections in process 2216 09:37:39 INFO - GECKO(4608) | Completed ShutdownLeaks collections in process 4608 09:37:39 INFO - 148 INFO TEST-START | Shutdown 09:37:39 INFO - 149 INFO Browser Chrome Test Summary 09:37:39 INFO - 150 INFO Passed: 189 09:37:39 INFO - 151 INFO Failed: 0 09:37:39 INFO - 152 INFO Todo: 0 09:37:39 INFO - 153 INFO Mode: e10s 09:37:39 INFO - 154 INFO *** End BrowserChrome Test Results *** 09:37:39 INFO - GECKO(4608) | !!! error running onStopped callback: TypeError: callback is not a function 09:37:39 INFO - GECKO(4608) | [Child 604, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 09:37:39 INFO - GECKO(4608) | [Parent 4608, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 09:37:39 INFO - GECKO(4608) | [Child 2216, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 09:37:39 INFO - GECKO(4608) | [Child 2216, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 09:37:39 INFO - GECKO(4608) | [Parent 4608, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 09:37:39 INFO - GECKO(4608) | [Child 6096, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 09:37:39 INFO - GECKO(4608) | [Child 6096, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 09:37:39 INFO - GECKO(4608) | [Parent 4608, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 09:37:39 INFO - GECKO(4608) | [Child 5432, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346 09:37:39 INFO - GECKO(4608) | [Parent 4608, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 188 09:37:41 INFO - GECKO(4608) | JavaScript error: jar:file:///Z:/task_1523092528/build/application/firefox/browser/omni.ja!/components/nsBrowserGlue.js, line 1019: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIAppShellService.hiddenDOMWindow] 09:37:49 INFO - GECKO(4608) | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"ServiceWorkerRegistrar: Flushing data","state":"(none)","filename":"z:/build/build/src/dom/serviceworkers/ServiceWorkerRegistrar.cpp","lineNumber":1060,"stack":"ServiceWorkerRegistrar: Flushing data"}] Barrier: profile-before-change 09:38:21 INFO - GECKO(4608) | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping 09:38:40 INFO - GECKO(4608) | FATAL ERROR: AsyncShutdown timeout in profile-before-change Conditions: [{"name":"ServiceWorkerRegistrar: Flushing data","state":"(none)","filename":"z:/build/build/src/dom/serviceworkers/ServiceWorkerRegistrar.cpp","lineNumber":1060,"stack":"ServiceWorkerRegistrar: Flushing data"}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources. 09:38:40 INFO - GECKO(4608) | [Parent 4608, Main Thread] ###!!! ABORT: file z:/build/build/src/dom/serviceworkers/ServiceWorkerRegistrar.cpp, line 1060 09:38:40 INFO - TEST-INFO | Main app process: exit 1 09:38:40 INFO - Buffered messages finished 09:38:40 ERROR - 155 ERROR TEST-UNEXPECTED-FAIL | browser/components/contextualidentity/test/browser/browser_windowOpen.js | application terminated with exit code 1 09:38:40 INFO - runtests.py | Application ran for: 0:01:20.013000 09:38:40 INFO - zombiecheck | Reading PID log: c:\users\task_1523092528\appdata\local\temp\tmprhjjmopidlog 09:38:40 INFO - ==> process 4608 launched child process 5432 ("Z:\task_1523092528\build\application\firefox\firefox.exe" -contentproc --channel="4608.0.1756209328\619583693" -childID 1 -isForBrowser -prefsHandle 1756 -prefsLen 16537 -schedulerPrefs 0001,2 -greomni "Z:\task_1523092528\build\application\firefox\omni.ja" -appomni "Z:\task_1523092528\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1523092528\build\application\firefox\browser" - 4608 "\\.\pipe\gecko-crash-server-pipe.4608" 1884 tab) 09:38:40 INFO - ==> process 4608 launched child process 6096 ("Z:\task_1523092528\build\application\firefox\firefox.exe" -contentproc --channel="4608.6.415962007\888604635" -childID 2 -isForBrowser -prefsHandle 2160 -prefsLen 16537 -schedulerPrefs 0001,2 -greomni "Z:\task_1523092528\build\application\firefox\omni.ja" -appomni "Z:\task_1523092528\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1523092528\build\application\firefox\browser" - 4608 "\\.\pipe\gecko-crash-server-pipe.4608" 2172 tab) 09:38:40 INFO - ==> process 4608 launched child process 2216 ("Z:\task_1523092528\build\application\firefox\firefox.exe" -contentproc --channel="4608.12.925871683\1923673353" -childID 3 -isForBrowser -prefsHandle 2912 -prefsLen 22087 -schedulerPrefs 0001,2 -greomni "Z:\task_1523092528\build\application\firefox\omni.ja" -appomni "Z:\task_1523092528\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1523092528\build\application\firefox\browser" - 4608 "\\.\pipe\gecko-crash-server-pipe.4608" 2924 tab) 09:38:40 INFO - ==> process 4608 launched child process 604 ("Z:\task_1523092528\build\application\firefox\firefox.exe" -contentproc --channel="4608.18.779896114\1784853302" -childID 4 -isForBrowser -prefsHandle 3496 -prefsLen 22262 -schedulerPrefs 0001,2 -greomni "Z:\task_1523092528\build\application\firefox\omni.ja" -appomni "Z:\task_1523092528\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1523092528\build\application\firefox\browser" - 4608 "\\.\pipe\gecko-crash-server-pipe.4608" 3216 tab) 09:38:40 INFO - ==> process 4608 launched child process 4192 ("Z:\task_1523092528\build\application\firefox\plugin-container.exe" --channel="4608.25.1886168855\1978918133" "Z:\task_1523092528\build\application\firefox\gmp-clearkey\0.1" -greomni "Z:\task_1523092528\build\application\firefox\omni.ja" -appomni "Z:\task_1523092528\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1523092528\build\application\firefox\browser" - 4608 "\\.\pipe\gecko-crash-server-pipe.4608" 3812 geckomediaplugin) 09:38:40 INFO - ==> process 4608 launched child process 2812 ("Z:\task_1523092528\build\application\firefox\plugin-container.exe" --channel="4608.28.1834382805\765530756" "Z:\task_1523092528\build\application\firefox\gmp-clearkey\0.1" -greomni "Z:\task_1523092528\build\application\firefox\omni.ja" -appomni "Z:\task_1523092528\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1523092528\build\application\firefox\browser" - 4608 "\\.\pipe\gecko-crash-server-pipe.4608" 3932 geckomediaplugin) 09:38:40 INFO - ==> process 4608 launched child process 5948 ("Z:\task_1523092528\build\application\firefox\plugin-container.exe" --channel="4608.30.1058267041\566741137" "Z:\task_1523092528\build\application\firefox\gmp-clearkey\0.1" -greomni "Z:\task_1523092528\build\application\firefox\omni.ja" -appomni "Z:\task_1523092528\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1523092528\build\application\firefox\browser" - 4608 "\\.\pipe\gecko-crash-server-pipe.4608" 3868 geckomediaplugin) 09:38:40 INFO - ==> process 4608 launched child process 5964 ("Z:\task_1523092528\build\application\firefox\plugin-container.exe" --channel="4608.32.846651660\2010307993" "Z:\task_1523092528\build\application\firefox\gmp-clearkey\0.1" -greomni "Z:\task_1523092528\build\application\firefox\omni.ja" -appomni "Z:\task_1523092528\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1523092528\build\application\firefox\browser" - 4608 "\\.\pipe\gecko-crash-server-pipe.4608" 4184 geckomediaplugin) 09:38:40 INFO - ==> process 4608 launched child process 5984 ("Z:\task_1523092528\build\application\firefox\plugin-container.exe" --channel="4608.34.1198941276\1469404098" "C:\Users\task_1523092528\AppData\Local\Temp\tmpdrrhod.mozrunner\plugins\npswftest.dll" -greomni "Z:\task_1523092528\build\application\firefox\omni.ja" -appomni "Z:\task_1523092528\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1523092528\build\application\firefox\browser" - 4608 "\\.\pipe\gecko-crash-server-pipe.4608" 4264 plugin) 09:38:40 INFO - zombiecheck | Checking for orphan process with PID: 4192 09:38:40 INFO - zombiecheck | Checking for orphan process with PID: 5984 09:38:40 INFO - zombiecheck | Checking for orphan process with PID: 5948 09:38:40 INFO - zombiecheck | Checking for orphan process with PID: 2216 09:38:40 INFO - zombiecheck | Checking for orphan process with PID: 2812 09:38:40 INFO - zombiecheck | Checking for orphan process with PID: 5964 09:38:40 INFO - zombiecheck | Checking for orphan process with PID: 6096 09:38:40 INFO - zombiecheck | Checking for orphan process with PID: 5432 09:38:40 INFO - zombiecheck | Checking for orphan process with PID: 604 09:38:40 INFO - mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/GgVq8uBVR8aSrKQDtonLcA/artifacts/public/build/target.crashreporter-symbols.zip 09:38:44 INFO - mozcrash Copy/paste: Z:\task_1523092528\build\win32-minidump_stackwalk.exe c:\users\task_1523092528\appdata\local\temp\tmpdrrhod.mozrunner\minidumps\433f352b-28c0-4359-9697-3edd74f9e7fb.dmp c:\users\task_1523092528\appdata\local\temp\tmppbmtil 09:38:58 INFO - mozcrash Saved minidump as Z:\task_1523092528\build\blobber_upload_dir\433f352b-28c0-4359-9697-3edd74f9e7fb.dmp 09:38:58 INFO - mozcrash Saved app info as Z:\task_1523092528\build\blobber_upload_dir\433f352b-28c0-4359-9697-3edd74f9e7fb.extra 09:38:58 WARNING - PROCESS-CRASH | browser/components/contextualidentity/test/browser/browser_windowOpen.js | application crashed [@ mozalloc_abort(char const * const)]

Ben, could you please take a look at this failure? FATAL ERROR: AsyncShutdown timeout in profile-before-change Conditions: [{"name":"ServiceWorkerRegistrar: Flushing data","state":"(none)","filename":"z:/build/build/src/dom/serviceworkers/ServiceWorkerRegistrar.cpp","lineNumber":1060,"stack":"ServiceWorkerRegistrar: Flushing data"}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process drainin GECKO(4556) | [Parent 4556, Main Thread] ###!!! ABORT: file z:/build/build/src/dom/serviceworkers/ServiceWorkerRegistrar.cpp, line 1060 This started from your push here: https://goo.gl/CQMtKM, now has been merged around because it started failing around 8 pushes later and has a failure rate between 2-3 fails from 10 jobs. It seems to be related to Bug 1450991 where you worked on ServiceWorkerRegistrar. Thanks!

Yea, this is almost assuredly caused by the retry mechanism I added in bug 1450991. I'll make a patch to disable the retry.

I'm just going to disable the retry with a very simple fix here and re-work it in bug 1452373. https://treeherder.mozilla.org/#/jobs?repo=try&revision=97dc66b90dc243b8772eb3a3a3b8275b11099e04

Andrew, this patch removes the ServiceWorkerRegistrar retry mechanism I added. I believe its causing intermittent shutdown crashes. I'll revisit retrying in bug 1452373. The use of the STS thread pool makes retrying more complicated than what this code was doing. https://treeherder.mozilla.org/#/jobs?repo=try&revision=5fcbba42053d195b16b268b48050d23a8b9636a1

Comment on attachment 8965969 [details] [diff] [review] Remove ServiceWorkerRegistrar retry mechanism to fix intermittent shutdown failures. r=asuth Try is green. Just needs review.

Comment on attachment 8965969 [details] [diff] [review] Remove ServiceWorkerRegistrar retry mechanism to fix intermittent shutdown failures. r=asuth Review of attachment 8965969 [details] [diff] [review]: ----------------------------------------------------------------- This patch reverts bug 1450991. lgtm.

Comment on attachment 8965969 [details] [diff] [review] Remove ServiceWorkerRegistrar retry mechanism to fix intermittent shutdown failures. r=asuth Andrea meant to r+ this in his previous comment.

Fix commit message.

Tree is closed at the moment and I need to step away from my computer. Should be good to checkin, though.

Pushed by ryanvm@gmail.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/a4bedd65b618 Remove ServiceWorkerRegistrar retry mechanism to fix intermittent shutdown failures. r=baku