Closed Bug 1365021 Opened 2 years ago Closed Last year

Intermittent test_bootstrap.js | checkMatches - [checkMatches : 244] "undefined" != "undefined"

Categories

(Toolkit :: Add-ons Manager, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla61
Tracking Status
firefox61 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: kmag)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

This isn't actually intermittent in the usual sense: what's intermittent is that intermittently we create a build or a test package or both which will 100% of the time fail this way.

That makes this much much more serious, since not only will that cause us to make the wrong decision and back out an innocent patch (that's why I know about it), it also means that until we know what is actually wrong, we're at risk of building a nightly, or starting next week after we merge to beta a release, which is broken in the way that this test failure is trying to tell us about.
Flags: needinfo?(amckay)
Something fishy is going on here:
https://treeherder.mozilla.org/logviewer.html#?job_id=99220527&repo=mozilla-inbound&lineNumber=6130-6150
which happens during the addons manager startup here:
http://searchfox.org/mozilla-central/rev/1a054419976437d0778a2b89be1b00207a744e94/toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js#1054-1064

The message "New add-on bootstrap1@tests.mozilla.org in app-profile" is expected, it means we found the sideloaded extension.  But then we call the bootstrap "startup" method without ever calling "install".  That should have happened from here:
http://searchfox.org/mozilla-central/rev/1a054419976437d0778a2b89be1b00207a744e94/toolkit/mozapps/extensions/internal/XPIProviderUtils.js#1667-1678

Kris, do you see anything funny here?
Flags: needinfo?(kmaglione+bmo)
I see 30 more failures in the last week, this is 2 weeks with a high failure count- :kmag can you take a look at this soon, or should we consider temporarily disabling this test case on osx/opt xpcshell?
Whiteboard: [stockwell needswork]
Whiteboard: [stockwell needswork] → [stockwell unknown]
Flags: needinfo?(amckay) → needinfo?(bob.silverberg)
The failure rate seems to have slowed, but comment 3 suggests this is more serious than a "normal" intermittent. Andrew, are you able to take another look, and/or follow up directly with Kris about this?
Flags: needinfo?(bob.silverberg) → needinfo?(aswan)
(In reply to Bob Silverberg [:bsilverberg] from comment #20)
> The failure rate seems to have slowed, but comment 3 suggests this is more
> serious than a "normal" intermittent. Andrew, are you able to take another
> look, and/or follow up directly with Kris about this?

not right now, no
Flags: needinfo?(aswan)
We have 35 failures in the last 7 days.
They occur on Linux, Linux x64, linux64-ccov and OS X 10.10. The affected builds type are asan, debug, opt.
A recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=153143150&lineNumber=8015
and a relevant part of the log:
10:49:19     INFO -  TEST-START | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js
8015
10:49:21  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js | xpcshell return code: 0
8016
10:49:21     INFO -  TEST-INFO took 2287ms
8017
10:49:21     INFO -  >>>>>>>
8018
10:49:21     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
8019
10:49:21     INFO -  (xpcshell/head.js) | test pending (2)
8020
10:49:21     INFO -  PID 6862 | 1513968559488	addons.manager	DEBUG	Application has been upgraded
8021
10:49:21     INFO -  PID 6862 | 1513968559525	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]
8022
10:49:21     INFO -  PID 6862 | 1513968559528	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/LightweightThemeManager.jsm: ["LightweightThemeManager"]
8023
10:49:21     INFO -  PID 6862 | 1513968559532	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm
8024
10:49:21     INFO -  PID 6862 | 1513968559534	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm
8025
10:49:21     INFO -  PID 6862 | 1513968559535	addons.manager	DEBUG	Starting provider: XPIProvider
8026
10:49:21     INFO -  PID 6862 | 1513968559535	addons.xpi	DEBUG	startup
8027
10:49:21     INFO -  PID 6862 | 1513968559536	addons.xpi	INFO	SystemAddonInstallLocation directory is missing
8028
10:49:21     INFO -  PID 6862 | 1513968559536	addons.xpi	INFO	Removing all system add-on upgrades.
8029
10:49:21     INFO -  PID 6862 | 1513968559536	addons.xpi	WARN	Failed to add built-in install location app-system-defaults: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource://gre/modules/FileUtils.jsm :: FileUtils_getDir :: line 64"  data: no] Stack trace: FileUtils_getDir()@resource://gre/modules/FileUtils.jsm:64 < addBuiltInInstallLocation()@resource://gre/modules/addons/XPIProvider.jsm:2053 < startup()@resource://gre/modules/addons/XPIProvider.jsm:2130 < callProvider()@resource://gre/modules/AddonManager.jsm:264 < _startProvider()@resource://gre/modules/AddonManager.jsm:740 < startup()@resource://gre/modules/AddonManager.jsm:907 < startup()@resource://gre/modules/AddonManager.jsm:3089 < observe()@jar:file:///Users/cltbld/tasks/task_1513966352/build/application/Firefox%20Nightly.app/Contents/Resources/omni.ja!/components/addonManager.js:65 < promiseStartupManager()@resource://testing-common/AddonTestUtils.jsm:585
8030
10:49:21     INFO -  PID 6862 | 1513968559538	addons.xpi	DEBUG	checkForChanges
8031
10:49:21     INFO -  PID 6862 | 1513968559538	addons.xpi	DEBUG	Loaded add-on state: ${}
8032
10:49:21     INFO -  PID 6862 | JavaScript strict warning: resource://gre/modules/addons/XPIProvider.jsm, line 1578: ReferenceError: reference to undefined property "app-temporary"
8033
10:49:21     INFO -  PID 6862 | 1513968559539	addons.xpi	DEBUG	getInstallState changed: false, state: {}
8034
10:49:21     INFO -  PID 6862 | 1513968559540	addons.xpi	INFO	SystemAddonInstallLocation directory is missing
8035
10:49:21     INFO -  PID 6862 | 1513968559540	addons.xpi	DEBUG	Empty XPI database, setting schema version preference to 23
8036
10:49:21     INFO -  PID 6862 | 1513968559540	addons.xpi	DEBUG	No changes found
8037
10:49:21     INFO -  PID 6862 | 1513968559549	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider
8038
10:49:21     INFO -  PID 6862 | 1513968559549	addons.manager	DEBUG	Provider finished startup: XPIProvider
8039
10:49:21     INFO -  PID 6862 | 1513968559550	addons.manager	DEBUG	Starting provider: LightweightThemeManager
8040
10:49:21     INFO -  PID 6862 | 1513968559550	addons.manager	DEBUG	Registering shutdown blocker for LightweightThemeManager
8041
10:49:21     INFO -  PID 6862 | 1513968559550	addons.manager	DEBUG	Provider finished startup: LightweightThemeManager
8042
10:49:21     INFO -  PID 6862 | 1513968559550	addons.manager	DEBUG	Starting provider: GMPProvider
8043
10:49:21     INFO -  PID 6862 | 1513968559553	addons.manager	DEBUG	Registering shutdown blocker for GMPProvider
8044
10:49:21     INFO -  PID 6862 | 1513968559553	addons.manager	DEBUG	Provider finished startup: GMPProvider
8045
10:49:21     INFO -  PID 6862 | 1513968559553	addons.manager	DEBUG	Starting provider: PluginProvider
8046
10:49:21     INFO -  PID 6862 | 1513968559553	addons.manager	DEBUG	Registering shutdown blocker for PluginProvider
8047
10:49:21     INFO -  PID 6862 | 1513968559554	addons.manager	DEBUG	Provider finished startup: PluginProvider
8048
10:49:21     INFO -  PID 6862 | 1513968559556	addons.manager	DEBUG	Completed startup sequence
8049
10:49:21     INFO -  TEST-PASS | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js | run_test - [run_test : 120] true == true
8050
10:49:21     INFO -  TEST-PASS | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js | run_test - [run_test : 122] true == true
:andym, can you please have a look at this?
Flags: needinfo?(amckay)
Whiteboard: [stockwell unknown] → [stockwell needswork:owner]
Flags: needinfo?(amckay)
There 30 failures over the last 7 days, they happen on Linux, Linux x64 and OSX 10.10

Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=154922149&lineNumber=8038

Here is a relevant part of the log:

20:00:34  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js | xpcshell return code: 0
20:00:34     INFO -  TEST-INFO took 6193ms
20:00:34     INFO -  >>>>>>>
20:00:34     INFO -  PID 5902 | [5902, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/workspace/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2734
20:00:34     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
20:00:34     INFO -  (xpcshell/head.js) | test pending (2)

:andym can you please take a look? Thank you!
Flags: needinfo?(amckay)
In the last 7 days we have 37 failures.
For failure pattern see Comment 30.
:amckay, any updates on this?
Duplicate of this bug: 1430525
Flags: needinfo?(amckay)
I've been trying unsuccessfully to reproduce this with a little extra debugging info.  In an attempt to rule out any issues with how tests are grouped, I've run with the exact same revision/platform/etc as an existing failure but still here's a try run with 75 (!!) retriggers that never failed:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=fb5e0ce0ca2f69952f381c0924c4ac571fba3780&selectedJob=158573638

I think the next step is to figure out some debugging info that will help but that we also feel comfortable landing in central.  I'll try to come up with something.
Assignee: nobody → aswan
Again, comment 3. You may not be able to repro on try at all, it may be the result of doing a dep build so the clobbers on try will never show it, but if it is possible to repro on try you would get it from doing 75 builds, each running 1 test, not by running tests 75 times on the same build.

Other than the hassles of unzipping and rezipping (and the possibility that we no longer allow such behavior, I haven't done it for years) and the hassle of finding working instructions for running a packaged build against packaged tests, you don't need try at all, because there's a linux32 build which will exhibit this failure 100% of the time at https://queue.taskcluster.net/v1/task/CT4M9XiwQjCjGGriROtFZg/runs/0/artifacts/public/build/target.tar.bz2 and a matching set of tests at https://queue.taskcluster.net/v1/task/CT4M9XiwQjCjGGriROtFZg/runs/0/artifacts/public/build/target.xpcshell.tests.zip and you can (or maybe can't, dunno) just unzip it and insert your logging code and rezip it and run it (or whatever your actual choice of platform is) locally.
Ah, thank you and sorry for overlooking that before.  I'll pick this up next week and see what I can do.
In the last 7 days there are 38 failures. Most of them On Linux x64 asan, pgo & opt (total 14), OS X opt (13) and few on linux64-jsdcov.
But in the last 2 days the rate of failures seem to go down a bit. 

Latest failure log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=160240071&lineNumber=11307

03:09:46  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js | checkMatches - [checkMatches : 248] "undefined" != "undefined"
03:09:46     INFO -  /Users/cltbld/tasks/task_1517654851/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js:checkMatches:248
03:09:46     INFO -  /Users/cltbld/tasks/task_1517654851/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js:observe:308
03:09:46     INFO -  resource://xpcshell-data/BootstrapMonitor.jsm:notify:17
03:09:46     INFO -  resource://gre/modules/addons/XPIProvider.jsm:callBootstrapMethod:4420
03:09:46     INFO -  resource://gre/modules/addons/XPIProvider.jsm:startup:2238
03:09:46     INFO -  resource://gre/modules/AddonManager.jsm:callProvider:258
03:09:46     INFO -  resource://gre/modules/AddonManager.jsm:_startProvider:733
03:09:46     INFO -  resource://gre/modules/AddonManager.jsm:startup:897
03:09:46     INFO -  resource://gre/modules/AddonManager.jsm:startup:2972
03:09:46     INFO -  jar:file:///Users/cltbld/tasks/task_1517654851/build/application/Firefox%20Nightly.app/Contents/Resources/omni.ja!/components/addonManager.js:observe:65
03:09:46     INFO -  resource://testing-common/AddonTestUtils.jsm:promiseStartupManager:585
03:09:46     INFO -  exiting test
03:09:46     INFO -  PID 6895 | JavaScript error: resource://xpcshell-data/BootstrapMonitor.jsm, line 17: uncaught exception: 2147500036
03:09:46     INFO -  PID 6895 | 1517656185474	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider
03:09:46     INFO -  PID 6895 | 1517656185474	addons.manager	DEBUG	Provider finished startup: XPIProvider
03:09:46     INFO -  PID 6895 | 1517656185474	addons.manager	DEBUG	Completed startup sequence
03:09:46     INFO -  (xpcshell/head.js) | test delayed callback finished (2)
03:09:46  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js | checkAddonInstalled - [checkAddonInstalled : 272] "undefined" != "undefined"
03:09:46     INFO -  /Users/cltbld/tasks/task_1517654851/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js:checkAddonInstalled:272
03:09:46     INFO -  /Users/cltbld/tasks/task_1517654851/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js:run_test_22/</<:1087
03:09:46     INFO -  resource://gre/modules/AddonManager.jsm:safeCall:182
03:09:46     INFO -  resource://gre/modules/AddonManager.jsm:makeSafe/<:197
03:09:46     INFO -  /Users/cltbld/tasks/task_1517654851/build/tests/xpcshell/head.js:_do_main:224
03:09:46     INFO -  /Users/cltbld/tasks/task_1517654851/build/tests/xpcshell/head.js:_execute_test:546
03:09:46     INFO -  -e:null:1
03:09:46     INFO -  exiting test

:andym, could you please take a look and say if you need more info?
Flags: needinfo?(amckay)
Attached patch Skipped the testSplinter Review
Attachment #8949421 - Flags: review?(gbrown)
Comment on attachment 8949421 [details] [diff] [review]
Skipped the test

Review of attachment 8949421 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks Eliza!
Attachment #8949421 - Flags: review?(gbrown) → review+
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/07d1197be2e0
disable test_bootstrap.js for intermittent failures r=gbrown
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Flags: needinfo?(amckay) → needinfo?(ddurst)
Comment on attachment 8962254 [details]
Bug 1365021: Refactor test_bootstrap.js to be less insane; re-enable.

https://reviewboard.mozilla.org/r/231116/#review237304

whew, thanks

::: toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js:186
(Diff revision 1)
> -        continue;
> +      continue;
>  
> -      Assert.ok(addon.id in data);
> -      let addonData = data[addon.id];
> +    ok(data.has(addon.id));
> +    let addonData = data.get(addon.id);
> +    data.delete(addon.id);
> -      delete data[addon.id];
> +    delete data[addon.id];

remove this line

::: toolkit/mozapps/extensions/test/xpcshell/test_bootstrap.js:799
(Diff revision 1)
>  // Tests that upgrading a disabled bootstrapped extension still calls uninstall
>  // and install but doesn't startup the new version
> -function run_test_15() {
> -  BootstrapMonitor.promiseAddonStartup(ID1).then(function test_15_after_startup() {
> -    AddonManager.getAddonByID(ID1, function(b1) {
> -      Assert.notEqual(b1, null);
> +add_task(async function test_15() {
> +  await Promise.all([
> +    BootstrapMonitor.promiseAddonStartup(ID1),
> +    promiseInstallFile(XPIS.test_bootstrap1_1),

sheesh, so much better than having this at the end of the function
Attachment #8962254 - Flags: review?(aswan) → review+
https://hg.mozilla.org/integration/mozilla-inbound/rev/2aa1a76c7dfb765f1434d8a774f83debc69ee305
Bug 1365021: Refactor test_bootstrap.js to be less insane; re-enable. r=aswan
https://hg.mozilla.org/integration/mozilla-inbound/rev/8ff9abf7087561d386f10ee84d87467237df4e4a
Bug 1365021: Refactor test_bootstrap.js to be less insane; re-enable. r=aswan
Assignee: aswan → kmaglione+bmo
Status: NEW → RESOLVED
Closed: Last year
Flags: needinfo?(kmaglione+bmo)
Flags: needinfo?(ddurst)
Keywords: leave-open
Resolution: --- → FIXED
AFAICT, the actual test re-enabling never happened?
https://hg.mozilla.org/mozilla-central/file/37b8862d354e/toolkit/mozapps/extensions/test/xpcshell/xpcshell.ini#l74
Status: RESOLVED → REOPENED
Flags: needinfo?(kmaglione+bmo)
Resolution: FIXED → ---
Hm. I probably botched a rebase
Flags: needinfo?(kmaglione+bmo)
https://hg.mozilla.org/mozilla-central/rev/c23d9c9be5ed
Status: REOPENED → RESOLVED
Closed: Last yearLast year
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
Flags: qe-verify-
Whiteboard: [stockwell disabled]
You need to log in before you can comment on or make changes to this bug.