1543880 - chrome.storage.local is not ready on startup causing extension corruption/ infinite page loading

Status: RESOLVED WORKSFORME

(WebExtensions :: Storage, defect, P3)

Description

[gwarser]

Attachment: log.txt

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101 Firefox/68.0

Steps to reproduce:

Lot of people report on reddit r/uBlockOring and r/Firefox that first page after browser startup is never loading / can take several minutes to start loading.
Some of these issues were caused by uBlock Origin "locking" when reading settings from extension storage. Some of these people reported that they had browser.tabs.remote.autostart in about:config set to false and toggling it back helped.
Also in some cases helped forcing uBO to NOT use IndexedDB for it's cache storage (filter list content) but use only extension storage (by seting cacheStorageAPI to browser.storage.local in uBO Advanced Setings)

I was able to reproduce this issue only on Firefox stable, with uBlock Origin 1.18.16:

• clean profile

• set to restore session on startup

• set browser.tabs.remote.autostart to false

• open page in one tab, for ex. http://raymondhill.net/ublock/tiles1.html

• close browser and open again with -jsconsole parameter

• if no errors in console

• open uBO

• click on "I am an advanced user..." checkbox

• click the gears icon at the end of "I am an advanced user..." line

• chage suspendTabsUntilReady value from unset to false of foo

• switch to opened page and restart browser again

Actual results:

• page is blank, loading infinitely
• console shows "fetch is undefined", where fetch should be data returned from chrome.storage.local
• next error: Unchecked lastError value: Error: TransactionInactiveError: A request was placed against a transaction which is currently not active, or which is finished. start.js:369 onSelectedFilterListsReady moz-extension://***/js/start.js:369

This is the issue where above STR was found https://github.com/uBlockOrigin/uBlock-issues/issues/507

Latest uBO development version have workaround allowing to start uBO without locks, but only with default settings.

First signs of this issue probably appeared in this huge thread https://github.com/uBlockOrigin/uBlock-issues/issues/416 with:

uBlock Origin version: 1.18.4
Browser Name and version: Firefox Nightly - 28/01/2019 build
Operating System and version: WIndows 10, 64-bit.

I cannot use mozregression - issue does not manifest itself. Can be having something to do with disk speed - I have /tmp in RAM. Also in other issue with problems to restore backed up settings caused by clearing database by removing it instead of only clearing, I was able to reproduce only on slow spinning disk.

Few days ago reddit user reported this problem again https://old.reddit.com/r/uBlockOrigin/comments/ba6bxn/ublock_preventing_firefox_opening_sites_sometimes/
This time multiprocessing was enabled. Log shows that also other extension, probably Decentraleyes and one other (may be S3 Google Translator or other from this author) have problems reading storage (attached browser console output).

Few reddit threads where toggling browser.tabs.remote.autostart or cacheStorageAPI resolved the issue:

https://old.reddit.com/r/firefox/comments/b3lnw4/help_firefox_not_loading_pages_after_update_66/
https://old.reddit.com/r/uBlockOrigin/comments/b3tqo3/ubo_completely_blocks_all_web_browsing_on_firefox/
https://old.reddit.com/r/uBlockOrigin/comments/b4vbqt/after_a_few_days_ublock_origin_stops_loading/
https://old.reddit.com/r/firefox/comments/b5btpa/firefox_6601_dead_tab_problem/
https://old.reddit.com/r/firefox/comments/b3lnw4/help_firefox_not_loading_pages_after_update_66/
https://old.reddit.com/r/uBlockOrigin/comments/b6zc8a/firefox_only_loading_when_disableenabled/
https://old.reddit.com/r/firefox/comments/b7rpvx/not_loading_pages/

There also few issues where changing these settings does not help.

Comment 1

[Victor Carciu]

I used the steps described in description with User Agent Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101 Firefox/68.0 and ublock Origin 1.18.16 but I was not able to reproduce the behavior described at actual results.

Do you have any additional steps for this issue or maybe a video in order to see where I am doing something different?

Comment 2

[gwarser]

Sorry, but for some reason reproducing this is very difficult now. Only way I can reproduce is on my old laptop, in dirty profile on which this happened to me very first time, and only when startup is delayed by something (high memory or disko I/O).
It's very strange, because in the day when this finally happened to me, I was able to reproduce "just like that", without any effort.

I'm trying to reproduce this for few days now, without success. I tried different browser and uBO versions, different configurations, different about:config pseudo-tweaks, and nothing :(

Looking at database, it seems to be OK. All files are here.

Comment 3

[gwarser]

I came across something strange. I'm trying to reduce my only profile where I can reproduce, by removing as much as possible from it, copying to test profile, and then testing offline. Turns out, after removing features/ folder with Firefox Monitor package, issue does not occur.

So I retried again by modifying prefs.js app.normandy.startupRolloutPrefs.extensions.fxmonitor.enabled to false, and retried - no issue. Then in this "modified" profile, when I then switch extensions.fxmonitor.enabled to true and restart, issue manifests itself again.

Unfortunately I cannot say it's 100% fxmonitor - this may be just another delay in startup sequence triggering it.

Comment 4

[BugBot [:suhaib / :marco/ :calixte]]

The priority flag is not set for this bug.
:ddurst, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 5

[juraj.masiar]

Some users of my addon (GroupSpeedDial) are reporting this error: "TransactionInactiveError: A request was placed against a transaction which is currently not active, or which is finished.".
So far I've received 4 e-mails in last two weeks. All of them with the same behavior:

• error appears not consistently - sometimes it works, sometimes not
• it can happen only when browser starts
• it started only recently, like several weeks ago
• their storage engine seems to be OK based on this test: https://firefox-storage-test.glitch.me/

One of them also mentioned he has only single process "Content process limit", which is also mentioned by "uBlock" team in their reddit discussion for this bug:
https://www.reddit.com/r/uBlockOrigin/comments/ba6bxn/ublock_preventing_firefox_opening_sites_sometimes/

Comment 6

[gwarser]

Something very similar started happening to me on Fennec from F-droid 67.0.2 (and few previous versions). On first Fennec start after phone restart, pages will stuck in loading state (progress bar around 10%). Turning uBO off->on unlock this, but browser is in some broken state - not everything works.

This is browser console log from last time:

18:01:42.216 Webconsole context has changed
17:57:17.458 Could not read chrome manifest 'file:///data/user/0/org.mozilla.fennec_fdroid/chrome.manifest'.
17:57:21.274 OpenGL compositor Initialized Succesfully.
Version: OpenGL ES 3.0 V@139.0 AU@ (GIT@I389a668de0)
Vendor: Qualcomm
Renderer: Adreno (TM) 305
FBO Texture Target: TEXTURE_2D
17:57:22.736 browser.js: loading Firefox Accounts WebChannel
17:57:22.989 TypeError: aBrowser is null PrivateBrowsingUtils.jsm:73:21
17:57:24.435 Error: Initialization failed storage-mozStorage.js:193:13
17:57:24.436 NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS: [JavaScript Error: "Initialization failed" {file: "resource://gre/modules/storage-mozStorage.js" line: 193}]'[JavaScript Error: "Initialization failed" {file: "resource://gre/modules/storage-mozStorage.js" line: 193}]' when calling method: [nsILoginManagerStorage::initialize] LoginManager.jsm:101
17:57:24.436 NS_ERROR_XPC_GS_RETURNED_FAILURE: ServiceManager::GetService returned failure code: XPCOMUtils.jsm:215
17:57:25.208 IndexedDB UnknownErr: ActorsParent.cpp:19062 4
17:57:26.188 1560700646188	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Error processing browser_action.browser_style: Unsupported on Android.
17:57:26.190 1560700646189	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Error processing browser_action.default_icon: Unsupported on Android.
17:57:26.291 1560700646291	addons.webextension.{1b1e6108-2d88-4f0f-a338-01f9dbcccd6f}	WARN	Loading extension '{1b1e6108-2d88-4f0f-a338-01f9dbcccd6f}': Reading manifest: Error processing browser_action.browser_style: Unsupported on Android.
17:57:26.292 1560700646292	addons.webextension.{1b1e6108-2d88-4f0f-a338-01f9dbcccd6f}	WARN	Loading extension '{1b1e6108-2d88-4f0f-a338-01f9dbcccd6f}': Reading manifest: Error processing browser_action.default_icon: Unsupported on Android.
17:57:26.505 1560700646504	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Error processing permissions.0: Value "contextMenus" must either: must either [must either [be one of ["clipboardRead", "clipboardWrite", "geolocation", "idle", "notifications"], be one of ["browserSettings"], be one of ["cookies"], be one of ["downloads", "downloads.open"], be one of ["topSites"], be one of ["webNavigation"], be one of ["webRequest", "webRequestBlocking"], or be one of ["activeTab", "tabs"]], be one of ["alarms", "mozillaAddons", "storage", "unlimitedStorage"], be one of ["contextualIdentities"], be one of ["dns"], be one of ["management"], be one of ["privacy"], be one of ["proxy"], be one of ["nativeMessaging"], be one of ["telemetry"], be one of ["theme"], be one of ["browsingData"], or match the pattern /^experiments(\.\w+)+$/], or must either [be one of ["<all_urls>"], must either [match the pattern /^(https?|wss?|file|ftp|\*):\/\/(\*|\*\.[^*/]+|[^*/]+)\/.*$/, or match the pattern /^file:\/\/\/.*$/], or match the pattern /^resource:\/\/(\*|\*\.[^*/]+|[^*/]+)\/.*$|^about:/]
17:57:26.518 1560700646517	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Error processing browser_action.browser_style: Unsupported on Android.
17:57:26.519 1560700646519	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Error processing browser_action.default_icon: Unsupported on Android.
17:57:26.523 1560700646523	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Error processing commands: An unexpected property was found in the WebExtension manifest.
17:57:26.526 1560700646525	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Error processing sidebar_action: An unexpected property was found in the WebExtension manifest.
17:57:26.598 1560700646598	addons.webextension.{aecec67f-0d10-4fa7-b7c7-609a2db280cf}	WARN	Loading extension '{aecec67f-0d10-4fa7-b7c7-609a2db280cf}': Reading manifest: Error processing browser_action.browser_style: Unsupported on Android.
17:57:26.602 1560700646601	addons.webextension.{aecec67f-0d10-4fa7-b7c7-609a2db280cf}	WARN	Loading extension '{aecec67f-0d10-4fa7-b7c7-609a2db280cf}': Reading manifest: Error processing browser_action.default_icon: Unsupported on Android.
17:57:26.610 1560700646610	addons.webextension.{aecec67f-0d10-4fa7-b7c7-609a2db280cf}	WARN	Loading extension '{aecec67f-0d10-4fa7-b7c7-609a2db280cf}': Reading manifest: Error processing options_page: An unexpected property was found in the WebExtension manifest.
17:57:26.739 IndexedDB getLastModified() The operation failed for reasons unrelated to the database itself and not covered by any other error code. kinto-offline-client.js:568
17:57:30.191 IndexedDB UnknownErr: ActorsParent.cpp:19062
17:57:31.612 Error: Error: Failed to persist storage for principal: moz-extension://3267600f-58da-461a-84e9-baf71821e3be ExtensionUtils.jsm
17:57:32.325 Services.policies is undefined ext-storage.js:29
17:57:32.369 IndexedDB UnknownErr: ActorsParent.cpp:19062
17:57:32.504 Error: UnknownError: The operation failed for reasons unrelated to the database itself and not covered by any other error code. ExtensionUtils.jsm
17:57:32.504 Error: Error: Failed to persist storage for principal: moz-extension://9919752d-fc46-42a5-b128-81d78b25b36f ExtensionUtils.jsm
17:57:32.916 Error: listener not re-registered ExtensionCommon.jsm:2173:24
17:57:32.930 Unchecked lastError value: Error: Error: Failed to persist storage for principal: moz-extension://3267600f-58da-461a-84e9-baf71821e3be storage.js:100
17:57:32.955 Unchecked lastError value: Error: Error: Failed to persist storage for principal: moz-extension://3267600f-58da-461a-84e9-baf71821e3be storage.js:259
17:57:33.550 IndexedDB UnknownErr: ActorsParent.cpp:19062
17:57:33.691 UnknownError: The operation failed for reasons unrelated to the database itself and not covered by any other error code.
17:57:33.740 Error: Error: Failed to persist storage for principal: moz-extension://3267600f-58da-461a-84e9-baf71821e3be 2 ExtensionUtils.jsm
17:57:33.741 IndexedDB UnknownErr: ActorsParent.cpp:19062 2
17:57:33.912 listener not re-registered ExtensionCommon.jsm:2173
17:57:33.921 Error: listener not re-registered ExtensionCommon.jsm:2173:24
17:57:33.922 Error: UnknownError: The operation failed for reasons unrelated to the database itself and not covered by any other error code. ExtensionUtils.jsm
17:59:21.381 XML Parsing Error: no root element found
Location: data:text/plain,
Line Number 1, Column 1: data::1:1
17:59:21.388 1560700761387	addons.productaddons	ERROR	Request failed certificate checks: [Exception... "SSL is required and URI scheme is not https."  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: resource://gre/modules/CertUtils.jsm :: checkCert :: line 139"  data: no] Log.jsm:679
17:59:27.207 1560700767202	addons.manager	WARN	Error in background update: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getBoolPref]"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: resource://gre/modules/AddonManager.jsm :: systemUpdateEnabled :: line 1254"  data: no] Stack trace: systemUpdateEnabled()@resource://gre/modules/AddonManager.jsm:1254
backgroundUpdateCheck/buPromise<()@resource://gre/modules/AddonManager.jsm:1324
17:59:52.908 IndexedDB UnknownErr: ActorsParent.cpp:19062
17:59:52.909 IndexedDB getLastModified() The operation failed for reasons unrelated to the database itself and not covered by any other error code. kinto-offline-client.js:568
18:01:02.412 Sending message
18:01:10.043 Error while calling actor 'preference's method 'getBoolPref' Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getBoolPref]
18:01:10.046 getBoolPref@resource://devtools/server/actors/preference.js:27:27
handler@resource://devtools/shared/protocol.js:1189:37
onPacket@resource://devtools/server/main.js:1291:58
_onJSONObjectReady/<@resource://devtools/shared/transport/transport.js:451:20
exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:109:22
exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:109:22

18:01:13.899 Failed to load module resource://gre/modules/PlacesUtils.jsm. builtin-modules.js:184
18:01:36.921 The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol. data:<h1>Your addon does not have any document opened yet.
18:01:42.216 Webconsole context has changed

I also noticed bit different issue, but maybe related: sometimes (not that often like above issue) browser start and page loads without issues, but looks like cookies database is not accessible - I'm logged out of all webpages. Simply killing browser and start again fixes this, and I'm logged again.

Comment 7

[Viktor Jägersküpper]

I came across this bug and I hope to give some useful input. This is what I have found so far:

• it only occurs when I don't use the private browsing mode, which I always use by default, except that I have to turn it off for a major video streaming service
• it occurs very reliably
• deactivating "uBlock Origin" (uBO) resolves the bug, i.e. everything seems to work fine, activating it again triggers the bug
• after starting with -jsconsole, I see "TypeError: this.hostnameSlots is undefined" in "static-ext-filtering.js:533:13" of uBO (but I don't see this when I start in private browsing mode), activating uBO from the deactivated state again leads to this error
• I only see this bug with the profile for the release channel, not with the profile I use for Nightly and so far not on my laptop

I tried to bisect this bug with mozregression, which turned out to be quite painful because I had to check every revision manually. I used a copy of the profile for the release channel and got as far as I could by testing Nightlies:

Last good revision: f78d5947333422ab09ec23e3dab0d48538c9d6ad (2017-10-17 22:04:15)
First bad revision: a29052590fc6538b89641e690d11731ca8e78120 (2017-10-18 10:01:40)

(between the 57 and 58 releases)

Pushlog:
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=f78d5947333422ab09ec23e3dab0d48538c9d6ad&tochange=a29052590fc6538b89641e690d11731ca8e78120

I couldn't bisect any further because mozregression couldn't find the revisions between the above commits (probably already deleted because of age).

My profile was created in March 2018 (after a new OS installation). The problem with my bisection is of course that the profile is "downgraded" all the time, so I don't know how reliable my result is. However I decided to test releases 55, 56 and 57 (actually the Nightlies chosen by mozregression by giving the "--good <release number>" parameter) and they didn't have the bug.

Can someone please tell me how I can get the revisions (something such as mozilla-inbound or mozilla-autoland builds) between the above commits? I assume they are still stored somewhere. Alternatively someone can look at the pushlog and tell which commit(s) could be related. Then I could try to compile a few revisions, but I would have to set up a VM first with an appropriate build environment.

If my findings turn out to be unrelated to this particular bug, I will file another one. Or maybe it's really a bug in uBO, but I can't say that.

Comment 8

[Viktor Jägersküpper]

I found bug 1344936 which has a link to a Google Groups discussion, and from both I conclude that the builds of the revisions which I would like to download have been deleted because they are older than one year. So I think I have to bisect by compiling the revisions. This will however take some time and I can't promise results in the next weeks.

Comment 9

[[e-mail]]

activating uBO from the deactivated state again leads to this error

You could try to put a breakpoint in the constructor at line 495 of static-ext-filtering.js, this is where this.hostnameSlots is initialized, in one of two ways, you would find out in stepping through the code until constructor completion.

Comment 10

[Viktor Jägersküpper]

The bisection gave the following result: It's either changeset ef893bc5edeb8ec183419ed120662a62a52f8945 (building this one failed) or efe85265a82ad64e2e82128f245a6281222a9a28, they are two of the three changesets of bug 1404344.

As a side remark, I tested the release versions from 56 to 66 because these changesets were backported to the 57 beta/release branch, and this is what I saw:
56 - works for me
57 - affected
58 - works for me
59 - works for me
60 - couldn't test because of "no internet connection" (didn't investigate further)
61-68 - affected

However, with the 58 and 59 releases I got the following error in the console which I didn't get with the "affected" releases:

bad serialized structured data (invalid structured clone scope) (unknown)
InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable (in cachestorage.js:252)
(unfolded extra line:)
gotOne moz-extension://fca24e5f-e996-4dc8-a045-d2e8256f9855/js/cachestorage.js:252:22

cachestorage.js is part of uBO. This might be relevant because my profile was created shortly after the 59 release, and I have been using uBO since then. Unfortunately I don't remember if I installed uBO in private browsing mode or not. I haven't tried to find the changeset that makes the 58 and 59 releases work for me (possibly related to this error), so if you think it might help to find that changeset, tell me.

Comment 11

[Viktor Jägersküpper]

(In reply to [e-mail] from comment #9)

activating uBO from the deactivated state again leads to this error

You could try to put a breakpoint in the constructor at line 495 of static-ext-filtering.js, this is where this.hostnameSlots is initialized, in one of two ways, you would find out in stepping through the code until constructor completion.

Unfortunately I don't know what I should do here because I'm not a (JS) programmer, so please tell me in detail what I should do. Do I have to change the code of uBO or is it enough to do some simple steps in the console?

Comment 12

[Viktor Jägersküpper]

You could try to put a breakpoint in the constructor at line 495 of static-ext-filtering.js, this is where this.hostnameSlots is initialized, in one of two ways, you would find out in stepping through the code until constructor completion.

Unfortunately I don't know what I should do here because I'm not a (JS) programmer, so please tell me in detail what I should do. Do I have to change the code of uBO or is it enough to do some simple steps in the console?

I found that I can use about:debugging and how to put a breakpoint at a specific line. So I have the following more specific questions:

• is line 495 still correct (uBO got updated after you commented)?
• how do I "step through the code" (I guess by changing the position of the breakpoint)?

Comment 13

[gwarser]

10 people reporting similar issue in one Reddit thread (one minute delay before loading page on first Firefox start) - https://www.reddit.com/r/firefox/comments/dgip69/firefox_takes_about_a_minute_to_connect_after/

Comment 15

[Wayne Mery (:wsmwk)]

(In reply to gwarser from comment #13)

10 people reporting similar issue in one Reddit thread (one minute delay before loading page on first Firefox start) - https://www.reddit.com/r/firefox/comments/dgip69/firefox_takes_about_a_minute_to_connect_after/

Some of those reports may have been resolved by bug 1702600 in version 102/103.

So is this issue still seeing?

Comment 16

[Viktor Jägersküpper]

I have tested three different profiles and can't reproduce any more what I observed initially. Maybe the issue I observed was in fact a bug in uBlock Origin and was fixed a long time ago, but I never noticed.