I encountered an AsyncShutdown crash in the Screenshots add-on when I ran a test in a debug build (the test is unrelated to Screenshots). The full logs are below, the part of interest is: Conditions: [{ "name": "Extension shutdown: screenshots@mozilla.org", "state": { "state": "Startup: Run manifest: asyncEmitManifestEntry(\"background\")" }, "filename": "resource://gre/modules/addons/XPIProvider.jsm", "lineNumber": 2211, "stack": ["resource://gre/modules/addons/XPIProvider.jsm:startup/<:2211"] }] $ mach test browser/components/extensions/test/browser/browser_ext_sessions_getRecentlyClosed.js --verify 2:49.13 INFO TEST-START | Shutdown 2:49.13 INFO Browser Chrome Test Summary 2:49.13 INFO Passed: 1260 2:49.13 INFO Failed: 0 2:49.13 INFO Todo: 0 2:49.13 INFO Mode: e10s 2:49.13 INFO *** End BrowserChrome Test Results *** 2:57.71 GECKO(31382) --DOMWINDOW == 7 (0x7f654d94cc00) [pid = 31494] [serial = 5] [outer = (nil)] [url = moz-extension://fe914f12-0309-4724-9829-e2028832f59c/_generated_background_page.html] 2:57.71 GECKO(31382) --DOMWINDOW == 6 (0x7f654d94c200) [pid = 31494] [serial = 3] [outer = (nil)] [url = moz-extension://f7dff20e-943e-4fcb-8808-0d9fc3e41f7c/_generated_background_page.html] 2:57.71 GECKO(31382) --DOMWINDOW == 5 (0x7f654e23b000) [pid = 31494] [serial = 1] [outer = (nil)] [url = moz-extension://c3aacaa0-1b7d-483a-8404-9580c5201bcf/_generated_background_page.html] 2:57.71 GECKO(31382) --DOCSHELL 0x7f654d92a000 == 3 [pid = 31494] [id = {ceec7310-35ad-41a0-88e0-429ea6f51780}] 2:57.71 GECKO(31382) --DOCSHELL 0x7f654e2e9000 == 2 [pid = 31494] [id = {af41c299-8056-4577-9f17-ab9d84e36725}] 2:57.71 GECKO(31382) --DOCSHELL 0x7f654d92e800 == 1 [pid = 31494] [id = {79a1dc78-fad6-41fb-b1ba-1c7d4e1e0969}] 2:57.75 GECKO(31382) --DOCSHELL 0x7f8cb276c800 == 0 [pid = 31571] [id = {1d52d29e-0a73-4b12-a8a8-440dab3007e9}] 2:59.40 GECKO(31382) WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"Extension shutdown: screenshots@mozilla.org","state":{"state":"Startup: Run manifest: asyncEmitManifestEntry(\"background\")"},"filename":"resource://gre/modules/addons/XPIProvider.jsm","lineNumber":2211,"stack":["resource://gre/modules/addons/XPIProvider.jsm:startup/<:2211"]}] Barrier: profile-change-teardown 3:01.74 GECKO(31382) --DOMWINDOW == 4 (0x7f654d988400) [pid = 31494] [serial = 7] [outer = (nil)] [url = moz-extension://c3aacaa0-1b7d-483a-8404-9580c5201bcf/_generated_background_page.html] 3:01.74 GECKO(31382) --DOMWINDOW == 3 (0x7f654d989800) [pid = 31494] [serial = 8] [outer = (nil)] [url = moz-extension://f7dff20e-943e-4fcb-8808-0d9fc3e41f7c/_generated_background_page.html] 3:01.74 GECKO(31382) --DOMWINDOW == 2 (0x7f654d98a800) [pid = 31494] [serial = 9] [outer = (nil)] [url = moz-extension://fe914f12-0309-4724-9829-e2028832f59c/_generated_background_page.html] 3:04.07 GECKO(31382) --DOMWINDOW == 1 (0x7f8cb26b2200) [pid = 31571] [serial = 310] [outer = (nil)] [url = about:blank] 3:08.14 GECKO(31382) --DOMWINDOW == 0 (0x7f8cb1971c00) [pid = 31571] [serial = 311] [outer = (nil)] [url = about:blank] 3:50.40 GECKO(31382) FATAL ERROR: AsyncShutdown timeout in profile-change-teardown Conditions: [{"name":"Extension shutdown: screenshots@mozilla.org","state":{"state":"Startup: Run manifest: asyncEmitManifestEntry(\"background\")"},"filename":"resource://gre/modules/addons/XPIProvider.jsm","lineNumber":2211,"stack":["resource://gre/modules/addons/XPIProvider.jsm:startup/<:2211"]}] 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. 3:50.40 GECKO(31382) [Parent 31382, Main Thread] ###!!! ABORT: file resource://gre/modules/addons/XPIProvider.jsm, line 2211 ... 3:51.20 INFO ::: Test verification summary for: 3:51.20 INFO ::: 3:51.20 INFO ::: browser/components/extensions/test/browser/browser_ext_sessions_getRecentlyClosed.js 3:51.20 INFO ::: browser/components/extensions/test/browser/test-oop-extensions/browser_ext_sessions_getRecentlyClosed.js 3:51.20 INFO ::: 3:51.20 INFO ::: 1. Run each test 10 times in one browser. : FAIL 3:51.20 INFO ::: 2. Run each test 5 times in a new browser each time. : not run / incomplete When I repeated the test, I got the same crash: 3:21.80 INFO TEST-START | Shutdown 3:21.80 INFO Browser Chrome Test Summary 3:21.80 INFO Passed: 120 3:21.80 INFO Failed: 0 3:21.80 INFO Todo: 0 3:21.80 INFO Mode: e10s 3:21.80 INFO *** End BrowserChrome Test Results *** 3:26.34 GECKO(1401) --DOCSHELL 0x7fe077633000 == 0 [pid = 1562] [id = {eef3779a-6866-4a14-908c-26dc810471e6}] 3:28.62 GECKO(1401) JavaScript error: chrome://browser/content/browser-ctrlTab.js, line 556: TypeError: this.tabList[i].linkedBrowser.currentURI is undefined; can't access its "spec" property 3:32.02 GECKO(1401) WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"Extension shutdown: screenshots@mozilla.org","state":{"state":"Startup: Run manifest: asyncEmitManifestEntry(\"background\")"},"filename":"resource://gre/modules/addons/XPIProvider.jsm","lineNumber":2211,"stack":["resource://gre/modules/addons/XPIProvider.jsm:startup/<:2211"]}] Barrier: profile-change-teardown 3:33.22 GECKO(1401) --DOMWINDOW == 7 (0x7f712a54d200) [pid = 1512] [serial = 5] [outer = (nil)] [url = moz-extension://369c5054-3c40-4f68-bdfc-77a2385ebff4/_generated_background_page.html] 3:33.22 GECKO(1401) --DOMWINDOW == 6 (0x7f712a54c200) [pid = 1512] [serial = 3] [outer = (nil)] [url = moz-extension://63bec00e-acae-4dbe-9d14-b1d365325aa8/_generated_background_page.html] 3:33.22 GECKO(1401) --DOMWINDOW == 5 (0x7f712ad3b000) [pid = 1512] [serial = 1] [outer = (nil)] [url = moz-extension://3b5c3650-18a6-47f0-b379-31f787e0a2c8/_generated_background_page.html] 3:33.22 GECKO(1401) --DOCSHELL 0x7f712ade9000 == 3 [pid = 1512] [id = {264de6e3-b284-4ecc-beb5-bb5a2dfda987}] 3:33.22 GECKO(1401) --DOCSHELL 0x7f712a529000 == 2 [pid = 1512] [id = {39d40aa0-71d4-414c-a5f2-025d3a4a7760}] 3:33.22 GECKO(1401) --DOCSHELL 0x7f712a52d800 == 1 [pid = 1512] [id = {f76220b6-a1c4-4f8c-94cc-59ba287f97fb}] 3:37.28 GECKO(1401) --DOMWINDOW == 4 (0x7f712a5a4400) [pid = 1512] [serial = 7] [outer = (nil)] [url = moz-extension://3b5c3650-18a6-47f0-b379-31f787e0a2c8/_generated_background_page.html] 3:37.28 GECKO(1401) --DOMWINDOW == 3 (0x7f712a5a5800) [pid = 1512] [serial = 8] [outer = (nil)] [url = moz-extension://63bec00e-acae-4dbe-9d14-b1d365325aa8/_generated_background_page.html] 3:37.29 GECKO(1401) --DOMWINDOW == 2 (0x7f712a5a6800) [pid = 1512] [serial = 9] [outer = (nil)] [url = moz-extension://369c5054-3c40-4f68-bdfc-77a2385ebff4/_generated_background_page.html] 3:37.66 GECKO(1401) --DOMWINDOW == 1 (0x7fe076fb8800) [pid = 1562] [serial = 30] [outer = (nil)] [url = about:blank] 3:41.68 GECKO(1401) --DOMWINDOW == 0 (0x7fe07642fc00) [pid = 1562] [serial = 32] [outer = (nil)] [url = about:blank] 4:23.02 GECKO(1401) FATAL ERROR: AsyncShutdown timeout in profile-change-teardown Conditions: [{"name":"Extension shutdown: screenshots@mozilla.org","state":{"state":"Startup: Run manifest: asyncEmitManifestEntry(\"background\")"},"filename":"resource://gre/modules/addons/XPIProvider.jsm","lineNumber":2211,"stack":["resource://gre/modules/addons/XPIProvider.jsm:startup/<:2211"]}] 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. ... 4:23.75 INFO ::: 1. Run each test 10 times in one browser. : Pass 4:23.75 INFO ::: 2. Run each test 5 times in a new browser each time. : FAIL After encountering the same failure thrice (100% crash rate), I clobbered the build and retried, just to observe the same crash. I created an artifact debug build based on https://hg.mozilla.org/mozilla-central/rev/af3fd0a2c2e6

This crash when because the extensions.webextensions.remote pref is flipped during the test (from the default true to false in non-remote tests), and the built-in screenshots add-on is initializing around this time. Then: - [main process] extension starts up, remote=true - [main process] starts initializing background page [1] and waits for message from child [2] - (webextension.extensions.remote pref is flipped to false, by head.js) - [extension process] receives initialization message (from [1]), and because the pref is false, WebExtensionPolicy.isExtensionProcess is false and no reply is sent. - [main process] waits forever for the reply that is never received, so startup never finishes. Extension shutdown depends on completion of extension start-up, so we get an AsyncShutdown crash. [1]: https://searchfox.org/mozilla-central/rev/d5fc6f3d4746279a7c6fd4f7a98b1bc5d05d6b01/toolkit/components/extensions/parent/ext-backgroundPage.js#39-41 [2]: https://searchfox.org/mozilla-central/rev/d5fc6f3d4746279a7c6fd4f7a98b1bc5d05d6b01/toolkit/components/extensions/parent/ext-backgroundPage.js#43

The extensions.webextensions.remote pref is used to determine whether extensions should run in a separate process. If false, extensions are hosted in the main process. If true (default), extensions are hosted in a special extension process. Flipping these preferences while an extension has been loaded is not really supported, but this still occurs in tests. Before this patch, ExtensionPolicyService::IsExtensionProcess would be false if the preference is flipped to false, and cause bug 1501375. Since extensions are only loaded in an extension process if the pref was true at extension start-up, we should ignore the pref if the extension is running in the extension process. This reduces the number of issues when the pref transitions from true (default) to false. There is still an issue when the value transitions from false to true, because ExtensionPolicyService::IsExtensionProcess in the parent process continues to depend on the latest value of the pref. Since false is not a default value, and flipping the pref is not really supported, this issue remains unaddressed.

Extension start-up is blocked on receiving an initialization message from the extension child process. If the extension browser goes away before a response is received (e.g. if the extension is crashed), stop waiting to avoid blocking the startup (and shutdown) forever. This is not the cause of bug 1501375, but still worth fixing ( for bug 1355239 ). Depends on D9958

Why don't we fix the tests to not flip the pref while the browser is running instead?

(In reply to Andrew Swan [:aswan] from comment #4) > Why don't we fix the tests to not flip the pref while the browser is running > instead? That is the ideal fix - see bug 1502525.

The patch in comment 2 is a partial fix for bug 1502525, in the sense that the extension process is indifferent to changes of the pref. The full fix is to also remove the dynamic preference look-up in the main process. The patch in comment 3 is not really related to this bug; I just identified it as a potential cause for startup hangs before adding a boatload of logging to find the actual cause of this bug.

Since the attached patches are not entire fixes for this bug, I'll wait to review until that is done. Do we ever expect to have to work non-remote again? If not, maybe we should just clean all that up (ie. remove it the ability).

Pushed by rob@robwu.nl: https://hg.mozilla.org/integration/autoland/rev/b374a5789689 Interrupt extension start-up if background page crashes r=mixedpuppy

Backed out for failing xpcshell at toolkit/components/extensions/test/xpcshell/test_ext_webRequest_startup.js Push that caused the failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception&classifiedState=unclassified&selectedJob=208718988&searchStr=xpcshell&revision=b374a5789689d1e589259183feefb099babb260e Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=208718988&repo=autoland&lineNumber=2557 Backout: https://hg.mozilla.org/integration/autoland/rev/476afc32c5d10abdd9e1b0a38239f9623f630fcc

I will move https://phabricator.services.mozilla.com/D9958 to bug 1502525. The back-out in comment 9 shows a very interesting issue: The shutdown logic does not account for delayed start-up. Previously we would likely have some sort of leak due to the wait for a promise that never resolves. With my patch, an error is thrown instead. I'll fix the startup/shutdown logic of ext-backgroundPage so that it will gracefully handle shutdowns. As noted in https://bugzilla.mozilla.org/show_bug.cgi?id=1464938#c44 , this crash signature is the #2 top reason for the AsyncShutdown crash.

Ensure that the windowless browser is only closed when its dummy XUL page has completely loaded, and that HiddenExtensionPage's browser is really cleared if the extension was shut down during initialization. Depends on D9959

Pushed by rob@robwu.nl: https://hg.mozilla.org/integration/autoland/rev/2def2f8d49e7 Interrupt extension start-up if background page crashes r=mixedpuppy https://hg.mozilla.org/integration/autoland/rev/2090ee542b58 Account for shutdown of bg page during extension start-up r=rpl,aswan https://hg.mozilla.org/integration/autoland/rev/3a5c6e81192d Clear primed listeners on extension shutdown r=aswan https://hg.mozilla.org/integration/autoland/rev/04b242fc5a70 Test extension shutdown during extension startup r=aswan