Closed Bug 1000695 Opened 11 years ago Closed 10 years ago

Intermittent browser_hotfix.js | Should not have seen an install of https://example.com/browser/toolkit/mozapps/extensions/test/browser/unsigned_hotfix.xpi in state 1

Categories

(Toolkit :: Add-ons Manager, defect)

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

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla36
Tracking Flags:
Tracking Status
firefox34 --- fixed
firefox35 --- fixed
firefox36 --- fixed
firefox-esr31 --- fixed

People

(Reporter: philor, Assigned: mossop)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 3 obsolete files)

Part 1 - convert backgroundUpdateCheck to Task.jsm (nit fixed)
10.65 KB, patch
Irving
: review+
Details | Diff | Splinter Review
Part 2 - rewrite browser_hotfix.js test to Task.js; yield to event loop after notifications (sanity check removed)
21.67 KB, patch
Unfocused
: review+
Details | Diff | Splinter Review
https://tbpl.mozilla.org/php/getParsedLog.php?id=38354172&tree=Mozilla-Inbound Ubuntu VM 12.04 mozilla-inbound debug test mochitest-browser-chrome-3 on 2014-04-23 16:32:31 PDT for push c81b25ae61c0 slave: tst-linux32-spot-659 16:45:52 INFO - TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_hotfix.js | Test 7 took 414ms 16:45:52 INFO - 1398296752508 addons.xpi DEBUG removeTemporaryFile: https://example.com/browser/toolkit/mozapps/extensions/test/browser/unsigned_hotfix.xpi removing temp file /tmp/tmp-68r.xpi 16:45:52 INFO - 1398296752511 addons.xpi DEBUG updateAddonRepositoryData found 6 visible add-ons 16:45:52 INFO - 1398296752515 addons.update-checker DEBUG Requesting http://127.0.0.1:8888/extensions-dummy/updateBackgroundURL 16:45:52 INFO - 1398296752529 addons.update-checker DEBUG Requesting http://127.0.0.1:8888/extensions-dummy/updateBackgroundURL 16:45:52 INFO - 1398296752541 addons.update-checker DEBUG Requesting http://127.0.0.1:8888/extensions-dummy/updateBackgroundURL 16:45:52 INFO - 1398296752549 addons.update-checker DEBUG Requesting http://127.0.0.1:8888/extensions-dummy/updateBackgroundURL 16:45:52 INFO - 1398296752559 addons.update-checker DEBUG Requesting http://127.0.0.1:8888/extensions-dummy/updateBackgroundURL 16:45:52 INFO - 1398296752571 addons.update-checker DEBUG Requesting http://127.0.0.1:8888/extensions-dummy/updateBackgroundURL 16:45:52 INFO - TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_hotfix.js | Console message: 1398296752456 addons.xpi DEBUG Download started for https://example.com/browser/toolkit/mozapps/extensions/test/browser/unsigned_hotfix.xpi to file /tmp/tmp-68r.xpi 16:45:52 INFO - TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_hotfix.js | Console message: 1398296752462 addons.xpi DEBUG Download of https://example.com/browser/toolkit/mozapps/extensions/test/browser/unsigned_hotfix.xpi completed. 16:45:52 INFO - TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_hotfix.js | Console message: 1398296752478 addons.repository DEBUG cacheAddons: enabled false IDs ["hotfix@tests.mozilla.org"] 16:45:52 INFO - TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_hotfix.js | Console message: [JavaScript Error: "A required certificate was not present." {file: "resource://gre/modules/CertUtils.jsm" line: 77}] 16:45:52 INFO - TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_hotfix.js | Console message: 1398296752494 addons.manager WARN The hotfix add-on was not signed by the expected certificate and so will not be installed. 16:45:52 INFO - TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_hotfix.js | Console message: 1398296752499 addons.xpi DEBUG Cancelling download of https://example.com/browser/toolkit/mozapps/extensions/test/browser/unsigned_hotfix.xpi 16:45:52 WARNING - TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_hotfix.js | Should not have seen an install of https://example.com/browser/toolkit/mozapps/extensions/test/browser/unsigned_hotfix.xpi in state 1 16:45:52 INFO - Stack trace: 16:45:52 INFO - JS frame :: chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/head.js :: <TOP_LEVEL> :: line 134 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: safeCall :: line 166 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: getInstallsByTypes_noMoreObjects :: line 1688 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: AOC_callNext :: line 261 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: AOC_callNext :: line 269 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: AOC_callNext :: line 269 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: getInstallsByTypes_safeCall :: line 1683 16:45:52 INFO - JS frame :: resource://gre/modules/addons/PluginProvider.jsm :: PL_getInstallsByTypes :: line 172 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: callProvider :: line 192 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: getInstallsByTypes_nextObject :: line 1681 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: AOC_callNext :: line 267 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: AOC_callNext :: line 269 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: getInstallsByTypes_safeCall :: line 1683 16:45:52 INFO - JS frame :: resource://gre/modules/addons/XPIProvider.jsm :: XPI_getInstallsByTypes :: line 3693 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: callProvider :: line 192 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: getInstallsByTypes_nextObject :: line 1681 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: AOC_callNext :: line 267 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: AsyncObjectCaller :: line 247 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: AMI_getInstallsByTypes :: line 1687 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: AMI_getAllInstalls :: line 1704 16:45:52 INFO - JS frame :: resource://gre/modules/AddonManager.jsm :: AM_getAllInstalls :: line 2675 16:45:52 INFO - JS frame :: chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/head.js :: <TOP_LEVEL> :: line 129 16:45:52 INFO - JS frame :: chrome://mochikit/content/browser-test.js :: Tester_nextTest :: line 325 16:45:52 INFO - JS frame :: chrome://mochikit/content/browser-test.js :: testScope/test_finish/< :: line 873 16:45:52 INFO - JS frame :: chrome://mochikit/content/browser-test.js :: testScope/test_executeSoon/<.run :: line 786 16:45:52 INFO - native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0 16:45:52 INFO - TEST-INFO | MEMORY STAT vsize after test: 945487872 16:45:52 INFO - TEST-INFO | MEMORY STAT residentFast after test: 386199552 16:45:52 INFO - INFO TEST-END | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_hotfix.js | finished in 4325ms
Not doing substantial work inside the add-on installation notification callbacks is necessary, but may not be sufficient; I've seen a couple of clean Try runs with this patch but that doesn't guarantee much. Investigating this bug makes me want to rewrite AddonManagerPrivate.backgroundUpdateCheck() using Task.jsm and Promises - should I do that here, or in a separate bug? The trigger for this is that the test isn't safely waiting for the background update check to end, and that would be easy to do if backgroundUpdateCheck() returned a Promise that resolved when it completed. The test case usually runs cleanly without the "are we restarting backgroundUpdateCheck?" sanity test, but fails with it in place, which makes me nervous that it will still random-orange.
Assignee: nobody → irving
Status: NEW → ASSIGNED
Attachment #8414774 - Flags: feedback?(bmcbride)
(In reply to :Irving Reid from comment #5) > Investigating this bug makes me want to rewrite > AddonManagerPrivate.backgroundUpdateCheck() using Task.jsm and Promises - > should I do that here, or in a separate bug? May as well do it here if it makes fixing this easier, and avoids temporary work.
Comment on attachment 8414774 [details] [diff] [review] Yield to the event loop from AddonInstall callbacks before continuing with test steps Review of attachment 8414774 [details] [diff] [review]: ----------------------------------------------------------------- ::: toolkit/mozapps/extensions/test/browser/browser_hotfix.js @@ +17,5 @@ > > var gNextTest; > > var SuccessfulInstallListener = { > + // onInstallEnded listeners are dangerous because they fire with a deep stack, and Do you think this is fixable on a more generic level? Say, firing that event async.
Attachment #8414774 - Flags: feedback?(bmcbride) → feedback+
This will make reliable tests easier to write, since they can just wait on the Promise; it also (hopefully) makes this function easier to understand and maintain. I split this into two separate patches; the existing test suite passes on my dev machine with this new backgroundUpdateCheck implementation, so it can be reviewed separately from the test changes that hopefully fix the orange.
Attachment #8416282 - Flags: review?(bmcbride)
If this fixes the orange on browser_hotfix.js we can copy the async patterns over to other intermittent tests.
Attachment #8414774 - Attachment is obsolete: true
Attachment #8416284 - Flags: review?(bmcbride)
Comment on attachment 8416282 [details] [diff] [review] Part 1 - convert backgroundUpdateCheck to Task.jsm Review of attachment 8416282 [details] [diff] [review]: ----------------------------------------------------------------- ::: toolkit/mozapps/extensions/AddonManager.jsm @@ +1185,5 @@ > // background updates should be applied. > if (aAddon.permissions & AddonManager.PERM_CAN_UPGRADE && > AddonManager.shouldAutoUpdate(aAddon)) { > + // XXX we really should resolve when this install is done, > + // not when update-available check completes, no? Hmm, yea, probably. Out of scope here though. @@ +1221,5 @@ > + > + Components.utils.import("resource://gre/modules/addons/AddonUpdateChecker.jsm"); > + let update = null; > + try { > + let aUpdates = yield new Promise((resolve, reject) => { Confusing naming of this variable - named as a passed-in param s/aUpdates/foundUpdates/ ?
Attachment #8416282 - Flags: review?(bmcbride) → review+
Comment on attachment 8416282 [details] [diff] [review] Part 1 - convert backgroundUpdateCheck to Task.jsm Review of attachment 8416282 [details] [diff] [review]: ----------------------------------------------------------------- ::: toolkit/mozapps/extensions/AddonManager.jsm @@ +1149,5 @@ > + Services.prefs.getBoolPref(PREF_APP_UPDATE_ENABLED) && > + Services.prefs.getBoolPref(PREF_APP_UPDATE_AUTO); > + > + if (!this.updateEnabled && !checkHotfix) > + return; Er, actually, I wonder if this should return an already resolved promise - so you don't have to check the return value if you're doing something like AddonManager.backgroundUpdateCheck().then(...)
Attachment #8416284 - Flags: review?(bmcbride) → review+
(In reply to Blair McBride [:Unfocused] from comment #12) > Comment on attachment 8416282 [details] [diff] [review] > Part 1 - convert backgroundUpdateCheck to Task.jsm ... > > + if (!this.updateEnabled && !checkHotfix) > > + return; > > Er, actually, I wonder if this should return an already resolved promise - > so you don't have to check the return value if you're doing something like > AddonManager.backgroundUpdateCheck().then(...) We're inside a Task.spawn(function* () { block, so the return just completes the task - callers of AM.backgroundUpdateCheck() received the Promise created by Task.spawn().
Nit fixed; carrying forward r=unfocused from comment 11.
Attachment #8416282 - Attachment is obsolete: true
Attachment #8417373 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/fcf5abdf9706 https://hg.mozilla.org/mozilla-central/rev/43306fac27e1
Status: ASSIGNED → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → mozilla32
Depends on: 1006075
Backed out in https://hg.mozilla.org/integration/fx-team/rev/c7fc9fadd71e for the near permafail from bug 1006075.
Status: RESOLVED → REOPENED
Flags: needinfo?(irving)
Resolution: FIXED → ---
The failure in bug 1006075 was caused by an unrelated issue, which happened to trip a sanity check I added in part 2 (detecting and preventing starting a new background update check while one is in progress). Rather than hold this patch up, I propose to move that sanity check over to bug 1006075 and land it when we have a fix for the underlying issue it exposed.
Attachment #8416284 - Attachment is obsolete: true
Attachment #8418786 - Flags: review?(bmcbride)
Flags: needinfo?(irving)
Attachment #8418786 - Flags: review?(bmcbride) → review+
https://hg.mozilla.org/mozilla-central/rev/b08560c528dc https://hg.mozilla.org/mozilla-central/rev/0552c02f54b0
Status: REOPENED → RESOLVED
Closed: 11 years ago → 11 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Literally on the push after this :(
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Assignee: irving → nobody
Depends on: 1095128
No longer depends on: 1095128
Depends on: 1095128
Hopefully fixed by bug 1095128
Status: REOPENED → RESOLVED
Closed: 11 years ago → 10 years ago
Resolution: --- → FIXED
Assignee: nobody → dtownsend+bugmail
status-firefox34: --- → fixed
status-firefox35: --- → fixed
status-firefox36: --- → fixed
status-firefox-esr31: --- → fixed
Target Milestone: mozilla32 → mozilla36
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: