Closed Bug 1000695 Opened 10 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: 10 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: 10 years ago → 10 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: 10 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: