1525729 - AsyncShutdown timeout in asyncEmitManifestEntry("chrome_settings_overrides")

Status: RESOLVED FIXED

(WebExtensions :: General, defect, P1)

Description

[[:philipp]]

+++ This bug was initially created as a clone of Bug #1493770 +++

This bug is for crash report bp-732d9200-05ae-4068-a66f-91cf50190206.

AsyncShutdownTimeout:

{

    "phase":"profile-change-teardown",
    "conditions":[
        {
            "name":"Extension shutdown: [e-mail]",
            "state":{
                "state":"Startup: Run manifest: asyncEmitManifestEntry("chrome_settings_overrides")"
            },
            "filename":"resource://gre/modules/addons/XPIProvider.jsm",
            "lineNumber":2236,
            "stack":[
                "resource://gre/modules/addons/XPIProvider.jsm:startup/<:2236",
                "resource://gre/modules/AsyncShutdown.jsm:observe:541",
                "jar:file:///C:/Program%20Files/Mozilla%20Firefox/omni.ja!/components/marionette.js:observe/<:384"
            ]
        }
    ]

}

these particular async shutdown timeout crashes started showing up since firefox 63 with webextensions adding a custom search provider.

bug 1493770 already took a stab at fixing those crashes, but that didn't make the crash volume noticeably decline in firefox 65, so i'm filing this as a followup.

this crash-stats query should catch the remaining issues:
https://crash-stats.mozilla.com/search/?async_shutdown_timeout=~chrome_settings_overrides&build_id=%3E%3D20190124174741&date=%3E%3D2019-01-01&_facets=signature&_facets=version&_facets=platform_pretty_version&_facets=useragent_locale#facet-signature

Comment 1

[Rob Wu [:robwu]]

TL;DR The crash is caused by await searchInitialized; at https://searchfox.org/mozilla-central/rev/cb7faaf6b4ad2528390186f1ce64618dea71031e/browser/components/extensions/parent/ext-chrome-settings-overrides.js#193

The onManifestEntry handler of ext-chrome-settings-overrides.js has several await calls, each of which could be responsible for this crash. I'm only looking at await because these block the promise. I'm not considering synchronous API calls because it's unlikely for those to block the promise for a minute.

I fetched all add-ons that were reported in the 1630 crash reports from this year until yesterday, and checked the content of the extensions' chrome_settings_override.

There are some crashes where the responsible add-on does not have chrome_settings_override.search_provider.is_default. This allows us to eliminate the majority of await uses, leaving only three potential causes of the hang:

• await ExtensionSettingsStore.initialize(); @ https://searchfox.org/mozilla-central/rev/cb7faaf6b4ad2528390186f1ce64618dea71031e/browser/components/extensions/parent/ext-chrome-settings-overrides.js#161
• await searchInitialized; @ https://searchfox.org/mozilla-central/rev/cb7faaf6b4ad2528390186f1ce64618dea71031e/browser/components/extensions/parent/ext-chrome-settings-overrides.js#193
• await this.addSearchEngine(); @ https://searchfox.org/mozilla-central/rev/cb7faaf6b4ad2528390186f1ce64618dea71031e/browser/components/extensions/parent/ext-chrome-settings-overrides.js#216

From the reports, 2 of the add-ons involved in a crash have only set a homepage_url. This rules out the first option (because then we should have seen significantly more crashes from add-ons that had only set chrome_settings_override.homepage, and we should also also have seen a similar volume of crashes for addons that use chrome_url_overrides, because it also uses similar code).

addSearchEngine currently has many awaits, but most of these were recently added. The crashes already happened before that, so that leaves the only cause in addSearchEngine to be await ExtensionSettingsStore.addSetting (https://searchfox.org/mozilla-central/rev/10ed8acc81f55dd9a7b0a2330447592a3e5c5027/browser/components/extensions/parent/ext-chrome-settings-overrides.js#286).

ExtensionSettingsStore.addSetting is also used by ext-url-overrides.js, for we have only 23 crash reports in the same time frame as the this bug (87 crash reports in the past six months) (reports with asyncEmitManifestEntry(\"chrome_url_overrides\")).
If ExtensionSettingsStore.addSetting were to be the cause of this bug, then the crash rates for chrome_url_overrides should also have been higher.

This leaves us with one possible cause for this crash, await searchInitialized;, which is defined at https://searchfox.org/mozilla-central/rev/01b4b3830ea3cae2e9e431019afa6391b471c6da/browser/components/extensions/parent/ext-browser.js#249-254

The searchInitialized promise is only fulfilled when the "browser-search-service" notification has been triggered. Coincidentally, the defaultSearchEngine / defaultSearchEngineData fields in the telemetry environment are only set up once the notification has been triggered.
These fields are missing from the telemetry environment in the crash reports of this bug, which offers conclusive evidence that this crash is caused by the await searchInitialized;.

Comment 2

[Rob Wu [:robwu]]

Attachment: Bug 1525729 - Stop blocking extension startup on searchInitialized

Comment 3

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/52747743fe65
Ignore searchInitialized promise on shutdown r=aswan

Comment 4

[Narcis Beleuzu [:NarcisB]]

Backed out for XPCShell failures on test_ext_chrome_settings_overrides_update.js

Backout link: https://hg.mozilla.org/integration/autoland/rev/008cdc952e8c48e4af1536fee05919970b1ce426
Push link: https://hg.mozilla.org/integration/autoland/rev/52747743fe65e7db44792f77f02aecd40634f931
Log link: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=231085320&repo=autoland&lineNumber=2177

Also bc failures on browser_ext_settings_overrides_default_search.js
Log link: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=231085051&repo=autoland&lineNumber=2366

Comment 5

[Rob Wu [:robwu]]

Attachment: Bug 1525729 - Avoid memory leak via AddonTestUtils.initMochiTest

When I added AddonTestUtils.initMochiTest to an existing test at
browser/components/preferences/in-content/tests/browser_extension_controlled.js
, the test started to fail often on debug builds, with errors like
"leaked 2 window(s) until shutdown".
Fix this by clearing the global that was saved by initMochiTest.

Comment 6

[Rob Wu [:robwu]]

I'm landing the patch from comment 5 first, because the other patch is part of a patch stack that has to land after comment 5's patch to avoid test failures.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e9f1a449031d
Avoid memory leak via AddonTestUtils.initMochiTest r=aswan

Comment 8

[Razvan Maries]

https://hg.mozilla.org/mozilla-central/rev/e9f1a449031d

Comment 9

[Rob Wu [:robwu]]

Now going to land the other stack.
Green try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=a5719215b8b9e36dcac09b69dd1218a136713b00
The commits of the patch stack aren't visible in the try push because they were part of a preview push (whose failures have been addressed in the above try push):
https://treeherder.mozilla.org/#/jobs?repo=try&revision=0db411f072f79dbf7dc9c399cd3b2a044947f249

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f28acbccbc62
Stop blocking extension startup on searchInitialized r=aswan

Comment 11

[Oana Pop-Rus]

https://hg.mozilla.org/mozilla-central/rev/f28acbccbc62

Comment 12

[Madalin Cotetiu]

Can you please provide us an extension that we can use to test this manually (and some steps to reproduce the crash would be much apreciated)?

Comment 13

[Rob Wu [:robwu]]

Covered by unit tests (at browser/components/extensions/test/xpcshell/test_ext_settings_overrides_shutdown.js ).

The only recent crashes after this patch has landed are in release (version 66, which does not have the patch):
https://crash-stats.mozilla.com/search/?signature=~AsyncShutdownTimeout%20%7C%20profile-change-teardown%20%7C%20Extension%20shutdown%3A&async_shutdown_timeout=~asyncEmitManifestEntry%28%5C%5C%5C%22chrome_settings_overrides%5C%5C%5C%22%29&build_id=%3E%3D20190315093917&date=%3E%3D2019-02-26T14%3A46%3A00.000Z&date=%3C2019-03-26T14%3A46%3A00.000Z&_facets=signature&_sort=-date&_columns=date&_columns=version&_columns=build_id&_columns=async_shutdown_timeout#crash-reports

Excluding release versions 66.0 and 66.0.1, there are no crashes (not in Beta 67, neither in Nightly 68):
https://crash-stats.mozilla.com/search/?signature=~AsyncShutdownTimeout%20%7C%20profile-change-teardown%20%7C%20Extension%20shutdown%3A&async_shutdown_timeout=~asyncEmitManifestEntry%28%5C%5C%5C%22chrome_settings_overrides%5C%5C%5C%22%29&build_id=%3E%3D20190315093917&version=%2166.0.1&version=%2166.0&date=%3E%3D2019-03-19T15%3A54%3A00.000Z&date=%3C2019-03-26T15%3A54%3A00.000Z&_facets=signature&_facets=addons&page=1&_sort=-uptime&_columns=date&_columns=version&_columns=build_id&_columns=async_shutdown_timeout&_columns=uptime#crash-reports