Racy IDBBatchAtomicVFS behavior when calling methods directly

[rhashimoto]

There is a report of strange racy behavior when calling IDBBatchAtomicVFS methods directly (i.e. not from SQLite) to load an external database. It is probably related to the workarounds used to avoid IndexedDB transaction timeouts. Investigate and fix if necessary.

[rhashimoto]

I haven't been able to reproduce this. I wrote a test page to upload a local database file to IDBBatchAtomicVFS, online here (source). This page allows you to select a file, copies it to IndexedDB, and verifies it with PRAGMA integrity_check. I have tested uploading files up to 6.3 GB.

The reported racy behavior occurs when there are time gaps between calls to the VFS xWrite method. So I injected some random delays in my local version like this:

diff --git a/demo/file/index.js b/demo/file/index.js
index 463732d..3f121cd 100644
--- a/demo/file/index.js
+++ b/demo/file/index.js
@@ -79,6 +79,9 @@ async function importDatabase(vfs, path, stream) {
       // Read enough chunks to produce the next page.
       while (chunks.reduce((sum, chunk) => sum + chunk.byteLength, 0) < pageSize) {
         const { done, value } = await reader.read();
+        const delay = Math.random() * 10000;
+        log(`${value.byteLength} byte read delayed ${delay / 1000} s`);
+        await new Promise(resolve => setTimeout(resolve, delay));
         if (done) throw new Error('Unexpected end of file');
         chunks.push(value);
       }

That looks like this in the output:

16:21:10.023 Importing to IndexedDB sqlite-vfs, path sqlite.db
16:21:10.025 Deleting sqlite.db...
16:21:10.026 Creating sqlite.db...
16:21:12.036 Reading file header...
16:21:12.037 29446 pages, 4096 bytes each, 120610816 bytes total
16:21:12.038 Copying pages...
16:21:12.044 1114112 byte read delayed 7.303834476873661 s
16:21:19.373 2097152 byte read delayed 1.1739099665803576 s
16:21:20.584 2097152 byte read delayed 0.4880555371694517 s
16:21:21.107 2097152 byte read delayed 8.103773431052572 s
16:21:29.250 2097152 byte read delayed 9.956796457679156 s
...

But it still ends with success:

...
16:29:59.846 2097152 byte read delayed 6.225078925323275 s
16:30:07.837 1073152 byte read delayed 0.14177988193586843 s
16:30:08.979 Import complete
16:30:08.979 Verifying database integrity
16:30:16.988 integrity result: ok
16:30:16.988 Verification complete

@AntonOfTheWoods My key function takes input from a ReadableStream so I think it should play nicely with fetch(). Maybe see how this works in your environment?

[rhashimoto]

Possibilities:

• The races were caused by application code.
• The races were caused by a VFS method call sequence not used by SQLite or the demo.
• It is still a latent IDBBatchAtomicVFS or IDBContext bug.
• It was a bug but has already been fixed (perhaps Corruption in vlcn fork with FTS5 #118).

[rhashimoto]

I added the option to fetch a database file over the network to the test page. I tried it with small local databases and then this 23.6 MB database on GitHub Pages, all look fine.

[AntonOfTheWoods]

Ok, so I tested with your code in my system and it also works fine. I didn't originally do any of the explicit transaction stuff, so I guess that was the difference. My existing code

    const vfs = new IDBBatchAtomicVFS(`/${TCDB_FILENAME}`);
    await vfs.isReady;
    const filename = TCDB_FILENAME;
    let result = await vfs.xOpen(
      filename,
      FILE_ID,
      VFS.SQLITE_OPEN_CREATE | VFS.SQLITE_OPEN_READWRITE | VFS.SQLITE_OPEN_MAIN_DB,
      new DataView(new ArrayBuffer(8)),
    );
    for (const { partNo, ab } of allBuffers) {
      if (ab.byteLength % PAGE_SIZE !== 0) throw new Error("The little file is not a multiple of the page size");
      const blockStart = partNo * BLOCK_SIZE;
      for (let i = 0; i < ab.byteLength; i += PAGE_SIZE) {
        result += await vfs.xWrite(FILE_ID, new Uint8Array(ab.slice(i, i + PAGE_SIZE)), blockStart + i);
      }
    }
    console.log("xsync", await vfs.xSync(FILE_ID, 0));
    console.log("xclose", await vfs.xClose(FILE_ID));
    console.log("close", await vfs.close());

is definitely still producing invalid dbs if there are sleeps in various places. I guess I was just holding it wrong.

There is now code that works in the wild though, so others can get inspiration from stuff we know should work.

Thanks again for all your help on the project and this problem in particular!

[rhashimoto]

@AntonOfTheWoods Thanks for testing! I understand what's happening now. It is related to #118 - not updating file metadata when not using batch atomic writes.

If batch atomic writes are used, as my export code does, things should work. As of the #118 fix, not using batch atomic writes should work as long as xFileControl() is called with op SQLITE_FCNTL_SYNC, which my export also does.

Your export code does neither and that's why it fails. The real surprise is not why it sometimes fails but how it can ever succeed. The reason is because IDBBatchAtomicVFS xWrite is usually synchronous. As long as all the xWrite calls are issued in the same JavaScript task, the metadata will likely be correct. If there are multiple tasks, either because of xWrite's internal timeout or initiated by the application, the metadata is highly likely to be wrong.

Your code should work, and this indicates that the #118 fix doesn't go far enough. The metadata should be written to storage if necessary in xSync as well as on SQLITE_FCNTL_SYNC.

[AntonOfTheWoods]

Perfect, thanks @rhashimoto , I retested and even my crusty old code now seems to work reliably. There was the additional sleep that I needed after opening but before starting to write which also seems to have been fixed. Thanks!