1633209 - InvalidStateError when storage.local.set is called while an extension is being debugged

Status: NEW

(Core :: Storage: IndexedDB, defect, P3)

Description

[Rob Wu [:robwu]]

Attachment: storage-indexeddb.zip

When browser.storage.localset is called from the extension while the debugger is paused in the debugger, an InvalidStateError is thrown from ExtensionStorageIDB.jsm. It appears that it is not reliable to call mutable IndexedDB operations while being paused in a debugger.

STR:

1. Visit about:debugging and load the attached extension.
2. Click on Inspect at the add-on to open the devtools for the extension's background page.
3. Click on the extension button.
   (The extension opens a new tab and calls runtime.sendMessage from it)
   (the devtools should pause at the debugger statement in the extension's background page.)
4. Click on Resume in the debugger.
5. Scroll down in the console and read the most recent messages.

Expected:

• The message should have this sequence (i.e. runtime.onMessage is not fired while being paused in the debugger):
  1. before debugger
  2. after debugger
  3. Calling storage.set
  4. storage.set succeeded
• Or at least the following (runtime.onMessage triggered while being debugged. Not desired, but not the point of this bug):
  1. before debugger
  2. Calling storage.set
  3. storage.set succeeded
  4. after debugger

Actual:

• The following messages are shown instead:
  1. before debugger
  2. Calling storage.set
  3. InvalidStateError: A mutation operation was attempted on a database that did not allow mutations. IndexedDB.jsm:120:34
  4. storage.set failed: Error: An unexpected error occurred

The stack trace is as follows (with links to Searchfox):

method resource://gre/modules/IndexedDB.jsm:120
set resource://gre/modules/ExtensionStorageIDB.jsm:260
AsyncFunctionNext self-hosted:693
(Async: async)
set chrome://extensions/content/child/ext-storage.js:122

The ExtensionStorageIDB.jsm:260 part is actually inside a catch handler. It is caused by await objectStore.put(items[key], key);.

Comment 1

[Rob Wu [:robwu]]

This is unrelated to runtime.onMessage, by the way. If you are willing to run code from the console, a minimal STR is:

1. Trigger debugger from an extension script, e.g. with the following background.js and clicking the extension button:

browser.browserAction.onClicked.addListener(()=>{ debugger; })

2. Run the following snippet from the devtools while being in the debugger: browser.storage.local.set({val:1})

The error appears again:

InvalidStateError: A mutation operation was attempted on a database that did not allow mutations. IndexedDB.jsm:120:34
Error: An unexpected error occurred

Comment 2

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

Hi Tom,
do you know if there are other issues related to INVALID_STATE_ERROR triggered by calling the IndexedDB API method while the debugger is paused?

Comment 3

[Tom Tung [:tt, :ttung]]

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

Hi Tom,
do you know if there are other issues related to INVALID_STATE_ERROR triggered by calling the IndexedDB API method while the debugger is paused?

I cannot recall an issue similar to this condition.

Per spec: An operation was called on an object on which it is not allowed or at a time when it is not allowed, or if a request is made on a source object that has been deleted or removed.

From my understanding this is often related to the transaction state is wrong.

Here are places where we return InvalidStateError. There are two places where related to objectstore, but none of these two is related to objectstore.put.

I wonder if this could be related to:

• IDBTransaction::Commit
• IDBRequest::GetResult
• IDBRequest::GetError

Rob, can you try to reproduce the issue with a debug build and share the log here so that we can narrow down this issue? Thanks!

(cc Simon since he recently touched IDBTransaction)

Comment 4

[Rob Wu [:robwu]]

Which environment variables and prefs should I set to produce the log of interest?

Comment 5

[Tom Tung [:tt, :ttung]]

(In reply to Rob Wu [:robwu] from comment #4)

Which environment variables and prefs should I set to produce the log of interest?

You can set the moz_log like export MOZ_LOG="IndexedDB:5", but a debug build would provide more information.
If you don't have a debug build by hand, you can download one from the treeherder. For instance, here is the lastest m-c, you can find a debug build for windows here ("target.zip" in "Job detail" section of the panel at the bottom;)
(I remember there is an official website/server that for us to download different builds for Firefox, but I couldn't find it at this moment)

Edit: you don't need to set any pref.

Comment 6

[Rob Wu [:robwu]]

(In reply to Tom Tung [:tt, :ttung] from comment #5)

(I remember there is an official website/server that for us to download different builds for Firefox, but I couldn't find it at this moment)

Maybe https://hg.mozilla.org/mozilla-central/firefoxreleases ? It is the link on the timestamp on every "first release with" / "last release without" link in a hg revision, e.g. at https://hg.mozilla.org/mozilla-central/rev/8e4a846c1c5bdb6f5c1d871b4d0e826a2a09b79e

I'm not getting a lot of info out of it. Only the child process (the WebExtension content process) is generating relevant logs, and it's just:

[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Request[1]: indexedDB.open("webExtensions-storage-local", 1)
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[-1] Request[1]: Firing "upgradeneeded" event
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[-1] Request[2]: database("webExtensions-storage-local").transaction([], "versionchange").createObjectStore("storage-local-data")
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[-1] Request[3]: Committing transaction (automatically)
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[-1]: Firing 'complete' event
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Request[1]: Firing "success" event
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[1]: database("webExtensions-storage-local").transaction(["storage-local-data"], "readwrite")
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[1] Request[4]: database("webExtensions-storage-local").transaction(["storage-local-data"], "readwrite").objectStore("storage-local-data").get("val")
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[1] Request[4]: Firing "success" event
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[1] Request[5]: Committing transaction (automatically)
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[1]: Firing 'complete' event

These succesful log entries match the objectStore.get call at https://searchfox.org/mozilla-central/rev/3262e013550a0db7c1840a78a3878a929801fe40/toolkit/components/extensions/ExtensionStorageIDB.jsm#246

The objectStore.put call does not appear at all. The code here is a straightforwards promise wrapper around IDBRequest.

Comment 7

[Rob Wu [:robwu]]

See comment 6. Let me know if you need more information to debug. I think that at this point we're beyond the built-in logging and that the next step is debugging with printf or a debugger such as gdb.

Comment 8

[Tom Tung [:tt, :ttung]]

(In reply to Rob Wu [:robwu] from comment #6)

Maybe https://hg.mozilla.org/mozilla-central/firefoxreleases ? It is the link on the timestamp on every "first release with" / "last release without" link in a hg revision, e.g. at https://hg.mozilla.org/mozilla-central/rev/8e4a846c1c5bdb6f5c1d871b4d0e826a2a09b79e

I meant adding ac_add_options --enable-debug in the mozconfig so that we can know if there is unexpected behavior in cpp code. It's unclear to me that this is an issue on ExtensionStorageIDB.jsm, debugger, or indexedDB itself.

I'm not getting a lot of info out of it. Only the child process (the WebExtension content process) is generating relevant logs, and it's just:

[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Request[1]: indexedDB.open("webExtensions-storage-local", 1)
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[-1] Request[1]: Firing "upgradeneeded" event
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[-1] Request[2]: database("webExtensions-storage-local").transaction([], "versionchange").createObjectStore("storage-local-data")
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[-1] Request[3]: Committing transaction (automatically)
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[-1]: Firing 'complete' event
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Request[1]: Firing "success" event
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[1]: database("webExtensions-storage-local").transaction(["storage-local-data"], "readwrite")
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[1] Request[4]: database("webExtensions-storage-local").transaction(["storage-local-data"], "readwrite").objectStore("storage-local-data").get("val")
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[1] Request[4]: Firing "success" event
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[1] Request[5]: Committing transaction (automatically)
[Child 366580: Main Thread]: W/IndexedDB IndexedDB {7ad2a992-330b-4e37-8960-f02e521fd6cc}: Child  Transaction[1]: Firing 'complete' event

These succesful log entries match the objectStore.get call at https://searchfox.org/mozilla-central/rev/3262e013550a0db7c1840a78a3878a929801fe40/toolkit/components/extensions/ExtensionStorageIDB.jsm#246

The objectStore.put call does not appear at all. The code here is a straightforwards promise wrapper around IDBRequest.

Could you post relevant logs for the failed case?

I feel like this could be an issue on debugger rather than on IndexedDB from the information I got so far.
Basically, what I want to know is whether the reason for the invalid state error is reasonable or not from the viewpoint of IndexedDB.
If it's not, then that is a bug in indexedDB.

There are only a few places that generate invalid state error in indexedDB. (I mentioned in comment #3). So, I guess that's a good entry point to dig into this issue.

Also, could you elaborate more on where you printed the "Calling storage.set" in comment #1? It would be useful to see if the issue occurred before the request was sent or after.

If an IDBRequest is fired after the debugger is paused (before it's resumed), then it looks like a bug in the debugger.
If an IDBRequest is fired before the debugger is paused, then it could because there is something wrong with the response or IPC, ... etc
For instance, it's the IPC actor dies, then there is no way to get the result/response from the parent process and you can get an invalid state error due to that.

Comment 9

[Rob Wu [:robwu]]

(In reply to Tom Tung [:tt, :ttung] from comment #8)

I meant adding ac_add_options --enable-debug in the mozconfig so that we can know if there is unexpected behavior in cpp code. It's unclear to me that this is an issue on ExtensionStorageIDB.jsm, debugger, or indexedDB itself.

I used a debug build.

These succesful log entries match the objectStore.get call at https://searchfox.org/mozilla-central/rev/3262e013550a0db7c1840a78a3878a929801fe40/toolkit/components/extensions/ExtensionStorageIDB.jsm#246

The objectStore.put call does not appear at all. The code here is a straightforwards promise wrapper around IDBRequest.

Could you post relevant logs for the failed case?

The failed case did not produce any logs in IndexedDB. In comment 6, I shared the full content of MOZ_LOG_FILE, and as you can see, it only contains logs related to the good case.

Also, could you elaborate more on where you printed the "Calling storage.set" in comment #1? It would be useful to see if the issue occurred before the request was sent or after.

Calling storage.set is when the devtools is already paused on the debugger statement. The message is printed before calling the IndexedDB logic. All IndexedDB requests are triggered and handled while the debugger is paused.

If an IDBRequest is fired after the debugger is paused (before it's resumed), then it looks like a bug in the debugger.

In what sense would this be a bug in the debugger?

I'd like to understand why getting called while being paused on the debugger is considered to be an invalid state by IndexedDB.

Comment 10

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

It seems likely the problem here likely relates to the debugger spinning a nested event loop and the semantics surrounding IndexedDB's self-closing transactions. When the transaction is created, it schedules itself as a runnable to be run by CleanupIDBTransactions which is aware of recursion depth once a microtask checkpoint occurs for the given debugger level and will render the transaction inactive.

We may need to make the cleanup logic more aware of what's going on with the debugger.

Comment 11

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

Spec-wise, the cleanup happens at https://html.spec.whatwg.org/#event-loop-processing-model:cleanup-indexed-database-transactions

Comment 12

[Tom Tung [:tt, :ttung]]

(In reply to Rob Wu [:robwu] from comment #9)

I used a debug build.

Ah, I expected there should be some messages for NS_WARN_IF or NS_WARNING that generated under the dom/indexedDB when I read comment #6. So I was assuming that I didn't explain it clearly. But, maybe they were filtered out? In my experience, there are often some IO failures while accessing files. Sorry for the misunderstanding!

The failed case did not produce any logs in IndexedDB. In comment 6, I shared the full content of MOZ_LOG_FILE, and as you can see, it only contains logs related to the good case.

I see.

Also, could you elaborate more on where you printed the "Calling storage.set" in comment #1? It would be useful to see if the issue occurred before the request was sent or after.

Calling storage.set is when the devtools is already paused on the debugger statement. The message is printed before calling the IndexedDB logic. All IndexedDB requests are triggered and handled while the debugger is paused.

If an IDBRequest is fired after the debugger is paused (before it's resumed), then it looks like a bug in the debugger.

In what sense would this be a bug in the debugger?

I meant I would expect the debugger should spinning a nested event loop and thus pauses/closes the transactions/IDBRequests for IndexedDB. If the pause happens before IndexedDB creates an IDBRequests or transaction, then there shouldn't have any error on indexedDB because it looks like the transaction's state or IDBRequest's status was incorrect from comment#0 .

Anyway, I think what Andrew mentioned in comment 10 is highly probably what's going on for this issue occurs. I am moving this bug to indexedDB.

Comment 15

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

The severity field for this bug is set to S3. However, the following bug duplicate has higher severity:

• Bug 1656669: S2

:janv, could you consider increasing the severity of this bug to S2?

For more information, please visit BugBot documentation.