diff --git a/.changeset/23635-sqlite-wasm-background-flush-failure.md b/.changeset/23635-sqlite-wasm-background-flush-failure.md new file mode 100644 index 00000000000..f2e1fd71ebb --- /dev/null +++ b/.changeset/23635-sqlite-wasm-background-flush-failure.md @@ -0,0 +1,11 @@ +--- +'@objectstack/driver-sqlite-wasm': patch +--- + +fix(driver-sqlite-wasm): a database-file write that fails in the background is reported once, at `error` with the file named, instead of reaching the process as an unhandled rejection + +`WasmSqliteConnection` writes the in-memory image to disk without anyone awaiting it in three places: after each write under `persist: 'on-write'`, when the `debounced:N` timer fires, and when a transaction closes with a flush deferred. A write that failed there (the disk full, the data directory removed under a live driver) had no caller to throw to, so its rejection reached the host process as an `unhandledRejection`: a failed run under Vitest, and a terminated process under Node's default. + +Those three flushes now go through one helper. A failed one is logged once per failure episode, at `error` where the logger has one and at `warn` where it does not, naming the database file and saying that writes since the last good flush are not on disk. The file stays marked dirty, so the next write's flush (or `close()`) retries it and lands once the cause is gone. Further failures stay quiet until a flush has succeeded. + +An awaited `flush()` and `close()` are unchanged and still throw to their caller. The `logger` option's type is unchanged; a logger that only has `warn` still hears the report, at `warn`. diff --git a/packages/drivers/driver-sqlite-wasm/src/sqlite-wasm-background-flush-failure.test.ts b/packages/drivers/driver-sqlite-wasm/src/sqlite-wasm-background-flush-failure.test.ts new file mode 100644 index 00000000000..b3f07dd415f --- /dev/null +++ b/packages/drivers/driver-sqlite-wasm/src/sqlite-wasm-background-flush-failure.test.ts @@ -0,0 +1,299 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; +import { mkdtempSync, mkdirSync, rmSync, existsSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; + +import { SqliteWasmDriver, WasmSqliteConnection } from './index.js'; +import type { PersistMode } from './index.js'; + +/** + * A flush nobody awaits — a write under `on-write`, the `debounced:` timer, a + * transaction closing — has no caller to throw to. Left as a bare + * `void this.flush()`, a failing one (ENOSPC, the data directory removed under a + * live driver) reached the process as an `unhandledRejection`, which fails a + * Vitest run and, under Node's default, terminates a host. + * + * The contract pinned here, per call site: + * - the failure is REPORTED once per failure episode, at `error`, naming the + * database file — never left to the process; + * - `dirty` stays set, so the next flush retries and lands once the cause is + * gone; + * - an AWAITED `flush()` / `close()` is unchanged: it still throws to its + * caller (the control). + * + * "No unhandled rejection" is asserted directly: every test attaches its own + * `process.on('unhandledRejection')` listener and requires that it saw nothing + * once the flush chain has settled. That keeps the verdict local to the test + * that owns the failing flush, instead of leaving it to whichever test happens + * to be running when Vitest's own run-level report fires. + */ +describe('a failing background flush', () => { + const dirs: string[] = []; + const conns: WasmSqliteConnection[] = []; + const drivers: SqliteWasmDriver[] = []; + let unhandled: unknown[] = []; + const onUnhandled = (reason: unknown): void => { + unhandled.push(reason); + }; + + beforeEach(() => { + unhandled = []; + process.on('unhandledRejection', onUnhandled); + }); + + afterEach(async () => { + process.off('unhandledRejection', onUnhandled); + await Promise.all(conns.splice(0).map((c) => c.close().catch(() => {}))); + await Promise.all(drivers.splice(0).map((d) => d.disconnect().catch(() => {}))); + for (const dir of dirs.splice(0)) rmSync(dir, { recursive: true, force: true }); + }); + + interface Captured { + errors: string[]; + warns: string[]; + } + + function capture(): { logger: { warn: (m: string) => void; error: (m: string) => void } } & Captured { + const errors: string[] = []; + const warns: string[] = []; + return { + errors, + warns, + logger: { warn: (m) => warns.push(m), error: (m) => errors.push(m) }, + }; + } + + /** A connection on a fresh file with one table, ready to take writes. */ + async function openConn( + persist: PersistMode, + logger: ConstructorParameters[0]['logger'], + ): Promise<{ conn: WasmSqliteConnection; dir: string; file: string }> { + const dir = mkdtempSync(join(tmpdir(), 'wasm-bgflush-')); + dirs.push(dir); + const file = join(dir, 'bg.db'); + const conn = new WasmSqliteConnection({ filename: file, persist, logger }); + conns.push(conn); + await conn.open(); + conn.raw.run('CREATE TABLE t (id TEXT)'); + return { conn, dir, file }; + } + + /** What the connection's dialect does for a write: change the image, then mark it. */ + function write(conn: WasmSqliteConnection, id: string): void { + conn.raw.run('INSERT INTO t VALUES (?)', [id]); + conn.markDirty(); + } + + /** + * Wait until every flush queued so far has settled, then give the handlers + * chained after it and Node's rejection tracking their turn. The chain tail is + * private, but it is the one deterministic "the background flush is over" + * signal: a fixed sleep would be a race against the very thing being tested. + */ + async function settled(conn: WasmSqliteConnection): Promise { + await (conn as unknown as { flushChain: Promise | null }).flushChain; + await new Promise((r) => setTimeout(r, 20)); + } + + function isDirty(conn: WasmSqliteConnection): boolean { + return (conn as unknown as { dirty: boolean }).dirty; + } + + /** Ids on disk, read through a second connection (the file as a fresh boot sees it). */ + async function idsOnDisk(file: string): Promise { + const reader = new WasmSqliteConnection({ filename: file, persist: 'on-disconnect' }); + conns.push(reader); + await reader.open(); + const res = reader.raw.exec('SELECT id FROM t ORDER BY id'); + return (res[0]?.values ?? []).map((row) => String(row[0])); + } + + // ── The three fire-and-forget sites ──────────────────────────────────────── + + it('on-write: a write whose flush fails is reported, not rejected unhandled', async () => { + const log = capture(); + const { conn, dir, file } = await openConn('on-write', log.logger); + rmSync(dir, { recursive: true, force: true }); + + write(conn, 'a'); + await settled(conn); + + expect(unhandled).toEqual([]); + expect(log.errors).toHaveLength(1); + expect(log.errors[0]).toContain(file); + expect(log.errors[0]).toContain('NOT on disk'); + expect(log.warns).toEqual([]); + expect(isDirty(conn)).toBe(true); + }); + + it('debounced: the timer-driven flush that fails is reported, not rejected unhandled', async () => { + const log = capture(); + const { conn, dir, file } = await openConn('debounced:5', log.logger); + rmSync(dir, { recursive: true, force: true }); + + write(conn, 'a'); + await vi.waitFor(() => { + if (!(conn as unknown as { flushChain: unknown }).flushChain) { + throw new Error('the debounced flush has not started'); + } + }); + await settled(conn); + + expect(unhandled).toEqual([]); + expect(log.errors).toHaveLength(1); + expect(log.errors[0]).toContain(file); + expect(isDirty(conn)).toBe(true); + }); + + it('transaction close: the flush deferred past a COMMIT that fails is reported, not rejected unhandled', async () => { + const log = capture(); + const { conn, dir, file } = await openConn('on-write', log.logger); + rmSync(dir, { recursive: true, force: true }); + + conn.noteTransactionControl('BEGIN'); + write(conn, 'a'); // wants a flush; deferred while the transaction is open + expect((conn as unknown as { flushChain: unknown }).flushChain).toBeNull(); + conn.noteTransactionControl('COMMIT'); // the transaction closes: the deferred flush runs now + await settled(conn); + + expect(unhandled).toEqual([]); + expect(log.errors).toHaveLength(1); + expect(log.errors[0]).toContain(file); + expect(isDirty(conn)).toBe(true); + }); + + // ── Retry, and one report per episode ────────────────────────────────────── + + it('dirty stays set: the next flush retries and lands once the cause is gone', async () => { + const log = capture(); + const { conn, dir, file } = await openConn('on-write', log.logger); + rmSync(dir, { recursive: true, force: true }); + + write(conn, 'a'); + write(conn, 'b'); + await settled(conn); + expect(isDirty(conn)).toBe(true); + expect(existsSync(file)).toBe(false); + + mkdirSync(dir, { recursive: true }); // the cause is gone + write(conn, 'c'); // the next write's background flush is the retry + await settled(conn); + + expect(unhandled).toEqual([]); + expect(isDirty(conn)).toBe(false); + expect(await idsOnDisk(file)).toEqual(['a', 'b', 'c']); // nothing lost to the failed attempts + }); + + it('reports once per failure episode: not once per write, again after a flush has landed', async () => { + const log = capture(); + const { conn, dir } = await openConn('on-write', log.logger); + rmSync(dir, { recursive: true, force: true }); + + write(conn, 'a'); + write(conn, 'b'); + write(conn, 'c'); + await settled(conn); + expect(log.errors).toHaveLength(1); // three failed flushes, one line + + mkdirSync(dir, { recursive: true }); + await conn.flush(); // lands + rmSync(dir, { recursive: true, force: true }); + write(conn, 'd'); + await settled(conn); + + expect(unhandled).toEqual([]); + expect(log.errors).toHaveLength(2); // a new episode is a new report + }); + + // ── The report itself can never become the rejection ─────────────────────── + + it('a logger with only warn still hears it, at warn', async () => { + const warns: string[] = []; + const { conn, dir, file } = await openConn('on-write', { warn: (m: string) => warns.push(m) }); + rmSync(dir, { recursive: true, force: true }); + + write(conn, 'a'); + await settled(conn); + + expect(unhandled).toEqual([]); + expect(warns).toHaveLength(1); + expect(warns[0]).toContain(file); + }); + + it('a logger that throws does not turn the report into an unhandled rejection', async () => { + const boom = (): never => { + throw new Error('logger is down'); + }; + const logger = { warn: boom, error: boom }; + const { conn, dir } = await openConn('on-write', logger); + rmSync(dir, { recursive: true, force: true }); + + write(conn, 'a'); + await settled(conn); + + expect(unhandled).toEqual([]); + expect(isDirty(conn)).toBe(true); + }); + + // ── CONTROL: an awaited flush still throws to its caller ─────────────────── + + it('CONTROL: an awaited flush() still rejects to its caller, and does not also log', async () => { + const log = capture(); + const { conn, dir } = await openConn('on-disconnect', log.logger); + rmSync(dir, { recursive: true, force: true }); + + write(conn, 'a'); // on-disconnect: marks dirty, schedules nothing + await expect(conn.flush()).rejects.toMatchObject({ code: 'ENOENT' }); + + expect(unhandled).toEqual([]); + expect(log.errors).toEqual([]); // the caller was told; no second voice + expect(isDirty(conn)).toBe(true); // and a later flush still retries + + mkdirSync(dir, { recursive: true }); + await expect(conn.flush()).resolves.toBeUndefined(); + expect(isDirty(conn)).toBe(false); + }); + + it('CONTROL: close() still rejects to its caller when the final flush fails', async () => { + const log = capture(); + const { conn, dir } = await openConn('on-disconnect', log.logger); + rmSync(dir, { recursive: true, force: true }); + + write(conn, 'a'); + await expect(conn.close()).rejects.toMatchObject({ code: 'ENOENT' }); + + expect(unhandled).toEqual([]); + expect(log.errors).toEqual([]); + }); + + // ── Through the driver: the shape of the dogfood race ────────────────────── + + it('driver on-write: the data directory removed under a live driver is reported, the public flush() still throws', async () => { + const log = capture(); + const dir = mkdtempSync(join(tmpdir(), 'wasm-bgflush-drv-')); + dirs.push(dir); + const file = join(dir, 'drv.db'); + const driver = new SqliteWasmDriver({ filename: file, persist: 'on-write', logger: log.logger }); + drivers.push(driver); + await driver.initObjects([{ name: 'acct', fields: { name: { type: 'string' } } }]); + const knex = (driver as any).knex; + await knex('acct').insert({ id: 'a1', name: 'A' }); + await driver.flush(); + expect(existsSync(file)).toBe(true); + + // The refused boot's driver is never torn down; the test's cleanup removes + // the directory under it; the next write's flush meets the missing directory. + rmSync(dir, { recursive: true, force: true }); + await knex('acct').insert({ id: 'a2', name: 'B' }); + const conn = await knex.client.acquireConnection(); + await knex.client.releaseConnection(conn); + await settled(conn); + + expect(unhandled).toEqual([]); + expect(log.errors).toHaveLength(1); + expect(log.errors[0]).toContain(file); + await expect(driver.flush()).rejects.toMatchObject({ code: 'ENOENT' }); + }); +}); diff --git a/packages/drivers/driver-sqlite-wasm/src/wasm-connection.ts b/packages/drivers/driver-sqlite-wasm/src/wasm-connection.ts index f1dbaffb3ae..1c1f08b8cb4 100644 --- a/packages/drivers/driver-sqlite-wasm/src/wasm-connection.ts +++ b/packages/drivers/driver-sqlite-wasm/src/wasm-connection.ts @@ -32,7 +32,11 @@ export interface WasmConnectionOptions { * (works in Node and WebContainer). */ locateFile?: (file: string) => string; - /** Optional logger; defaults to `console`. */ + /** + * Optional logger; defaults to `console`. A failed background flush is a + * durability loss: it is reported through the logger's `error` when it has + * one (`console` does), else through `warn`. + */ logger?: { warn: (msg: string, meta?: unknown) => void }; } @@ -106,7 +110,21 @@ export class WasmSqliteConnection { private debounceTimer: ReturnType | null = null; private flushChain: Promise | null = null; private destroyed = false; - private logger: { warn: (msg: string, meta?: unknown) => void }; + /** + * The injected logger as this class reads it. `error` is not part of the + * public option type (adding it would widen a published surface); it is used + * when the object happens to have one, which every real logger does. + */ + private logger: { + warn: (msg: string, meta?: unknown) => void; + error?: (msg: string, meta?: unknown) => void; + }; + /** + * A background flush failure was already reported and no flush has landed + * since. Keeps `on-write` (one flush per write) from logging the same + * unchanged cause once per write; cleared when a flush actually writes. + */ + private flushFailureReported = false; /** * Whether a `BEGIN…COMMIT/ROLLBACK` transaction is currently open. Tracked @@ -326,7 +344,7 @@ export class WasmSqliteConnection { // close() instead of flushing on every COMMIT. if (!this.inTransaction && this.flushDeferred) { this.flushDeferred = false; - void this.flush(); + this.flushInBackground(); } } @@ -349,14 +367,14 @@ export class WasmSqliteConnection { this.dirty = true; if (this.persist === 'on-write') { - void this.flush(); + this.flushInBackground(); return; } if (this.debounceMs > 0) { if (this.debounceTimer) clearTimeout(this.debounceTimer); this.debounceTimer = setTimeout(() => { this.debounceTimer = null; - void this.flush(); + this.flushInBackground(); }, this.debounceMs); } // 'on-disconnect' → flush only at close() @@ -396,6 +414,8 @@ export class WasmSqliteConnection { // sql.js returns a Uint8Array; Buffer.from on it shares memory but // works fine for the atomic write below. await this.atomicWriteFile(Buffer.from(exported)); + // A flush landed: the next failure is a new episode worth reporting. + this.flushFailureReported = false; } catch (err) { this.dirty = true; // let a later flush retry throw err; @@ -407,6 +427,49 @@ export class WasmSqliteConnection { await step; } + /** + * Run a flush nobody awaits: a write under `on-write`, the debounce timer, a + * transaction closing. There is no caller to throw to, so a failure is + * reported here (see {@link reportBackgroundFlushFailure}) instead of being + * left as a floating rejection, which the host process meets as an + * `unhandledRejection` — fatal under Node's default. {@link flush} has + * already re-marked `dirty`, so the next flush retries. An AWAITED + * {@link flush} or {@link close} is unaffected and still throws. + */ + private flushInBackground(): void { + void this.flush().catch((err) => this.reportBackgroundFlushFailure(err)); + } + + /** + * Say, once per failure episode, that the database file is not being + * written. The memory image keeps answering queries, so nothing else looks + * wrong while committed writes stay off disk: that is a durability loss, hence + * `error`, with the consequence and the fix in the first line. + * + * Never throws. It runs in a rejection handler, where a throw would become + * the very unhandled rejection this exists to remove; a logger that cannot + * log is the end of the line, so its failure is dropped. + */ + private reportBackgroundFlushFailure(err: unknown): void { + if (this.flushFailureReported) return; + this.flushFailureReported = true; + const reason = typeof err === 'string' ? err : (err as Error)?.message ?? String(err); + try { + (this.logger.error ?? this.logger.warn).call( + this.logger, + `[driver-sqlite-wasm] Writing ${this.filename} to disk failed (${reason}). ` + + `Writes since the last successful flush are NOT on disk: the database keeps ` + + `answering from memory and looks healthy, but they are lost if this process ` + + `stops before a flush succeeds. The flush is retried after the next write and ` + + `on close (close() throws if it still fails) - free disk space or restore the ` + + `data directory (ENOSPC, a removed or read-only directory). Reported once, ` + + `until a flush succeeds.`, + ); + } catch { + /* the logger itself failed: nowhere left to report */ + } + } + /** * Write the database bytes to disk atomically: write to a sibling temp file, * fsync it, then `rename()` it over the target.