Closed Bug 1365021 Opened 8 years ago Closed 7 years ago

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

Categories

(Toolkit :: Add-ons Manager, defect)

Product:
Toolkit
Component:
Add-ons Manager
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla61
Tracking Flags:
Tracking Status
firefox61 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

Skipped the test
757 bytes, patch
gbrown
: review+
Details | Diff | Splinter Review
Bug 1365021: Refactor test_bootstrap.js to be less insane; re-enable.
59 bytes, text/x-review-board-request
aswan
: review+
Details
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?
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 test — — Splinter 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: 7 years ago
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: 7 years ago → 7 years ago
status-firefox61: --- → fixed
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.

Attachment

General

Creator:
Created:
Updated:
Size: