From 34bef99875b3f3221fef8d6df64831aa2b4f3ee5 Mon Sep 17 00:00:00 2001 From: Markus Hartung Date: Tue, 8 Sep 2026 02:20:21 +0200 Subject: [PATCH] fix(db): report checkpoint failure instead of a false "completed" on WAL TRUNCATE busy checkpointDb() called `wal_checkpoint(mode)` and unconditionally returned true, ignoring the {busy, log, checkpointed} row the pragma always returns (https://www.sqlite.org/pragma.html#pragma_wal_checkpoint). busy != 0 means SQLite could not get the lock TRUNCATE needs (full exclusivity -- any other open connection, reader or not, blocks it), and the WAL file was NOT shrunk, no matter how many frames "checkpointed" reports. Both callers logged success unconditionally as a result: - The periodic scheduler (startWalTruncateScheduler, every 6h by default) always printed "[DB] Periodic SQLite WAL checkpoint completed (TRUNCATE)." even when the checkpoint silently no-oped. - closeDbInstance() did the same on shutdown. On a server that is rarely fully idle (continuous SSE/embedding/batch traffic keeps a connection open), TRUNCATE may never actually get the lock it needs, so the WAL just grows monotonically -- with the logs claiming success the entire time. Observed live: an 11.7 GB WAL file, nearly as large as the 11 GB main database it shadows, which then blocked all HTTP traffic for ~15-20 minutes on the next restart while an unrelated startup VACUUM churned through the bloated database. Fix: checkpointDb() now reads the pragma's own busy field and only reports success when busy === 0. Both call sites now log the deferred/no-op case too (previously silent), so a WAL that never finds an idle moment is visible in the logs instead of looking identical to a healthy server. Regression test (tests/unit/db-wal-checkpoint-busy-detection.test.ts) opens a real WAL-mode SQLite file, holds it busy from a second connection with an open read transaction, and asserts checkpointDb() correctly reports false while busy and true once the lock is available -- reproducing the same busy=1 SQLite returns in production, empirically verified locally before writing the fix. Evidence: - node --test tests/unit/db-wal-checkpoint-busy-detection.test.ts: 2/2 pass - node --test tests/unit/db-wal-truncate-scheduler.test.ts (pre-existing, unmodified): 6/6 pass - node --test tests/unit/db-core-extended.test.ts tests/unit/db-core-init.test.ts tests/unit/db-reset-module-state.test.ts tests/unit/graceful-shutdown-sighup-8045.test.ts: 44/44 pass (unaffected) - eslint on both touched files: clean (3 pre-existing unrelated errors in core.ts confirmed present on unmodified release/v3.8.51 too, not touched) - tsc --noEmit: no errors in touched files Co-Authored-By: Claude Sonnet 5 --- src/lib/db/core.ts | 28 +++++- .../db-wal-checkpoint-busy-detection.test.ts | 88 +++++++++++++++++++ 2 files changed, 112 insertions(+), 4 deletions(-) create mode 100644 tests/unit/db-wal-checkpoint-busy-detection.test.ts diff --git a/src/lib/db/core.ts b/src/lib/db/core.ts index c8ba9b1f1801..f91ded9220c8 100644 --- a/src/lib/db/core.ts +++ b/src/lib/db/core.ts @@ -529,10 +529,20 @@ declare global { var __omnirouteDbOomFailureCount: number | undefined; } -function checkpointDb(db: SqliteDatabase, mode: CheckpointMode = "TRUNCATE"): boolean { +// `wal_checkpoint(mode)` always returns exactly one row of {busy, log, checkpointed} +// (see https://www.sqlite.org/pragma.html#pragma_wal_checkpoint). busy != 0 means +// SQLite could not get the lock this mode needs (for TRUNCATE: full exclusivity -- +// any other open connection, reader or not, blocks it) and the WAL was NOT shrunk, +// no matter how many frames "checkpointed" reports. This used to be ignored, so +// callers always reported "completed" even when TRUNCATE silently no-oped -- on a +// server that is rarely fully idle, that hid a WAL that grew unboundedly (observed +// live: an 11.7 GB WAL file, nearly as large as the 11 GB main database it shadows). +export function checkpointDb(db: SqliteDatabase, mode: CheckpointMode = "TRUNCATE"): boolean { if (isCloud || isBuildPhase || !SQLITE_FILE) return false; - db.pragma(`wal_checkpoint(${mode})`); - return true; + const [result] = db.pragma(`wal_checkpoint(${mode})`) as [ + { busy: number; log: number; checkpointed: number }, + ]; + return result?.busy === 0; } function summarizePreservedTables(tables: PreservedTableSnapshot[]): string { @@ -995,9 +1005,15 @@ function startWalTruncateScheduler(db: SqliteDatabase) { try { if (!db.open) return; // TRUNCATE waits for readers; under concurrent write load it can no-op without - // shrinking the file. That is expected — it retries on the next tick. + // shrinking the file. That is expected — it retries on the next tick. Log the + // no-op case too (previously silent) so a WAL that never finds an idle moment + // is visible in the logs instead of looking identical to a healthy server. if (checkpointDb(db, "TRUNCATE")) { console.log("[DB] Periodic SQLite WAL checkpoint completed (TRUNCATE)."); + } else { + console.log( + "[DB] Periodic SQLite WAL checkpoint deferred (TRUNCATE busy -- a concurrent connection held the lock it needs); will retry next tick." + ); } } catch (error: unknown) { const message = error instanceof Error ? error.message : String(error); @@ -1429,6 +1445,10 @@ export function closeDbInstance(options?: { checkpointMode?: CheckpointMode | nu try { if (checkpointDb(db, checkpointMode)) { console.log(`[DB] SQLite WAL checkpoint completed (${checkpointMode}).`); + } else { + console.warn( + `[DB] SQLite WAL checkpoint did not fully complete during close (${checkpointMode}) -- another connection held the lock it needs; the WAL file may remain large.` + ); } } catch (error: unknown) { const message = error instanceof Error ? error.message : String(error); diff --git a/tests/unit/db-wal-checkpoint-busy-detection.test.ts b/tests/unit/db-wal-checkpoint-busy-detection.test.ts new file mode 100644 index 000000000000..05bf3236e8fc --- /dev/null +++ b/tests/unit/db-wal-checkpoint-busy-detection.test.ts @@ -0,0 +1,88 @@ +// checkpointDb() used to call `wal_checkpoint(mode)` and unconditionally return true, +// ignoring the {busy, log, checkpointed} row the pragma always returns. On a server +// that is rarely fully idle, wal_checkpoint(TRUNCATE) regularly comes back busy=1 -- +// it got SOME lock to copy frames back into the main file, but not the exclusive one +// TRUNCATE needs to shrink the file -- yet callers logged "completed" every time +// anyway. Observed live: an 11.7 GB WAL file, nearly as large as the 11 GB main +// database it shadows, with the periodic scheduler's own logs claiming success the +// entire time. +// +// checkpointDb() itself isn't gated by isAutomatedTestProcess() (only the scheduler +// wrapper around it is -- see db-wal-truncate-scheduler.test.ts, which pins that +// wiring via source inspection since the scheduler can't run in this harness). This +// exercises the real function against a real WAL-mode SQLite file and a genuinely +// busy second connection, the same way SQLite itself reports busy=1 in production. + +import test from "node:test"; +import assert from "node:assert/strict"; +import fs from "node:fs"; +import os from "node:os"; +import path from "node:path"; +import Database from "better-sqlite3"; + +const TEST_DATA_DIR = fs.mkdtempSync(path.join(os.tmpdir(), "omniroute-wal-checkpoint-")); +process.env.DATA_DIR = TEST_DATA_DIR; + +const core = await import("../../src/lib/db/core.ts"); + +function makeWalDb(): { file: string; db: InstanceType } { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), "omniroute-wal-checkpoint-db-")); + const file = path.join(dir, "test.sqlite"); + const db = new Database(file); + db.pragma("journal_mode = WAL"); + // better-sqlite3 defaults busy_timeout to 5000ms, which would make the busy-path + // assertions below block for 5s each retrying a lock they're deliberately testing + // will not become available -- 0 makes SQLITE_BUSY come back immediately. + db.pragma("busy_timeout = 0"); + db.exec("CREATE TABLE t (id INTEGER PRIMARY KEY, v TEXT)"); + db.exec("INSERT INTO t (v) VALUES ('hello')"); + return { file, db }; +} + +test("checkpointDb reports failure (not success) when TRUNCATE cannot get the lock it needs", () => { + const { file, db } = makeWalDb(); + + // A second connection with an open read transaction reproduces the real + // "server never fully idle" condition that let this bug hide in production -- + // reads happen continuously, so TRUNCATE's exclusivity requirement is rarely met. + const reader = new Database(file); + reader.exec("BEGIN"); + reader.prepare("SELECT * FROM t").get(); + + assert.equal( + core.checkpointDb(db, "TRUNCATE"), + false, + "must report failure while a concurrent reader holds the file open" + ); + assert.notEqual( + fs.statSync(`${file}-wal`).size, + 0, + "the WAL file must NOT have been truncated while busy" + ); + + reader.exec("COMMIT"); + reader.close(); + db.close(); +}); + +test("checkpointDb reports success once TRUNCATE actually gets exclusivity", () => { + const { file, db } = makeWalDb(); + + const reader = new Database(file); + reader.exec("BEGIN"); + reader.prepare("SELECT * FROM t").get(); + assert.equal(core.checkpointDb(db, "TRUNCATE"), false); + + // Committing (even without closing the connection) releases the lock TRUNCATE needs. + reader.exec("COMMIT"); + + assert.equal( + core.checkpointDb(db, "TRUNCATE"), + true, + "must report success once no connection holds a blocking lock" + ); + assert.equal(fs.statSync(`${file}-wal`).size, 0, "the WAL file must be truncated to zero"); + + reader.close(); + db.close(); +});