717904 - Add-ons Manager is broken after installing an extension with browser restart

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: General, defect, P1)

Description

[Wladimir Palant]

Steps to reproduce:

* Install an extension requiring a browser restart, e.g. https://adblockplus.org/devbuilds/adblockplus/adblockplus-2.0.4a.3399.xpi
* Restart the browser (manually, because of bug 704406)

Expected results:

Installed extension is listed in the Add-ons Manager and functions correctly.

Actual results:

Installed extension is active but not listed in the Add-ons Manager. Also, some other extensions are missing in the list as well (and inactive). It looks like Add-ons Manager initialization was interrupted while it was loading add-ons. Restarting the browser "fixes" the issue.

Some unusual errors have been logged to the console:

> E/GeckoConsole( 8201): [JavaScript Warning: "Duplicate resource declaration for 'services-sync' ignored." {file: "jar:jar:file:///data/app/org.mozilla.fennec_aurora-1.apk!/omni.ja!/components/components.manifest" line: 168}]
> E/GeckoConsole( 8201): [JavaScript Warning: "Duplicate resource declaration for 'services-crypto' ignored." {file: "jar:jar:file:///data/app/org.mozilla.fennec_aurora-1.apk!/omni.ja!/components/components.manifest" line: 169}]
> E/GeckoConsole( 8201): [JavaScript Warning: "Duplicate resource declaration for 'gre-resources' ignored." {file: "jar:jar:file:///data/app/org.mozilla.fennec_aurora-1.apk!/omni.ja!/chrome/nonlocalized.manifest" line: 11}]
> E/GeckoConsole( 8201): [JavaScript Warning: "WARN addons.manager: InstallListener threw exception when calling onInstallEnded: ReferenceError: AddonManager is not defined" {file: "chrome://browser/content/browser.js" line: 2721}]
> E/GeckoConsole( 8326): [JavaScript Error: "ERROR addons.xpi: Failed to open database (1st attempt): [Exception... "Component returned failure code: 0x80570016 (NS_ERROR_XPC_GS_RETURNED_FAILURE) [nsIJSCID.getService]"  nsresult: "0x80570016 (NS_ERROR_XPC_GS_RETURNED_FAILURE)"  location: "JS frame :: resource://gre/modules/XPCOMUtils.jsm :: XPCU_serviceLambda :: line 232"  data: no]" {file: "resource://gre/modules/XPCOMUtils.jsm" line: 232}]
> E/GeckoConsole( 8326): [JavaScript Error: "ERROR addons.xpi: Failed to open database (2nd attempt): TypeError: Services.storage is undefined" {file: "resource://gre/modules/XPIProvider.jsm" line: 4228}]
> E/GeckoConsole( 8326): [JavaScript Error: "ERROR addons.xpi: Error during startup file checks, rolling back any database changes: TypeError: Services.storage is undefined" {file: "resource://gre/modules/XPIProvider.jsm" line: 4236}]
> E/GeckoConsole( 8326): [JavaScript Error: "ERROR addons.xpi: Error creating statement rollbackSavepoint (ROLLBACK TO SAVEPOINT 'default')" {file: "resource://gre/modules/XPIProvider.jsm" line: 4591}]
> E/GeckoConsole( 8326): [JavaScript Error: "ERROR addons.manager: Exception calling provider startup: TypeError: this.connection is undefined" {file: "resource://gre/modules/XPIProvider.jsm" line: 4588}]

The log is from an Aurora nightly (11.0a2 build 20120112) but I have the same problem in a trunk nightly as well (12.0a1 build 20120112).

Comment 1

[Mark Finkle (:mfinkle) (use needinfo?)]

(In reply to Wladimir Palant from comment #0)

> * Restart the browser (manually, because of bug 704406)

> > E/GeckoConsole( 8201): [JavaScript Warning: "WARN addons.manager: InstallListener threw exception when calling onInstallEnded: ReferenceError: AddonManager is not defined" {file: "chrome://browser/content/browser.js" line: 2721}]

The missing restart doorhanger is from this error. The actual problem was an undeclared variable in the method: "buttons"

With that syntax error fixed, the restart doorhanger appears and will restart the app. Unfortunately, the other "ERROR adons.xpi" errors still exist on restart.

Comment 2

[Mark Finkle (:mfinkle) (use needinfo?)]

(In reply to Mark Finkle (:mfinkle) from comment #1)
> (In reply to Wladimir Palant from comment #0)
> 
> > * Restart the browser (manually, because of bug 704406)
> 
> > > E/GeckoConsole( 8201): [JavaScript Warning: "WARN addons.manager: InstallListener threw exception when calling onInstallEnded: ReferenceError: AddonManager is not defined" {file: "chrome://browser/content/browser.js" line: 2721}]
> 
> The missing restart doorhanger is from this error. The actual problem was an
> undeclared variable in the method: "buttons"
> 
> With that syntax error fixed, the restart doorhanger appears and will
> restart the app.

Filed bug 718257 with a fix

Comment 3

[Mark Finkle (:mfinkle) (use needinfo?)]

Dave, Blair - Any idea as to what Fennec is not doing correctly to get all the "ERROR addons.xip" errors? They happen during startup, after an add-on install restart.

Comment 4

[Dave Townsend [:mossop]]

These are pretty troubling:

> E/GeckoConsole( 8326): [JavaScript Error: "ERROR addons.xpi: Failed to open database (1st attempt): [Exception... "Component returned failure code: 0x80570016 (NS_ERROR_XPC_GS_RETURNED_FAILURE) [nsIJSCID.getService]"  nsresult: "0x80570016 (NS_ERROR_XPC_GS_RETURNED_FAILURE)"  location: "JS frame :: resource://gre/modules/XPCOMUtils.jsm :: XPCU_serviceLambda :: line 232"  data: no]" {file: "resource://gre/modules/XPCOMUtils.jsm" line: 232}]
> E/GeckoConsole( 8326): [JavaScript Error: "ERROR addons.xpi: Failed to open database (2nd attempt): TypeError: Services.storage is undefined" {file: "resource://gre/modules/XPIProvider.jsm" line: 4228}]
> E/GeckoConsole( 8326): [JavaScript Error: "ERROR addons.xpi: Error during startup file checks, rolling back any database changes: TypeError: Services.storage is undefined" {file: "resource://gre/modules/XPIProvider.jsm" line: 4236}]

It suggests that Services.storage is undefined, the first error is possibly the getService call for mozIStorageService failing or possibly something else but it suggests something very wrong in XPCOM land.

Comment 5

[Doug Turner (:dougt)]

this sounds like it may track 11.  mfinkle, does this effect all addons that require a restart?

Comment 6

[Brad Lassey [:blassey] (use needinfo?)]

tracking fennec 11, not desktop 11

Comment 8

[Mark Finkle (:mfinkle) (use needinfo?)]

Bug 721784 says this happens for XUL too. I asked for help in getting a regression range in the XUL version of Fennec.

Comment 9

[Kevin Brosnan [Ex-Mozilla]]

No, bug 721784 states that installing extensions in XUL Fennec then upgrading to Fennec Native results in the extensions being marked as disabled.

Comment 10

[Matt Brubeck (:mbrubeck)]

In addition to the above errors, I get:

E/GeckoConsole(23232): [JavaScript Error: "ERROR addons.xpi: Failed to remove database that could not be opened: [Exception... "Component returned failure code: 0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST) [nsILocalFile.remove]"  nsresult: "0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST)"  location: "JS frame :: resource://gre/modules/XPIProvider.jsm :: XPIDB_openDatabaseFile :: line 4222"  data: no]" {file: "resource://gre/modules/XPIProvider.jsm" line: 4222}]

Comment 11

[Matt Brubeck (:mbrubeck)]

and the first time I try to download an add-on, I get:

E/GeckoConsole(23542): [JavaScript Warning: "WARN addons.xpi: Download failed: TypeError: this.connection is undefined" {file: "resource://gre/modules/AddonRepository.jsm" line: 1551}]

Comment 12

[Matt Brubeck (:mbrubeck)]

I don't see these errors in a clean (empty profile) installation of native Fennec, but I do see them after following these steps:

1. Install XUL Fennec.
2. Install at least one add-on.
3. Quit XUL Fennec.
4. Install Native Fennec.
5. Error messages appear at startup and when installing an add-on.

I can reproduce the errors only during the first run of Native Fennec after upgrading from XUL Fennec.  If I quit and restart Native Fennec, the errors do not occur.

Comment 14

[Matt Brubeck (:mbrubeck)]

I'm bisecting nightlies to narrow down a regression range.

Comment 15

[Dave Townsend [:mossop]]

It might be useful to just debug into the C++ for the getService call for Services.storage and see why it is failing.

Comment 16

[Matt Brubeck (:mbrubeck)]

The last good nightly is http://ftp.mozilla.org/pub/mozilla.org/mobile/nightly/2011/12/2011-12-19-03-12-09-mozilla-central-android-xul/fennec-11.0a1.multi.android-arm.apk

The first bad nightly is http://ftp.mozilla.org/pub/mozilla.org/mobile/nightly/2011/12/2011-12-20-11-28-24-mozilla-central-android-xul/fennec-12.0a1.multi.android-arm.txt

The regression range is:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=d75ebb37080e&tochange=f890732ebaa3

Possibly a regression from add-on sync (bug 534956 and related bugs)?

Comment 17

[Matt Brubeck (:mbrubeck)]

(In reply to Dave Townsend (:Mossop) from comment #15)
> It might be useful to just debug into the C++ for the getService call for
> Services.storage and see why it is failing.

This line in mozilla::storage::Service::initialize:
http://hg.mozilla.org/mozilla-central/file/13b571bde26a/storage/src/mozStorageService.cpp#l634

> rc = ::sqlite3_quota_initialize("telemetry-vfs", 0);

is returning a result code of 21 (SQLITE_MISUSE: "Library used incorrectly").

Comment 18

[Matt Brubeck (:mbrubeck)]

Actually, now it appears to be this line causing the error:
http://mxr.mozilla.org/mozilla-central/source/storage/src/mozStorageService.cpp#614

> rc = ::sqlite3_config(SQLITE_CONFIG_MALLOC, &memMethods);

(Maybe I was just confused before, or maybe it was because I was running an opt build before and the code got shuffled around a bit.)

What I know so far is that this happens because sqlite3_initialize is called earlier in startup by sqlite3_mprintf, which is called here during NSS initialization:
http://mxr.mozilla.org/mozilla-central/source/security/nss/lib/softoken/sdb.c#367

Then mozilla::storage::Service::initialize calls sqlite3_config, which returns SQLITE_MISUSE if it is called *after* sqlite3_initialize.

Comment 19

[Aaron Train [:aaronmt]]

@Akeybl - This bug is in 11.0b4; bug 729954 as a duplicate of this. This is a major loss of functionality for those using add-ons, at least in XUL, they will not install properly.

Comment 20

[Aaron Train [:aaronmt]]

STR on XUL:

1) Install 11.0b4 build candidate
2) Install Ad-block Plus
3) Restart

Notice no Ad-Block Plus listed after re-start in installed add-ons; can't install any other-addons.

Comment 21

[Alex Keybl [:akeybl]]

(In reply to Aaron Train [:aaronmt] from comment #19)
> @Akeybl - This bug is in 11.0b4; bug 729954 as a duplicate of this. This is
> a major loss of functionality for those using add-ons, at least in XUL, they
> will not install properly.

Given that, tracking for FF11. This should not block sign-off for Fennec Beta 4, however, since it's not a regression from b3.

Once we've driven to resolution, please nominate for Aurora/Beta uplift to resolve both the XUL and Native cases.

Comment 22

[Matt Brubeck (:mbrubeck)]

The first bad revision is:

http://hg.mozilla.org/mozilla-central/rev/91881c0cf3f3
Gregory Szorc <[e-mail]>
Bug 704973 - syncGUID defined earlier, not always call to database; r=Mossop

This patch makes XPIProvider.jsm's loadManifestFromRDF function create an nsIRandomNumberGenerator, which I am guessing causes NSS to be initialized earlier, causing the problem described in comment 18.

Comment 23

[Matt Brubeck (:mbrubeck)]

Attachment: band-aid

This is not a proper fix, but it papers over the problem and is probably a good candidate to ship in Beta and Aurora.

I don't know yet what the real long-term fix should look like...

Comment 24

[Matt Brubeck (:mbrubeck)]

Filed bug 730495 for the long-term fix.

Comment 25

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Comment on attachment 600419 [details] [diff] [review]
band-aid

Review of attachment 600419 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/mozapps/extensions/XPIProvider.jsm
@@ +822,5 @@
>    }
>  
>    addon.applyBackgroundUpdates = AddonManager.AUTOUPDATE_DEFAULT;
>  
> +  // Load the storage service before NSS, to avoid a SQLite initialization error

Should explicitly mention nsIRandomGenerator here, as it's not obvious.

Comment 26

[Aaron Train [:aaronmt]]

Can this land on XUL-Beta prior to tagging preferably today or tomorrow?

Comment 27

[Matt Brubeck (:mbrubeck)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/9a3da4d27d13

Comment 28

[Matt Brubeck (:mbrubeck)]

Comment on attachment 600419 [details] [diff] [review]
band-aid

[Approval Request Comment]
Regression caused by (bug #): bug 704973

User impact if declined: Add-on installation for non-bootstrapped extensions is broken in XUL Fennec, and various add-on operations fail silently after installing an add-on.

Testing completed (on m-c, etc.): Landed on inbound 2/27.

Risk to taking this patch (and alternatives if risky): Very low-risk one-line patch that just changes the order that some code runs during startup.

String changes made by this patch: None.

Comment 29

[Matt Brubeck (:mbrubeck)]

https://hg.mozilla.org/mozilla-central/rev/9a3da4d27d13

Comment 30

[Alex Keybl [:akeybl]]

Comment on attachment 600419 [details] [diff] [review]
band-aid

[Triage Comment]
When suggesting we nominate for Beta, I didn't realize that this would require a change in shared code. Given the fact that we're not shipping XUL Fennec 11 and FF12 will soon be on Beta, approving for Aurora 12 only.

Comment 31

[Matt Brubeck (:mbrubeck)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/8e997efa140b

Comment 32

[Aaron Train [:aaronmt]]

Verified fixed in XUL Android Mobile 12.0b1 (build #2) (20120314194604)

Comment 33

[Cristian Nicolae (:xti)]

Verified fixed on:

Firefox 15.0a1 (2012-04-30)
Firefox 14.0a2 (2012-04-30)

Device: Samsung Captivate
OS: Android 2.2