Open Bug 1419183 Opened 4 years ago Updated 4 months ago

Intermittent toolkit/components/extensions/test/xpcshell/test_ext_management.js | test_management_getAll - [test_management_getAll : 253] A promise chain failed to handle a rejection: The ExtensionSettingsStore was accessed before the initialize

Categories

(WebExtensions :: General, defect, P2)

Product:
WebExtensions
Component:
General
Platform:
Unspecified
Windows
Type:
defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, leave-open, Whiteboard: [stockwell disabled])

Attachments

(1 file)

disable_bug1419183.patch
891 bytes, patch
jmaher
: review+
Details | Diff | Splinter Review 
Filed by: archaeopteryx [at] coole-files.de

https://treeherder.mozilla.org/logviewer.html#?job_id=145996861&repo=autoland

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

01:32:08     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_management.js | test_management_getAll - [test_management_getAll : 65] Additional extension metadata was correct - "get_all_test1@tests.mozilla.com" == "get_all_test1@tests.mozilla.com"
01:32:08     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_management.js | test_management_getAll - [test_management_getAll : 69] The extension with id get_all_test2@tests.mozilla.com was returned by get. - "get_all_test2@tests.mozilla.com" == "get_all_test2@tests.mozilla.com"
01:32:08     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_management.js | test_management_getAll - [test_management_getAll : 70] Additional extension metadata was correct - "get_all_test2@tests.mozilla.com" == "get_all_test2@tests.mozilla.com"
01:32:08     INFO -  PID 10916 | JavaScript strict warning: resource://gre/modules/ExtensionStorage.jsm, line 334: ReferenceError: reference to undefined property "processType"
01:32:08     INFO -  PID 10916 | JavaScript strict warning: resource://gre/modules/EventEmitter.jsm, line 123: ReferenceError: reference to undefined property "_originalListener"
01:32:08     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (2)
01:32:08     INFO -  (xpcshell/head.js) | test test_management_getAll finished (2)
01:32:08     INFO -  "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "processType"" {file: "resource://gre/modules/ExtensionStorage.jsm" line: 334}]"
01:32:08     INFO -  "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "_originalListener"" {file: "resource://gre/modules/EventEmitter.jsm" line: 123}]"
01:32:08     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (1)
01:32:08     INFO -  exiting test
01:32:08     INFO -  PID 10916 | JavaScript error: resource://gre/modules/ExtensionSettingsStore.jsm, line 103: Error: The ExtensionSettingsStore was accessed before the initialize promise resolved.
01:32:08     INFO -  PID 10916 | JavaScript error: resource://gre/modules/ExtensionSettingsStore.jsm, line 103: Error: The ExtensionSettingsStore was accessed before the initialize promise resolved.
01:32:08     INFO -  PID 10916 | JavaScript error: resource://gre/modules/ExtensionSettingsStore.jsm, line 103: Error: The ExtensionSettingsStore was accessed before the initialize promise resolved.
01:32:08     INFO -  PID 10916 | JavaScript error: resource://gre/modules/ExtensionSettingsStore.jsm, line 103: Error: The ExtensionSettingsStore was accessed before the initialize promise resolved.
01:32:08     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "Error: The ExtensionSettingsStore was accessed before the initialize promise resolved." {file: "resource://gre/modules/ExtensionSettingsStore.jsm" line: 103}]"
01:32:08     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "Error: The ExtensionSettingsStore was accessed before the initialize promise resolved." {file: "resource://gre/modules/ExtensionSettingsStore.jsm" line: 103}]"
01:32:08     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "Error: The ExtensionSettingsStore was accessed before the initialize promise resolved." {file: "resource://gre/modules/ExtensionSettingsStore.jsm" line: 103}]"
01:32:08     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "Error: The ExtensionSettingsStore was accessed before the initialize promise resolved." {file: "resource://gre/modules/ExtensionSettingsStore.jsm" line: 103}]"
01:32:08  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_management.js | test_management_getAll - [test_management_getAll : 253] A promise chain failed to handle a rejection: The ExtensionSettingsStore was accessed before the initialize promise resolved. - stack: observe@resource://gre/modules/AsyncShutdown.jsm:535:9
01:32:08     INFO -  _execute_test@Z:\\task_1511137528\\build\\tests\\xpcshell\\head.js:626:5
01:32:08     INFO -  @-e:1:1
01:32:08     INFO -  Rejection date: Mon Nov 20 2017 01:32:08 GMT+0000 (Coordinated Universal Time) - false == true
01:32:08     INFO -  resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:253
01:32:08     INFO -  Z:\task_1511137528\build\tests\xpcshell\head.js:_execute_test:634
01:32:08     INFO -  -e:null:1
01:32:08     INFO -  exiting test
01:32:08     INFO -  PID 10916 | JavaScript error: , line 0: uncaught exception: 2147500036
01:32:08     INFO -  PID 10916 | [GPU 6012, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
01:32:08     INFO -  <<<<<<<
There have been a total of 33 failures in the last week, according to Orange Factor.

Occurrences per platform:
-windows10-64: 20
-Windows 7: 9
-windows10-64-nightly: 2
-android-6-0-armv8-api16: 1

Occurrences per build type:
-debug: 1
-opt: 5
-pgo: 27


Here is a recent log file and a snippet with the failure:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=159301866&lineNumber=10275

12:06:20     INFO -  TEST-START | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_management.js
12:06:20  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_management.js | xpcshell return code: 0
12:06:20     INFO -  TEST-INFO took 693ms

The duplicate bug: 1422180 was resolved.

:andym could you please take a look?
Flags: needinfo?(amckay)
Whiteboard: [stockwell needswork]
I'll take a look at this.
Assignee: nobody → bob.silverberg
Flags: needinfo?(amckay)
Priority: P5 → P3
I've done some digging into this, and am able to reproduce this fairly frequently on Windows 10. Dumping a stack trace where the error is occurring, I see the following:

ensureType@resource://gre/modules/ExtensionSettingsStore.jsm:104:28
getItem@resource://gre/modules/ExtensionSettingsStore.jsm:135:3
getSetting@resource://gre/modules/ExtensionSettingsStore.jsm:445:12
removeEngine@chrome://browser/content/ext-chrome-settings-overrides.js:71:22
async*removeSearchSettings@chrome://browser/content/ext-chrome-settings-overrides.js:88:5
onUninstall@chrome://browser/content/ext-chrome-settings-overrides.js:94:5
apiManager</</<@resource://gre/modules/ExtensionParent.jsm:107:9
Async*apiManager</<@resource://gre/modules/ExtensionParent.jsm:105:26
emit@resource://gre/modules/ExtensionUtils.jsm:234:40
uninstall@resource://gre/modules/Extension.jsm:1032:5
callBootstrapMethod@resource://gre/modules/addons/XPIProvider.jsm:4420:20
uninstallAddon@resource://gre/modules/addons/XPIProvider.jsm:4685:11
uninstall@resource://gre/modules/addons/XPIProvider.jsm:5615:5
unload@resource://testing-common/ExtensionXPCShellUtils.jsm:319:7
async*unload@resource://testing-common/ExtensionXPCShellUtils.jsm:568:12
async*test_management_getAll@c:/mozilla-source/mozilla-central/obj-ff-opt-artifact/_tests/xpcshell/toolkit/components/extensions/test/xpcshell/test_ext_management.js:73:9
etc...

So what seems to be happening is that when the test extension is unloaded, the onUninstall method in ext-chrome-settings-overrides.js is called, which in turn calls removeEngine in ext-chrome-settings-overrides.js. removeEngine then interacts with the ExtensionSettingsStore, which results in the "The ExtensionSettingsStore was accessed before the initialize promise resolved." exception, BUT, it doesn't seem like that should be happening.

removeEngine calls await ExtensionSettingsStore.initialize() before attempting to interact with the settings store [1], and that's supposed to ensure that the exception above cannot happen. So I'm not sure what's happening here. It seems like either removeEngine isn't actually waiting for that promise to resolve before calling ExtensionSettingsStore.getSetting, or that the promise returned from ExtensionSettingsStore.initialize doesn't actually do what we expect it to do, and can resolve before the store is actually initialized.

Andrew, do you have any ideas about what might be happening here?

[1] https://searchfox.org/mozilla-central/rev/e06af9c36a73a27864302cd2f829e6200dee8541/browser/components/extensions/ext-chrome-settings-overrides.js#70
Flags: needinfo?(aswan)
(In reply to Bob Silverberg [:bsilverberg] from comment #16)
> removeEngine calls await ExtensionSettingsStore.initialize() before
> attempting to interact with the settings store [1], and that's supposed to
> ensure that the exception above cannot happen. So I'm not sure what's
> happening here. It seems like either removeEngine isn't actually waiting for
> that promise to resolve before calling ExtensionSettingsStore.getSetting, or
> that the promise returned from ExtensionSettingsStore.initialize doesn't
> actually do what we expect it to do, and can resolve before the store is
> actually initialized.

It looks like removeSearchSettings() doesn't actually wait for the removeEngine() promise.  And even if it did, onUninstall() also doesn't wait for removeSearchSettings()
Flags: needinfo?(aswan)
This in the last 7 days still has 52 failures and this in the conditions that the trees were closed in the last 12h and nothing has been pushed. Most of them on windows10-64 pgo (39), some on windows 7 (7) and some on windows10-64-nightly (5) and one on windows10-64-devedition. 

:bsilverberg would you try a fix for it or do you think we could disabled it for now until you have a fix? Thank you.
Flags: needinfo?(bob.silverberg)
(In reply to Cosmin Sabou [:cosmin_s] from comment #20)
> This in the last 7 days still has 52 failures and this in the conditions
> that the trees were closed in the last 12h and nothing has been pushed. Most
> of them on windows10-64 pgo (39), some on windows 7 (7) and some on
> windows10-64-nightly (5) and one on windows10-64-devedition. 
> 
> :bsilverberg would you try a fix for it or do you think we could disabled it
> for now until you have a fix? Thank you.

mstriemer has kindly offered to take another look at this, so I'm reassigning to him, and if we could hold off disabling it for a few more days that would be great. Thanks!
Assignee: bob.silverberg → mstriemer
Flags: needinfo?(bob.silverberg)
Hi! Another patch for review. Thanks.
Attachment #8952764 - Flags: review?(jmaher)
Attachment #8952764 - Flags: review?(jmaher) → review+
Pushed by csabou@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/655aa8e5fb99
Disable toolkit/components/extensions/test/xpcshell/test_ext_management.js for frequent failures. r=jmaher
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Product: Toolkit → WebExtensions

api test disabled on win release. This stuff changed a lot, so a push to try to see if there is still an issue would probably resolve it.

Assignee: mstriemer → nobody
Severity: normal → S2
OS: Unspecified → Windows
Priority: P3 → P2
You need to log in before you can comment on or make changes to this bug.