Closed Bug 1452374 Opened 6 years ago Closed 6 years ago

Intermittent 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"

Categories

(Core :: DOM: Service Workers, defect, P1)

Product:
Core
Component:
DOM: Service Workers
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla61
Tracking Flags:
Tracking Status
firefox61 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: bkelly)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed:product])

Attachments

(1 file, 2 obsolete files)

Remove ServiceWorkerRegistrar retry mechanism to fix intermittent shutdown failures. r=baku
2.12 KB, patch
bkelly
: review+
Details | Diff | Splinter Review 
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!
Flags: needinfo?(bkelly)
Yea, this is almost assuredly caused by the retry mechanism I added in bug 1450991.  I'll make a patch to disable the retry.
Assignee: nobody → bkelly
Blocks: ServiceWorkers-stability
Status: NEW → ASSIGNED
Depends on: 1450991
Flags: needinfo?(bkelly)
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
Attachment #8965969 - Flags: review?(bugmail)
Component: Gecko Profiler → DOM: Service Workers
Comment on attachment 8965969 [details] [diff] [review]
Remove ServiceWorkerRegistrar retry mechanism to fix intermittent shutdown failures. r=asuth

Try is green.  Just needs review.
Attachment #8965969 - Attachment description: bug1452374_disableretry.patch → Remove ServiceWorkerRegistrar retry mechanism to fix intermittent shutdown failures. r=asuth
Attachment #8965959 - Attachment is obsolete: true
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.
Attachment #8965969 - Flags: review?(bugmail) → review+
Tree is closed at the moment and I need to step away from my computer.  Should be good to checkin, though.
Keywords: checkin-needed
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
Keywords: checkin-needed
Priority: -- → P1
https://hg.mozilla.org/mozilla-central/rev/a4bedd65b618
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
status-firefox61: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
Whiteboard: [stockwell needswork:owner] → [stockwell fixed:product]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: