System addons (`features/` directory) extraction races Gecko/XPIProvider startup in Fennec
Categories
(Firefox for Android Graveyard :: Profile Handling, defect, P1)
Tracking
(firefox-esr60 wontfix, firefox-esr6869+ verified, firefox68 wontfix, firefox69 verified, firefox70 verified)
People
(Reporter: denschub, Assigned: nalexander)
References
(Regression)
Details
(Keywords: regression, Whiteboard: [fennec68.1])
Attachments
(1 file, 1 obsolete file)
|
47 bytes,
text/x-phabricator-request
|
RyanVM
:
approval-mozilla-beta+
RyanVM
:
approval-mozilla-release-
RyanVM
:
approval-mozilla-esr68+
|
Details | Review |
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...
|
Reporter | |
Updated•6 years ago
|
|
|
Reporter | |
Comment 2•6 years ago
|
||
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.
| Comment hidden (obsolete) |
|
|
Reporter | |
Comment 4•6 years ago
|
||
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.
|
Assignee | |
Comment 5•6 years ago
|
||
(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.
|
|
Assignee | |
Comment 6•6 years ago
|
||
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.
|
||
Updated•6 years ago
|
|
|
Assignee | |
Comment 7•6 years ago
|
||
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:
adb shell pm clear org.mozilla.fennec_nalexanderto start freshadb logcat -cto clear logs./mach run --no-install --app org.mozilla.fennec_nalexander --restartto startadb 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.
|
|
Assignee | |
Comment 8•6 years ago
|
||
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).
|
|
Assignee | |
Updated•6 years ago
|
|
||
Comment 9•6 years ago
|
||
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.
|
||
Comment 10•6 years ago
|
||
@ 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).
|
|
Reporter | |
Comment 11•6 years ago
|
||
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.
|
||
Comment 12•6 years ago
|
||
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.
|
||
Comment 13•6 years ago
|
||
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.
|
|
Assignee | |
Comment 14•6 years ago
|
||
(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
|
||
Comment 17•6 years ago
|
||
The pref is unrelated to this bug (which is about them starting up, not updated).
|
|
Assignee | |
Comment 18•6 years ago
|
||
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.
|
|
Assignee | |
Comment 19•6 years ago
|
||
Depends on D41687
|
|
Assignee | |
Comment 20•6 years ago
|
||
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
...
|
||
Updated•6 years ago
|
|
|
Assignee | |
Comment 21•6 years ago
|
||
Try build percolating at:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=967f71441d8efefd2fc9f2aad348d2b4e3cd4429
|
|
Assignee | |
Updated•6 years ago
|
|
|
Assignee | |
Updated•6 years ago
|
|
||
Updated•6 years ago
|
|
|
||
Comment 22•6 years ago
|
||
[Tracking Requested - why for this release]: This blocks Bug 1564594, so we'll want to uplift this once it's landed.
|
|
||
Updated•6 years ago
|
|
||
Comment 23•6 years ago
|
||
|
|
||
Comment 24•6 years ago
|
||
| bugherder | ||
|
||
Updated•6 years ago
|
|
|
||
Comment 25•6 years ago
|
||
Please nominate this for Beta & ESR68 approval when you get a chance.
|
|
Assignee | |
Comment 26•6 years ago
|
||
(In reply to Ryan VanderMeulen [:RyanVM] from comment #25)
Please nominate this for Beta & ESR68 approval when you get a chance.
Roger that.
|
|
Assignee | |
Comment 27•6 years ago
|
||
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)
adb shell pm clear org.mozilla.fennec_aurora- verify that "Report site issue" button appears in main (kebab) menu
- 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:
|
|
Assignee | |
Updated•6 years ago
|
|
|
||
Comment 28•6 years ago
|
||
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.
|
|
||
Comment 29•6 years ago
|
||
| bugherder uplift | ||
|
|
||
Comment 30•6 years ago
|
||
| bugherder uplift | ||
|
||
Updated•6 years ago
|
|
||
Comment 31•6 years ago
|
||
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)
|
||
Comment 32•6 years ago
|
||
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.
|
||
Updated•6 years ago
|
|
|
||
Updated•5 years ago
|
Description
•