1438998 - 5,053 instances of "NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001 (NS_ERROR_STORAGE_BUSY)" emitted from storage/mozStorage(Connection|Service).cpp during linux64 debug testing

Status: NEW

(Core :: SQLite and Embedded Database Bindings, defect, P3)

Description

[Eric Rahm [:erahm]]

> 3738 WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001: file storage/mozStorageConnection.cpp, line 759

This warning [1] shows up in the following test suites:

>    799 - test-linux64/debug-web-platform-tests-e10s-12 wpt12
>    235 - test-linux64/debug-mochitest-e10s-5 5
>    227 - test-linux64/debug-mochitest-plain-headless-e10s-5 h5
>    208 - test-linux64/debug-web-platform-tests-wdspec-e10s Wd
>    143 - test-linux64/debug-web-platform-tests-e10s-9 wpt9
>    136 - test-linux64/debug-web-platform-tests-e10s-6 wpt6
>    131 - test-linux64/debug-web-platform-tests-e10s-10 wpt10
>    120 - test-linux64/debug-web-platform-tests-e10s-11 wpt11
>    119 - test-linux64/debug-web-platform-tests-e10s-3 wpt3
>    112 - test-linux64/debug-web-platform-tests-e10s-1 wpt1
>    109 - test-linux64/debug-web-platform-tests-e10s-7 wpt7
>    100 - test-linux64/debug-web-platform-tests-e10s-2 wpt2
>     98 - test-linux64/debug-web-platform-tests-e10s-5 wpt5
>     96 - test-linux64/debug-web-platform-tests-e10s-8 wpt8
>     95 - test-linux64/debug-web-platform-tests-e10s-4 wpt4
>     74 - test-linux64/debug-web-platform-tests-reftests-e10s-1 Wr1
>     62 - test-linux64/debug-mochitest-devtools-chrome-e10s-7 dt7
>     61 - test-linux64/debug-web-platform-tests-reftests-e10s-5 Wr5
>     53 - test-linux64/debug-web-platform-tests-reftests-e10s-4 Wr4
>     47 - test-linux64/debug-web-platform-tests-reftests-e10s-6 Wr6
>     46 - test-linux64/debug-mochitest-clipboard-e10s cl
>     39 - test-linux64/debug-web-platform-tests-reftests-e10s-2 Wr2
>     36 - test-linux64/debug-mochitest-chrome-2 c2
>     29 - test-linux64/debug-mochitest-chrome-3 c3
>     29 - test-linux64/debug-marionette-e10s Mn
>     26 - test-linux64/debug-marionette-headless-e10s MnH
>     25 - test-linux64/debug-mochitest-e10s-16 16
>     17 - test-linux64/debug-mochitest-browser-chrome-e10s-10 bc10
>     16 - test-linux64/debug-mochitest-chrome-1 c1
>     15 - test-linux64/debug-firefox-ui-functional-local-e10s en-US
>     13 - test-linux64/debug-mochitest-browser-chrome-e10s-8 bc8
>     13 - test-linux64/debug-mochitest-plain-headless-e10s-15 h15
>     12 - test-linux64/debug-mochitest-browser-chrome-e10s-3 bc3
>     12 - test-linux64/debug-mochitest-e10s-7 7
>     12 - test-linux64/debug-mochitest-browser-chrome-e10s-4 bc4
>     11 - test-linux64/debug-mochitest-browser-chrome-e10s-5 bc5
>     11 - test-linux64/debug-mochitest-browser-chrome-e10s-7 bc7
>     11 - test-linux64/debug-mochitest-browser-chrome-e10s-1 bc1
>     11 - test-linux64/debug-mochitest-browser-chrome-e10s-6 bc6
>     11 - test-linux64/debug-mochitest-e10s-15 15
>     10 - test-linux64/debug-mochitest-browser-chrome-e10s-2 bc2
>     10 - test-linux64/debug-mochitest-e10s-4 4
>     10 - test-linux64/debug-mochitest-browser-chrome-e10s-9 bc9
>     10 - test-linux64/debug-mochitest-gpu-e10s gpu
>      9 - test-linux64/debug-mochitest-e10s-11 11
>      9 - test-linux64/debug-mochitest-plain-headless-e10s-11 h11
>      9 - test-linux64/debug-mochitest-plain-headless-e10s-4 h4
>      9 - test-linux64/debug-mochitest-e10s-10 10
>      8 - test-linux64/debug-mochitest-e10s-12 12
>      8 - test-linux64/debug-mochitest-e10s-14 14
>      8 - test-linux64/debug-mochitest-plain-headless-e10s-13 h13
>      8 - test-linux64/debug-mochitest-plain-headless-e10s-7 h7
>      8 - test-linux64/debug-mochitest-plain-headless-e10s-12 h12
>      7 - test-linux64/debug-mochitest-e10s-6 6
>      7 - test-linux64/debug-mochitest-e10s-9 9
>      7 - test-linux64/debug-mochitest-e10s-3 3
>      7 - test-linux64/debug-mochitest-plain-headless-e10s-9 h9
>      7 - test-linux64/debug-mochitest-plain-headless-e10s-8 h8
>      7 - test-linux64/debug-mochitest-plain-headless-e10s-10 h10
>      7 - test-linux64/debug-mochitest-e10s-13 13
>      7 - test-linux64/debug-mochitest-devtools-chrome-e10s-6 dt6
>      6 - test-linux64/debug-reftest-e10s-7 R7
>      6 - test-linux64/debug-mochitest-e10s-8 8
>      6 - test-linux64/debug-mochitest-plain-headless-e10s-16 h16
>      6 - test-linux64/debug-mochitest-devtools-chrome-e10s-2 dt2
>      6 - test-linux64/debug-mochitest-plain-headless-e10s-6 h6
>      6 - test-linux64/debug-mochitest-plain-headless-e10s-1 h1
>      5 - test-linux64/debug-mochitest-plain-headless-e10s-3 h3
>      5 - test-linux64/debug-reftest-no-accel-e10s-4 Ru4
>      4 - test-linux64/debug-mochitest-e10s-2 2
>      4 - test-linux64/debug-mochitest-devtools-chrome-e10s-3 dt3
>      4 - test-linux64/debug-crashtest-e10s C
>      4 - test-linux64/debug-mochitest-devtools-chrome-e10s-4 dt4
>      4 - test-linux64/debug-mochitest-devtools-chrome-e10s-5 dt5
>      4 - test-linux64/debug-firefox-ui-functional-remote-e10s en-US
>      4 - test-linux64/debug-mochitest-e10s-1 1
>      4 - test-linux64/debug-reftest-e10s-4 R4
>      3 - test-linux64/debug-reftest-stylo-e10s-1 Rs1
>      3 - test-linux64/debug-mochitest-browser-chrome-e10s-16 bc16
>      3 - test-linux64/debug-reftest-no-accel-e10s-8 Ru8
>      3 - test-linux64/debug-mochitest-plain-headless-e10s-2 h2
>      3 - test-linux64/debug-mochitest-devtools-chrome-e10s-1 dt1
>      3 - test-linux64/debug-reftest-stylo-e10s-4 Rs4
>      3 - test-linux64/debug-jsreftest-e10s-2 J2
>      3 - test-linux64/debug-reftest-stylo-e10s-3 Rs3
>      3 - test-linux64/debug-reftest-no-accel-e10s-6 Ru6
>      3 - test-linux64/debug-mochitest-plain-headless-e10s-14 h14
>      2 - test-linux64/debug-reftest-no-accel-e10s-1 Ru1
>      2 - test-linux64/debug-reftest-e10s-2 R2
>      2 - test-linux64/debug-reftest-no-accel-e10s-2 Ru2
>      2 - test-linux64/debug-jsreftest-e10s-1 J1
>      2 - test-linux64/debug-reftest-no-accel-e10s-5 Ru5
>      2 - test-linux64/debug-mochitest-media-e10s-3 mda3
>      2 - test-linux64/debug-reftest-e10s-3 R3
>      2 - test-linux64/debug-reftest-no-accel-e10s-7 Ru7
>      2 - test-linux64/debug-reftest-stylo-e10s-2 Rs2
>      2 - test-linux64/debug-mochitest-media-e10s-2 mda2
>      2 - test-linux64/debug-reftest-e10s-1 R1
>      1 - test-linux64/debug-reftest-e10s-8 R8
>      1 - test-linux64/debug-reftest-e10s-5 R5
>      1 - test-linux64/debug-jsreftest-e10s-3 J3
>      1 - test-linux64/debug-reftest-stylo-e10s-8 Rs8
>      1 - test-linux64/debug-mochitest-devtools-chrome-e10s-8 dt8
>      1 - test-linux64/debug-reftest-e10s-6 R6
>      1 - test-linux64/debug-reftest-stylo-e10s-5 Rs5
>      1 - test-linux64/debug-mochitest-a11y a11y
>      1 - test-linux64/debug-mochitest-browser-chrome-e10s-15 bc15
>      1 - test-linux64/debug-mochitest-browser-chrome-e10s-13 bc13
>      1 - test-linux64/debug-mochitest-webgl-e10s-3 gl3
>      1 - test-linux64/debug-mochitest-browser-chrome-e10s-12 bc12
>      1 - test-linux64/debug-reftest-stylo-e10s-6 Rs6
>      1 - test-linux64/debug-mochitest-webgl-e10s-1 gl1
>      1 - test-linux64/debug-reftest-no-accel-e10s-3 Ru3
>      1 - test-linux64/debug-mochitest-media-e10s-1 mda1

It shows up in 1561 tests. A few of the most prevalent:

>    387 - [e10s] Shutdown
>     77 -        Shutdown
>     36 - [e10s] /webdriver/tests/sessions/new_session/create_firstMatch.py
>     30 - [e10s] /webdriver/tests/sessions/new_session/create_alwaysMatch.py
>     20 - [e10s] /IndexedDB/key-conversion-exceptions.htm
>     18 - [e10s] /IndexedDB/idbobjectstore-rename-store.html
>     15 - [e10s] /IndexedDB/key_valid.html
>     15 - [e10s] dom/indexedDB/test/test_rename_objectStore.html
>     14 - [e10s] /IndexedDB/idbindex-rename.html
>     14 - [e10s] /IndexedDB/idb-binary-key-roundtrip.htm

[1] https://hg.mozilla.org/mozilla-central/annotate/928f0f09172f/storage/mozStorageConnection.cpp#l759

Comment 2

[Marco Bonardo [:mak]]

uhm, this is rv = initializeInternal(); not very positive.
Do we have a better pseudo stack?
Maybe it's tests without a profile. The warning looks correct, the caller likely doesn't check if it can run in that context.

Comment 3

[Marco Bonardo [:mak]]

ah this comes from openDatabaseWithFileURL that is indexedDB indeed.
Let's see what Jan thinks.

Comment 4

[Khyati Agarwal]

Attachment: bug 1438998 - 7,500 instances of "NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001" emitted from storage/mozStorage(Connection|Service).cpp during linux64 debug testing

7,500 instances of "NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001" emitted from storage/mozStorage(Connection|Service).cpp during linux64 debug testing

Comment 5

[Khyati Agarwal]

Hi, I would like to work on this. Please check the submitted patch.

Comment 6

[Marco Bonardo [:mak]]

The fix here doesn't just consist into removing the warning, you should run one (or more) of the above test get a stack of where and why initializeInternal() is returning an error, probably one of the executeSql calls inside it return a native SQLITE error, it would be useful to know which one. It would also be useful to know what's the url passed to openDatabaseWithFileURL

At that point we should be able to evaluate whether this warning is correct and the consumers should be fixed, or wrong, and then we could mute it.

Comment 7

[Eric Rahm [:erahm]]

To inspect this locally you'll want to have a debug build, you can enable this by adding the following to your .mozconfig build file:

ac_add_options --enable-debug

One of the tests where this reproduces is the wpt idbobjectstore-rename-store.html test, you can run that locally with:

./mach test testing/web-platform/tests/IndexedDB/idbobjectstore-rename-store.html

Marco would like to know which line is returning a failure in initializeInternal [1]. You can either inspect with a debugger or more simply just add a printf indicating which line is returning. Additionally it would be useful to log error that comes back from sqlite. You'll also want to confirm that we still see this warning

[1] https://searchfox.org/mozilla-central/rev/44a212460990ffffecf50a8e972d3cbde2e7216b/storage/mozStorageConnection.cpp#703

Comment 8

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

Per https://www.oxymoronical.com/nsresult/:

Results for 0x80630001
    NS_ERROR_STORAGE_BUSY
    SQLite database connection is busy

This likely indicates that an IndexedDB test is attempting to open a database that's currently being checkpointed on another thread. I believe bug 1541550 most specifically covers this, but bug 1541548 could also be involved. Fixing those bugs is likely to be the best way to eliminate this spam.

In general, a connection being busy does indicate a scheduling/coordination problem, so the spam is arguably good, except for how long it's taken to address it. It could make sense to have some kind of open flag that indicates that a busy-wait is expected/possible and the specific error shouldn't be warned. When a bug is filed to fix the underlying issue (as has been done for IDB), the open requests related to that bug could then be marked as expecting the busy-wait to suppress the spam.

Context

The general issue is that there are potentially 3 threads involved in IDB database work:

1. The PBackground thread where IndexedDB coordinates access to databases and decides what thread should handle an IDB requests.
2. The QuotaManager I/O thread where IDB open requests are serviced. This thread will initially open a database to do a version check, and then subsequently close the database so it can be re-opened on the next thread. That's bug 1541548.
3. The IDB connection thread where all of the database transactions are serviced. When the database is closed, write-ahead-log checkpointing may occur which does blocking IO. Bug 1541550 is about IDB doing a better job of tracking/coordinating this closure so QM I/O opens don't get run while this is still happening.

Comment 9

[Andrew McCreight [:mccr8]]

I think this is still happening:

5053 WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80630001 (NS_ERROR_STORAGE_BUSY): file storage/mozStorageConnection.cpp:1189

It is in the top 100 for warnings, but only around number 70.