1072768 - Failure to install addon: "TypeError: this.installs is null"

Status: RESOLVED INACTIVE

(Toolkit :: Add-ons Manager, defect)

Description

[Andrei Eftimie]

We've recently been seeing failures in mozmill tests in installing addons. 

Here are some relevant part of the logs. Looks like a possible race condition.

Failure to install:
> 06:19:23 1411564581061  addons.xpi  WARN  Failed to install /Users/mozauto/Library/Caches/TemporaryItems/tmp-x3n.xpi from ftp://ftp.mozqa.com/data/firefox/addons/extensions/empty.xpi: [Exception... "AddonManager is not initialized"  nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame :: resource://gre/modules/AddonManager.jsm :: AMI_callInstallListeners :: line 1399"  data: no] Stack trace: AMI_callInstallListeners()@resource://gre/modules/AddonManager.jsm:1399 < AMP_callInstallListeners()@resource://gre/modules/AddonManager.jsm:2358 < AI_startInstall/<()@resource://gre/modules/addons/XPIProvider.jsm:5588 < TaskImpl_run()@resource://gre/modules/Task.jsm:330 < Handler.prototype.process()@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:866 < this.PromiseWalker.walkerLoop()@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:745 < Spinner.prototype.observe()@resource://gre/modules/AsyncShutdown.jsm:347 < <file:unknown>
> 06:19:23 *************************
> 06:19:23 A coding exception was thrown in a Promise rejection callback.
> 06:19:23 See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise
> 06:19:23 
> 06:19:23 Full message: TypeError: this.installs is null
> 06:19:23 Full stack: XPI_removeActiveInstall@resource://gre/modules/addons/XPIProvider.jsm:3656:9
> 06:19:23 AI_startInstall/<@resource://gre/modules/addons/XPIProvider.jsm:5694:7
> 06:19:23 Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:869:21
> 06:19:23 this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:745:7
> 06:19:23 Spinner.prototype.observe@resource://gre/modules/AsyncShutdown.jsm:347:9
> 06:19:23 
> 06:19:23 *************************

Here's a sample report where this happened (this doesn't have any additional information):
http://mozmill-release.blargon7.com/#/remote/report/bfd52839a01858de2f33d25f769a685f

This has a pretty low reproduce rate. We're seeing it more lately because we've dramatically increased the number of builds we test, I don't think the reproducibility rate has changed at all:
http://mozmill-release.blargon7.com/#/remote/failure?app=Firefox&branch=All&platform=All&from=2014-09-01&test=%2FrestartTests%2FtestAddons_installFromFTP%2Ftest2.js&func=testAddonInstalled

We don't have any reliable way of reproducing the failure.

====

Simplified version of what the test is doing:
0) set prefs - security.dialog_enable_delay: 1000
1) visit ftp://ftp.mozqa.com/data/firefox/addons/extensions/empty.xpi
2) click on `Install Now`
3) restart Firefox
4) check that the installed addon is present in about:addons
The failure occurs before the restart (3).

Looking again at the failure is it possible the restart is triggered _before_ the addon install promise manages to resolve?

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1] (away from Feb 12th - Feb 22nd)]

Blair, do you have an idea why the list of addons to be installed can be null?

Comment 2

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Redirecting to Irving, since it's possibly his recent work has affected this.

Comment 3

[:Irving Reid (No longer working on Firefox)]

I haven't worked with the Mozmill suite, and I can't make sense of what http://hg.mozilla.org/qa/mozmill-tests/file/bcd7ff416375c33ff85ea07d047b9cc4e40efeac/firefox/tests/remote/restartTests/testAddons_installFromFTP/test2.js is doing (if that's even the test that's failing). Can you point me at the lines of test code that execute the test steps you describe above?

At first glance, it does look like a Promise.then() is calling AI_startInstall() after the XPI provider is already shutting down. We don't have explicit checks to prevent that. I don't think we ever call startInstall directly from a promise resolution, so unless the JS stack is missing a few frames I don't know where that call is coming from.

Do you run the test harness with the 'extensions.logging.enabled' preference set to True? If not, please do; that will give us much detailed output on standard out to help diagnose.

Comment 4

[Andrei Eftimie]

We don't currently have `extensions.logging.enabled`, and since we're not able to reproduce this issue we can't properly test it. We could try enabling this pref and see when this happens again if we get more information. I'll need to check first how much of an impact this will have on our overall logs.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+1] (away from Feb 12th - Feb 22nd)]

If that problem is happening in a single test, I would propose to get the logging added for this particular test. Once investigation is done, we can remove it again.

Comment 6

[Ed Morley [:emorley]]

Removing keyword, since it's intended for test failures that are seen on Treeherder (and otherwise you'll end up with bugs being marked as worksforme if no occurrences are seen on Treeherder).

Comment 7

[BMO Automation]

Per policy at https://wiki.mozilla.org/Bug_Triage/Projects/Bug_Handling/Bug_Husbandry#Inactive_Bugs. If this bug is not an enhancement request or a bug not present in a supported release of Firefox, then it may be reopened.