Last Comment Bug 717904 - Add-ons Manager is broken after installing an extension with browser restart
: Add-ons Manager is broken after installing an extension with browser restart
Status: VERIFIED FIXED
: regression
Product: Firefox for Android
Classification: Client Software
Component: General (show other bugs)
: Trunk
: ARM Android
P1 major (vote)
: Firefox 13
Assigned To: Matt Brubeck (:mbrubeck)
:
: Sebastian Kaspari (:sebastian)
Mentors:
: 729954 (view as bug list)
Depends on: 730495
Blocks: abp aom 704973
  Show dependency treegraph
 
Reported: 2012-01-13 06:01 PST by Wladimir Palant
Modified: 2016-07-29 14:21 PDT (History)
16 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
unaffected
+
wontfix
verified
fixed
verified
verified
beta+
11+


Attachments
band-aid (1.09 KB, patch)
2012-02-24 09:50 PST, Matt Brubeck (:mbrubeck)
blair: review+
akeybl: approval‑mozilla‑aurora+
akeybl: approval‑mozilla‑beta-
Details | Diff | Splinter Review

Description User image Wladimir Palant 2012-01-13 06:01:48 PST
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 User image Mark Finkle (:mfinkle) (use needinfo?) 2012-01-14 21:13:48 PST
(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 User image Mark Finkle (:mfinkle) (use needinfo?) 2012-01-14 21:17:44 PST
(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 User image Mark Finkle (:mfinkle) (use needinfo?) 2012-01-15 08:54:53 PST
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 User image Dave Townsend [:mossop] 2012-01-15 10:24:12 PST
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 User image Doug Turner (:dougt) 2012-01-23 18:40:26 PST
this sounds like it may track 11.  mfinkle, does this effect all addons that require a restart?
Comment 6 User image Brad Lassey [:blassey] (use needinfo?) 2012-01-24 15:28:43 PST
tracking fennec 11, not desktop 11
Comment 7 User image Mark Finkle (:mfinkle) (use needinfo?) 2012-01-27 09:53:00 PST
*** Bug 721784 has been marked as a duplicate of this bug. ***
Comment 8 User image Mark Finkle (:mfinkle) (use needinfo?) 2012-01-27 09:53:58 PST
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 User image Kevin Brosnan [:kbrosnan] 2012-01-27 12:45:35 PST
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 User image Matt Brubeck (:mbrubeck) 2012-02-16 09:25:13 PST
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 User image Matt Brubeck (:mbrubeck) 2012-02-16 09:28:57 PST
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 User image Matt Brubeck (:mbrubeck) 2012-02-16 14:39:00 PST
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 13 User image Aaron Train [:aaronmt] 2012-02-23 10:05:52 PST
*** Bug 729954 has been marked as a duplicate of this bug. ***
Comment 14 User image Matt Brubeck (:mbrubeck) 2012-02-23 10:52:07 PST
I'm bisecting nightlies to narrow down a regression range.
Comment 15 User image Dave Townsend [:mossop] 2012-02-23 10:57:40 PST
It might be useful to just debug into the C++ for the getService call for Services.storage and see why it is failing.
Comment 17 User image Matt Brubeck (:mbrubeck) 2012-02-23 14:27:12 PST
(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 User image Matt Brubeck (:mbrubeck) 2012-02-23 16:12:42 PST
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 User image Aaron Train [:aaronmt] 2012-02-24 05:33:08 PST
@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 User image Aaron Train [:aaronmt] 2012-02-24 05:48:49 PST
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 User image Alex Keybl [:akeybl] 2012-02-24 08:50:34 PST
(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 User image Matt Brubeck (:mbrubeck) 2012-02-24 09:42:41 PST
The first bad revision is:

http://hg.mozilla.org/mozilla-central/rev/91881c0cf3f3
Gregory Szorc <gps@mozilla.com>
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 User image Matt Brubeck (:mbrubeck) 2012-02-24 09:50:26 PST
Created attachment 600419 [details] [diff] [review]
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 User image Matt Brubeck (:mbrubeck) 2012-02-24 16:26:01 PST
Filed bug 730495 for the long-term fix.
Comment 25 User image Blair McBride [:Unfocused] (UNAVAILABLE) 2012-02-27 16:26:44 PST
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 User image Aaron Train [:aaronmt] 2012-02-28 06:11:13 PST
Can this land on XUL-Beta prior to tagging preferably today or tomorrow?
Comment 28 User image Matt Brubeck (:mbrubeck) 2012-02-28 09:18:05 PST
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 User image Matt Brubeck (:mbrubeck) 2012-02-28 09:56:03 PST
https://hg.mozilla.org/mozilla-central/rev/9a3da4d27d13
Comment 30 User image Alex Keybl [:akeybl] 2012-02-28 13:19:26 PST
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 User image Matt Brubeck (:mbrubeck) 2012-02-28 13:26:11 PST
https://hg.mozilla.org/releases/mozilla-aurora/rev/8e997efa140b
Comment 32 User image Aaron Train [:aaronmt] 2012-03-16 08:35:56 PDT
Verified fixed in XUL Android Mobile 12.0b1 (build #2) (20120314194604)
Comment 33 User image Cristian Nicolae (:xti) 2012-04-30 08:21:06 PDT
Verified fixed on:

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

Device: Samsung Captivate
OS: Android 2.2

Note You need to log in before you can comment on or make changes to this bug.