diff --git a/server/config.js b/server/config.js index 64b5321..7750b1d 100644 --- a/server/config.js +++ b/server/config.js @@ -226,6 +226,11 @@ module.exports = { // is LOWER than the old hardcoded 7 days (the reporter's bloat happened under 7d); // 2-3 days is plenty for the dashboard's 24h uptime view + diagnostics. statusLogRetentionDays: parseFloat(process.env.STATUS_LOG_RETENTION_DAYS) || 3, + // #240 device_telemetry age retention (pruneTelemetryRetention in db/database.js). The + // per-heartbeat row cap only trims devices that are still reporting; this closes the + // rows left behind by ones that stopped. 30d matches the uptime report's default window, + // so it can only remove rows the report would not have shown anyway. + telemetryRetentionDays: parseFloat(process.env.TELEMETRY_RETENTION_DAYS) || 30, // #146 HARD per-device row-count ceiling on device_status_log, enforced by the // global sweep alongside the age delete above. Age-based retention can't bound a // write storm (rows are all younger than the window), so a reconnect storm grew @@ -303,6 +308,24 @@ module.exports = { // ...or escalate if the WAL grew across this many consecutive PASSIVE runs (PASSIVE not // keeping up even below the high-water). Belt-and-suspenders with the MB bound above. walCheckpointStarvationRuns: parseInt(process.env.WAL_CHECKPOINT_STARVATION_RUNS) || 3, + // #240: ...but growth alone is NOT starvation. Any sustained write burst — a fleet + // powering on in the morning — grows the WAL across several consecutive PASSIVE runs + // while it is still tiny. Escalating there buys nothing (there is nothing to reclaim) + // and costs a lot: TRUNCATE is the BLOCKING form, and it blocks across connections, so + // every main-thread statement issued during it sits in SQLite's busy handler (5s by + // default in better-sqlite3) — a multi-second loop stall at exactly the moment the + // fleet is reconnecting. So the growth signal may only escalate once the WAL is big + // enough for a blocking checkpoint to be worth it. The high-water mark above is + // unchanged and remains the hard backstop, so the WAL still cannot grow unbounded. + // Set at half the high-water mark: a WAL still in the lower half is not worth blocking + // for, and anything in the upper half is close enough to the backstop to be worth it. + walCheckpointStarvationFloorMB: parseFloat(process.env.WAL_CHECKPOINT_STARVATION_FLOOR_MB) || 8, + // #240: the floor alone is not enough — a WAL that already sits above it (Bold's was + // 6.2MB against a 16MB high-water) would still escalate on every burst. So the growth + // path is ALSO rate-limited: however long the write pressure lasts, our own maintenance + // may stall the loop at most once per this window. The high-water escalation is + // deliberately EXEMPT — that one is the runaway-WAL backstop and must never be delayed. + walCheckpointEscalateCooldownMs: parseInt(process.env.WAL_CHECKPOINT_ESCALATE_COOLDOWN_MS) || 300000, // Worker-death handling: with autocheckpoint=0 a dead worker means nothing checkpoints and // the WAL grows until the disk fills. An unexpectedly-dead worker is respawned up to // RespawnMax times per RespawnWindowMs (with a small backoff); if that's exhausted we diff --git a/server/db/database.js b/server/db/database.js index da1be8a..48f89fb 100644 --- a/server/db/database.js +++ b/server/db/database.js @@ -1116,6 +1116,40 @@ function pruneTelemetry(deviceId) { _delTelemetry.run(deviceId, config.statusLogPruneBatch); } +// #240: the per-heartbeat cap above is the only thing that ever trimmed device_telemetry, +// and it only trims the device whose heartbeat is being handled — so a device that STOPS +// reporting (decommissioned, swapped, seasonally dark) leaves its rows behind forever and +// the table only ever grows. This is the matching age sweep, mirroring pruneStatusLog: +// per-device so it rides idx_telemetry_device(device_id, reported_at DESC) instead of +// scanning, chunked so a backlog trims across many bounded DELETEs, and yielding between +// devices so it can never own the loop. +// +// The retention default is deliberately LOOSER than the per-device cap (6000 rows ~= 25h +// for a device reporting every 15s) and matches the uptime report's default 30-day window, +// so this sweep cannot change a report that the row cap wasn't already truncating. +const _nextTelemetryDevice = db.prepare('SELECT device_id FROM device_telemetry WHERE device_id > ? ORDER BY device_id LIMIT 1'); +const _delTelemetryOld = db.prepare('DELETE FROM device_telemetry WHERE rowid IN (SELECT rowid FROM device_telemetry WHERE device_id = ? AND reported_at < ? LIMIT ?)'); +let _telemetryPruneRunning = false; +async function pruneTelemetryRetention(opts = {}) { + if (_telemetryPruneRunning) return 0; + if (opts.bandGate && config.maintenanceBandGateEnabled && currentBand() !== 'normal') return 0; + _telemetryPruneRunning = true; + try { + const batch = config.statusLogPruneBatch; + const cutoff = Math.floor(Date.now() / 1000) - Math.round(config.telemetryRetentionDays * 86400); + let total = 0, lastDev = ''; + for (;;) { + const row = _nextTelemetryDevice.get(lastDev); // O(log n) seek to the next distinct device_id + if (!row) break; + lastDev = row.device_id; + total += (await chunkedDelete((lim) => _delTelemetryOld.run(lastDev, cutoff, lim).changes, { batch })).deleted; + await yieldTick(); // breathe between devices + } + if (total > 0) console.log(`[telemetry] pruned ${total} row(s) older than ${config.telemetryRetentionDays}d (per-device, batches of ${batch})`); + return total; + } catch (_) { return 0; } finally { _telemetryPruneRunning = false; } +} + // Prune old screenshots (keep only latest per device) function pruneScreenshots(deviceId) { const old = db.prepare(` @@ -1176,4 +1210,4 @@ try { const { verifyAndRepairSchema } = require('../lib/schema-check'); verifyAndRepairSchema(db); -module.exports = { db, pruneTelemetry, pruneScreenshots, pruneStatusLog, getMaintenanceStats }; +module.exports = { db, pruneTelemetry, pruneTelemetryRetention, pruneScreenshots, pruneStatusLog, getMaintenanceStats }; diff --git a/server/db/wal-checkpointer-worker.js b/server/db/wal-checkpointer-worker.js index 7378884..0e88543 100644 --- a/server/db/wal-checkpointer-worker.js +++ b/server/db/wal-checkpointer-worker.js @@ -10,7 +10,7 @@ const { workerData, parentPort } = require('worker_threads'); const fs = require('fs'); const Database = require('better-sqlite3'); -const { dbPath, intervalMs, highWaterBytes, starvationRuns } = workerData; +const { dbPath, intervalMs, highWaterBytes, starvationRuns, starvationFloorBytes, escalateCooldownMs } = workerData; // Fault injection for TESTS ONLY (env-gated; inert in prod). Exits immediately on start so // the controller's respawn / autocheckpoint-fallback path can be exercised deterministically. @@ -25,7 +25,9 @@ const walFile = dbPath + '-wal'; function walBytes() { try { return fs.statSync(walFile).size; } catch { return 0; } } let lastBytes = 0; -let growthRuns = 0; // consecutive PASSIVE runs where the WAL failed to shrink +let growthRuns = 0; // consecutive PASSIVE runs where the WAL failed to shrink +let lastTruncateAt = 0; // #240: when we last blocked for a TRUNCATE (0 = never) +let coolingReported = false; let timer = null; function tick() { @@ -36,16 +38,47 @@ function tick() { const bytes = walBytes(); // --- STARVATION BOUND (this is where "WAL cannot grow forever" is enforced) --- - // Either signal forces a TRUNCATE, which BLOCKS until it has checkpointed everything - // and truncated the file to 0. Blocking is fatal on the loop but FINE here on the worker. + // Escalating forces a TRUNCATE, which BLOCKS until it has checkpointed everything and + // truncated the file to 0. #240: "fine here on the worker" was only ever half true — + // the fsync is off the loop, but SQLite's locks are held across CONNECTIONS, so the + // main thread's next statement waits it out in the busy handler. Hence the gates below. if (bytes > lastBytes) growthRuns++; else growthRuns = 0; const overHighWater = bytes > highWaterBytes; - const starved = growthRuns >= starvationRuns; + // #240: TRUNCATE blocks ACROSS connections — the main thread's next statement waits in + // SQLite's busy handler for the whole checkpoint — so the growth signal alone must not + // be able to spend it. Two gates, because either on its own leaves the hole open: + // FLOOR: a WAL in the lower half of its budget has little to reclaim; blocking for it + // is pure cost. (Ungated, every morning fleet power-on wave bought a loop stall.) + // COOLDOWN: a WAL that already sits ABOVE the floor would otherwise escalate on every + // burst forever. However long the pressure lasts, we stall the loop at most once + // per window and let PASSIVE do the rest. + // overHighWater bypasses both — a runaway WAL is the one case worth blocking for. + const sinceLast = Date.now() - lastTruncateAt; + const starved = growthRuns >= starvationRuns && bytes >= starvationFloorBytes; + const cooling = starved && lastTruncateAt > 0 && sinceLast < escalateCooldownMs; + + if (cooling && !overHighWater) { + // Report the transition only — a starved-and-cooling state persists for the whole + // window and this check runs every interval; one line, not a log flood. + if (!coolingReported) { + coolingReported = true; + post(`starvation escalation held off (WAL ${(bytes / 1e6).toFixed(1)}MB, last TRUNCATE ${Math.round(sinceLast / 1000)}s ago) — PASSIVE continues`); + } + lastBytes = bytes; + return; + } if (overHighWater || starved) { - db.pragma('wal_checkpoint(TRUNCATE)', { simple: false }); + lastTruncateAt = Date.now(); + coolingReported = false; + const r = db.pragma('wal_checkpoint(TRUNCATE)', { simple: false }); const after = walBytes(); - post(`escalated TRUNCATE (${overHighWater ? 'high-water' : 'starvation'}): WAL ${(bytes / 1e6).toFixed(1)}MB -> ${(after / 1e6).toFixed(1)}MB`); + // #240: TRUNCATE does NOT throw when it can't get the locks — it returns busy=1 having + // sat on SQLite's busy timeout for its full duration. Measured at ~4.9s with a single + // reader mid-transaction, reclaiming nothing, while every main-thread statement waited + // behind it. Say so plainly: a silent 5-second loss is the worst thing this can do. + const busy = Array.isArray(r) && r[0] && r[0].busy === 1; + post(`escalated TRUNCATE (${overHighWater ? 'high-water' : 'starvation'}): WAL ${(bytes / 1e6).toFixed(1)}MB -> ${(after / 1e6).toFixed(1)}MB${busy ? ' — BUSY: reclaimed nothing, blocked writers for the busy timeout' : ''}`); growthRuns = 0; lastBytes = after; } else { diff --git a/server/db/wal-checkpointer.js b/server/db/wal-checkpointer.js index d6a9c60..78f8462 100644 --- a/server/db/wal-checkpointer.js +++ b/server/db/wal-checkpointer.js @@ -12,6 +12,7 @@ // autocheckpoint on the main connection as a degraded-but-safe fallback (occasional inline // stall << unbounded WAL growth). const path = require('path'); +const fs = require('fs'); const { Worker } = require('worker_threads'); const config = require('../config'); @@ -29,6 +30,8 @@ function spawnWorker() { intervalMs: config.walCheckpointIntervalMs, highWaterBytes: config.walCheckpointHighWaterMB * 1024 * 1024, starvationRuns: config.walCheckpointStarvationRuns, + starvationFloorBytes: config.walCheckpointStarvationFloorMB * 1024 * 1024, // #240 + escalateCooldownMs: config.walCheckpointEscalateCooldownMs, // #240 }, }); w.on('message', (m) => { if (m && m.log) console.log('[wal-checkpoint] ' + m.log); }); @@ -77,8 +80,27 @@ function engageFallback() { if (fallbackEngaged) return; fallbackEngaged = true; try { mainDb.pragma(`wal_autocheckpoint = ${config.walCheckpointFallbackPages}`); } catch (_) {} - try { mainDb.pragma('wal_checkpoint(TRUNCATE)'); } catch (_) {} // one-time reclaim of the dead-worker backlog - console.error('[wal-checkpoint] worker unrecoverable — re-enabled inline autocheckpoint as fallback'); + // #240: reclaim the dead worker's backlog, but pick the CHEAPEST form that does the job. + // The old unconditional TRUNCATE ran a blocking, fsync-heavy checkpoint on the MAIN + // thread — on slow storage a single multi-second loop stall, and one that only ever + // happens on a degraded server that can least afford it. PASSIVE reclaims what it can + // without blocking; the blocking form is reserved for a WAL that is genuinely over the + // high-water mark, where leaving it is the worse of the two risks. + const over = walBytes() > config.walCheckpointHighWaterMB * 1024 * 1024; + try { mainDb.pragma(`wal_checkpoint(${over ? 'TRUNCATE' : 'PASSIVE'})`); } catch (_) {} + console.error(`[wal-checkpoint] worker unrecoverable — re-enabled inline autocheckpoint as fallback (backlog reclaim: ${over ? 'TRUNCATE' : 'PASSIVE'})`); +} + +// #240: the fallback is STICKY for the life of the process — once engaged, checkpoints are +// back on the main thread until a restart. That is exactly the shape of "it degrades with +// uptime and a restart fixes it", so it must be visible on /api/status rather than inferable +// only from a log line that may have rolled. +function getCheckpointerState() { + return { worker: !!worker, fallbackEngaged, respawns: respawnAt.length, walBytes: walBytes() }; +} + +function walBytes() { + try { return mainDbPath ? fs.statSync(mainDbPath + '-wal').size : 0; } catch (_) { return 0; } } // Call ONCE at boot, after the DB is open + migrated. `db` is the main connection (used to @@ -115,4 +137,4 @@ async function stopWalCheckpointer() { try { await w.terminate(); } catch (_) {} } -module.exports = { startWalCheckpointer, stopWalCheckpointer, _getWorker: () => worker }; +module.exports = { startWalCheckpointer, stopWalCheckpointer, getCheckpointerState, _getWorker: () => worker }; diff --git a/server/routes/status.js b/server/routes/status.js index 56c35c4..6b7fb8a 100644 --- a/server/routes/status.js +++ b/server/routes/status.js @@ -16,6 +16,7 @@ const otaBreaker = require('../lib/ota-breaker'); const otaDownloadGuard = require('../lib/ota-download-guard'); const logCoalescer = require('../lib/log-coalescer'); const { getMaintenanceStats } = require('../db/database'); +const { getCheckpointerState } = require('../db/wal-checkpointer'); // #240 const heartbeat = require('../services/heartbeat'); const appSettings = require('../lib/app-settings'); @@ -47,6 +48,7 @@ router.get('/', (req, res) => { ota_breaker: otaBreaker.stats(), // rateBackoff{Total,LastWindow} ota_download: otaDownloadGuard.stats(), // inFlight, served/shed ThisWindow + Total maintenance: getMaintenanceStats(), // deleted, ms, at, running, sweepsTotal + wal_checkpoint: getCheckpointerState(), // #240 worker alive?, sticky fallback?, respawns, WAL bytes log_coalescer_buffer: logCoalescer._size(), }; } diff --git a/server/services/heartbeat.js b/server/services/heartbeat.js index 863bad2..c3b7d65 100644 --- a/server/services/heartbeat.js +++ b/server/services/heartbeat.js @@ -1,4 +1,4 @@ -const { db, pruneStatusLog } = require('../db/database'); +const { db, pruneStatusLog, pruneTelemetryRetention } = require('../db/database'); const config = require('../config'); const { deviceRoom, emitToWorkspace } = require('../lib/socket-rooms'); const statusLogWriter = require('../lib/status-log-writer'); @@ -173,6 +173,7 @@ async function runMaintenance() { await pruneProvisioningDevices(); await prunePlayLogs(); await pruneStatusLog({ bandGate: true }); // per-device chunked; own re-entrancy + await pruneTelemetryRetention({ bandGate: true }); // #240 device_telemetry age sweep (per-device chunked) await pruneDeviceEvents(); // offline-cause log: incident-feed age retention (chunked) await capDeviceEvents(); // offline-cause log: per-device incident row cap await pruneUsageDaily(); // #146 BILLING rollup retention (chunked) diff --git a/server/services/loop-lag.js b/server/services/loop-lag.js index d422aaf..39d0c17 100644 --- a/server/services/loop-lag.js +++ b/server/services/loop-lag.js @@ -29,7 +29,23 @@ const LEVEL = { normal: 0, elevated: 1, critical: 2 }; let histogram = null; let band = 'normal'; let calmSamples = 0; -let current = { mean_ms: 0, p50_ms: 0, p99_ms: 0, max_ms: 0, band: 'normal', sampled_at: 0 }; +// #240: `samples` and the tick-gap fields exist to make ONE window's numbers +// interpretable. An IntervalHistogram window that recorded a single delay reports +// mean = p50 = p99 = max (the mean is the raw value, the percentiles are the bucket +// ceiling above it) — indistinguishable, from the numbers alone, from a fixed cost +// paid on every cycle. It is the opposite: one long loop turn. `samples` is the +// histogram's record count for the window (~50 at a 20ms resolution when healthy, +// 1 when a single turn swallowed the whole second), and tick_gap_ms is the +// WALL-CLOCK gap between consecutive sampler runs — ground truth for whether the +// loop is actually late, measured independently of the histogram. +let current = { + mean_ms: 0, p50_ms: 0, p99_ms: 0, max_ms: 0, samples: 0, + tick_gap_ms: 0, worst_tick_gap_ms: 0, worst_tick_at: 0, + band: 'normal', sampled_at: 0, +}; +let lastSampleAt = 0; // wall clock of the previous sample() run +let worstTickGapMs = 0; // largest gap seen since process start... +let worstTickAt = 0; // ...and when (epoch seconds). Survives coarse polling. const lagBuffer = []; // #146 Item E: pending telemetry rows, batch-inserted on flush // Pure band-transition function (exported for deterministic unit tests). Given the @@ -65,18 +81,35 @@ const round2 = (x) => Math.round(x * 100) / 100; const metric = (x) => (Number.isFinite(x) ? round2(x) : 0); function sample() { + // #240: measure the sampler's OWN lateness first. This interval is armed for + // lagSampleIntervalMs, so any excess is loop delay that the histogram cannot + // misreport — if the histogram claims seconds of lag while this stays at the + // interval, the block did not happen where the histogram says it did. + const nowMs = Date.now(); + const tickGap = lastSampleAt ? nowMs - lastSampleAt : config.lagSampleIntervalMs; + lastSampleAt = nowMs; + if (tickGap > worstTickGapMs) { worstTickGapMs = tickGap; worstTickAt = Math.floor(nowMs / 1000); } + const p99 = histogram.percentile(99) / NS_PER_MS; const snap = { mean_ms: metric(histogram.mean / NS_PER_MS), p50_ms: metric(histogram.percentile(50) / NS_PER_MS), p99_ms: metric(p99), max_ms: metric(histogram.max / NS_PER_MS), + samples: histogram.count, // MUST be read before reset() }; histogram.reset(); const prev = band; [band, calmSamples] = nextBand(band, snap.p99_ms, calmSamples); - current = { ...snap, band, sampled_at: Math.floor(Date.now() / 1000) }; + current = { + ...snap, + tick_gap_ms: tickGap, + worst_tick_gap_ms: worstTickGapMs, + worst_tick_at: worstTickAt, + band, + sampled_at: Math.floor(nowMs / 1000), + }; // #146 Item E: BUFFER the telemetry row (batch-inserted on the flush interval) instead // of a synchronous INSERT per sample — under DB contention (a bloated table slowing @@ -89,7 +122,9 @@ function sample() { // COALESCED (one summarized line per flush) so a sustained-critical storm can't turn // logging into its own loop hog. Healthy steady state stays quiet. if (band !== prev) { - console.log(`[loop-lag] band=${band} (was ${prev}) mean=${snap.mean_ms}ms p99=${snap.p99_ms}ms max=${snap.max_ms}ms`); + // #240: samples + tick gap ride along on the band line — without them a one-sample + // window reads as a permanent per-cycle cost to whoever finds this in the logs. + console.log(`[loop-lag] band=${band} (was ${prev}) mean=${snap.mean_ms}ms p99=${snap.p99_ms}ms max=${snap.max_ms}ms samples=${snap.samples} tick_gap=${tickGap}ms`); } else if (band !== 'normal') { // #146 P3.7: coalesce repeats and carry the PEAK p99 over the window (not a random // sample's) — the peak is the number that matters during an incident. diff --git a/server/test/loop-lag-sample-count.test.js b/server/test/loop-lag-sample-count.test.js new file mode 100644 index 0000000..75b3df6 --- /dev/null +++ b/server/test/loop-lag-sample-count.test.js @@ -0,0 +1,57 @@ +// #240 — a loop-lag window must report how many samples it is made of. +// +// The bug this closes is a reading bug, not a code bug. An IntervalHistogram window that +// recorded exactly ONE delay reports mean = p50 = p99 = max, with the mean sitting just +// below the identical percentiles (the mean is the raw value; the percentiles are the +// HdrHistogram bucket ceiling above it). From the four numbers alone that is +// indistinguishable from a fixed cost paid on every single cycle — and it was read that +// way on a production incident. It is the opposite: one long loop turn, once. +// +// So /api/status now carries `samples` and an independently-measured wall-clock tick gap. +// These assertions pin the arithmetic that makes the distinction real. +const { test } = require('node:test'); +const assert = require('node:assert/strict'); +const { createHistogram, monitorEventLoopDelay } = require('perf_hooks'); + +const NS = 1e6; +const r2 = (x) => Math.round(x * 100) / 100; + +test('#240: one recorded sample produces the mean=p50=p99=max signature', () => { + const h = createHistogram(); + h.record(1329070000); // 1329.07ms, the production reading + assert.equal(h.count, 1); + assert.equal(r2(h.mean / NS), 1329.07, 'mean is the raw value'); + const p50 = r2(h.percentile(50) / NS), p99 = r2(h.percentile(99) / NS), max = r2(h.max / NS); + assert.equal(p50, p99); + assert.equal(p99, max, 'every percentile collapses onto the same bucket ceiling'); + assert.ok(max > r2(h.mean / NS), 'the ceiling sits ABOVE the mean — the tell that count is 1'); +}); + +test('#240: a busy window does NOT produce that signature — p50 stays at the floor', () => { + // Many small delays plus one big one: the real shape of an intermittent stall. + const h = createHistogram(); + for (let i = 0; i < 49; i++) h.record(20000000); // 20ms, the resolution floor + h.record(1329070000); // one 1.3s stall + assert.equal(h.count, 50); + assert.notEqual(r2(h.percentile(50) / NS), r2(h.max / NS), + 'with real samples in the window the median cannot equal the max'); + assert.ok(r2(h.mean / NS) < r2(h.percentile(99) / NS), 'mean stays well under p99'); +}); + +test('#240: an idle loop reports the RESOLUTION, not zero — the healthy baseline is the floor', async () => { + const h = monitorEventLoopDelay({ resolution: 20 }); + h.enable(); + await new Promise((r) => setTimeout(r, 250)); + h.disable(); + assert.ok(h.count > 5, 'the sampler should have recorded several ticks'); + const mean = h.mean / NS; + assert.ok(mean >= 19 && mean < 60, `idle mean should sit at ~the 20ms resolution, got ${r2(mean)}`); +}); + +test('#240: getLag() carries samples and the independent tick-gap fields', () => { + const loopLag = require('../services/loop-lag'); + const lag = loopLag.getLag(); + for (const k of ['mean_ms', 'p50_ms', 'p99_ms', 'max_ms', 'samples', 'tick_gap_ms', 'worst_tick_gap_ms', 'worst_tick_at', 'band', 'sampled_at']) { + assert.ok(k in lag, `/api/status loop_lag must expose ${k}`); + } +}); diff --git a/server/test/wal-checkpoint-starvation-floor.test.js b/server/test/wal-checkpoint-starvation-floor.test.js new file mode 100644 index 0000000..a0f2bba --- /dev/null +++ b/server/test/wal-checkpoint-starvation-floor.test.js @@ -0,0 +1,131 @@ +// #240 — the WAL checkpointer's STARVATION escalation must be gated on WAL size. +// +// Why this test exists: TRUNCATE is the blocking checkpoint form and it blocks across +// connections, so a main-thread statement issued during one waits in SQLite's busy handler +// for its whole duration. The old rule escalated on growth ALONE — three consecutive +// PASSIVE runs where the WAL got bigger — which any sustained write burst satisfies. A +// customer's fleet powering on in the morning bought itself a multi-second event-loop +// stall against a WAL of a couple of MB, where a blocking checkpoint had nothing to +// reclaim in the first place. +// +// The decision is deliberately tested as the pure predicate the worker evaluates rather +// than by driving a real worker thread: the property that matters is WHEN we are willing +// to block, and that must not silently regress behind a timing-dependent test. +const { test } = require('node:test'); +const assert = require('node:assert/strict'); +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const config = require('../config'); + +const MB = 1024 * 1024; + +// The worker's escalation rule, kept in one place so the assertions below read as policy. +function shouldEscalate({ bytes, growthRuns, sinceLastTruncateMs, everTruncated, + highWaterBytes, starvationRuns, starvationFloorBytes, escalateCooldownMs }) { + const overHighWater = bytes > highWaterBytes; + const starved = growthRuns >= starvationRuns && bytes >= starvationFloorBytes; + const cooling = starved && everTruncated && sinceLastTruncateMs < escalateCooldownMs; + if (cooling && !overHighWater) return { overHighWater, starved, cooling, escalate: false }; + return { overHighWater, starved, cooling, escalate: overHighWater || starved }; +} + +const RULE = { + highWaterBytes: config.walCheckpointHighWaterMB * MB, + starvationRuns: config.walCheckpointStarvationRuns, + starvationFloorBytes: config.walCheckpointStarvationFloorMB * MB, + escalateCooldownMs: config.walCheckpointEscalateCooldownMs, + sinceLastTruncateMs: Infinity, + everTruncated: false, +}; + +test('#240: a small WAL growing across runs no longer triggers the blocking TRUNCATE', () => { + // The morning-wave shape: sustained writes, WAL grew every run, still only 2MB. + const r = shouldEscalate({ ...RULE, bytes: 2 * MB, growthRuns: 5 }); + assert.equal(r.escalate, false, 'growth alone must not escalate while the WAL is small'); +}); + +test('#240: growth still escalates once the WAL is actually large', () => { + const r = shouldEscalate({ ...RULE, bytes: config.walCheckpointStarvationFloorMB * MB, growthRuns: config.walCheckpointStarvationRuns }); + assert.equal(r.starved, true, 'at the floor, sustained growth is real starvation'); + assert.equal(r.escalate, true); +}); + +test('#240: the high-water backstop is untouched — the WAL still cannot grow unbounded', () => { + // No growth signal at all (a single huge run), well over the high-water mark. + const r = shouldEscalate({ ...RULE, bytes: (config.walCheckpointHighWaterMB + 1) * MB, growthRuns: 0 }); + assert.equal(r.overHighWater, true); + assert.equal(r.escalate, true, 'high-water must escalate regardless of the growth counter'); +}); + +test('#240: the floor sits below the high-water mark, so the two rules cannot invert', () => { + assert.ok( + config.walCheckpointStarvationFloorMB < config.walCheckpointHighWaterMB, + 'a floor at or above high-water would make the starvation rule dead code' + ); +}); + +// The floor on its own does NOT close this. Bold's WAL sat at 6.2MB against a 16MB +// high-water — already above any sane floor — so a morning wave would still have escalated +// on every burst. The cooldown is what bounds how often our own maintenance may stall the +// loop, regardless of how long the write pressure lasts. +test('#240: a WAL already above the floor escalates ONCE, then holds off', () => { + const big = { ...RULE, bytes: 12 * MB, growthRuns: 5 }; + + const first = shouldEscalate({ ...big }); + assert.equal(first.escalate, true, 'the first sustained-growth burst still escalates'); + + const during = shouldEscalate({ ...big, everTruncated: true, sinceLastTruncateMs: 30_000 }); + assert.equal(during.cooling, true); + assert.equal(during.escalate, false, 'a second burst inside the cooldown must not stall the loop again'); + + const after = shouldEscalate({ ...big, everTruncated: true, sinceLastTruncateMs: config.walCheckpointEscalateCooldownMs + 1 }); + assert.equal(after.escalate, true, 'once the window passes, escalation is available again'); +}); + +test('#240: the cooldown never delays the runaway-WAL backstop', () => { + const runaway = { + ...RULE, bytes: (config.walCheckpointHighWaterMB + 1) * MB, growthRuns: 5, + everTruncated: true, sinceLastTruncateMs: 1000, // deep inside the cooldown + }; + const r = shouldEscalate(runaway); + assert.equal(r.escalate, true, 'over high-water must escalate even mid-cooldown — that rule is the safety net'); +}); + +test('#240: the worker actually applies the floor it is handed', () => { + const src = fs.readFileSync(path.join(__dirname, '..', 'db', 'wal-checkpointer-worker.js'), 'utf8'); + assert.match(src, /growthRuns >= starvationRuns && bytes >= starvationFloorBytes/, + 'worker starvation check must include the size floor'); + assert.match(src, /starvationFloorBytes/, 'worker must destructure starvationFloorBytes from workerData'); + assert.match(src, /sinceLast < escalateCooldownMs/, 'worker must apply the escalation cooldown'); + const ctl = fs.readFileSync(path.join(__dirname, '..', 'db', 'wal-checkpointer.js'), 'utf8'); + assert.match(ctl, /starvationFloorBytes:\s*config\.walCheckpointStarvationFloorMB/, + 'controller must pass the floor through workerData — an undefined floor would make every comparison false'); + assert.match(ctl, /escalateCooldownMs:\s*config\.walCheckpointEscalateCooldownMs/, + 'controller must pass the cooldown through workerData'); +}); + +// Measured, not assumed: with a single reader mid-transaction, TRUNCATE returns busy=1 +// after sitting on its 5s busy timeout and reclaims nothing (probe: WAL 8.8MB -> 8.8MB, +// worst main-thread write 4,936ms). That outcome must not be logged as a success. +test('#240: a TRUNCATE that reclaimed nothing says so', () => { + const src = fs.readFileSync(path.join(__dirname, '..', 'db', 'wal-checkpointer-worker.js'), 'utf8'); + assert.match(src, /busy === 1/, 'worker must inspect the checkpoint result'); + assert.match(src, /reclaimed nothing/, 'a busy TRUNCATE must be reported as the loss it is'); +}); + +test('#240: the unrecoverable-worker fallback no longer blocks the loop for a small WAL', () => { + const ctl = fs.readFileSync(path.join(__dirname, '..', 'db', 'wal-checkpointer.js'), 'utf8'); + assert.match(ctl, /wal_checkpoint\(\$\{over \? 'TRUNCATE' : 'PASSIVE'\}\)/, + 'fallback reclaim must pick TRUNCATE only when the WAL is over the high-water mark'); +}); + +test('#240: /api/status exposes the sticky fallback state', () => { + const { getCheckpointerState } = require('../db/wal-checkpointer'); + const s = getCheckpointerState(); + // Not started in this process — the point is the shape, and that reading it is safe + // before startWalCheckpointer() has ever run (status is served during boot too). + assert.deepEqual(Object.keys(s).sort(), ['fallbackEngaged', 'respawns', 'walBytes', 'worker']); + assert.equal(s.fallbackEngaged, false); + assert.equal(typeof s.walBytes, 'number'); +});