1161690 - Transactions created in a Promise callback on a worker that do not have any associated requests will stall the processing of transactions. (Does not occur on main thread.)

Status: RESOLVED WORKSFORME

(Core :: Storage: IndexedDB, defect)

Description

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

Attachment: sad time log

I'm doing this on a worker and I love me some promises, so I sorta suspect this is the fallout of the promises bug 1132436 with pre-empted runnables and in my case identical/equivalent object store sets.  But it's been a month since :bent said "Ugh, promises are broken." in bug 1152026 comment 7, so I don't feel too bad about a gentle poke since this is now causing correctness errors in addition to make it hard to begin to look into the cycle collector crashes I experience at the hands of IndexedDB.

Short story log excerpts (noting that there are more requests/etc. visible in the attachments).

=== Sad time with an empty readonly request:
27055872[7f10cfa26c00]: IndexedDB {007762da-7ab8-4cc2-b2c7-a6beabb41fb5}: Child  Transaction[5]: database("b2g-email").transaction(["bodies", "config", "convIdsByFolder", "convInfo", "folderInfo", "headers", "syncStates", "tasks"], "readonly")
-552601856[7f10cfa24260]: IndexedDB {007762da-7ab8-4cc2-b2c7-a6beabb41fb5}: Parent Transaction[0]: Beginning database work
logic: <LogicEvent MailDB/finishMutate:begin {"ctxId":3085160261900}>
27055872[7f10cfa26c00]: IndexedDB {007762da-7ab8-4cc2-b2c7-a6beabb41fb5}: Child  Transaction[6]: database("b2g-email").transaction(["bodies", "config", "convIdsByFolder", "convInfo", "folderInfo", "headers", "syncStates", "tasks"], "readwrite")
27055872[7f10cfa26c00]: IndexedDB {007762da-7ab8-4cc2-b2c7-a6beabb41fb5}: Child  Transaction[6] Request[11]: database("b2g-email").transaction(["bodies", "config", "convIdsByFolder", "convInfo", "folderInfo", "headers", "syncStates", "tasks"], "readwrite").objectStore("config").delete("accountDef:0")
...

=== Happy time where I don't issue the readonly request:
-1233127680[7fafb81c3540]: IndexedDB {1c10ad56-400b-4d15-9145-1b4215f26a19}: Child  Transaction[4]: database("b2g-email").transaction(["bodies", "config", "convIdsByFolder", "convInfo", "folderInfo", "headers", "syncStates", "tasks"], "readwrite")
-1233127680[7fafb81c3540]: IndexedDB {1c10ad56-400b-4d15-9145-1b4215f26a19}: Child  Transaction[4] Request[9]: database("b2g-email").transaction(["bodies", "config", "convIdsByFolder", "convInfo", "folderInfo", "headers", "syncStates", "tasks"], "readwrite").objectStore("tasks").delete(3.08518e+12)
-1192237312[7fafbed12f20]: IndexedDB {1c10ad56-400b-4d15-9145-1b4215f26a19}: Parent Transaction[0]: Beginning database work
-1192237312[7fafbed12f20]: IndexedDB {1c10ad56-400b-4d15-9145-1b4215f26a19}: Parent Transaction[4] Request[9]: Beginning database work
-1192237312[7fafbed12f20]: IndexedDB {1c10ad56-400b-4d15-9145-1b4215f26a19}: Parent Transaction[4] Request[9]: Finished database work
-1233127680[7fafb81c3540]: IndexedDB {1c10ad56-400b-4d15-9145-1b4215f26a19}: Child  Transaction[4] Request[9]: Firing "success" event
-1233127680[7fafb81c3540]: IndexedDB {1c10ad56-400b-4d15-9145-1b4215f26a19}: Child  Transaction[4] Request[10]: All requests complete, committing transaction

Comment 1

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

Attachment: happy time log (without the preceding overlapping readonly transaction)

Comment 2

[Ben Turner (not reading bugmail, use the needinfo flag!)]

That you see this on a worker is just incidental right? Can you wedge with the same steps on the main thread?

Comment 3

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

It's a bit complicated for me to duplicate the situation on the main thread with my existing code.  I'm happy to write a mochitest that can run in both contexts if you think that would be useful.  (I just didn't want to write one if it's 100% obvious that it's just that same promises problem and the test would be discarded.)

Comment 4

[Ben Turner (not reading bugmail, use the needinfo flag!)]

I don't know. A test case would certainly help determine that!

Comment 5

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

Attachment: promise-worker-emtpy-transaction-stall-test-v1.diff

To excerpt the reduced test case:
// In bug 1161690, transactions without any requests created in promises in
// workers will stall.  Things are fine if:
// - We do this on the main thread
// - We make a request as part of this transaction.
// - We don't do this inside a Promise callback

The follow-up transaction doesn't matter at all.

The test name is bad but it could be worse.

Comment 6

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

Hm, wait, I broke my mochitest somehow.  Do not try to use yet.

Comment 7

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

Attachment: promise-worker-emtpy-transaction-stall-test-v2.diff

(I left the mozGetAll in that made it work when trying to figure out what would make it work.)

readonly versus readwrite does not matter for the transaction.

Comment 8

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

Attachment: promise-worker-emtpy-transaction-stall-test-v3.diff

So, I realized that oncomplete for an empty transaction might be ambiguous (or not).  I think on its own it's enough to break the world, but to make the test more clear-cut, I added back the second transaction (that does stuff) in order to demonstrate that stuff gets wedged no matter what the right spec answer is to "oncomplete" for an empty transaction since the second transaction's oncomplete never fires.

Comment 9

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

(Noting that the oncomplete for an empty transaction *does* fire on the main thread.  I didn't obsolete the v2 test for this reason.  Feel free to use that one instead if you like.  And now I must away like five minutes ago.)

Comment 10

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

This was fixed by bug 1179909 (hooray!).  However, that fix only had the one promise test and no IndexedDB tests, so maybe we'd like to land one of these?

Comment 11

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

The test in comment 8 doesn't seem to fail on beta (even before the alternative fix landed).  Why doesn't it fail without the issue fixed?

Comment 12

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

It definitely looks like this bug was not caused by bug 1179909 after all, and instead was fixed earlier.  I was able to do a quick-build check that things were already fixed by the landing of bug 1184410.  Unfortunately, attempts to spin earlier builds circa the time I filed this and in-between the time ranges bug seem to all result in "-Wunused-but-set-variable" explosions from inside nsprpub and it seems most efficient to just declare victory than do a mozregression dance or pursue the build error further.

Obviously, feel free to reopen if you think it's worth determining what the actual fixing bug was.  For my part, I'll comment out my workaround logic from the mail app conversations branch that generates wasted reads to avoid the was-bug.  That way I'll notice the bug if it somehow comes back.