1501375 - AsyncShutdown timeout in asyncEmitManifestEntry("background")

Status: RESOLVED FIXED

(WebExtensions :: General, defect, P2)

Description

[Rob Wu [:robwu]]

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: [e-mail]",
    "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: [e-mail]","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: [e-mail]","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: [e-mail]","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: [e-mail]","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

Comment 1

[Rob Wu [:robwu]]

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

Comment 2

[Rob Wu [:robwu]]

Attachment: Bug 1501375 - Ignore pref in content processes in EPS::IsExtensionProcess

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.

Comment 3

[Rob Wu [:robwu]]

Attachment: Bug 1501375 - Interrupt extension start-up if background page crashes

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

Comment 4

[Andrew Swan [:aswan]]

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

Comment 5

[Rob Wu [:robwu]]

(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.

Comment 6

[Rob Wu [:robwu]]

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.

Comment 7

[Shane Caraveo (:mixedpuppy)]

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).

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b374a5789689
Interrupt extension start-up if background page crashes r=mixedpuppy

Comment 9

[Andreea Pavel [:apavel]]

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

Comment 10

[Rob Wu [:robwu]]

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.

Comment 11

[Rob Wu [:robwu]]

Attachment: Bug 1501375 - Account for shutdown of bg page during extension start-up

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

Comment 12

[Rob Wu [:robwu]]

Attachment: Bug 1501375 - Clear primed listeners on extension shutdown

In D9959 and D10954, the implementation of background page machinery
was updated so that the build method of BackgroundPage is
guaranteed to return eventually, without error. Even if the load of
the background page was interrupted by an extension shut down.

When an extension shuts down during start-up, primed listeners have
likely not been re-registered. To prevent interruption of startup
from causing the loss of persistent listeners, this commit changes
the implementation such that persistent listeners are only updated if
the background page was fully loaded.
Otherwise listeners are cleared from memory, but not unregistered.

Depends on D10954

Comment 13

[Rob Wu [:robwu]]

Attachment: Bug 1501375 - Test extension shutdown during extension startup

Depends on D17700

Comment 14

[Pulsebot]

Pushed by [e-mail]:
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

Comment 15

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/2def2f8d49e7
https://hg.mozilla.org/mozilla-central/rev/2090ee542b58
https://hg.mozilla.org/mozilla-central/rev/3a5c6e81192d
https://hg.mozilla.org/mozilla-central/rev/04b242fc5a70

Comment 16

[Rob Wu [:robwu]]

Covered by automated tests.