fix(db): persist WAL busy counter across restarts (#13218)

The WAL busy counter survives restarts: it is persisted in `key_value` and restored at boot, so the health output no longer resets to zero after every restart.

Maintainer rework before merge (kept the idea, no default behavior change):
- `recordBusy()` no longer writes synchronously on the contended path (with `busy_timeout = 2000` that could block the event loop for up to 2s); it accumulates in memory and `flushBusyTotal()` upserts the delta on a clean passive/TRUNCATE tick or best-effort at stop.
- The boot wiring is tested for real: a child Node process drives `startWalMaintenance` against a real SQLite file (restore at boot, zero writes while busy, one flush at stop, restore after restart).

Validated first on the combined board of all 38 PRs of this batch (10 merged as-is, 28 after the maintainer rework) on top of release/v3.8.51 c0f92ec: typecheck:core, check:open-sse-typecheck and check:dashboard-typecheck clean; ESLint clean on every changed file; file-size (rebaselined for the combined growth), complexity, cognitive-complexity, changelog-integrity, docs-counts, docs-sync, migration-numbering and i18n new-key gates green; 735 focused node:test cases with the only batch-caused failure (a flag-count assertion) fixed. Then re-validated alone on the fresh release tip right before this merge: ESLint on the changed files, typecheck:core, check:open-sse-typecheck, the file-size/complexity/changelog gates and this PR's own tests.

Thanks @maxmad64bis!
This commit is contained in:
Dizzle
2026-09-15 18:21:52 +02:00
committed by GitHub
parent 7cabac4985
commit 62cd27720a
3 changed files with 235 additions and 0 deletions

View File

@@ -0,0 +1 @@
- **fix(db):** the WAL checkpoint busy counter reported by `/api/monitoring/health` now survives restarts — busy checkpoints are counted in memory and persisted from the next clean maintenance tick or at shutdown, never with a write while the database is contended ([#13218](https://github.com/diegosouzapw/OmniRoute/pull/13218)) — thanks @maxmad64bis

View File

@@ -41,6 +41,9 @@ const DEFAULT_WAL_PASSIVE_INTERVAL_MS = 5 * 60 * 1000;
const DEFAULT_WAL_GUARD_MAX_BYTES = 256 * 1024 * 1024;
const RETRY_DELAY_MS = 60_000;
export const WAL_BUSY_NAMESPACE = "walMaintenance";
export const WAL_BUSY_KEY = "busyTotal";
let walTimer: NodeJS.Timeout | null = null;
let walPassiveTimer: NodeJS.Timeout | null = null;
let retryTimer: NodeJS.Timeout | null = null;
@@ -49,13 +52,44 @@ let busyStreak = 0;
let busyTotal = 0;
let lastBusyAt: string | null = null;
let lastOkAt: string | null = null;
// Busy events counted in memory but not yet added to the persisted counter.
let pendingBusyDelta = 0;
// The handle the running scheduler was started with; used for the shutdown flush.
let activeDb: SqliteAdapter | null = null;
/**
* Count one busy checkpoint. Memory only, on purpose: a busy checkpoint means the
* database is contended RIGHT NOW, and a write here would wait up to `busy_timeout`
* (2s) on the event loop. The increment is persisted later by flushBusyTotal() from
* a non-busy scheduler tick or at shutdown.
*/
function recordBusy(): void {
busyStreak++;
busyTotal++;
pendingBusyDelta++;
lastBusyAt = new Date().toISOString();
}
/**
* Add the pending busy events to the persisted counter. Best-effort and single-shot:
* any failure (locked, closed, missing table) keeps the delta pending for the next
* non-busy tick — there is no retry loop. The additive UPSERT stays correct when
* several processes share the database file.
*/
export function flushBusyTotal(db: SqliteAdapter | null): boolean {
if (pendingBusyDelta === 0 || !db || !db.open) return false;
try {
db.prepare(
"INSERT INTO key_value(namespace, key, value) VALUES(?, ?, ?) " +
"ON CONFLICT(namespace, key) DO UPDATE SET value = CAST(value AS INTEGER) + excluded.value"
).run(WAL_BUSY_NAMESPACE, WAL_BUSY_KEY, pendingBusyDelta);
pendingBusyDelta = 0;
return true;
} catch {
return false;
}
}
function recordOk(): void {
busyStreak = 0;
lastOkAt = new Date().toISOString();
@@ -207,6 +241,7 @@ function schedulePassiveRetry(db: SqliteAdapter): void {
logCheckpointOutcome(outcome, "PASSIVE", busyStreak);
} else if (outcome.ok) {
recordOk();
flushBusyTotal(db);
} else {
logCheckpointOutcome(outcome, "PASSIVE", busyStreak);
}
@@ -239,6 +274,7 @@ function startWalPassiveScheduler(
isBuildPhase: isNextBuildPhase(),
});
if (stats.skipped) return;
if (!stats.busy && stats.ok) flushBusyTotal(db);
if (stats.busy || (stats.checkpointedFrames ?? 0) > 0) {
console.log(
`[DB] WAL passive checkpoint (busy=${stats.busy ? 1 : 0} logFrames=${stats.logFrames} ` +
@@ -273,8 +309,13 @@ export function startWalMaintenance(
sqliteFile: string | null,
env: NodeJS.ProcessEnv = process.env
): void {
// stopWalMaintenance() flushes what it can and zeroes session state, so capture the
// in-memory total first; the gate stays before any DB touch.
const priorBusyTotal = busyTotal;
stopWalMaintenance();
if (sqliteFile === null || isCloud || isNextBuildPhase() || isAutomatedTestProcess()) return;
activeDb = db;
busyTotal = mergeBusyTotal(priorBusyTotal, loadPersistedBusyTotal(db));
const intervalMs = getWalMaintenanceIntervalMs(env);
if (intervalMs <= 0) {
startWalPassiveScheduler(db, sqliteFile, env);
@@ -294,6 +335,7 @@ export function startWalMaintenance(
schedulePassiveRetry(db);
} else if (outcome.ok) {
recordOk();
flushBusyTotal(db);
console.log(
`[DB] Periodic SQLite WAL checkpoint completed (TRUNCATE) in ${Date.now() - startedAtMs}ms ` +
`(walMbBefore=${formatWalMb(walBeforeBytes)} walMbAfter=${formatWalMb(getWalFileSizeBytes(sqliteFile))} ` +
@@ -311,6 +353,10 @@ export function startWalMaintenance(
}
export function stopWalMaintenance(): void {
// Shutdown / restart: best-effort persist of busy events not flushed by a tick.
flushBusyTotal(activeDb);
activeDb = null;
pendingBusyDelta = 0;
if (walTimer) {
clearInterval(walTimer);
walTimer = null;
@@ -334,6 +380,27 @@ export function getWalMaintenanceState(): WalMaintenanceState {
return { ticks, busyStreak, busyTotal, lastBusyAt, lastOkAt };
}
export function loadPersistedBusyTotal(db: SqliteAdapter): number {
try {
const row = db
.prepare("SELECT value FROM key_value WHERE namespace = ? AND key = ?")
.get(WAL_BUSY_NAMESPACE, WAL_BUSY_KEY) as { value: unknown } | undefined;
const n = Number(row?.value);
return Number.isFinite(n) && n >= 0 ? Math.floor(n) : 0;
} catch (error) {
// Boot read-path, not the hot scheduler path: never fail silently.
console.warn(`[DB] WAL busy counter unreadable, starting from 0: ${String(error)}`);
return 0;
}
}
export function mergeBusyTotal(prior: number, loaded: number): number {
// Both inputs floored, non-finite or negative → 0 (matches load fallback).
const p = Number.isFinite(prior) && prior > 0 ? Math.floor(prior) : 0;
const l = Number.isFinite(loaded) && loaded > 0 ? Math.floor(loaded) : 0;
return Math.max(p, l);
}
export function __resetForTests(): void {
stopWalMaintenance();
}

View File

@@ -164,3 +164,170 @@ test("start is silent and stateless under the test-process gate", async () => {
test.beforeEach(async () => {
(await import("../../src/lib/db/walMaintenance.ts")).__resetForTests();
});
test("mergeBusyTotal keeps the max, floors at 0", async () => {
const { mergeBusyTotal } = await import("../../src/lib/db/walMaintenance.ts");
assert.equal(mergeBusyTotal(5, 3), 5);
assert.equal(mergeBusyTotal(3, 5), 5);
assert.equal(mergeBusyTotal(0, 0), 0);
assert.equal(mergeBusyTotal(-2, -7), 0);
assert.equal(mergeBusyTotal(2.9, 1), 2);
});
test("loadPersistedBusyTotal reads the key, falls back to 0", async () => {
const { loadPersistedBusyTotal } = await import("../../src/lib/db/walMaintenance.ts");
const store = new Map<string, string>([["walMaintenance/busyTotal", "41"]]);
const db = {
pragma: () => [{ busy: 0, log: 0, checkpointed: 0 }],
prepare: (_sql: string) => ({
get: () => {
const v = store.get("walMaintenance/busyTotal");
return v === undefined ? undefined : { value: v };
},
run: () => {},
}),
};
assert.equal(loadPersistedBusyTotal(db as never), 41);
store.set("walMaintenance/busyTotal", "abc");
assert.equal(loadPersistedBusyTotal(db as never), 0);
store.delete("walMaintenance/busyTotal");
assert.equal(loadPersistedBusyTotal(db as never), 0);
});
test("flushBusyTotal is a no-op with nothing pending or no open handle", async () => {
const { flushBusyTotal } = await import("../../src/lib/db/walMaintenance.ts");
let prepared = 0;
const db = {
open: true,
prepare: () => {
prepared++;
return { run: () => {} };
},
};
assert.equal(flushBusyTotal(db as never), false);
assert.equal(flushBusyTotal(null), false);
assert.equal(prepared, 0);
});
/**
* The scheduler is gated off inside test runners (isAutomatedTestProcess), so the real boot
* wiring runs in a child Node process that is not a test process. It drives the actual
* startWalMaintenance()/stopWalMaintenance() against a real SQLite file; only the checkpoint
* pragma result is scripted (busy vs clean) so contention can be produced on demand. Module
* paths travel through env vars so no argv token makes the child look like a test runner.
*/
const CHILD_SCRIPT = `
const { startWalMaintenance, stopWalMaintenance, getWalMaintenanceState } = await import(process.env.WAL_MODULE_URL);
const { tryOpenSync } = await import(process.env.DRIVER_MODULE_URL);
const file = process.env.WAL_DB_FILE;
const sleep = (ms) => new Promise((r) => setTimeout(r, ms));
const real = tryOpenSync(file);
if (!real) { console.log("WALCHILD " + JSON.stringify({ skipped: true })); process.exit(0); }
let mode = "busy";
const writes = [];
const db = {
get open() { return real.open; },
pragma: (s, o) => s.startsWith("wal_checkpoint")
? [mode === "busy" ? { busy: 1, log: 5, checkpointed: 0 } : { busy: 0, log: 0, checkpointed: 0 }]
: real.pragma(s, o),
prepare: (sql) => { if (/INSERT/i.test(sql)) writes.push(mode); return real.prepare(sql); },
exec: (sql) => real.exec(sql),
close: () => real.close(),
};
const persisted = () => Number(real.prepare("SELECT value FROM key_value WHERE namespace='walMaintenance' AND key='busyTotal'").get()?.value ?? 0);
const env = { OMNIROUTE_WAL_TRUNCATE_INTERVAL_MS: "60", OMNIROUTE_WAL_PASSIVE_INTERVAL_MS: "0" };
const out = {};
startWalMaintenance(db, file, env);
out.restoredAtBoot = getWalMaintenanceState().busyTotal;
await sleep(400);
out.afterBusy = { total: getWalMaintenanceState().busyTotal, persisted: persisted(), writes: writes.length };
mode = "ok";
await sleep(300);
out.afterOkTick = { total: getWalMaintenanceState().busyTotal, persisted: persisted(), busyWrites: writes.filter((m) => m === "busy").length };
mode = "busy";
await sleep(300);
out.beforeStop = { total: getWalMaintenanceState().busyTotal, persisted: persisted() };
mode = "stopping";
stopWalMaintenance();
out.afterStop = { persisted: persisted(), busyWrites: writes.filter((m) => m === "busy").length, stopWrites: writes.filter((m) => m === "stopping").length };
startWalMaintenance(db, file, env);
out.restoredAfterRestart = getWalMaintenanceState().busyTotal;
stopWalMaintenance();
real.close();
console.log("WALCHILD " + JSON.stringify(out));
process.exit(0);
`;
test("boot wiring: restores the persisted total, never writes on a busy tick, flushes on a clean tick and at stop", async (t) => {
const { spawnSync } = await import("node:child_process");
const fs = await import("node:fs");
const os = await import("node:os");
const path = await import("node:path");
const { pathToFileURL } = await import("node:url");
const { tryOpenSync } = await import("../../src/lib/db/adapters/driverFactory.ts");
const dir = fs.mkdtempSync(path.join(os.tmpdir(), "omniroute-wal-boot-"));
const file = path.join(dir, "storage.sqlite");
const seed = tryOpenSync(file);
if (!seed) {
fs.rmSync(dir, { recursive: true, force: true });
t.skip("no sync SQLite driver available");
return;
}
try {
seed.exec(
"CREATE TABLE IF NOT EXISTS key_value (namespace TEXT NOT NULL, key TEXT NOT NULL, value TEXT NOT NULL, PRIMARY KEY (namespace, key))"
);
seed
.prepare(
"INSERT INTO key_value (namespace, key, value) VALUES ('walMaintenance', 'busyTotal', '41')"
)
.run();
seed.close();
const repoRoot = path.resolve(import.meta.dirname, "../..");
const env: NodeJS.ProcessEnv = {
...process.env,
WAL_MODULE_URL: pathToFileURL(path.join(repoRoot, "src/lib/db/walMaintenance.ts")).href,
DRIVER_MODULE_URL: pathToFileURL(path.join(repoRoot, "src/lib/db/adapters/driverFactory.ts"))
.href,
WAL_DB_FILE: file,
NODE_ENV: "production",
};
delete env.VITEST;
delete env.NODE_TEST_CONTEXT;
const child = spawnSync(
process.execPath,
["--import", "tsx/esm", "--input-type=module", "-e", CHILD_SCRIPT],
{ cwd: repoRoot, env, encoding: "utf8", timeout: 120_000 }
);
const line = (child.stdout || "").split("\n").find((l) => l.startsWith("WALCHILD "));
assert.ok(line, `child produced no result (status ${child.status}): ${child.stderr}`);
const out = JSON.parse(line.slice("WALCHILD ".length));
if (out.skipped) {
t.skip("child could not open a sync SQLite driver");
return;
}
assert.equal(out.restoredAtBoot, 41, "boot restores the persisted counter");
assert.ok(out.afterBusy.total > 41, "busy ticks are counted in memory");
assert.equal(out.afterBusy.writes, 0, "no database write on the busy path");
assert.equal(out.afterBusy.persisted, 41, "persisted value untouched while contended");
assert.equal(out.afterOkTick.busyWrites, 0);
assert.equal(
out.afterOkTick.persisted,
out.afterOkTick.total,
"a clean tick flushes the delta"
);
assert.ok(out.beforeStop.total > out.afterOkTick.total, "more busy ticks after the flush");
assert.equal(out.beforeStop.persisted, out.afterOkTick.total, "still no write while busy");
assert.equal(out.afterStop.busyWrites, 0);
assert.equal(out.afterStop.stopWrites, 1, "exactly one flush at stop");
assert.equal(out.afterStop.persisted, out.beforeStop.total, "stop flushes the remaining delta");
assert.equal(out.restoredAfterRestart, out.beforeStop.total, "restart restores the full total");
} finally {
fs.rmSync(dir, { recursive: true, force: true });
}
});