Closed Bug 1624586 Opened 4 years ago Closed 7 months ago

storage.local failing on developer edition 75 beta 7

Categories

(WebExtensions :: Storage, defect, P3)

Product:
WebExtensions
Component:
Storage
Version:
75 Branch
Platform:
x86_64
Linux
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: jon, Unassigned)

References

(Blocks 1 open bug)

Details

Attachments

(2 files)

MOZ_LOG="IndexedDB:5:sync" execution log with broken profile
580.99 KB, text/plain
Details
Log output from a debug version of firefox on the broken profile
92.74 KB, text/plain
Details

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

Steps to reproduce:

Upgraded from Firefox Developer edition 75.0b6 to 75.0b7

Actual results:

Extensions that support Firefox Sync can no longer access their storage, or can only do so in limited ways. By inspecting the extensions through about:debugging#/runtime/this-firefox, both the failing extensions (uBlock Origin and Multi-Account Containers) have the same set of errors:

sendRemoveListener on closed conduit @testpilot-containers.1236950581256 ConduitsChild.jsm:108
    _send resource://gre/modules/ConduitsChild.jsm:108
    _send self-hosted:976
    removeListener resource://gre/modules/ExtensionChild.jsm:1138
    removeListener resource://gre/modules/ExtensionChild.jsm:1359
    onClicked chrome://browser/content/child/ext-menus.js:282
    removeListener resource://gre/modules/ExtensionCommon.jsm:2542
    revoke resource://gre/modules/ExtensionCommon.jsm:2564
    close resource://gre/modules/ExtensionCommon.jsm:2569
    unload resource://gre/modules/ExtensionCommon.jsm:910
    unload resource://gre/modules/ExtensionPageChild.jsm:261
    unload resource://gre/modules/ExtensionPageChild.jsm:310
    destroyExtensionContext resource://gre/modules/ExtensionPageChild.jsm:494
    observe resource://gre/modules/ExtensionPageChild.jsm:407
UnknownError: The operation failed for reasons unrelated to the database itself and not covered by any other error code. ExtensionStorageIDB.jsm:802
    normalizeStorageError resource://gre/modules/ExtensionStorageIDB.jsm:802
    method chrome://extensions/content/child/ext-storage.js:273
    AsyncFunctionThrow self-hosted:699
    (Async: async)
    callAsyncFunction resource://gre/modules/ExtensionCommon.jsm:1087
    callAsyncFunction resource://gre/modules/ExtensionChild.jsm:1194
    callAndLog resource://gre/modules/ExtensionChild.jsm:1170
    callAsyncFunction resource://gre/modules/ExtensionChild.jsm:1193
    stub resource://gre/modules/Schemas.jsm:2679
    getSyncEnabled moz-extension://35fe757d-ba36-4abd-b466-29faea178710/js/background/assignManager.js:50
    init moz-extension://35fe757d-ba36-4abd-b466-29faea178710/js/background/sync.js:202
    <anonymous> moz-extension://35fe757d-ba36-4abd-b466-29faea178710/js/background/sync.js:314
Error: An unexpected error occurred

The second and third error repeats over and over.

Expected results:

The upgrade should not have affected extension sync storage.

It looks like maybe local storage is broken? Running

localStorage.setItem('hello', 'world');

in the console on an arbitrary website gives me:

[Exception... "Unexpected error"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: debugger eval code :: <TOP_LEVEL> :: line 1"  data: no] debugger eval code:1:14
    <anonymous> debugger eval code:1

Which doesn't seem right?

Could this perhaps be related to https://bugzilla.mozilla.org/show_bug.cgi?id=1619948 ?

Bugbug thinks this bug should belong to this component, but please revert this change in case of error.

Component: Untriaged → Storage
Product: Firefox → WebExtensions

To add some additional information, if I create a new profile, local storage seems to work okay on websites. But if I install uBlock Origin in that new profile, its setting page shows "?" storage used.

In the broken profile, running

await navigator.storage.estimate()

gives

TypeError: Internal error while estimating storage usage

In the backtrace, the relevant call (for Multi-Account Containers) is here, which is really just:

await browser.storage.local.get("syncEnabled");

Which makes it seem like access to local storage has been corrupted somehow.

The error accessing storage also occurs when restarting in safe mode with add-ons disabled.

I've been trying an alternate profile (synced to the same account) for a while now, and that's working fine, which suggests something happened when migrating my main profile from beta6 to beta7. beta8 does not fix the issue.

I can also report that while:

await browser.storage.local.get()

errors

await browser.storage.sync.get()

does not.

OS: Unspecified → Linux
Hardware: Unspecified → x86_64
Summary: Extension sync storage failures after on developer edition 75 beta 7 → Local storage failing on developer edition 75 beta 7

This looks like it may be related to syncing too, since I discovered this error in weave/logs:

1585229773612	Sync.Engine.Extension-Storage	ERROR	Syncing @testpilot-containers: request failed: Error: HTTP 507 Insufficient Storage: Resource access is forbidden for this user (Collection maximum size exceeded (213283 > 204800 Bytes).)(resource://services-common/kinto-http-client.js:2771:5) JS Stack trace: ServerResponse@kinto-http-client.js:2771:5

Could it be that when sync fails to synchronize, it breaks local storage? See also this related report: https://github.com/mozilla/multi-account-containers/issues/1675#issuecomment-606698746

Did your weave/logs also get as full as mine was (17 GB)?

I apologize in advance for my wild guess but did you check if you have enough storage space on the disk your profile is stored? Any chance you're using -sync or -ramdisk scripts that could keep your main profile (but not the alternate profile) on a filesystem with too low space remaining?

If we had the same issue including the creation of way too many error logs in your main profile it could cause problems with Storage limits: https://developer.mozilla.org/en-US/docs/Web/API/IndexedDB_API/Browser_storage_limits_and_eviction_criteria#Storage_limits

I'm not sure if this is related or could actually break Local Storage but I guess it doesn't hurt bringing up.

(In reply to jon from comment #8)

This looks like it may be related to syncing too, since I discovered this error in weave/logs:

I suspect that's unrelated to this bug.

(In reply to aru from comment #9)

Did your weave/logs also get as full as mine was (17 GB)?

Ouch! That's insane - do you mind opening a new bug for that, CCing me? Sync is supposed to clean them up, so it will be good for us to know what's going wrong for you. Please include how many logs you have, what the earliest dated file is, and some rough analysis of the sizes (eg, most the same size, a small number of files with extreme sizes, etc?)

Thanks!

(In reply to aru from comment #9)

Did your weave/logs also get as full as mine was (17 GB)?

Ah, no, mine are just barely over the limit I think. I also have plenty of both disk and memory headroom.

Flags: needinfo?(lgreco)

I'd be happy to provide more info — what would help you debug this?

storage.sync shouldn't be related to the actual issue (based on the stack trace included in comment 0 and the fact that storage.sync uses its own backend and so in general it should be able to break storage.local or any other storage that depends by the QuotaManager, like IndexedDB and the LSNG, "NextGen LocalStorage").

On the contrary LSNG may be related to it, I recall that something similar happened before in Firefox 74 (where enabling LSNG was affecting QuotaManager for some users, and when QuotaManager breaks everything that depends on it does not work as well).

I tried to reproduce it using mozregression and the following steps:

  • create a new profile with Firefox 75.0b6
  • install ublock and multiaccount container
  • run Firefox 75.0b7 on the existing profile

But unfortunately it wasn't enough, but it isn't too surprising because this kind of issue are very often triggered by something in the profile of the users affected, e.g. In the past similar issues were triggered by unexpected files in the storage sub directories of the Firefox profile affected (Bug 1482662 is tracking at least some of the issues related to storage initialization failures).

Flags: needinfo?(lgreco)

(In reply to jon from comment #12)

I'd be happy to provide more info — what would help you debug this?

Some additional info that may help investigating this issue:

  • list and timestamps (and maybe the size as well?) of the files in the <PROFILE>/storage sub-directories
  • collect the verbose logs emitted when firefox is being executed from a shell with the environment variable MOZ_LOG="IndexedDB:5:sync" defined
Flags: needinfo?(jon)

Hi Jan,
Besides what I mentioned in comment 14, is there any other info that the reporter may collect from the profile affected by this issue which may help us investigating what is triggering the storage failures? (and/or if it may be related or not to LSNG)

Flags: needinfo?(jvarga)

I've attached the execution log from running Firefox with MOZ_LOG="IndexedDB:5:sync" on the broken profile, and testing a few local storage commands in the console.

As for the number of files and files sizes, here's an overview. I can give you a more detailed breakdown if it'd be useful:

storage $ find . -type f -print | wc -l
1060
storage $ du -hs *
78M     default
16M     permanent
4.0K    temporary
storage $ du -hs default/moz-extension+++*
8.4M    default/moz-extension+++6cdac5c1-e444-4aa7-86fd-01d946404f89
108K    default/moz-extension+++6cdac5c1-e444-4aa7-86fd-01d946404f89^userContextId=4294967295
92K     default/moz-extension+++35fe757d-ba36-4abd-b466-29faea178710^userContextId=4294967295
60K     default/moz-extension+++811389b7-eeb3-4ddd-8d9a-4dd7770ec88f^userContextId=4294967295
60K     default/moz-extension+++c375d641-9acd-4ebc-991f-89a177761226
60K     default/moz-extension+++c375d641-9acd-4ebc-991f-89a177761226^userContextId=4294967295
storage $ ls default/http* | wc -l
251
Flags: needinfo?(jon)

Running a debug build using the problematic profile would provide very useful logs in the the system console.

Flags: needinfo?(jvarga)

Ah, sorry, and file times:

storage $ ls -l
drwxr-xr-x - jon 23 Mar 17:45 default
drwxr-xr-x - jon 24 Mar  9:19 permanent
drwxr-xr-x - jon 21 Mar  9:59 temporary

There are a bunch of directories in default with domain names and such in them, and most (though not quite all) have a timestamp of "24 Mar 9:54". The moz-extension directories have:

drwxr-xr-x - jon 21 Mar 10:04 moz-extension+++6cdac5c1-e444-4aa7-86fd-01d946404f89
drwxr-xr-x - jon 21 Mar 10:04 moz-extension+++6cdac5c1-e444-4aa7-86fd-01d946404f89^userContextId=4294967295
drwxr-xr-x - jon 21 Mar 10:04 moz-extension+++35fe757d-ba36-4abd-b466-29faea178710^userContextId=4294967295
drwxr-xr-x - jon 21 Mar  9:59 moz-extension+++811389b7-eeb3-4ddd-8d9a-4dd7770ec88f^userContextId=4294967295
drwxr-xr-x - jon 24 Mar  9:54 moz-extension+++c375d641-9acd-4ebc-991f-89a177761226
drwxr-xr-x - jon 21 Mar 10:04 moz-extension+++c375d641-9acd-4ebc-991f-89a177761226^userContextId=4294967295

And those times roughly match the times of the files they contain.

(In reply to Jan Varga [:janv] from comment #17)

Running a debug build using the problematic profile would provide very useful logs in the the system console.

I'd be happy to try that. Is there a quick start for how to compile/get a debug build?

You can download builds from treeherder. For example the beta channel:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-beta
You probably want "Linux x64 debug"
Click on "B" and then select "Job Details"
Find target.tar.bz2 and download it by clicking on it.

Attached a log from a debug run with the broken profile.

The JavaScript errors towards the end was me attempting to type await navigator.storage.estimate(), and the eager evaluator catching up :p

The "unexpected file" is this one:

.rw-r--r--   0 jon 21 Mar 11:08 3647222921wleabcEoxlt-eengsairo.

I'll try deleting it and seeing what happens.

[Parent 57889, QuotaManager IO] WARNING: An unexpected file exists in the storage area: "/home/jon/.mozilla/firefox/uq4zveqx.dev-edition-default/storage/default/moz-extension+++811389b7-eeb3-4ddd-8d9a-4dd7770ec88f^userContextId=4294967295/idb/3647222921wleabcEoxlt-eengsairo.": file /builds/worker/checkouts/gecko/dom/indexedDB/ActorsParent.cpp, line 17547

Can you first provide full listing of that directory ?

(In reply to Jan Varga [:janv] from comment #24)

[Parent 57889, QuotaManager IO] WARNING: An unexpected file exists in the storage area: "/home/jon/.mozilla/firefox/uq4zveqx.dev-edition-default/storage/default/moz-extension+++811389b7-eeb3-4ddd-8d9a-4dd7770ec88f^userContextId=4294967295/idb/3647222921wleabcEoxlt-eengsairo.": file /builds/worker/checkouts/gecko/dom/indexedDB/ActorsParent.cpp, line 17547

Can you first provide full listing of that directory ?

The full listing was

.rw-r--r--   0 jon 21 Mar 11:08 3647222921wleabcEoxlt-eengsairo.
drwxr-xr-x   - jon 21 Mar  9:59 3647222921wleabcEoxlt-eengsairo.files
.rw-r--r-- 49k jon 21 Mar  9:59 3647222921wleabcEoxlt-eengsairo.sqlite

The .files directory is empty.

Deleting the file without an extension made the entire profile work again, including local storage. Seems like an odd thing to make all local storage fail?

Yeah, we are working on addressing that. Thanks for the help with identifying this issue.

(In reply to Jan Varga [:janv] from comment #26)

Yeah, we are working on addressing that. Thanks for the help with identifying this issue.

Happily! Thanks for making an awesome browser awesomer! Anything else I can do to help, or do you have what you need?

Stay safe :)

One thing is not clear to me, is Firefox Sync trying to sync anything that is stored under <profile>/storage directory ? I hope not.

(In reply to Jan Varga [:janv] from comment #28)

One thing is not clear to me, is Firefox Sync trying to sync anything that is stored under <profile>/storage directory ? I hope not.

Sync doesn't sync "files" - it uses the APIs in the browser. For example, it doesn't sync places.sqlite, it uses the bookmarks/history APIs. Sync doesn't use any local storage APIs, so I believe the answer is that no, no data stored by the browser in that directory is synced.

(In reply to Jan Varga [:janv] from comment #28)

One thing is not clear to me, is Firefox Sync trying to sync anything that is stored under <profile>/storage directory ? I hope not.

I also confirm what Mark said in comment 29. As I mentioned in comment 13, Firefox Sync shouldn't be never touched the content of the storage sub-directories and so it should not be able to directly trigger this kind of issue, and the storage.sync data is not stored in the storage directory (it is stored in a file named storage-sync.sqlite in the profile directory).

Good, thanks for the confirmation.

See Also: → 1621916

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

For more information, please visit auto_nag documentation.

Flags: needinfo?(mixedpuppy)
Flags: needinfo?(mixedpuppy)

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

For more information, please visit auto_nag documentation.

Flags: needinfo?(mixedpuppy)

(In reply to aru from comment #9)

Did your weave/logs also get as full as mine was (17 GB)?

I apologize in advance for my wild guess but did you check if you have enough storage space on the disk your profile is stored? Any chance you're using -sync or -ramdisk scripts that could keep your main profile (but not the alternate profile) on a filesystem with too low space remaining?

If we had the same issue including the creation of way too many error logs in your main profile it could cause problems with Storage limits: https://developer.mozilla.org/en-US/docs/Web/API/IndexedDB_API/Browser_storage_limits_and_eviction_criteria#Storage_limits

I'm not sure if this is related or could actually break Local Storage but I guess it doesn't hurt bringing up.

(In reply to Mark Hammond [:markh] [:mhammond] from comment #10)

(In reply to aru from comment #9)

Did your weave/logs also get as full as mine was (17 GB)?

Ouch! That's insane - do you mind opening a new bug for that, CCing me? Sync is supposed to clean them up, so it will be good for us to know what's going wrong for you. Please include how many logs you have, what the earliest dated file is, and some rough analysis of the sizes (eg, most the same size, a small number of files with extreme sizes, etc?)

Thanks!

Note that there's already a bug about oversized weave/logs: https://bugzilla.mozilla.org/show_bug.cgi?id=1627638

Fix targeted for Firefox 77.

Flags: needinfo?(mixedpuppy)
Summary: Local storage failing on developer edition 75 beta 7 → storage.local failing on developer edition 75 beta 7
Severity: -- → S3
Priority: -- → P3

Reporter, can you still reproduce this bug?

Flags: needinfo?(jon)

Redirect a needinfo that is pending on an inactive user to the triage owner.
:zombie, since the bug has recent activity, could you have a look please?

For more information, please visit auto_nag documentation.

Flags: needinfo?(jon) → needinfo?(tomica)
Status: UNCONFIRMED → RESOLVED
Closed: 7 months ago
Flags: needinfo?(tomica)
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: