diff --git a/changelog.d/fixes/12394-deflake-exclusive-connection-leases.md b/changelog.d/fixes/12394-deflake-exclusive-connection-leases.md new file mode 100644 index 0000000000..a8f145d6d9 --- /dev/null +++ b/changelog.d/fixes/12394-deflake-exclusive-connection-leases.md @@ -0,0 +1 @@ +- **fix(db):** install `busy_timeout` before the SQLite connection's first statement so a process opening the database while another one closes its WAL connection waits out the transient EXCLUSIVE lock instead of dying with `database is locked`, and recognise the drivers' real BUSY/PROTOCOL/IOERR errors as transient in the corruption probe so the same lock no longer renames the database away as corrupt; deflakes `cross-process contenders never both acquire the same connection` (#12394 — thanks @pacocartones) diff --git a/src/lib/db/core.ts b/src/lib/db/core.ts index 43132c6f7e..d636899a32 100644 --- a/src/lib/db/core.ts +++ b/src/lib/db/core.ts @@ -1277,13 +1277,18 @@ export function getDbInstance(): SqliteDatabase { // selected on the server's primary DB path too, not only the backup-import // route. console.log(`[DB] Driver: ${db.driver} | file: ${sqliteFile}`); - db.pragma("journal_mode = WAL"); // better-sqlite3 is synchronous, so a contended write parks the Node event loop for up to // busy_timeout ms (a 0-CPU freeze that stacks under load → /health stops responding). The // hot-path writers here (usage_history, call_logs) are best-effort and the WinUI host opens // the same DB, so cap the block at 2s instead of 5s: normal writes complete in <1ms, and a // contended op can no longer freeze the loop past the host watchdog's 6s liveness probe. + // + // Install the busy handler before the connection's first statement. `journal_mode = WAL` + // needs a SHARED lock, and another process closing its WAL connection briefly holds the + // file EXCLUSIVE (checkpoint + WAL delete); node:sqlite opens with busy timeout 0, so with + // the pragmas in the other order that window surfaced as `database is locked` at startup. db.pragma("busy_timeout = 2000"); + db.pragma("journal_mode = WAL"); db.pragma("synchronous = NORMAL"); db.pragma(`cache_size = -${DEFAULT_DATABASE_SETTINGS.optimization.cacheSize}`); db.pragma("temp_store = MEMORY"); diff --git a/src/lib/db/probeUtils.ts b/src/lib/db/probeUtils.ts index e5f2bd3885..4f0df076e8 100644 --- a/src/lib/db/probeUtils.ts +++ b/src/lib/db/probeUtils.ts @@ -22,7 +22,19 @@ import path from "node:path"; */ export function isTransientProbeError(error: unknown): boolean { const message = error instanceof Error ? error.message : String(error); - return /SQLITE_BUSY|SQLITE_PROTOCOL|SQLITE_IOERR|ENOENT/i.test(message); + if (/SQLITE_BUSY|SQLITE_PROTOCOL|SQLITE_IOERR|ENOENT|database is locked/i.test(message)) { + return true; + } + // The real drivers do not put the result-code name in the message: both + // report plain "database is locked" for SQLITE_BUSY. better-sqlite3 carries + // the name in `code`, node:sqlite the numeric primary code in `errcode` + // (5 BUSY, 10 IOERR, 15 PROTOCOL; extended codes live in the high bits). + // Without this, a transient lock during the probe was classified as + // corruption and the database was renamed away. + if (typeof error !== "object" || error === null) return false; + const { code, errcode } = error as { code?: unknown; errcode?: unknown }; + if (typeof code === "string" && /^SQLITE_(BUSY|PROTOCOL|IOERR)/.test(code)) return true; + return typeof errcode === "number" && [5, 10, 15].includes(errcode & 0xff); } /** diff --git a/tests/unit/db-open-first-statement-busy-timeout.test.ts b/tests/unit/db-open-first-statement-busy-timeout.test.ts new file mode 100644 index 0000000000..5ff8661eb9 --- /dev/null +++ b/tests/unit/db-open-first-statement-busy-timeout.test.ts @@ -0,0 +1,118 @@ +import assert from "node:assert/strict"; +import { spawn } from "node:child_process"; +import fs from "node:fs"; +import os from "node:os"; +import path from "node:path"; +import { DatabaseSync } from "node:sqlite"; +import test from "node:test"; + +// Regression for the "cross-process contenders never both acquire the same +// connection" flake (tests/unit/exclusive-connection-leases.test.ts): the +// faster contender exited while the slower one was still opening, and a +// closing WAL connection briefly takes an EXCLUSIVE lock on the database file +// (checkpoint + WAL delete). getDbInstance() issued `PRAGMA journal_mode = WAL` +// — the connection's first statement, which needs a SHARED lock — *before* +// installing the busy handler, so on node:sqlite (busy timeout 0 by default) +// the slower process died with `database is locked` instead of waiting the few +// milliseconds the lock is held. The corruption probe that runs first had the +// same gap: it only recognised BUSY when the driver put "SQLITE_BUSY" in the +// message, which neither node:sqlite nor better-sqlite3 does, so a transient +// lock there renamed the database away as corrupt. +// +// The holder below reproduces the lock deterministically (WAL + EXCLUSIVE +// locking mode keeps the file lock from the first read until close) and +// releases it only after the child has reached getDbInstance(), so the open +// path meets the lock on every run and must wait it out via busy_timeout. + +const CORE_URL = new URL("../../src/lib/db/core.ts", import.meta.url).href; +// Longer than the probe's first transient-retry delay (500ms), so the main +// open still meets the lock after the probe has retried; well inside the +// 2000ms busy_timeout getDbInstance() configures, so the fixed open waits it +// out instead of timing out. +const HOLD_MS = 1200; + +type ChildResult = { code: number | null; stdout: string; stderr: string }; + +function runChild(script: string, env: Record): Promise { + return new Promise((resolve, reject) => { + const child = spawn( + process.execPath, + ["--import", "tsx/esm", "--input-type=module", "-e", script], + { + cwd: process.cwd(), + env: { ...process.env, ...env }, + stdio: ["ignore", "pipe", "pipe"], + } + ); + let stdout = ""; + let stderr = ""; + child.stdout.setEncoding("utf8").on("data", (chunk) => (stdout += chunk)); + child.stderr.setEncoding("utf8").on("data", (chunk) => (stderr += chunk)); + child.once("error", reject); + child.once("exit", (code) => resolve({ code, stdout, stderr })); + }); +} + +async function waitForFile(file: string, timeoutMs: number): Promise { + const deadline = Date.now() + timeoutMs; + while (!fs.existsSync(file)) { + if (Date.now() > deadline) throw new Error(`timed out waiting for ${file}`); + await new Promise((resolve) => setTimeout(resolve, 5)); + } +} + +test("getDbInstance() waits out a transient exclusive file lock instead of failing on its first statement", async () => { + const dataDir = fs.mkdtempSync(path.join(os.tmpdir(), "omniroute-open-busy-")); + const sqliteFile = path.join(dataDir, "storage.sqlite"); + const ready = path.join(dataDir, "ready"); + const env = { DATA_DIR: dataDir, OPEN_READY_FILE: ready }; + let holder: DatabaseSync | null = null; + try { + // Seed a real database (schema + migrations) so the corruption probe in + // getDbInstance() sees a healthy file rather than a skeleton. + const seed = await runChild( + `const core = await import(${JSON.stringify(CORE_URL)}); core.getDbInstance(); core.closeDbInstance();`, + env + ); + assert.equal(seed.code, 0, seed.stderr); + + // Hold the database file's EXCLUSIVE lock from another connection, exactly + // what a closing WAL connection holds while it checkpoints and deletes the WAL. + holder = new DatabaseSync(sqliteFile); + holder.exec("PRAGMA locking_mode = EXCLUSIVE"); + holder.prepare("SELECT count(*) AS n FROM sqlite_master").get(); + + const opener = runChild( + [ + `import fs from "node:fs";`, + `const core = await import(${JSON.stringify(CORE_URL)});`, + `fs.writeFileSync(process.env.OPEN_READY_FILE, "ready");`, + `const busyTimeout = core.getDbInstance().pragma("busy_timeout", { simple: true });`, + `core.closeDbInstance();`, + `process.stdout.write(JSON.stringify({ busyTimeout }) + "\\n");`, + ].join("\n"), + env + ); + await waitForFile(ready, 30_000); + await new Promise((resolve) => setTimeout(resolve, HOLD_MS)); + holder.close(); + holder = null; + + const result = await opener; + assert.equal(result.code, 0, `open failed under a transient lock: ${result.stderr}`); + // The probe may log that it met the lock; what must not happen is the + // corruption path (rename + manual-recovery abort) or a failed main open. + assert.doesNotMatch(result.stderr, /Renamed corrupt DB|probe-failed|Manual recovery/); + assert.deepEqual( + fs.readdirSync(dataDir).filter((name) => name.includes("probe-failed")), + [], + "a transient lock must not rename the database away as corrupt" + ); + const summary = result.stdout.match(/^\{"busyTimeout":(\d+)\}$/m); + assert.ok(summary, `child did not report its busy timeout: ${result.stdout}`); + assert.equal(Number(summary[1]), 2000); + } finally { + holder?.close(); + fs.rmSync(dataDir, { recursive: true, force: true, maxRetries: 5, retryDelay: 100 }); + } +});