Bug 1735191 Comment 7 Edit History

Note: The actual edited comment in the bug view page will always show the original commenter’s name and original timestamp.

Original comment by
on 
Not sure if all of this is relevant, but I see in the log:

```
[task 2021-10-11T16:38:37.221Z] 16:38:37     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "IndexedDB UnknownErr: ActorsParent.cpp:9549"]"
```
coming from [`Database::InvalidateAll`](https://searchfox.org/mozilla-central/rev/702199bca53babc925e47fd8f86ed56487d42492/dom/indexedDB/ActorsParent.cpp#9535). It seems, `IDB_REPORT_INTERNAL_ERR();` is called always there (if there was something to abort)? That feels weird. In any case we seem to abort a transaction **before** we enter QM shutdown (see messages below).

In fact the next messages talk about starting QM shutdown:
```
[task 2021-10-11T16:38:37.222Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: idb: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.222Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: cache: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.222Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: sdb: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.223Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: ls: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
```
Then we find 4 anonymous IPC message discarded events:
```
[task 2021-10-11T16:38:37.223Z] 16:38:37     INFO -  PID 10364 | [Child 8476, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-10-11T16:38:37.223Z] 16:38:37     INFO -  PID 10364 | [Child 8476, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-10-11T16:38:37.224Z] 16:38:37     INFO -  PID 10364 | [Child 8476, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-10-11T16:38:37.224Z] 16:38:37     INFO -  PID 10364 | [Child 8476, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
```
followed by the assertion and the successful finish of the QM shutdown (which probably happened earlier but the log message order is wrong?)
```
[task 2021-10-11T16:38:37.224Z] 16:38:37     INFO -  PID 10364 | Assertion failure: mReadyState == ReadyState::Finished, at /builds/worker/checkouts/gecko/dom/indexedDB/IDBTransaction.cpp:135
[task 2021-10-11T16:38:37.225Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: idb: '0.047000s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.225Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: idb: '0.047000s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.225Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: idb: '0.047000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.226Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: cache: '0.047000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.226Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: sdb: '0.063000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.226Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: ls: '0.063000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
```

My guess would be that we miss some `mReadyState` transition to `Finished` while we abort a transaction. We do not touch `mReadyState` during abort if [the transaction is already comitting](https://searchfox.org/mozilla-central/rev/702199bca53babc925e47fd8f86ed56487d42492/dom/indexedDB/IDBTransaction.cpp#682-686).
Revision 1 by
on 
Not sure if all of this is relevant, but I see in the log:

```
[task 2021-10-11T16:38:37.221Z] 16:38:37     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "IndexedDB UnknownErr: ActorsParent.cpp:9549"]"
```
coming from [`Database::InvalidateAll`](https://searchfox.org/mozilla-central/rev/702199bca53babc925e47fd8f86ed56487d42492/dom/indexedDB/ActorsParent.cpp#9535). It seems, `IDB_REPORT_INTERNAL_ERR();` is called always there (if there was something to abort)? That feels weird. In any case we seem to abort a transaction **before** we enter QM shutdown (see messages below).

In fact the next messages talk about starting QM shutdown:
```
[task 2021-10-11T16:38:37.222Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: idb: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.222Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: cache: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.222Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: sdb: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.223Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: ls: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
```
Then we find 4 anonymous IPC message discarded events:
```
[task 2021-10-11T16:38:37.223Z] 16:38:37     INFO -  PID 10364 | [Child 8476, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-10-11T16:38:37.223Z] 16:38:37     INFO -  PID 10364 | [Child 8476, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-10-11T16:38:37.224Z] 16:38:37     INFO -  PID 10364 | [Child 8476, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-10-11T16:38:37.224Z] 16:38:37     INFO -  PID 10364 | [Child 8476, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
```
followed by the assertion and the successful finish of the QM shutdown (which probably happened earlier but the log message order is wrong?)
```
[task 2021-10-11T16:38:37.224Z] 16:38:37     INFO -  PID 10364 | Assertion failure: mReadyState == ReadyState::Finished, at /builds/worker/checkouts/gecko/dom/indexedDB/IDBTransaction.cpp:135
[task 2021-10-11T16:38:37.225Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: idb: '0.047000s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.225Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: idb: '0.047000s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.225Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: idb: '0.047000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.226Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: cache: '0.047000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.226Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: sdb: '0.063000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
[task 2021-10-11T16:38:37.226Z] 16:38:37     INFO -  PID 10364 | [Parent 10364, IPDL Background] WARNING: ls: '0.063000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3788
```

My guess would be that we miss some `mReadyState` transition to `Finished` while we abort a transaction. FWIW, we do not touch `mReadyState` during abort if [the transaction is already comitting](https://searchfox.org/mozilla-central/rev/702199bca53babc925e47fd8f86ed56487d42492/dom/indexedDB/IDBTransaction.cpp#682-686).

Back to Bug 1735191 Comment 7