Corruption in vlcn fork with FTS5

[rhashimoto]

vlcn-io/js#31

[rhashimoto]

Second try:

import SQLiteESMFactory from '../dist-xl/wa-sqlite-async.mjs';
import * as SQLite from '../src/sqlite-api.js';
import { IDBBatchAtomicVFS } from '../src/examples/IDBBatchAtomicVFS-shadow.js';

(async function() {
  await indexedDB.databases()
    .then(databases => Promise.all(databases.map(({name}) => {
      return new Promise((resolve, reject) => {
        const req = indexedDB.deleteDatabase(name);
        req.onsuccess = resolve;
        req.onerror = reject;
      });
    })));

  const module = await SQLiteESMFactory();
  const sqlite3 = SQLite.Factory(module);

  const vfs = new IDBBatchAtomicVFS('00118');
  sqlite3.vfs_register(vfs, true);

  const db = await sqlite3.open_v2(
    'myDB',
    SQLite.SQLITE_OPEN_READWRITE | SQLite.SQLITE_OPEN_CREATE,
    '00118');

  await sqlite3.exec(db, 'DROP TABLE IF EXISTS test_fts;');
  await sqlite3.exec(db, 'CREATE VIRTUAL TABLE IF NOT EXISTS test_fts USING fts5(fieldA, fieldB, fieldC, fieldD, fieldE, id UNINDEXED, prefix=2, detail=none);');

  for (let i = 0; i < 1000; i++) {
    await sqlite3.exec(db, `INSERT INTO test_fts (fieldA, fieldB, fieldC, fieldD, fieldE, id) VALUES ('test', 'test', 'test', 'test', 'test', '${i}');`);
  }

  const results = { columns: [], rows: [] }
  await sqlite3.exec(db, `SELECT * FROM test_fts LIMIT 10;`, (row, columns) => {
    results.columns = columns;
    results.rows.push(row);
  });
  console.log(results);
  await sqlite3.close(db);
})();

This fails on iteration 877, just as claimed in the original report.

[rhashimoto]

This might be related to #111:

• It is a SQLITE_CORRUPT error.
• Using shadow files in RAM shows no xRead/xWrite discrepancies.
• No error if SQLITE_IOCAP_BATCH_ATOMIC is removed.

A distinction from #111 is the synchronous mode is unchanged, so this is potentially a much more serious problem.

Here are the VFS method calls on the failing iteration:

INSERT INTO test_fts (fieldA, fieldB, fieldC, fieldD, fieldE, id) VALUES ('test', 'test', 'test', 'test', 'test', '877');
xLock /myDB 1
xAccess /myDB-journal 0
xRead /myDB 16 24
xAccess /myDB-wal 0
xFileSize /myDB
xDeviceCharacteristics
xUnlock /myDB 0

This log is identical to the other iterations up to xDeviceCharacteriestics. So most likely one of the prior methods is returning data that SQLite doesn't like. The shadow checks make it unlikely it is xRead (which would otherwise be the prime suspect), so examine the others.

[rhashimoto]

Here are the relevant VFS method calls on iteration 876, one iteration before the error is reported:

xFileControl /myDB 31
xFileControl /myDB 5
xWrite /myDB 4096 0
xWrite /myDB 4096 4096
xWrite /myDB 4096 8192
xWrite /myDB 4096 57344
xWrite /myDB 4096 65536
xWrite /myDB 4096 69632
xFileControl /myDB 32
xFileSize /myDB
xFileControl /myDB 5
xWrite /myDB 4096 73728
xFileControl /myDB 21
xSync /myDB 2

xFileControl 31 (SQLITE_FCNTL_BEGIN_ATOMIC_WRITE) opens the batch atomic write and xFileControl 32 (SQLITE_FCNTL_COMMIT_ATOMIC_WRITE) closes it. Most of the xWrite calls are inside the batch atomic group, but if you look closely there is one xWrite after the end of the group. That extra xWrite causes the problem because it appends to the file after the new metadata, which includes the file size, is written.

This can and should be fixed in IDBBatchAtomicVFS, but I think it is a bug in SQLite itself that this ever happens. If a crash occurs between the SQLITE_FCNTL_COMMIT_ATOMIC_WRITE and the extra xWrite, then the database file will be left in an inconsistent state (the page count in the file header will be wrong) with no rollback journal.

[rhashimoto]

This can and should be fixed in IDBBatchAtomicVFS, but I think it is a bug in SQLite itself that this ever happens.

Reported upstream.

[sgbeal]

Reported upstream.

Just FYI: fixed in https://sqlite.org/src/info/c9fdd680 and will be included in the pending 3.44 release.

[rhashimoto]

Just FYI: fixed in https://sqlite.org/src/info/c9fdd680 and will be included in the pending 3.44 release.

That was fast, wasn't really expecting that! The SQLite bug only happened with a particular type of VFS that requires a non-default compile flag, and then only with a crash in a very small window. Probably no one has seen this happen. I figured it would go into a .1 release.

[sgbeal]

That was fast,

Richard and Dan both appreciate interesting problems and detailed bug reports with repro cases :). As someone who only very superficially understands the core, it's always interesting to watch them discuss that sort of bug and toss around solutions.