Skip to content

Commit c7dd48a

Browse files
fix(driver-sqlite-wasm): handle a failing background flush instead of rejecting unhandled (#23643)
Fixes #23635 Clause-②: no A flush that fails in the background in `driver-sqlite-wasm` is now handled at the producer: reported once, at `error`, with the database file named, and the file stays dirty so a later flush retries. It no longer reaches the process as an unhandled rejection. An awaited `flush()` / `close()` still throws to its caller. ## What changed `packages/drivers/driver-sqlite-wasm/src/wasm-connection.ts`, one file: - The three fire-and-forget flushes (`markDirty` under `on-write`, the `debounced:N` timer, and the flush deferred past a transaction's close in `noteTransactionControl`) now call one private helper, `flushInBackground()`, in place of three bare `void this.flush()`. - On rejection the helper calls `reportBackgroundFlushFailure()`: one line at `error` (at `warn` for a logger that has no `error`) naming the file, the consequence (writes since the last good flush are not on disk while the database keeps answering from memory and looks healthy) and the fix. It reports once per failure episode: a latch is set by the first report and cleared when a flush actually writes, so `on-write` does not log once per write (AGENTS.md, "Degradation log levels": say it once, at the first degradation). The reporter never throws, because a throwing logger inside a rejection handler would recreate the unhandled rejection. - `flush()` is unchanged except that it clears the latch after a landed write. It still re-marks `dirty` and rethrows, so the next flush retries and an awaited caller still gets the error. `close()` is untouched. - The exported type surface is unchanged: `error` is read off the injected logger when it has one (`console` does). Declaring it on the exported `logger` option type would be a Clause-② widening and a `minor`; see Acceptance notes. One patch changeset: `.changeset/23635-sqlite-wasm-background-flush-failure.md`. ## The pin, and how it asserts "no unhandled rejection" `src/sqlite-wasm-background-flush-failure.test.ts`, 10 tests. The assertion is direct: every test attaches its own `process.on('unhandledRejection')` listener and requires that it saw nothing once the flush chain has settled. It awaits the chain tail and then 20 ms of event-loop turn, so no fixed sleep races the flush, and it does not lean on Vitest's run-level unhandled-error report. - One test per call site (on-write, debounce timer, transaction close). Each makes the flush fail by removing the database's directory, as the dogfood teardown did, and asserts: no unhandled rejection, exactly one `error` line naming the file, `dirty` still set. - Retry: once the directory is back, the next write's flush lands, and a second connection reads back every row written during the failure. - Once per episode: three failed writes give one line; after a flush lands, a new failure reports again. - Report robustness: a `warn`-only logger still hears it, at `warn`; a logger that throws produces no unhandled rejection. - CONTROL: an awaited `flush()` rejects with `ENOENT` and does not also log, `dirty` stays set and a later `flush()` resolves; `close()` rejects with `ENOENT`. - Through the driver: the dogfood race itself (a live `SqliteWasmDriver` on `on-write`, its directory removed, the next insert) is reported, and the public `driver.flush()` still rejects. ### Ablation Each leg mutated `wasm-connection.ts` through `scripts/ablation-replace.mjs` (anchor hit once, blob changed on disk, restore proven: blob equal to HEAD and `git diff HEAD` empty). The test imports `src` directly, so no `dist/` rebuild leg applies. The first attempt of the once-guard leg was refused by the tool as a no-op (its replacement was a substring of its anchor) and redone with a distinct replacement. | Mutation | Result | |---|---| | on-write site back to bare `void this.flush()` | the on-write test and the 5 tests that drive on-write fail (6 of 10); debounce and transaction tests stay green | | debounce site back to bare | exactly the debounce test fails (1 of 10) | | transaction-close site back to bare | exactly the transaction test fails (1 of 10) | | helper body back to bare `void this.flush()` (all three sites) | 8 of 10 fail; the two CONTROL tests stay green | | once-guard removed | the once-per-episode test fails (1 of 10) | | latch reset after a landed write removed | the once-per-episode test fails (1 of 10) | | logger try/catch removed | the throwing-logger test fails (1 of 10) | | `warn` fallback removed | the `warn`-only test fails (1 of 10) | | `this.dirty = true` on failure removed (existing line) | 8 of 10 fail, including the retry test | On the unmutated tree the file passes 10 of 10. ## Verification At `aa42889b36`. The patch round changed one thing: the private `logger` field's type is now one literal, with `warn` required and `error` optional. Every run below was repeated at this head. - `pnpm check:optional-error-sink` (a wide-population family that `--commands` does not print) was red at `e3b5224c85`, on the old intersection type. It exits 0 at this head: 37 sinks declare an optional `error` beside a required `warn`, and 0 are `no-fallback`. Both blocks `dispatch-gates.mjs` prints on every run were also run, each with its own command: the artifact-roster block, 53 of 53 exit 0, and the wide-population block, 11 of 11 exit 0. - `pnpm --filter @objectstack/driver-sqlite-wasm typecheck`: exit 0. Whole package suite: 37 files, 685 tests, all pass. - `node scripts/pm/dispatch-gates.mjs --commands` derived 62 commands from this tree; all 62 ran at this commit and exited 0, and `--ran` reconciles 62 derived, 62 run, 0 NOT-MEASURED. One of them, `check:logger-receiver-detach`, was red on my first spelling (a logger channel read off `this.logger` into a local) and is fixed in the last commit. `pnpm check:durability-log-level` is also green. - eslint with `--no-inline-config` on the two changed source files, `--format json`: 2 files, 0 errors, 0 warnings. The repo config never enables type-aware linting (no `parserOptions.project`, no typed rules; see the note near line 328 of `eslint.config.mjs`), so this diff cannot move the verdict of an untouched file. The repo-wide `pnpm lint` is left to CI. - NOT MEASURED: the Dogfood Regression Gate (2/3). It is CI-owned and the race is intermittent, so a local run could not prove it; the pin reproduces the mechanism deterministically instead. ## Measured, out of scope and not fixed here: where the refused boot's driver is left open The seat filed this as #23644. A boot that fails after a plugin's `start()` connected a driver never tears that driver down. - Connect: `ObjectQLPlugin.start` (`packages/objectql/src/plugin.ts`, `await this.ql?.init()`) reaches `driver.connect()` in `ObjectQLEngine.init` (`packages/objectql/src/engine.ts`, the `for (const [name, driver] of this.drivers)` loop). - Failure: the ownership guard throws at `kernel:ready`, Phase 3 of `ObjectKernel.bootstrap()` (`packages/core/src/kernel.ts`, `await this.context.trigger('kernel:ready')`). - Why nothing closes it: `rollbackStartedPlugins()` is called only inside the Phase 2 branch for a plugin whose `start()` failed. The outer `catch (error)` of `bootstrap()` sets the state to `stopped`, releases the signal listeners and rethrows; the comment there states that `shutdown()` on such a kernel is a no-op. So no plugin `destroy()` runs, including `DefaultDatasourcePlugin.destroy` (`packages/runtime/src/default-datasource-plugin.ts`), the path that disconnects the default datasource. The two in-process callers, `Runtime.start()` (`packages/runtime/src/runtime.ts`) and `bootStack` (`packages/verify/src/harness.ts`, `await kernel.bootstrap()`), add no teardown of their own. - Probe (core `dist`, scratch script outside the repo): plugin A's `start()` records a connect and its `destroy()` records a disconnect; plugin B hooks `kernel:ready` and throws. Result: `["driver.connect()", "bootstrap rejected: refused at kernel:ready", "shutdown() returned"]`, with no disconnect. Positive control, same kernel but plugin B's `start()` throws (Phase 2 rollback): `["driver.connect()", "driver.disconnect() via destroy()", "bootstrap rejected: ..."]`, so the probe can see a destroy when one happens. ## Acceptance notes - Typing `error` on the exported `WasmConnectionOptions['logger']` would let a typed caller pass a logger with `error` without a cast, and it is the declared home of this behaviour. It widens a published surface (Clause-② `yes (widening)`, `minor`), which the card's claim declared `no`, so it is not done here. The seat can take that as its own card. - `SqliteWasmDriver.connect()` registers a `beforeExit` handler (`packages/drivers/driver-sqlite-wasm/src/sqlite-wasm-driver.ts`) that calls `void this.flush().catch(() => { /* ignore */ })`, so a flush that fails at process exit is swallowed with no log. Read from source, not run. It sits outside this card's file surface and is not filed. --- _Generated by [Claude Code](https://claude.ai/code/session_01ADzJtzYTLUfgrRZHxkagkX)_ --------- Co-authored-by: Claude <noreply@anthropic.com>
1 parent 7cb33cf commit c7dd48a

3 files changed

Lines changed: 378 additions & 5 deletions

File tree

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,11 @@
1+
---
2+
'@objectstack/driver-sqlite-wasm': patch
3+
---
4+
5+
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
6+
7+
`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.
8+
9+
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.
10+
11+
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`.
Lines changed: 299 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,299 @@
1+
// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license.
2+
3+
import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest';
4+
import { mkdtempSync, mkdirSync, rmSync, existsSync } from 'node:fs';
5+
import { tmpdir } from 'node:os';
6+
import { join } from 'node:path';
7+
8+
import { SqliteWasmDriver, WasmSqliteConnection } from './index.js';
9+
import type { PersistMode } from './index.js';
10+
11+
/**
12+
* A flush nobody awaits — a write under `on-write`, the `debounced:` timer, a
13+
* transaction closing — has no caller to throw to. Left as a bare
14+
* `void this.flush()`, a failing one (ENOSPC, the data directory removed under a
15+
* live driver) reached the process as an `unhandledRejection`, which fails a
16+
* Vitest run and, under Node's default, terminates a host.
17+
*
18+
* The contract pinned here, per call site:
19+
* - the failure is REPORTED once per failure episode, at `error`, naming the
20+
* database file — never left to the process;
21+
* - `dirty` stays set, so the next flush retries and lands once the cause is
22+
* gone;
23+
* - an AWAITED `flush()` / `close()` is unchanged: it still throws to its
24+
* caller (the control).
25+
*
26+
* "No unhandled rejection" is asserted directly: every test attaches its own
27+
* `process.on('unhandledRejection')` listener and requires that it saw nothing
28+
* once the flush chain has settled. That keeps the verdict local to the test
29+
* that owns the failing flush, instead of leaving it to whichever test happens
30+
* to be running when Vitest's own run-level report fires.
31+
*/
32+
describe('a failing background flush', () => {
33+
const dirs: string[] = [];
34+
const conns: WasmSqliteConnection[] = [];
35+
const drivers: SqliteWasmDriver[] = [];
36+
let unhandled: unknown[] = [];
37+
const onUnhandled = (reason: unknown): void => {
38+
unhandled.push(reason);
39+
};
40+
41+
beforeEach(() => {
42+
unhandled = [];
43+
process.on('unhandledRejection', onUnhandled);
44+
});
45+
46+
afterEach(async () => {
47+
process.off('unhandledRejection', onUnhandled);
48+
await Promise.all(conns.splice(0).map((c) => c.close().catch(() => {})));
49+
await Promise.all(drivers.splice(0).map((d) => d.disconnect().catch(() => {})));
50+
for (const dir of dirs.splice(0)) rmSync(dir, { recursive: true, force: true });
51+
});
52+
53+
interface Captured {
54+
errors: string[];
55+
warns: string[];
56+
}
57+
58+
function capture(): { logger: { warn: (m: string) => void; error: (m: string) => void } } & Captured {
59+
const errors: string[] = [];
60+
const warns: string[] = [];
61+
return {
62+
errors,
63+
warns,
64+
logger: { warn: (m) => warns.push(m), error: (m) => errors.push(m) },
65+
};
66+
}
67+
68+
/** A connection on a fresh file with one table, ready to take writes. */
69+
async function openConn(
70+
persist: PersistMode,
71+
logger: ConstructorParameters<typeof WasmSqliteConnection>[0]['logger'],
72+
): Promise<{ conn: WasmSqliteConnection; dir: string; file: string }> {
73+
const dir = mkdtempSync(join(tmpdir(), 'wasm-bgflush-'));
74+
dirs.push(dir);
75+
const file = join(dir, 'bg.db');
76+
const conn = new WasmSqliteConnection({ filename: file, persist, logger });
77+
conns.push(conn);
78+
await conn.open();
79+
conn.raw.run('CREATE TABLE t (id TEXT)');
80+
return { conn, dir, file };
81+
}
82+
83+
/** What the connection's dialect does for a write: change the image, then mark it. */
84+
function write(conn: WasmSqliteConnection, id: string): void {
85+
conn.raw.run('INSERT INTO t VALUES (?)', [id]);
86+
conn.markDirty();
87+
}
88+
89+
/**
90+
* Wait until every flush queued so far has settled, then give the handlers
91+
* chained after it and Node's rejection tracking their turn. The chain tail is
92+
* private, but it is the one deterministic "the background flush is over"
93+
* signal: a fixed sleep would be a race against the very thing being tested.
94+
*/
95+
async function settled(conn: WasmSqliteConnection): Promise<void> {
96+
await (conn as unknown as { flushChain: Promise<void> | null }).flushChain;
97+
await new Promise((r) => setTimeout(r, 20));
98+
}
99+
100+
function isDirty(conn: WasmSqliteConnection): boolean {
101+
return (conn as unknown as { dirty: boolean }).dirty;
102+
}
103+
104+
/** Ids on disk, read through a second connection (the file as a fresh boot sees it). */
105+
async function idsOnDisk(file: string): Promise<string[]> {
106+
const reader = new WasmSqliteConnection({ filename: file, persist: 'on-disconnect' });
107+
conns.push(reader);
108+
await reader.open();
109+
const res = reader.raw.exec('SELECT id FROM t ORDER BY id');
110+
return (res[0]?.values ?? []).map((row) => String(row[0]));
111+
}
112+
113+
// ── The three fire-and-forget sites ────────────────────────────────────────
114+
115+
it('on-write: a write whose flush fails is reported, not rejected unhandled', async () => {
116+
const log = capture();
117+
const { conn, dir, file } = await openConn('on-write', log.logger);
118+
rmSync(dir, { recursive: true, force: true });
119+
120+
write(conn, 'a');
121+
await settled(conn);
122+
123+
expect(unhandled).toEqual([]);
124+
expect(log.errors).toHaveLength(1);
125+
expect(log.errors[0]).toContain(file);
126+
expect(log.errors[0]).toContain('NOT on disk');
127+
expect(log.warns).toEqual([]);
128+
expect(isDirty(conn)).toBe(true);
129+
});
130+
131+
it('debounced: the timer-driven flush that fails is reported, not rejected unhandled', async () => {
132+
const log = capture();
133+
const { conn, dir, file } = await openConn('debounced:5', log.logger);
134+
rmSync(dir, { recursive: true, force: true });
135+
136+
write(conn, 'a');
137+
await vi.waitFor(() => {
138+
if (!(conn as unknown as { flushChain: unknown }).flushChain) {
139+
throw new Error('the debounced flush has not started');
140+
}
141+
});
142+
await settled(conn);
143+
144+
expect(unhandled).toEqual([]);
145+
expect(log.errors).toHaveLength(1);
146+
expect(log.errors[0]).toContain(file);
147+
expect(isDirty(conn)).toBe(true);
148+
});
149+
150+
it('transaction close: the flush deferred past a COMMIT that fails is reported, not rejected unhandled', async () => {
151+
const log = capture();
152+
const { conn, dir, file } = await openConn('on-write', log.logger);
153+
rmSync(dir, { recursive: true, force: true });
154+
155+
conn.noteTransactionControl('BEGIN');
156+
write(conn, 'a'); // wants a flush; deferred while the transaction is open
157+
expect((conn as unknown as { flushChain: unknown }).flushChain).toBeNull();
158+
conn.noteTransactionControl('COMMIT'); // the transaction closes: the deferred flush runs now
159+
await settled(conn);
160+
161+
expect(unhandled).toEqual([]);
162+
expect(log.errors).toHaveLength(1);
163+
expect(log.errors[0]).toContain(file);
164+
expect(isDirty(conn)).toBe(true);
165+
});
166+
167+
// ── Retry, and one report per episode ──────────────────────────────────────
168+
169+
it('dirty stays set: the next flush retries and lands once the cause is gone', async () => {
170+
const log = capture();
171+
const { conn, dir, file } = await openConn('on-write', log.logger);
172+
rmSync(dir, { recursive: true, force: true });
173+
174+
write(conn, 'a');
175+
write(conn, 'b');
176+
await settled(conn);
177+
expect(isDirty(conn)).toBe(true);
178+
expect(existsSync(file)).toBe(false);
179+
180+
mkdirSync(dir, { recursive: true }); // the cause is gone
181+
write(conn, 'c'); // the next write's background flush is the retry
182+
await settled(conn);
183+
184+
expect(unhandled).toEqual([]);
185+
expect(isDirty(conn)).toBe(false);
186+
expect(await idsOnDisk(file)).toEqual(['a', 'b', 'c']); // nothing lost to the failed attempts
187+
});
188+
189+
it('reports once per failure episode: not once per write, again after a flush has landed', async () => {
190+
const log = capture();
191+
const { conn, dir } = await openConn('on-write', log.logger);
192+
rmSync(dir, { recursive: true, force: true });
193+
194+
write(conn, 'a');
195+
write(conn, 'b');
196+
write(conn, 'c');
197+
await settled(conn);
198+
expect(log.errors).toHaveLength(1); // three failed flushes, one line
199+
200+
mkdirSync(dir, { recursive: true });
201+
await conn.flush(); // lands
202+
rmSync(dir, { recursive: true, force: true });
203+
write(conn, 'd');
204+
await settled(conn);
205+
206+
expect(unhandled).toEqual([]);
207+
expect(log.errors).toHaveLength(2); // a new episode is a new report
208+
});
209+
210+
// ── The report itself can never become the rejection ───────────────────────
211+
212+
it('a logger with only warn still hears it, at warn', async () => {
213+
const warns: string[] = [];
214+
const { conn, dir, file } = await openConn('on-write', { warn: (m: string) => warns.push(m) });
215+
rmSync(dir, { recursive: true, force: true });
216+
217+
write(conn, 'a');
218+
await settled(conn);
219+
220+
expect(unhandled).toEqual([]);
221+
expect(warns).toHaveLength(1);
222+
expect(warns[0]).toContain(file);
223+
});
224+
225+
it('a logger that throws does not turn the report into an unhandled rejection', async () => {
226+
const boom = (): never => {
227+
throw new Error('logger is down');
228+
};
229+
const logger = { warn: boom, error: boom };
230+
const { conn, dir } = await openConn('on-write', logger);
231+
rmSync(dir, { recursive: true, force: true });
232+
233+
write(conn, 'a');
234+
await settled(conn);
235+
236+
expect(unhandled).toEqual([]);
237+
expect(isDirty(conn)).toBe(true);
238+
});
239+
240+
// ── CONTROL: an awaited flush still throws to its caller ───────────────────
241+
242+
it('CONTROL: an awaited flush() still rejects to its caller, and does not also log', async () => {
243+
const log = capture();
244+
const { conn, dir } = await openConn('on-disconnect', log.logger);
245+
rmSync(dir, { recursive: true, force: true });
246+
247+
write(conn, 'a'); // on-disconnect: marks dirty, schedules nothing
248+
await expect(conn.flush()).rejects.toMatchObject({ code: 'ENOENT' });
249+
250+
expect(unhandled).toEqual([]);
251+
expect(log.errors).toEqual([]); // the caller was told; no second voice
252+
expect(isDirty(conn)).toBe(true); // and a later flush still retries
253+
254+
mkdirSync(dir, { recursive: true });
255+
await expect(conn.flush()).resolves.toBeUndefined();
256+
expect(isDirty(conn)).toBe(false);
257+
});
258+
259+
it('CONTROL: close() still rejects to its caller when the final flush fails', async () => {
260+
const log = capture();
261+
const { conn, dir } = await openConn('on-disconnect', log.logger);
262+
rmSync(dir, { recursive: true, force: true });
263+
264+
write(conn, 'a');
265+
await expect(conn.close()).rejects.toMatchObject({ code: 'ENOENT' });
266+
267+
expect(unhandled).toEqual([]);
268+
expect(log.errors).toEqual([]);
269+
});
270+
271+
// ── Through the driver: the shape of the dogfood race ──────────────────────
272+
273+
it('driver on-write: the data directory removed under a live driver is reported, the public flush() still throws', async () => {
274+
const log = capture();
275+
const dir = mkdtempSync(join(tmpdir(), 'wasm-bgflush-drv-'));
276+
dirs.push(dir);
277+
const file = join(dir, 'drv.db');
278+
const driver = new SqliteWasmDriver({ filename: file, persist: 'on-write', logger: log.logger });
279+
drivers.push(driver);
280+
await driver.initObjects([{ name: 'acct', fields: { name: { type: 'string' } } }]);
281+
const knex = (driver as any).knex;
282+
await knex('acct').insert({ id: 'a1', name: 'A' });
283+
await driver.flush();
284+
expect(existsSync(file)).toBe(true);
285+
286+
// The refused boot's driver is never torn down; the test's cleanup removes
287+
// the directory under it; the next write's flush meets the missing directory.
288+
rmSync(dir, { recursive: true, force: true });
289+
await knex('acct').insert({ id: 'a2', name: 'B' });
290+
const conn = await knex.client.acquireConnection();
291+
await knex.client.releaseConnection(conn);
292+
await settled(conn);
293+
294+
expect(unhandled).toEqual([]);
295+
expect(log.errors).toHaveLength(1);
296+
expect(log.errors[0]).toContain(file);
297+
await expect(driver.flush()).rejects.toMatchObject({ code: 'ENOENT' });
298+
});
299+
});

0 commit comments

Comments
 (0)