1885297 - The extension is unable to get/set/clear setting from the browser.storage.local using a specific key.

Status: RESOLVED FIXED

(WebExtensions :: Storage, defect, P3)

Description

[maximtop]

Attachment: bug.png

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/122.0.0.0 Safari/537.36

Steps to reproduce:

Actually, I do not have steps to reproduce the issue, as it occurred for one of the users of AdGuard AdBlocker.

Actual results:

It appears that Firefox occasionally lacks the ability to set, retrieve, or delete data in local storage using the specific key "adguard-settings". This issue can typically be resolved by reinstalling the extension.

What's not working:

browser.storage.local.get('adguard-settings')
browser.storage.local.set('adguard-settings')
browser.storage.local.clear()
What's working:

browser.storage.local.get('adguard-settings2')
browser.storage.local.set('adguard-settings2')

Here is the link to issue in AdGuard AdBlocker repository
https://github.com/AdguardTeam/AdguardBrowserExtension/issues/2663#issuecomment-1980982715

Expected results:

browser.storage.local - should work

Comment 1

[BugBot [:suhaib / :marco]]

The Bugbug bot thinks this bug should belong to the 'WebExtensions::Untriaged' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Comment 2

[Alex Cornestean]

Hello,

I could not reproduce the issue on the latest Nightly (125.0a1/20240317212740) or Release (123.0.1/20240304104836) under Windows 10 x64 or macOS 11.3.1.

Based on the attached screenshot and the information from Comment 0, I started setting values for adguard-settings and adguard-settings2 in the extension storage and then getting, clearing and removing those values. I did not encounter any issues so far and I repeated these actions several times.

I’ll keep at it and in case anything changes, I’ll update the report.

Comment 3

[maximtop]

Yes, we were also unable to reproduce the issue on our side. However, there was one user on whose PC I was able to replicate the problem. Additionally, the issue was resolved after the extension was reinstalled. It seems that, at certain times, Firefox encounters an error with the data stored in the browser's local storage, preventing the data from being modified or retrieved.

Comment 4

[Luca Greco [:rpl] [:luca] [:lgreco]]

(In reply to maximtop from comment #3)

Yes, we were also unable to reproduce the issue on our side. However, there was one user on whose PC I was able to replicate the problem. Additionally, the issue was resolved after the extension was reinstalled. It seems that, at certain times, Firefox encounters an error with the data stored in the browser's local storage, preventing the data from being modified or retrieved.

The details we gathered so far seems to suggest this may be a corruption issue, if the user reporting this issue is still able to reproduce this issue some more details to confirm if that's the case may be available through the following two tools:

• in the Browser Console, after enabling the multi process mode, there may be the internal IndexedDb error being hit (the error from the screenshot attached on the github issue is the one that is sent to the extension code, which is the generic an errror occurred one, because the underlying internal Firefox error is never sent to the extension itself).

• looking into which telemetry events have been collected for the "extensions.data" "storageLocalError" probe from an about:telemetry tab (then selecting "Events" in the sidebar and filtering the events using the "storageLocalError" string), right after trigger the issue.

Comment 5

[maximtop]

(In reply to Luca Greco [:rpl] [:luca] [:lgreco] from comment #4)

if the user reporting this issue is still able to reproduce this issue some more details to confirm if that's the case may be available through the following two tools:

no, after the extension was reinstalled, the issue was resolved. However, if it occurs again, I'll know what to ask users.

Comment 6

[Luca Greco [:rpl] [:luca] [:lgreco]]

Thanks Maxim,
I'm closing it as incomplete for now, but feel free to needinfo me if you manage to gather those additional details, so that we can consider re-open this bug if we got enough to make it actionable.

As a side note, there is a known issue with browser.storage.local is being called while the same extension is being debugged, tracked by Bug 1633209, just wanted to mention it to you in case that issue may create confusion while trying to investigate the issue through the Addon Debugging window (but I'm not marking this issue a duplicate of that one because the details got so far doesn't seem to suggest that is the issue reported by this bugzilla issue).

Comment 7

[maximtop]

Hi, Luca,

We've noticed similar issues reported by other users as well. Following your suggestion, we requested additional information from them to better understand the problem. One user has agreed to provide more detailed information, which can be found here: https://github.com/AdguardTeam/AdguardBrowserExtension/issues/2775#issuecomment-2034639183.

If further details are required, please don't hesitate to let me know.

Comment 8

[Luca Greco [:rpl] [:luca] [:lgreco]]

Hi Maxim,
thanks for gathering some more details from users that are hitting this issue.

In the second console logs file attached to https://github.com/AdguardTeam/AdguardBrowserExtension/issues/2775#issuecomment-2034639183
I see a few logs that seems to confirm the underlying IndexedDB is hitting an unexpected issue:

IndexedDB UnknownErr: ActorsParent.cpp:551
UnknownError: The operation failed for reasons unrelated to the database itself and not covered by any other error code. ExtensionStorageIDB.sys.mjs:838
Uncaught (in promise) Error: An unexpected error occurred undefined

The IndexedDB UnknownErr seems to have been logged from https://searchfox.org/mozilla-central/rev/b94e479d0b79b157029379832d05229df646e134/dom/indexedDB/ActorsParent.cpp#551

I'm re-opening the bug to needinfo a peer from the DOM Storage team to double-check if there is some additional logging we could ask the user hitting the error to enable to gather some more details about why IndexedDB UnknownErr is getting hit.

Comment 9

[Luca Greco [:rpl] [:luca] [:lgreco]]

Hi Jan,
we are trying to pin-point what is making some users of the AdGuard extension to hit an UnknownErr on the storage.local IndexedDB backend, see comment 8, is there any additional logging we may ask the user to enable to be able to provide us some more details about how we are hitting the UnknownErr?

I also recall there was a test webpage we were often mentioning in bugzilla comments to make it easier for users reporting IndexedDB errors to confirm us if in their browser instance IndexedDB was working fine when used from a webpage to exclude more generic issues, do you have a link to that test page?

Comment 10

[Jan Varga [:janv]]

Hi, yes there's a page for checking storage status:
https://firefox-storage-test.glitch.me/

Other useful information can be collected from the browser console, basically everything which starts with QM_TRY is likely related to storage initialization failures.

Comment 11

[maximtop]

Here are the results of checking the storage status from https://firefox-storage-test.glitch.me/.

https://github.com/AdguardTeam/AdguardBrowserExtension/issues/2775#issuecomment-2120875802

It seems that the storage status is okay.

Comment 12

[maximtop]

Results from one more user
https://github.com/AdguardTeam/AdguardBrowserExtension/issues/2775#issuecomment-2394739459

Comment 13

[Luca Greco [:rpl] [:luca] [:lgreco]]

Hi Jan,
based on the results collected by a few AdGuard Firefox users that have hit this issue so far and collected using the https://firefox-storage-test.glitch.me/ it seems we can exclude more general quota manager service initialization failures, and so it seems that users hitting this are experiencing a single key stored in IndexedDB to be hitting the issue (and as in comment 0, accessing other keys from the same IndexedDB database to be working fine).

What would be the possible underlying reasons for a single key's value to enter in a state where trying to retrieve would keep hitting an UnknownErr?

I'm not sure how practical that would be for users hitting the issue to try using a debug build on their profile hitting the issue, but in the meantime I wanted also to confirm with you:

Would a debug build be able to produce some more useful details to pin point how the underlying IndexedDB storage got into that state?

Comment 14

[Luca Greco [:rpl] [:luca] [:lgreco]]

On the ExtensionStorageIDB.sys.mjs side, it may be worth to consider to make the part of the storage.local.remove/storage.local.clear/storage.local.set internal implementation that reads the existing value to be handling reading failures (at least UnknownErr errors) more gracefully

All those methods are still reading the existing value before removing/clearing/setting, because the storage API event onChanged is meant to be fired with the oldValue included.

It is not unlikely that reading the value (once the key/value got into some kind of corrupted state) may be part of what makes browser.storage.local.clear/remove/set to also hit the UnknownErr because of the corrupted key/value.

Handling more gracefully reading failures on reading the current value may at least help to allow the extension to get out of the broken state without having to uninstall and reinstall the entire addon, which seems the way users are currently workarounding the issue.

Comment 15

[Jan Varga [:janv]]

(In reply to Luca Greco [:rpl] [:luca] [:lgreco] from comment #13)

Would a debug build be able to produce some more useful details to pin point how the underlying IndexedDB storage got into that state?

Testing using a debug build would provide more useful information for sure.
You mentioned that it's probably not about "general quota manager service initialization failures", so if a problem happens later, we won't get QM_TRY logging for that in the browser console, because only general storage initialization failures are reported to the browser console. However, in debug builds all QM_TRY failures are logged to the terminal. So we would see exact line number in the source code where a failure happened and how it was propagated.

Comment 16

[Andrew Sutherland [:asuth] (he/him)]

(In reply to Luca Greco [:rpl] [:luca] [:lgreco] from comment #14)

On the ExtensionStorageIDB.sys.mjs side, it may be worth to consider to make the part of the storage.local.remove/storage.local.clear/storage.local.set internal implementation that reads the existing value to be handling reading failures (at least UnknownErr errors) more gracefully

Currently the right course of action is probably deleting the database on UnknownErr, especially on release or beta. On nightly, there's always the potential for there to have been some kind of short-term regression that might explain the problem and that would be backed out, but regressions like that have been incredibly rare, so it's probably best to still just delete the database.

Comment 17

[Andrew Sutherland [:asuth] (he/him)]

Note that in https://github.com/w3c/IndexedDB/issues/423 we're discussing changing the error to NotReadableError in some cases, so it would also be appropriate to check for that error if handling UnknownErr.

Comment 18

[maximtop]

Testing using a debug build would provide more useful information for sure.

We can ask users to use the debug build, but I'm not sure if the issue will occur again in that environment, since, as I understand it, reinstalling the extension resolves the problem.

Comment 19

[maximtop]

We were finally able to get the storages data from a user with similar symptoms.
https://github.com/AdguardTeam/AdguardBrowserExtension/issues/3284#issuecomment-3202354354

Comment 20

[Rob Wu [:robwu]]

Might share a root cause similar to bug 1979997. Needinfo'ing Luca to confirm.

Comment 21

[Luca Greco [:rpl] [:luca] [:lgreco]]

I've been able to hit the same issue as the user by using the dump the user shared in the github comment linked from comment 19.

To reproduce the issue I used the following STR:

• list the content of the zip file and pick up the uuid assigned to the AdGuard addon in that installation (52ded703-4439-4d38-bab0-b198a9f814a6) based on the moz-extension storage/default directories included in the zip file (named moz-extension+++UUID and moz-extension+++UUID^userContextId=429496729).
• started a local Firefox build on a brand new profile, installed AdGuard from AMO listing page (https://addons.mozilla.org/en-US/firefox/addon/adguard-adblocker/) and then quit the Firefox instance
• before starting Firefox again on the newly created profile:
  • edit the user_pref extensions.webextensions.uuid to replace the uuid associated to "[e-mail]" with the one got from the zip file (52ded703-4439-4d38-bab0-b198a9f814a6)
• unzip the content of the zip file in the storage/default subdirectory from the newly created profile
• start Firefox again on the tweaked profile
• open the BrowserConsole, enable multiprocess mode and expect to see the error logs related to the underlying IndexedDB errors as the ones mentioned in comment 8

Digging into the content of the sqlite file using sqlite3 it seems that there is a mismatch between the file name included in the internal IndexedDB sqlite db and the one actually on disk, in particular the one in the sqlite db is expected to be 38035 whereas the name of the file actually on disk is 38037 (see "Content of the sqlite3 db and related files on disk" section below).

As an additional confirmation that the mismatch between the file name in the sqlite db vs the one on disk is the reason behind the failure, when I tried to rename the file to the expected name 38037 the error was not hit anymore and storage.local.get of the "adguard-settings" key was resolving again.

As a side note, I have noticed that the sqlite db has a few triggers and one in particular is meant to remove entries in the file table when the refcount value of a record in that table gets to 0:

CREATE TRIGGER file_update_trigger AFTER UPDATE ON file FOR EACH ROW WHEN NEW.refcount = 0 BEGIN DELETE FROM file WHERE id = OLD.id; END;

but interestingly the missing file on disk that is still listed in the DB has refcount set to 1, while there is no entry for the file named 38037 which is actually on disk.

---

Content of the sqlite3 db and related files on disk

$ sqlite3 moz-extension+++52ded703-4439-4d38-bab0-b198a9f814a6^userContextId=4294967295/idb/3647222921wleabcEoxlt-eengsairo.sqlite

sqlite> select * from object_store;

1|0|storage-local-data|
sqlite> select * from object_data;
1|0behvbse.tfuujoht||.38035|4294967296
1|0bqq.wfstjpo|||
1|0dmjfou.je|||
1|0gjmufst.iju.dpvou|||
1|0qbhf.tubujtujd|||
1|0svmft.mjnjut|||
1|0tc.msv.dbdif|||
1|0tdifnb.wfstjpo|||<
1|0usvtufe.epdvnfout|||
1|0vqebufDifdlUjnfNt|||<

sqlite> select * from file;

38035|1

sqlite> ^D

$ ls moz-extension+++52ded703-4439-4d38-bab0-b198a9f814a6^userContextId=4294967295/idb/3647222921wleabcEoxlt-eengsairo.files

38037

Comment 22

[Luca Greco [:rpl] [:luca] [:lgreco]]

Hi Andrew,
wdyt about what I'm mentioning in comment 21 related to investigating the state of the IDB storage data that a user has kindly shared recently in the github issue linked from 19?

My best guess at the moment is that the sqlite db may have a chance to get into that state if we hit a crash while we are still in the process of updating the IndexedDB data on disk, do you have any other thoughts about how we could get into that state?

Based on what observed and mentioned in comment 21, it feels even more that the most reliable way to get the add-on storage out of the corrupted state would be to delete and recreate the db as you were suggesting in comment 16, but I'm also concerned that by just doing that we may end up losing any data that could help us to actually investigate the underlying issues because the data would be gone (the users may still be able to notice the issues due to the data expected to be stored to be missing, but they would not be able to provide the underlying data and investigate the issue would become tricky).

Another tweak of that idea could be to only change browser.storage.local.clear to drop the DB if iterating over the keys fails (after still trying to iterate over the keys for the "happy path", because we should emit the storage.onChanged event).

This would at least allow the extension itself would still be able to get the users outside of the corrupted state by calling browser.storage.local.clear themselves, and we could introduce an about:config pref that would not drop the database, that we could ask users to set if they gets into the corrupted state (and consequent data loss) more than just once and they would be willing to gather more details (and the corrupted files) to allow us to investigate the underlying issue.

What do you think?

Comment 23

[Luca Greco [:rpl] [:luca] [:lgreco]]

Hi Maxim,
have we ever asked explicitly to the users hitting this issue to look to about:crashes for crashes hit around the time they got into the corrupted state? (or did any user mention a crash?)

I took a look to the comments in this bug and in https://github.com/AdguardTeam/AdguardBrowserExtension/issues/2775 but didn't see any mention to about:crashes or crashes (from what I recall we may have asked to test out their Firefox instance for general IndexedDB issues through https://firefox-storage-test.glitch.me/ and asked to look for other errors in the BrowserConsole, and so it is possible that we may not have asked about crash reports before).

As a side note, it could be potentially a shutdown crash that users may not easily notice at that point.

Comment 24

[Andrew Sutherland [:asuth] (he/him)]

(In reply to Luca Greco [:rpl] [:luca] [:lgreco] from comment #22)

My best guess at the moment is that the sqlite db may have a chance to get into that state if we hit a crash while we are still in the process of updating the IndexedDB data on disk, do you have any other thoughts about how we could get into that state?

I filed bug 1984204 to try and capture my understanding of what's happening. Conceptually we're doing a thorough enough 2-phase commit that this should not happen absent the filesystem betraying us.

Based on what observed and mentioned in comment 21, it feels even more that the most reliable way to get the add-on storage out of the corrupted state would be to delete and recreate the db as you were suggesting in comment 16, but I'm also concerned that by just doing that we may end up losing any data that could help us to actually investigate the underlying issues because the data would be gone (the users may still be able to notice the issues due to the data expected to be stored to be missing, but they would not be able to provide the underlying data and investigate the issue would become tricky).

• It's really fantastic that we got the data in this case. It's invaluable. Thank you to everyone involved in getting the data and you for digging in!
• Quota Manager for a long time erred on the side of not automatically deleting data for the reason you enumerate; it eliminates the ability for engineers to dig into what might have happened and the user might potentially lose some data. There's historically been a few perspectives on our team, but my take is that on balance this has caused more problems for people than is justified and that the right balance is probably to delete the database and make sure there is some telemetry that can quantify how often we are having to do that to help understand how often this problem happens.
  • A related problem is that archiving off broken files potentially creates privacy problems if normal data clearing APIs are unable to clear the broken files.
• It's not clear we're going to get anything more useful in the future if we leave this breakage around than the data you got from comment 21.

Another tweak of that idea could be to only change browser.storage.local.clear to drop the DB if iterating over the keys fails (after still trying to iterate over the keys for the "happy path", because we should emit the storage.onChanged event).

So for this situation where we are missing the file we seem to return an unknown error and this is consistent with our general behavior that unknown errors mean "this database is largely permanently broken". While this situation is interesting and unique in that it's the blob reference that's bad and it can sorta be side-stepped, I do think it probably does make sense to just clear the db entirely because then you can have a healthy db going forward and...

This would at least allow the extension itself would still be able to get the users outside of the corrupted state by calling browser.storage.local.clear themselves,

While it's clear that we've got some really great extension developers out there who make the effort to try and handle and investigate these failures, error-handling for edge-cases is notoriously difficult to test and therefore also very hard to get right. I think it would make sense to just clear the db by default, possibly restarting the extension after doing so, when this happens, and making sure to log telemetry. I could see an argument for letting webextensions to add some kind of attribute that says "please never clear my corrupt databases", but that's not really something that our QM layer would likely be able to honor as we try and improve our corruption handling.

Comment 25

[maximtop]

(In reply to Luca Greco [:rpl] [:luca] [:lgreco] from comment #23)

Hi Maxim,
have we ever asked explicitly to the users hitting this issue to look to about:crashes for crashes hit around the time they got into the corrupted state? (or did any user mention a crash?)

I took a look to the comments in this bug and in https://github.com/AdguardTeam/AdguardBrowserExtension/issues/2775 but didn't see any mention to about:crashes or crashes (from what I recall we may have asked to test out their Firefox instance for general IndexedDB issues through https://firefox-storage-test.glitch.me/ and asked to look for other errors in the BrowserConsole, and so it is possible that we may not have asked about crash reports before).

As a side note, it could be potentially a shutdown crash that users may not easily notice at that point.

No, we haven’t explicitly asked users to check about:crashes, and none of them have mentioned it.
We’ll make sure to ask about crash reports next time if the issue occurs again.

Comment 26

[Rob Wu [:robwu]]

Crash reports can be retrieved and submitted after the fact. If anything was present, the user can see it at about:crashes. I'll ask in the GitHub issue for this information.

Comment 27

[maximtop]

We received a few crash reports from a user experiencing the same symptoms.
Reference: https://github.com/AdguardTeam/AdguardBrowserExtension/issues/2775#issuecomment-3215932172
Crash reports:
• https://crash-stats.mozilla.org/report/index/c15bbd12-9646-4837-91bc-4dbcb0250804
• https://crash-stats.mozilla.org/report/index/8cd066a7-dd97-4e6c-9371-663630250801
The user also sent extension logs and storages to me via email, which suggests he prefers not to make them public. I can forward them if needed.

Comment 28

[Andrew Sutherland [:asuth] (he/him)]

I think the crashes are not related to the problem[1], although I should note I'm actively working on correcting that family of crashes currently. Thank you for providing them, though!

1: Those crashes are in the content process and the storage key disagreement that the assertion is ~preventing isn't something that would impact webextensions.

Comment 29

[Luca Greco [:rpl] [:luca] [:lgreco]]

Attachment: Bug 1885297 - Make sure storage.local.clear can successfully drop an underlying corrupted IDB database. r=robwu!

Comment 30

[Luca Greco [:rpl] [:luca] [:lgreco]]

Attachment: Bug 1885297 - Prevent test_ext_storage_local_corrupted_idb.js failure on uncaught rejection in in-process mode and unskip on android builds. r?robwu!

Comment 31

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/36bd15ca9dfd
https://hg.mozilla.org/integration/autoland/rev/95c676c6b5a6
Make sure storage.local.clear can successfully drop an underlying corrupted IDB database. r=robwu
https://github.com/mozilla-firefox/firefox/commit/d4e424d8b7f3
https://hg.mozilla.org/integration/autoland/rev/0ce678b35d96
Prevent test_ext_storage_local_corrupted_idb.js failure on uncaught rejection in in-process mode and unskip on android builds. r=robwu

Comment 32

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/95c676c6b5a6
https://hg.mozilla.org/mozilla-central/rev/0ce678b35d96

Comment 33

[maximtop]

Hi! It looks like this issue may have become more frequent again after recent Firefox updates.
Since June 30, we have received four AMO reviews describing settings being reset after restarting Firefox and repeated filter auto-activation notifications. Three of them were posted between July 7 and July 11. The affected users are running AdGuard 5.4.3.1, which has not been updated since May 14, while Firefox received several 152.x updates during this period.
We do not have diagnostic data from these users yet, but we are contacting them and asking them not to reinstall the extension before we collect it. Could you please check whether the storage_local_corrupted_reset telemetry shows an increase around Firefox 152.0.4/152.0.5?
Example review: https://addons.mozilla.org/en-US/firefox/addon/adguard-adblocker/reviews/2727513/