Closed Bug 1570690 Opened 4 months ago Closed 4 months ago

System addons (`features/` directory) extraction races Gecko/XPIProvider startup in Fennec

Categories

(Firefox for Android :: Profile Handling, defect, P1)

defect

Tracking

()

VERIFIED FIXED
Firefox 70
Tracking Status
firefox-esr60 --- wontfix
firefox-esr68 69+ verified
firefox68 --- wontfix
firefox69 --- verified
firefox70 --- verified

People

(Reporter: denschub, Assigned: nalexander)

References

(Blocks 1 open bug, Regression)

Details

(Keywords: regression, Whiteboard: [fennec68.1])

Attachments

(1 file, 1 obsolete file)

On Fennec (affecting both Release and Nightly builds from the Play store, as well as self-built versions), system addons to not work reliably.

In non-release and non-esr-builds, there should be two system addons: webcompat@mozilla.org and webcompat-reporter@mozilla.org. On release builds, only webcompat@mozilla.org is expected to be there. The presence of the repoter can be tested by accessing a website and checking if there is a "Report site issue..." menu item in the hamburger menu, the presence of the other addon can be verified by trying to load about:compat.

None of them appear to be working reliably at the moment. We see a couple of errors that might be indications:

08-01 09:34:04.547 10851 10869 I Gecko   : 1564677244544    addons.xpi    WARN    List of valid built-in add-ons could not be parsed.: [Exception... "Component returned failure code: 0x80520012 (NS_ERROR_FILE_NOT_FOUND) [nsIXPCComponents_Utils.readUTF8URI]"  nsresult: "0x80520012 (NS_ERROR_FILE_NOT_FOUND)"  location: "JS frame :: resource://gre/modules/addons/XPIProvider.jsm :: startup :: line 2243"  data: no] Stack trace: startup()@resource://gre/modules/addons/XPIProvider.jsm:2243
08-01 09:34:04.547 10851 10869 I Gecko   : callProvider()@resource://gre/modules/AddonManager.jsm:193
08-01 09:34:04.547 10851 10869 I Gecko   : _startProvider()@resource://gre/modules/AddonManager.jsm:568
08-01 09:34:04.547 10851 10869 I Gecko   : startup()@resource://gre/modules/AddonManager.jsm:723
08-01 09:34:04.547 10851 10869 I Gecko   : startup()@resource://gre/modules/AddonManager.jsm:2731
08-01 09:34:04.547 10851 10869 I Gecko   : observe()@resource://gre/modules/addonManager.js:65
08-01 09:34:04.550 10851 10869 I Gecko   : 1564677244550    addons.xpi    WARN    No list of valid system add-ons found.

as well as

1564673563627	addons.xpi	WARN	Can't get modified time of /data/user/0/org.mozilla.fennec_denschub/features/webcompat-reporter@mozilla.org
1564673563630	addons.xpi	WARN	Can't get modified time of /data/user/0/org.mozilla.fennec_denschub/features/webcompat@mozilla.org
1564673563728	addons.xpi-utils	WARN	addMetadata: Add-on webcompat-reporter@mozilla.org is invalid: [Exception... "Component returned failure code: 0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST) [nsIFile.isFile]"  nsresult: "0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST)"  location: "JS frame :: resource://gre/modules/addons/XPIInstall.jsm :: get :: line 202"  data: no] Stack trace: get()@resource://gre/modules/addons/XPIInstall.jsm:202
loadManifestFromFile()@resource://gre/modules/addons/XPIInstall.jsm:600
syncLoadManifestFromFile()@resource://gre/modules/addons/XPIInstall.jsm:614
addMetadata()@resource://gre/modules/addons/XPIDatabase.jsm:2408
processFileChanges()@resource://gre/modules/addons/XPIDatabase.jsm:2779
checkForChanges()@resource://gre/modules/addons/XPIProvider.jsm:2719
startup()@resource://gre/modules/addons/XPIProvider.jsm:2265
callProvider()@resource://gre/modules/AddonManager.jsm:200
_startProvider()@resource://gre/modules/AddonManager.jsm:651
startup()@resource://gre/modules/AddonManager.jsm:807
startup()@resource://gre/modules/AddonManager.jsm:2806
observe()@resource://gre/modules/addonManager.js:65
1564673563731	addons.xpi-utils	WARN	Could not uninstall invalid item from locked install location
1564673563732	addons.xpi-utils	WARN	addMetadata: Add-on webcompat@mozilla.org is invalid: [Exception... "Component returned failure code: 0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST) [nsIFile.isFile]"  nsresult: "0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST)"  location: "JS frame :: resource://gre/modules/addons/XPIInstall.jsm :: get :: line 202"  data: no] Stack trace: get()@resource://gre/modules/addons/XPIInstall.jsm:202
loadManifestFromFile()@resource://gre/modules/addons/XPIInstall.jsm:600
syncLoadManifestFromFile()@resource://gre/modules/addons/XPIInstall.jsm:614
addMetadata()@resource://gre/modules/addons/XPIDatabase.jsm:2408
processFileChanges()@resource://gre/modules/addons/XPIDatabase.jsm:2779
checkForChanges()@resource://gre/modules/addons/XPIProvider.jsm:2719
startup()@resource://gre/modules/addons/XPIProvider.jsm:2265
callProvider()@resource://gre/modules/AddonManager.jsm:200
_startProvider()@resource://gre/modules/AddonManager.jsm:651
startup()@resource://gre/modules/AddonManager.jsm:807
startup()@resource://gre/modules/AddonManager.jsm:2806
observe()@resource://gre/modules/addonManager.js:65
1564673563734	addons.xpi-utils	WARN	Could not uninstall invalid item from locked install location

Filing into our component, since we're the only system addons in Fennec, so it doesn't really matter...

ni? Nick as discussed on Zoom.

Flags: needinfo?(nalexander)
Priority: -- → P1

Ksenia has found what might be a regression range.

Last good: https://hg.mozilla.org/mozilla-central/rev/76bbedc1ec1ae367906390c01a8ca008d7944cac (tested with this apk)
First bad: https://hg.mozilla.org/mozilla-central/rev/4b635d928b2bd42890ffc97c55622072092351e9 (tested with this apk)

Which means one of the changes in this set might be the cause of those issues. I can reproduce that on my Pixel 2 - but both builds are working fine in the emulator.

Ksenia and I were both able to verify bug 1534451 as a possible cause in mozregression, running with

mozregression -n fennec --repo autoland --good 10571a393265c39d8b42627b2f0a3c0c2c79f842 --bad 9e68d485f7ccea5d8f065fb5f833858e71b4b04a

Given that you, Tom, had to force-enable telemetry on your local build to have it fail, this feels oddly related. Nick is digging into that.

(In reply to Dennis Schubert [:denschub] from comment #1)

ni? Nick as discussed on Zoom.

Here's what I think is happening:

The PostUpdateHandler at https://searchfox.org/mozilla-central/source/mobile/android/base/java/org/mozilla/gecko/BrowserApp.java#332 unpacks features/ in onStart. The new TelemetryActivationPingDelegate accesses the profile before that, in onCreate. This is almost certainly wrong (without reference to this bug) -- see the beautiful comments in TelemetryCorePingDelegate.java.

So all told, the new delegate tickles an existing condition such that it's a race, and the profile gets created before the features/ directory is unpacked. The XPI state is all set up, and only then is the features/ directory unpacked (and ignored).

While reading the code, I saw that the copyFeaturesFromAPK is async, on a background thread (and there's no synchronization mechanism to ensure it's in place before anything reads it). That's almost certainly not right, because BrowserApp.onCreate gets the profile very early (see https://searchfox.org/mozilla-central/source/mobile/android/base/java/org/mozilla/gecko/BrowserApp.java#813) and the profile it gets might not "see" features/ at that point.

There are bunch of ways to address this. We can make the PostUpdateHandler do the work earlier. We can make the TelemetryActivationPingDelegate do its work later (I think this is better than what we have now for other reasons). Or we can teach the Profile to wait for the features/ unpack to be done.

Frankly, this whole thing is a race.

This is regressed by Bug 1534451, but it's a little cruel to pin it on that ticket, 'cuz the underlying issue was there all along.

Flags: needinfo?(nalexander)
Regressed by: 1534451

With the following patch, one can clearly see the issue:

diff --git a/mobile/android/base/java/org/mozilla/gecko/BrowserApp.java b/mobile/android/base/java/org/mozilla/gecko/BrowserApp.java
--- a/mobile/android/base/java/org/mozilla/gecko/BrowserApp.java
+++ b/mobile/android/base/java/org/mozilla/gecko/BrowserApp.java
@@ -331,7 +331,7 @@ public class BrowserApp extends GeckoApp
             new ReaderViewBookmarkPromotion(),
             new PostUpdateHandler(),
             mTelemetryCorePingDelegate,
-            mTelemetryActivationPingDelegate,
+            // mTelemetryActivationPingDelegate,
             new OfflineTabStatusDelegate(),
             new AdjustBrowserAppDelegate(mTelemetryCorePingDelegate)
     ));
diff --git a/mobile/android/base/java/org/mozilla/gecko/updater/PostUpdateHandler.java b/mobile/android/base/java/org/mozilla/gecko/updater/PostUpdateHandler.java
--- a/mobile/android/base/java/org/mozilla/gecko/updater/PostUpdateHandler.java
+++ b/mobile/android/base/java/org/mozilla/gecko/updater/PostUpdateHandler.java
@@ -29,7 +29,7 @@ import java.io.OutputStream;
  */
 public class PostUpdateHandler extends BrowserAppDelegateWithReference {
     private static final String LOGTAG = "GeckoPostUpdateHandler";
-    private static final boolean DEBUG = false;
+    private static final boolean DEBUG = true;
 
     @Override
     public void onStart(final BrowserApp browserApp) {
diff --git a/mobile/android/geckoview/src/main/java/org/mozilla/gecko/GeckoProfile.java b/mobile/android/geckoview/src/main/java/org/mozilla/gecko/GeckoProfile.java
--- a/mobile/android/geckoview/src/main/java/org/mozilla/gecko/GeckoProfile.java
+++ b/mobile/android/geckoview/src/main/java/org/mozilla/gecko/GeckoProfile.java
@@ -348,6 +348,8 @@ public final class GeckoProfile {
             throw new IllegalArgumentException("Unable to create GeckoProfile for empty profile name.");
         }
 
+        Log.w(LOGTAG, "GeckoPostUpdateHandler XXX First profile access!");
+
         mName = profileName;
         mMozillaDir = GeckoProfileDirectories.getMozillaDirectory(context);
 
diff --git a/toolkit/mozapps/extensions/internal/XPIProvider.jsm b/toolkit/mozapps/extensions/internal/XPIProvider.jsm
--- a/toolkit/mozapps/extensions/internal/XPIProvider.jsm
+++ b/toolkit/mozapps/extensions/internal/XPIProvider.jsm
@@ -188,6 +188,7 @@ const LOGGER_ID = "addons.xpi";
 // Create a new logger for use by all objects in this Addons XPI Provider module
 // (Requires AddonManager.jsm)
 var logger = Log.repository.getLogger(LOGGER_ID);
+logger.level = "All";
 
 XPCOMUtils.defineLazyGetter(this, "gStartupScanScopes", () => {
   let appBuildID = Services.appinfo.appBuildID;

That just bumps the logging (and avoids the new delegate, which doesn't actually matter). Then:

  1. adb shell pm clear org.mozilla.fennec_nalexander to start fresh
  2. adb logcat -c to clear logs
  3. ./mach run --no-install --app org.mozilla.fennec_nalexander --restart to start
  4. adb logcat -d | grep 'PostUpdate\|addons.xpi' to query logging

I observe a log like:

08-01 11:28:31.546 21092 21111 W GeckoProfile: GeckoPostUpdateHandler XXX First profile access!
08-01 11:28:31.830 21092 21117 I GeckoConsole: 1564684111830	addons.xpi	DEBUG	startup
08-01 11:28:31.831 21092 21117 I Gecko   : 1564684111830	addons.xpi	DEBUG	startup
08-01 11:28:31.832 21092 21117 I GeckoConsole: 1564684111832	addons.xpi	INFO	SystemAddonLocation directory is missing
08-01 11:28:31.833 21092 21117 I Gecko   : 1564684111832	addons.xpi	INFO	SystemAddonLocation directory is missing
08-01 11:28:31.848 21092 21117 I GeckoConsole: 1564684111848	addons.xpi	INFO	Removing all system add-on upgrades.
08-01 11:28:31.848 21092 21117 I Gecko   : 1564684111848	addons.xpi	INFO	Removing all system add-on upgrades.
08-01 11:28:31.850 21092 21117 I GeckoConsole: 1564684111850	addons.xpi	DEBUG	checkForChanges
08-01 11:28:31.850 21092 21117 I Gecko   : 1564684111850	addons.xpi	DEBUG	checkForChanges
08-01 11:28:31.850 21092 21117 I GeckoConsole: 1564684111850	addons.xpi	DEBUG	Loaded add-on state: ${}
08-01 11:28:31.850 21092 21117 I Gecko   : 1564684111850	addons.xpi	DEBUG	Loaded add-on state: ${}
08-01 11:28:31.851 21092 21117 I GeckoConsole: 1564684111851	addons.xpi	DEBUG	New add-on webcompat-reporter@mozilla.org in app-system-defaults
08-01 11:28:31.851 21092 21117 I Gecko   : 1564684111851	addons.xpi	DEBUG	New add-on webcompat-reporter@mozilla.org in app-system-defaults
08-01 11:28:31.852 21092 21117 I GeckoConsole: 1564684111852	addons.xpi	WARN	Can't get modified time of /data/user/0/org.mozilla.fennec_nalexander/features/webcompat-reporter@mozilla.org
08-01 11:28:31.852 21092 21117 I Gecko   : 1564684111852	addons.xpi	WARN	Can't get modified time of /data/user/0/org.mozilla.fennec_nalexander/features/webcompat-reporter@mozilla.org
08-01 11:28:31.853 21092 21117 I GeckoConsole: 1564684111853	addons.xpi	DEBUG	New add-on webcompat@mozilla.org in app-system-defaults
08-01 11:28:31.853 21092 21117 I Gecko   : 1564684111853	addons.xpi	DEBUG	New add-on webcompat@mozilla.org in app-system-defaults
08-01 11:28:31.853 21092 21117 I GeckoConsole: 1564684111853	addons.xpi	WARN	Can't get modified time of /data/user/0/org.mozilla.fennec_nalexander/features/webcompat@mozilla.org
08-01 11:28:31.853 21092 21117 I Gecko   : 1564684111853	addons.xpi	WARN	Can't get modified time of /data/user/0/org.mozilla.fennec_nalexander/features/webcompat@mozilla.org
08-01 11:28:31.854 21092 21117 I GeckoConsole: 1564684111854	addons.xpi	DEBUG	scanForChanges changed: true, state: {}
08-01 11:28:31.854 21092 21117 I Gecko   : 1564684111854	addons.xpi	DEBUG	scanForChanges changed: true, state: {}
08-01 11:28:31.940 21092 21117 I GeckoConsole: 1564684111938	addons.xpi-utils	WARN	addMetadata: Add-on webcompat-reporter@mozilla.org is invalid: [Exception... "Component returned failure code: 0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST) [nsIFile.isFile]"  nsresult: "0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST)"  location: "JS frame :: resource://gre/modules/addons/XPIInstall.jsm :: get :: line 235"  data: no] Stack trace: get()@resource://gre/modules/addons/XPIInstall.jsm:235
08-01 11:28:31.941 21092 21117 I Gecko   : 1564684111938	addons.xpi-utils	WARN	addMetadata: Add-on webcompat-reporter@mozilla.org is invalid: [Exception... "Component returned failure code: 0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST) [nsIFile.isFile]"  nsresult: "0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST)"  location: "JS frame :: resource://gre/modules/addons/XPIInstall.jsm :: get :: line 235"  data: no] Stack trace: get()@resource://gre/modules/addons/XPIInstall.jsm:235
08-01 11:28:31.942 21092 21117 I GeckoConsole: 1564684111942	addons.xpi-utils	WARN	Could not uninstall invalid item from locked install location
08-01 11:28:31.943 21092 21117 I Gecko   : 1564684111942	addons.xpi-utils	WARN	Could not uninstall invalid item from locked install location
08-01 11:28:31.944 21092 21117 I GeckoConsole: 1564684111943	addons.xpi-utils	WARN	addMetadata: Add-on webcompat@mozilla.org is invalid: [Exception... "Component returned failure code: 0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST) [nsIFile.isFile]"  nsresult: "0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST)"  location: "JS frame :: resource://gre/modules/addons/XPIInstall.jsm :: get :: line 235"  data: no] Stack trace: get()@resource://gre/modules/addons/XPIInstall.jsm:235
08-01 11:28:31.944 21092 21117 I Gecko   : 1564684111943	addons.xpi-utils	WARN	addMetadata: Add-on webcompat@mozilla.org is invalid: [Exception... "Component returned failure code: 0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST) [nsIFile.isFile]"  nsresult: "0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST)"  location: "JS frame :: resource://gre/modules/addons/XPIInstall.jsm :: get :: line 235"  data: no] Stack trace: get()@resource://gre/modules/addons/XPIInstall.jsm:235
08-01 11:28:31.944 21092 21117 I GeckoConsole: 1564684111944	addons.xpi-utils	WARN	Could not uninstall invalid item from locked install location
08-01 11:28:31.944 21092 21117 I Gecko   : 1564684111944	addons.xpi-utils	WARN	Could not uninstall invalid item from locked install location
08-01 11:28:32.097 21092 21111 D GeckoPostUpdateHandler: Build ID changed since last start: '20190801092607', 'null'
08-01 11:28:32.097 21092 21111 D GeckoPostUpdateHandler: Copying system add-ons from APK to dataDir
08-01 11:28:32.099 21092 21111 D GeckoPostUpdateHandler: Copying 'features/webcompat-reporter@mozilla.org.xpi' from APK to dataDir
08-01 11:28:32.099 21092 21111 D GeckoPostUpdateHandler: Creating /data/user/0/org.mozilla.fennec_nalexander/features
08-01 11:28:32.100 21092 21111 D GeckoPostUpdateHandler: Copying 'features/webcompat@mozilla.org.xpi' from APK to dataDir
08-01 11:28:32.768 21092 21117 I GeckoConsole: 1564684112768	addons.xpi	DEBUG	XPIStates adding add-on default-theme@mozilla.org in {"addons":{},"staged":{}}: null
08-01 11:28:32.768 21092 21117 I Gecko   : 1564684112768	addons.xpi	DEBUG	XPIStates adding add-on default-theme@mozilla.org in {"addons":{},"staged":{}}: null
08-01 11:28:32.769 21092 21117 I GeckoConsole: 1564684112769	addons.xpi	DEBUG	Updating XPIState for {"id":"default-theme@mozilla.org","syncGUID":"{093c230f-8a2b-4c90-8ce9-ba66046e2b51}","version":"1.0","type":"theme","loader":null,"updateURL":null,"optionsURL":null,"optionsType":null,"optionsBrowserStyle":true,"aboutURL":null,"defaultLocale":{"name":"Default","description":"A theme with the operating system color scheme.","creator":"Mozilla","developers":null,"translators":null,"contributors":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"installDate":1564684112767,"applyBackgroundUpdates":1,"path":null,"skinnable":false,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"toolkit@mozilla.org","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"seen":true,"dependencies":[],"userPermissions":null,"icons":{"32":"icon.svg"},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTel
08-01 11:28:32.769 21092 21117 I Gecko   : 1564684112769	addons.xpi	DEBUG	Updating XPIState for {"id":"default-theme@mozilla.org","syncGUID":"{093c230f-8a2b-4c90-8ce9-ba66046e2b51}","version":"1.0","type":"theme","loader":null,"updateURL":null,"optionsURL":null,"optionsType":null,"optionsBrowserStyle":true,"aboutURL":null,"defaultLocale":{"name":"Default","description":"A theme with the operating system color scheme.","creator":"Mozilla","developers":null,"translators":null,"contributors":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"installDate":1564684112767,"applyBackgroundUpdates":1,"path":null,"skinnable":false,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"toolkit@mozilla.org","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"seen":true,"dependencies":[],"userPermissions":null,"icons":{"32":"icon.svg"},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTel
08-01 11:28:32.770 21092 21117 I GeckoConsole: 1564684112770	addons.xpi	DEBUG	Loading bootstrap scope from resource://gre/modules/themes/default/
08-01 11:28:32.770 21092 21117 I Gecko   : 1564684112770	addons.xpi	DEBUG	Loading bootstrap scope from resource://gre/modules/themes/default/
08-01 11:28:32.770 21092 21117 I GeckoConsole: 1564684112770	addons.xpi	DEBUG	Calling bootstrap method install on default-theme@mozilla.org version 1.0
08-01 11:28:32.770 21092 21117 I Gecko   : 1564684112770	addons.xpi	DEBUG	Calling bootstrap method install on default-theme@mozilla.org version 1.0
08-01 11:28:32.771 21092 21117 I GeckoConsole: 1564684112771	addons.xpi	DEBUG	Calling bootstrap method startup on default-theme@mozilla.org version 1.0
08-01 11:28:32.771 21092 21117 I Gecko   : 1564684112771	addons.xpi	DEBUG	Calling bootstrap method startup on default-theme@mozilla.org version 1.0

which very clearly shows that the profile is created (on the Java side), then Gecko starts up and the XPIProvider fails to load features/, and then we try to unpack the features. No bueno.

I'll leave it to others to make the features/ extraction robust. Do we need to extract them from the APK at all? Would it work to look for them on disk and then fall back to the APK? Would that support out-of-band updates? Otherwise we should make extraction part of profile creation (again guarded by build ID or something else, so as to not ruin in-place updates).

Summary: System addons on Fennec do not work reliably → System addons (`features/` directory) extraction races Gecko/XPIProvider startup in Fennec

While we're at it, if it isn't too tough to change things so our addons load before session restore, that would also help. Right now the addons start too late, so ghag if the user has about:compat or a site needing an intervention in their session as they reload Fennec, the addons aren't available to power those things.

@ Dennis, is the Webcompat team responsible for fixing these system addon issues? Or is this a core Gecko issue?

We'll need to uplift Fennec fixes to mozilla-esr68. Fennec ESR 68 is the last major version of Fennec. Fennec Release is version 68.0. Fennec Nightly and Beta are pre-release builds of ESR 68.1 (September 3).

Flags: needinfo?(dschubert)
Whiteboard: [fennec68.1]

Dennis, is the Webcompat team responsible for fixing these system addon issues? Or is this a core Gecko issue?

As outlined by Nick's comments, this is an issue in the way Fennec builds profiles and unpacks the packaged XPIs. Other system addons would be affected as well - it just so happened that the only two system addons in Fennec are ours. So I don't think this is in our plate.

I would love to work on this, but quite frankly, I don't understand enough about Fennec internals to even consider working on this. As outlined in Comment 5, there are multiple possible solutions, and we'd need a decision on what to do first. However, even if we'd have a decision, I don't think the WebCompat team is able to handle this efficiently, so I'd appreciate if someone more experienced with Fennec could work on this.

Flags: needinfo?(dschubert)

I have been running into this bug and can confirm that nalexander's analysis is correct.

On first startup FF is trying to install the system extensions from a list that is generated at build time built_in_addons.json, that is referred to as the system.manifest in JS. However, the Java code that copies the XPIs from the APK onto the filesystem is not getting run until after the AddonManager.js starts up, it is in PostUpdateHandler.java. So when the AddonManager tries to install the XPIs they are not there and it fails. But the extensions are still added to the list of installed extensions but they are marked as disabled. Even if the AddonManager tries to install the XPIs again when they have been copied over, they were already marked as disabled so they will never get enabled.

I have a fix to run the PostUpdateHandler as soon as possible in BrowserApp, in onCreate instead of onStart. It is sort of a hack because the APKs are copied in a background thread so it is still not guaranteed to finish before the AddonManager is started.

https://github.com/censorship-no/gecko-dev/commit/2a043dbedbad8d385ebc5955c857c9c480471c08

I am surprised this wasn't reported before, I ran into this in May.

Blocks: 1564594

This seems high priority. Nick I'm not sure how much work there is here -- is this something you could whip up (perhaps a starter patch) or can you recommend someone?
NI+ cpeterson in case we have the right Softvision bandwidth.

Flags: needinfo?(nalexander)
Flags: needinfo?(cpeterson)

(In reply to David Bolter [:davidb] (NeedInfo me for attention) from comment #13)

This seems high priority. Nick I'm not sure how much work there is here -- is this something you could whip up (perhaps a starter patch) or can you recommend someone?
NI+ cpeterson in case we have the right Softvision bandwidth.

I think https://bugzilla.mozilla.org/show_bug.cgi?id=1570690#c12 is probably appropriate: we want certain parts of PostUpdateHandler to run in onCreate. As for the race that :rabbit correclty concludes still exists, I like CountdownLatch for such things. Here, we'd make the initial GeckoProfile.get() wait for the PostUpdateHandler to have completed. Note to self: only do this in the main process!

I can look at the first patch this Monday coming. Leaving the NI for that.

I noticed that I don't have a pref called extensions.systemAddon.update.enabled on any of my Fennec installs (release/beta). Could this be a reason why the SAO are not updating on Fennec?

We just confirmed that the absence of that pref is the reason why Fennec SAOs are not getting updated. MTaylor tested it on his Fennec

Flags: needinfo?(miket)

The pref is unrelated to this bug (which is about them starting up, not updated).

Flags: needinfo?(miket)

Right now, there are a lot of things that race to complete before
Gecko creates or first reads the profile. One of those things is
extracting system addons (the assets/features/ directory of the APK)
to disk, ready for the Gecko profile code to enumerate them.

Bug 1534451 added a non-trivial amount of background
computation during onCreate. This tickled the existing race
conditions such that system addon extraction frequently loses the
race, making system addons unreliable.

In addition, for reasons unknown, PostUpdateHandler did its work
during onStart. But the Gecko profile was created/first read
earlier, in onCreate. This widened the race window.

This commit pulls the update handler into onCreate, which is at
least early enough for it to have a chance of winning the race; and it
makes the work synchronous, which is the simplest way to ensure that
it is actually in place before Gecko startup (and profile
creation/first read). Since system addons are our "get out of jail"
card in many situations, the cost of extracting earlier seems like a
good trade-off. That is, I'm sure the early disk access will appear
in profiles, and it may even regress Raptor -- but it's a good
trade-off.

With my patches (about to be attached), I get a sensible log, like:

$ adb logcat -d | grep 'PostUpdate\|addons.xpi'
08-13 03:27:50.719  5860  5860 D GeckoPostUpdateHandler: Build ID changed since last start: '20190812115556', 'null'
08-13 03:27:50.719  5860  5860 D GeckoPostUpdateHandler: Copying system add-ons from APK to dataDir
08-13 03:27:50.720  5860  5877 W GeckoProfile: GeckoPostUpdateHandler XXX First profile access!
08-13 03:27:50.731  5860  5860 D GeckoPostUpdateHandler: Copying 'features/webcompat-reporter@mozilla.org.xpi' from APK to dataDir
08-13 03:27:50.732  5860  5860 D GeckoPostUpdateHandler: Creating /data/user/0/org.mozilla.fennec_nalexander/features
08-13 03:27:50.732  5860  5860 D GeckoPostUpdateHandler: Copying 'features/webcompat@mozilla.org.xpi' from APK to dataDir
08-13 03:27:51.566  5860  5883 I GeckoConsole: 1565663271566	addons.xpi	DEBUG	startup
08-13 03:27:51.566  5860  5883 I Gecko   : 1565663271566	addons.xpi	DEBUG	startup
08-13 03:27:51.575  5860  5883 I GeckoConsole: 1565663271575	addons.xpi	INFO	SystemAddonLocation directory is missing
08-13 03:27:51.577  5860  5883 I Gecko   : 1565663271575	addons.xpi	INFO	SystemAddonLocation directory is missing
08-13 03:27:51.599  5860  5883 I GeckoConsole: 1565663271599	addons.xpi	INFO	Removing all system add-on upgrades.
08-13 03:27:51.599  5860  5883 I Gecko   : 1565663271599	addons.xpi	INFO	Removing all system add-on upgrades.
08-13 03:27:51.601  5860  5883 I GeckoConsole: 1565663271601	addons.xpi	DEBUG	checkForChanges
08-13 03:27:51.601  5860  5883 I Gecko   : 1565663271601	addons.xpi	DEBUG	checkForChanges
08-13 03:27:51.602  5860  5883 I GeckoConsole: 1565663271602	addons.xpi	DEBUG	Loaded add-on state: ${}
08-13 03:27:51.602  5860  5883 I Gecko   : 1565663271602	addons.xpi	DEBUG	Loaded add-on state: ${}
08-13 03:27:51.604  5860  5883 I GeckoConsole: 1565663271603	addons.xpi	DEBUG	New add-on webcompat-reporter@mozilla.org in app-system-defaults
08-13 03:27:51.604  5860  5883 I Gecko   : 1565663271603	addons.xpi	DEBUG	New add-on webcompat-reporter@mozilla.org in app-system-defaults
08-13 03:27:51.604  5860  5883 I GeckoConsole: 1565663271604	addons.xpi	DEBUG	New add-on webcompat@mozilla.org in app-system-defaults
08-13 03:27:51.605  5860  5883 I Gecko   : 1565663271604	addons.xpi	DEBUG	New add-on webcompat@mozilla.org in app-system-defaults
08-13 03:27:51.605  5860  5883 I GeckoConsole: 1565663271605	addons.xpi	DEBUG	scanForChanges changed: true, state: {}
08-13 03:27:51.605  5860  5883 I Gecko   : 1565663271605	addons.xpi	DEBUG	scanForChanges changed: true, state: {}
08-13 03:27:52.216  5860  5883 I GeckoConsole: 1565663272216	addons.xpi	DEBUG	Loading bootstrap scope from jar:file:///data/user/0/org.mozilla.fennec_nalexander/features/webcompat-reporter@mozilla.org.xpi!/
08-13 03:27:52.216  5860  5883 I Gecko   : 1565663272216	addons.xpi	DEBUG	Loading bootstrap scope from jar:file:///data/user/0/org.mozilla.fennec_nalexander/features/webcompat-reporter@mozilla.org.xpi!/
08-13 03:27:52.216  5860  5883 I GeckoConsole: 1565663272216	addons.xpi	DEBUG	Calling bootstrap method install on webcompat-reporter@mozilla.org version 1.1.0
08-13 03:27:52.216  5860  5883 I Gecko   : 1565663272216	addons.xpi	DEBUG	Calling bootstrap method install on webcompat-reporter@mozilla.org version 1.1.0
...
Attachment #9084945 - Attachment is obsolete: true
Assignee: nobody → nalexander
Status: NEW → ASSIGNED
Component: Tooling & Investigations → Profile Handling
Product: Web Compatibility → Firefox for Android

[Tracking Requested - why for this release]: This blocks Bug 1564594, so we'll want to uplift this once it's landed.

Flags: needinfo?(cpeterson)
Pushed by nalexander@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/d374e582afbc
Synchronously extract system addons before Gecko startup in Fennec. r=VladBaicu,Grisha
Status: ASSIGNED → RESOLVED
Closed: 4 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 70

Please nominate this for Beta & ESR68 approval when you get a chance.

Flags: needinfo?(nalexander)

(In reply to Ryan VanderMeulen [:RyanVM] from comment #25)

Please nominate this for Beta & ESR68 approval when you get a chance.

Roger that.

Flags: needinfo?(nalexander)

Comment on attachment 9084944 [details]
Bug 1570690 - Synchronously extract system addons before Gecko startup in Fennec.

Beta/Release Uplift Approval Request

  • User impact if declined: An unknown proportion of our users will have no system addons at all on a fresh install. Those system addons are, at this time, the Webcompat reporting and mitigation addons. This ticket prevents us deploying additional system addons for targeted experiments, or -- in extremis -- deploying "get out of jail" hotfixes to Fennec.
  • Is this code covered by automated tests?: No
  • Has the fix been verified in Nightly?: No
  • Needs manual test from QE?: Yes
  • If yes, steps to reproduce: 1. install Fennec (org.mozilla.fennec_aurora)
  1. adb shell pm clear org.mozilla.fennec_aurora
  2. verify that "Report site issue" button appears in main (kebab) menu
  3. verify that system addons (webcompat related) are listed in addons list
  • List of other uplifts needed: None
  • Risk to taking this patch: Medium
  • Why is the change risky/not risky? (and alternatives if risky): This change reorders certain operations around profile initialization. That is always fraught; there's inherent risk here.

This change will put some I/O on the main thread. It's possible Android's strict mode has not been configured correctly in the patch, which would cause immediate crashes on release. (I think this very unlikely, but it's possible.). We'll regress performance on first start up and after-upgrade start ups; it's possible the regression is so large that some users will leave. (Again, I think this very unlikely.)

  • String changes made/needed:

ESR Uplift Approval Request

  • If this is not a sec:{high,crit} bug, please state case for ESR consideration: System addons are one "get out of jail card" Mozilla can play in certain extreme situations. If we can't trust them, we're denying ourselves that opportunity.
  • User impact if declined: An unknown proportion of our users will have no system addons at all on a fresh install. Those system addons are, at this time, the Webcompat reporting and mitigation addons.
  • Fix Landed on Version: 70
  • Risk to taking this patch: Medium
  • Why is the change risky/not risky? (and alternatives if risky): See above.
  • String or UUID changes made by this patch:
Attachment #9084944 - Flags: approval-mozilla-release?
Attachment #9084944 - Flags: approval-mozilla-esr68?
Attachment #9084944 - Flags: approval-mozilla-beta?

Comment on attachment 9084944 [details]
Bug 1570690 - Synchronously extract system addons before Gecko startup in Fennec.

Not needed on m-r, but approved for Fennec 68.1b7. Should be in tomorrow's Nightly builds too if QA wants to get a jump start on testing.

Attachment #9084944 - Flags: approval-mozilla-release?
Attachment #9084944 - Flags: approval-mozilla-release-
Attachment #9084944 - Flags: approval-mozilla-esr68?
Attachment #9084944 - Flags: approval-mozilla-esr68+
Attachment #9084944 - Flags: approval-mozilla-beta?
Attachment #9084944 - Flags: approval-mozilla-beta+
QA Whiteboard: [qa-triaged]

Hi, *verified as fixed on Fennec 68.1b7 using the following devices:
Samsung S9 (Android 8)
Samsung S7 (Android 7)
Samsung S5 (Android 6.0.1)

Hi,
verified as fixed on Firefox Nightly 70.0a1 (2019-08-20) using:

  • Samsung Galaxy S6 (Android 6.0.1)
  • Samsung Galaxy S9 (Android 8.0.0)
  • Sony Xperia Z5 (Android 7.0)
  • Google Pixel 3a XL (Android 9)

verified as fixed on Firefox Beta 690b16 using:

  • Samsung Galaxy S6 (Android 6.0.1)
  • Samsung Galaxy S9 (Android 8.0.0)
  • Sony Xperia Z5 (Android 7.0)
  • Google Pixel 3a XL (Android 9)

I will remove the qa-verify status and set the ticket as VERIFIED.

Status: RESOLVED → VERIFIED
Flags: qe-verify+
Regressions: 1577137
QA Whiteboard: [qa-triaged]
You need to log in before you can comment on or make changes to this bug.