1521083 - Perma Windows10CCov xpcshell FATAL ERROR: AsyncShutdown timeout in AddonManager: Waiting for providers to shut down. Conditions: [{"name":"JSON store: writing data","state":"(none)","filename":"resource://gre/modules/JSONFile.jsm","lineNumber":117

Status: RESOLVED WORKSFORME

(Web Compatibility :: Tooling & Investigations, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ebalazs [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=222686476&repo=mozilla-central

https://queue.taskcluster.net/v1/task/HNcOZC2bTMyC70kIK51BRA/runs/0/artifacts/public/logs/live_backing.log

TEST-PASS | xpcshell.ini:toolkit/mozapps/extensions/test/xpcshell/test_systemaddomstartupprefs.js | systemAddonPreffedOn - [systemAddonPreffedOn : 149] Should have seen startup method call for [e-mail] - [object Object] == true
11:58:13 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "startupPromise"" {file: "resource://testing-common/AddonTestUtils.jsm" line: 806}]"
11:58:13 INFO - "CONSOLE_MESSAGE: (info) 1547812632725 addons.manager DEBUG shutdown"
11:58:13 INFO - "CONSOLE_MESSAGE: (info) 1547812632729 addons.manager DEBUG Calling shutdown blocker for LightweightThemeManager"
11:58:13 INFO - "CONSOLE_MESSAGE: (info) 1547812632730 addons.manager DEBUG Calling shutdown blocker for GMPProvider"
11:58:13 INFO - "CONSOLE_MESSAGE: (info) 1547812632732 addons.manager DEBUG Calling shutdown blocker for PluginProvider"
11:58:13 INFO - "CONSOLE_MESSAGE: (info) 1547812632734 addons.manager DEBUG Calling shutdown blocker for XPIProvider"
11:58:13 INFO - "CONSOLE_MESSAGE: (info) 1547812632734 addons.xpi DEBUG shutdown"
11:58:13 INFO - "CONSOLE_MESSAGE: (info) 1547812632735 addons.xpi-utils DEBUG shutdown"
11:58:13 INFO - "CONSOLE_MESSAGE: (info) 1547812632792 addons.xpi DEBUG Calling bootstrap method shutdown on [e-mail] version 1.0"
11:58:13 INFO - PID 9324 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"JSON store: writing data","state":"(none)","filename":"resource://gre/modules/JSONFile.jsm","lineNumber":117,"stack":["resource://gre/modules/JSONFile.jsm:JSONFile:117","resource://gre/modules/addons/XPIProvider.jsm:save:1448","resource://gre/modules/addons/XPIDatabase.jsm:updateXPIStates:1939","resource://gre/modules/addons/XPIDatabase.jsm:makeAddonVisible:1962","resource://gre/modules/addons/XPIDatabase.jsm:applyStartupChange:2865","resource://gre/modules/addons/XPIDatabase.jsm:processFileChanges:2741","resource://gre/modules/addons/XPIProvider.jsm:checkForChanges:2570","resource://gre/modules/addons/XPIProvider.jsm:startup:2148","resource://gre/modules/AddonManager.jsm:callProvider:203","resource://gre/modules/AddonManager.jsm:_startProvider:652","resource://gre/modules/AddonManager.jsm:startup:805","resource://gre/modules/AddonManager.jsm:startup:2775","jar:file:///Z:/task_1547810364/build/application/firefox/omni.ja!/components/addonManager.js:observe:66","resource://testing-common/AddonTestUtils.jsm:promiseStartupManager:796"]},{"name":"XPIProvider","state":"(none)","filename":"resource://gre/modules/AddonManager.jsm","lineNumber":676,"stack":["resource://gre/modules/AddonManager.jsm:_startProvider:676","resource://gre/modules/AddonManager.jsm:startup:805","resource://gre/modules/AddonManager.jsm:startup:2775","jar:file:///Z:/task_1547810364/build/application/firefox/omni.ja!/components/addonManager.js:observe:66","resource://testing-common/AddonTestUtils.jsm:promiseStartupManager:796"]}] Barrier: AddonManager: Waiting for providers to shut down.
11:58:13 INFO - PID 9324 | JavaScript strict warning: resource://gre/modules/Extension.jsm, line 2022: ReferenceError: reference to undefined property "cleanupFile"
11:58:13 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "cleanupFile"" {file: "resource://gre/modules/Extension.jsm" line: 2022}]"
11:58:13 INFO - PID 9324 | FATAL ERROR: AsyncShutdown timeout in AddonManager: Waiting for providers to shut down. Conditions: [{"name":"JSON store: writing data","state":"(none)","filename":"resource://gre/modules/JSONFile.jsm","lineNumber":117,"stack":["resource://gre/modules/JSONFile.jsm:JSONFile:117","resource://gre/modules/addons/XPIProvider.jsm:save:1448","resource://gre/modules/addons/XPIDatabase.jsm:updateXPIStates:1939","resource://gre/modules/addons/XPIDatabase.jsm:makeAddonVisible:1962","resource://gre/modules/addons/XPIDatabase.jsm:applyStartupChange:2865","resource://gre/modules/addons/XPIDatabase.jsm:processFileChanges:2741","resource://gre/modules/addons/XPIProvider.jsm:checkForChanges:2570","resource://gre/modules/addons/XPIProvider.jsm:startup:2148","resource://gre/modules/AddonManager.jsm:callProvider:203","resource://gre/modules/AddonManager.jsm:_startProvider:652","resource://gre/modules/AddonManager.jsm:startup:805","resource://gre/modules/AddonManager.jsm:startup:2775","jar:file:///Z:/task_1547810364/build/application/firefox/omni.ja!/components/addonManager.js:observe:66","resource://testing-common/AddonTestUtils.jsm:promiseStartupManager:796"]},{"name":"XPIProvider","state":"(none)","filename":"resource://gre/modules/AddonManager.jsm","lineNumber":676,"stack":["resource://gre/modules/AddonManager.jsm:_startProvider:676","resource://gre/modules/AddonManager.jsm:startup:805","resource://gre/modules/AddonManager.jsm:startup:2775","jar:file:///Z:/task_1547810364/build/application/firefox/omni.ja!/components/addonManager.js:observe:66","resource://testing-common/AddonTestUtils.jsm:promiseStartupManager:796"]}] 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.
11:58:13 INFO - PID 9324 | WARNING: No crash reporter available
11:58:13 INFO - PID 9324 | [9324, Main Thread] ###!!! ABORT: file resource://gre/modules/JSONFile.jsm, line 117

Comment 1

[Eliza Balazs [:ebalazs_]]

Thomas: Hi, This started on m-c:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&resultStatus=pending%2Crunning%2Ctestfailed%2Cbusted%2Cexception%2Cusercancel%2Crunnable&revision=3aa256c255f664c500714c34a3b9e353e545d196&selectedJob=222686476
and seems to be related to https://bugzilla.mozilla.org/show_bug.cgi?id=1513541.
Can you please have a look? Thank you!

Comment 2

[Thomas Wisniewski [:twisniewski]]

Yes, aswan and I will try to figure this out ASAP.

Comment 3

[Thomas Wisniewski [:twisniewski]]

Hmm, I can't reproduce this one locally (I've tried using --verify and running a batch of tests including this one, but no dice).

However, looking at the test-utils startup methods for addons, I see this line which makes me wonder if that's what's happening (somehow intermittently). Since the test is seeing an [object] instead of true, maybe it's getting an exception or a promise-rejection, because of this line? That would explain why it fails before startupPromise is ever set to anything. Maybe we also need that return-clause to set startupPromise to a rejection instead of just throwing?

Other than that, I can't really tell why the startupPromise would be undefined during promiseStartupManager, unless for some reason the startup() method is just not called before checking the promise... but I wouldn't know why it would race like that (otherwise wouldn't the test fail all the time, or at least frequently enough for --verify to fail locally?)

Comment 4

[Intermittent Failures Robot]

4 failures in 2378 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 4

Platform breakdown:

• windows10-64-ccov: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1521083&startday=2019-01-14&endday=2019-01-20&tree=all

Comment 5

[Intermittent Failures Robot]

15 failures in 382 pushes (0.039 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 15

Platform breakdown:

• windows10-64-ccov: 15

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1521083&startday=2019-01-22&endday=2019-01-22&tree=all

Comment 6

[Andrew Swan [:aswan]]

I suspect this is just extreme slowness of ccov builds. I'd be fine either disabling this test or extending the timeout for ccov.

Comment 7

[Intermittent Failures Robot]

34 failures in 2383 pushes (0.014 failures/push) were associated with this bug in the last 7 days.

This is the #37 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 34

Platform breakdown:

• windows10-64-ccov: 34

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1521083&startday=2019-01-21&endday=2019-01-27&tree=all

Comment 8

[Dennis Schubert [:denschub]]

This hasn't failed for 3 years, so I'll just close this... :)