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.

(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.

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.

If this fixes the orange on browser_hotfix.js we can copy the async patterns over to other intermittent tests.

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/ ?

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(...)

(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.

https://hg.mozilla.org/integration/fx-team/rev/fcf5abdf9706 https://hg.mozilla.org/integration/fx-team/rev/43306fac27e1

https://hg.mozilla.org/mozilla-central/rev/fcf5abdf9706 https://hg.mozilla.org/mozilla-central/rev/43306fac27e1

Backed out in https://hg.mozilla.org/integration/fx-team/rev/c7fc9fadd71e for the near permafail from bug 1006075.

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.

https://hg.mozilla.org/integration/fx-team/rev/73782d1e750c https://hg.mozilla.org/integration/fx-team/rev/1d9b6d754b9d

https://hg.mozilla.org/mozilla-central/rev/b08560c528dc https://hg.mozilla.org/mozilla-central/rev/0552c02f54b0

Literally on the push after this :(