From edb9f2f14cd7394a4d31f94ebc871531ef498ab0 Mon Sep 17 00:00:00 2001 From: Colby Mchenry Date: Fri, 10 Jul 2026 08:25:23 -0500 Subject: [PATCH] =?UTF-8?q?fix(watchdog):=20don't=20kill=20a=20healthy=20i?= =?UTF-8?q?ndex=20on=20degraded=20storage=20=E2=80=94=20require=20heartbea?= =?UTF-8?q?t=20silence=20AND=20no=20disk=20progress=20(#1231)=20(#1244)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The liveness watchdog judged the main thread by heartbeat silence alone, which cannot distinguish a true wedge (the #850 infinite loop it exists to kill) from one long synchronous SQLite statement on severely degraded storage — so it SIGKILLed valid, in-progress indexes (observed on a 150-IOPS throttled rig, and latent on real HDDs at scale). The CLI index/init paths now hand the watchdog the project's DB + WAL paths. On a silent timeout the watchdog child stats them first: if they advanced during the silence, the block is a slow store making forward progress — defer and keep watching; if not, kill at the base timeout exactly as before. Deferral is bounded by a hard cap (10× the timeout) of continuous silence so a wedge coinciding with unrelated file activity, or I/O hung beyond any legitimate statement, still dies. The daemon path is unchanged (no progress paths — pure heartbeat). Validated with real spawned processes (defer-on-progress, kill-on-static, hard-cap kill) and on the throttled rig: a 150-IOPS index under a 10s watchdog window — 6× tighter than production, with store stalls measured at 10-20s — completes cleanly where the old watchdog killed it, while true-wedge kill latency is unchanged. Co-authored-by: Claude Fable 5 --- CHANGELOG.md | 3 + __tests__/liveness-watchdog.test.ts | 68 +++++++++++++++++++- src/bin/codegraph.ts | 14 +++-- src/bin/command-supervision.ts | 12 +++- src/mcp/liveness-watchdog.ts | 96 +++++++++++++++++++++++++---- 5 files changed, 172 insertions(+), 21 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 5492815..eef0b61 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,9 @@ and adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ## [Unreleased] +### Fixes + +- The safety watchdog no longer kills a healthy index on severely degraded storage. It used to judge liveness purely by the event loop, so one long database write on a struggling disk looked identical to a hung process and could get a valid, in-progress index terminated. During `codegraph index`/`codegraph init` the watchdog now also checks whether the index files on disk are advancing before it acts: slow-but-progressing work is left alone (bounded by a hard cap), while a genuinely hung process is still killed exactly as fast as before. (#1231) ## [1.4.0] - 2026-07-10 diff --git a/__tests__/liveness-watchdog.test.ts b/__tests__/liveness-watchdog.test.ts index 8798bcc..025b419 100644 --- a/__tests__/liveness-watchdog.test.ts +++ b/__tests__/liveness-watchdog.test.ts @@ -57,11 +57,12 @@ describe('liveness watchdog (spawned, real watchdog process)', () => { function runChild( env: Record, body: string, - hardTimeoutMs: number + hardTimeoutMs: number, + progressPaths?: string[] ): Promise<{ code: number | null; signal: NodeJS.Signals | 'TIMEOUT' | null }> { const src = ` const { installMainThreadWatchdog } = require(${JSON.stringify(MODULE)}); - installMainThreadWatchdog(); + installMainThreadWatchdog(${progressPaths ? JSON.stringify({ progressPaths }) : ''}); ${body} `; const child = spawn(process.execPath, ['-e', src], { @@ -119,6 +120,69 @@ describe('liveness watchdog (spawned, real watchdog process)', () => { expect(code).toBe(7); // exited on its own terms }, 12000); + // --- disk-progress deferral (#1231): a blocked event loop is NOT a wedge + // when the watched DB files keep advancing (a slow synchronous SQLite + // statement on degraded storage). --- + + /** Grow `file` every 150ms for `forMs`; resolves when done. */ + function growFile(file: string, forMs: number): Promise { + return new Promise((resolve) => { + const iv = setInterval(() => { fs.appendFileSync(file, 'x'.repeat(64)); }, 150); + setTimeout(() => { clearInterval(iv); resolve(); }, forMs); + }); + } + + it('does NOT kill a blocked loop while the watched files advance (slow store, not a wedge)', async () => { + const tmp = path.join(fs.mkdtempSync(path.join(require('os').tmpdir(), 'cg-wd-')), 'db-wal'); + fs.writeFileSync(tmp, 'seed'); + // Base timeout 500ms; the loop blocks for 2.5s (5 timeouts, under the 10× + // cap) while the test process grows the watched file. Old behavior: killed + // at ~500ms. New: deferred, exits on its own with code 5. + const [r] = await Promise.all([ + runChild( + { CODEGRAPH_WATCHDOG_TIMEOUT_MS: '500' }, + 'setTimeout(() => { const end = Date.now() + 2500; while (Date.now() < end) {} process.exit(5); }, 200);', + 10_000, + [tmp] + ), + growFile(tmp, 3200), + ]); + expect(r.signal).toBeNull(); + expect(r.code).toBe(5); + }, 15000); + + it('still kills a blocked loop when the watched files do NOT advance (a true wedge)', async () => { + const tmp = path.join(fs.mkdtempSync(path.join(require('os').tmpdir(), 'cg-wd-')), 'db-wal'); + fs.writeFileSync(tmp, 'seed'); + // Same blocked loop, nobody grows the file: the base timeout kills it long + // before its own exit(5) at 2.5s. + const r = await runChild( + { CODEGRAPH_WATCHDOG_TIMEOUT_MS: '500' }, + 'setTimeout(() => { const end = Date.now() + 2500; while (Date.now() < end) {} process.exit(5); }, 200);', + 10_000, + [tmp] + ); + expectKilled(r); + }, 15000); + + it('kills at the hard cap even with ongoing file activity (bounded deferral)', async () => { + const tmp = path.join(fs.mkdtempSync(path.join(require('os').tmpdir(), 'cg-wd-')), 'db-wal'); + fs.writeFileSync(tmp, 'seed'); + // Base timeout 300ms ⇒ cap 3s. The loop blocks for 8s with continuous file + // growth: deferral carries it past 300ms but the cap kills it around ~3s, + // well before its own exit(5). + const [r] = await Promise.all([ + runChild( + { CODEGRAPH_WATCHDOG_TIMEOUT_MS: '300' }, + 'setTimeout(() => { const end = Date.now() + 8000; while (Date.now() < end) {} process.exit(5); }, 200);', + 15_000, + [tmp] + ), + growFile(tmp, 9000), + ]); + expectKilled(r); + }, 20000); + it('does NOT kill a wedged process when CODEGRAPH_NO_WATCHDOG=1', async () => { const { code, signal } = await runChild( { CODEGRAPH_WATCHDOG_TIMEOUT_MS: '500', CODEGRAPH_NO_WATCHDOG: '1' }, diff --git a/src/bin/codegraph.ts b/src/bin/codegraph.ts index 97448f3..826305c 100644 --- a/src/bin/codegraph.ts +++ b/src/bin/codegraph.ts @@ -590,7 +590,7 @@ program return; } - const { default: CodeGraph } = await loadCodeGraph(); + const { default: CodeGraph, getDatabasePath } = await loadCodeGraph(); const cg = await CodeGraph.init(projectPath, { index: false }); clack.log.success(`Initialized in ${projectPath}`); @@ -598,10 +598,13 @@ program // accepted (so existing muscle memory and scripts don't break) but is a // no-op — initializing always builds the initial index. // Supervise the index: self-terminate if orphaned or wedged (#999). + // The DB + WAL paths let the liveness watchdog tell a slow store on + // degraded storage from a true wedge (#1231). // A closure so we can re-run the exact same supervised, progress-rendered // index if the user opts gitignored child repos in below (#1156). + const dbPath = getDatabasePath(projectPath); const runIndex = async (): Promise => { - const supervision = installCommandSupervision('init'); + const supervision = installCommandSupervision('init', { progressPaths: [dbPath, `${dbPath}-wal`] }); try { if (options.verbose) { return await cg.indexAll({ onProgress: createVerboseProgress(), verbose: true }); @@ -727,7 +730,7 @@ program process.exit(1); } - const { default: CodeGraph } = await loadCodeGraph(); + const { default: CodeGraph, getDatabasePath } = await loadCodeGraph(); // `index` is a FULL re-index — identical to a fresh `init`. RECREATE the // database from scratch (discard .codegraph/codegraph.db + its WAL) rather // than opening the old graph and DELETE-ing every row. The clear-then-index @@ -741,7 +744,10 @@ program // Supervise the indexer: self-terminate if orphaned (parent shim killed) // or if the main thread wedges — neither was guarded on this path (#999). - const supervision = installCommandSupervision('index'); + // The DB + WAL paths let the liveness watchdog tell a slow store on + // degraded storage from a true wedge (#1231). + const dbPath = getDatabasePath(projectPath); + const supervision = installCommandSupervision('index', { progressPaths: [dbPath, `${dbPath}-wal`] }); try { if (options.quiet) { // Quiet mode: no UI, just run against the freshly-recreated graph. diff --git a/src/bin/command-supervision.ts b/src/bin/command-supervision.ts index cd4a5aa..6031a49 100644 --- a/src/bin/command-supervision.ts +++ b/src/bin/command-supervision.ts @@ -28,7 +28,7 @@ * work — is exactly what cooperative yielding buys: a genuinely stuck span never * reaches its next yield, so it still trips the timeout. */ -import { installMainThreadWatchdog } from '../mcp/liveness-watchdog'; +import { installMainThreadWatchdog, WatchdogOptions } from '../mcp/liveness-watchdog'; import { supervisionLostReason, parsePpidPollMs, parseHostPpid } from '../mcp/ppid-watchdog'; import { isProcessAlive } from '../mcp/daemon-registry'; import { EARLY_PPID } from '../mcp/early-ppid'; @@ -44,12 +44,18 @@ export interface CommandSupervision { * `label` is used in the shutdown notice (e.g. `"index"`). Returns a handle * whose `stop()` must be called when the command completes so neither watchdog * outlives it. + * + * Pass `watchdog.progressPaths` (the project's SQLite DB + `-wal`) so the + * liveness watchdog can tell a slow-but-progressing store on degraded storage + * (files advancing) from a true wedge (they aren't) — one long synchronous + * SQLite statement on a 150-IOPS disk otherwise gets a healthy index + * SIGKILLed (#1231). */ -export function installCommandSupervision(label: string): CommandSupervision { +export function installCommandSupervision(label: string, watchdog: WatchdogOptions = {}): CommandSupervision { // Liveness watchdog: a separate process that SIGKILLs us if our event loop // stops turning for too long (a wedged synchronous loop). Self-disables on // CODEGRAPH_NO_WATCHDOG. - const liveness = installMainThreadWatchdog(); + const liveness = installMainThreadWatchdog(watchdog); // PPID watchdog: detect that the parent (or the host threaded past the // relaunch shim) died and we've been orphaned, then exit instead of leaking. diff --git a/src/mcp/liveness-watchdog.ts b/src/mcp/liveness-watchdog.ts index 0c033b3..77aa011 100644 --- a/src/mcp/liveness-watchdog.ts +++ b/src/mcp/liveness-watchdog.ts @@ -29,10 +29,26 @@ * orphan). * * **Won't fire on real work.** Heavy parsing runs in the parse worker - * (off-thread) and indexing shells out to a child process, so the daemon's main - * thread only ever does fast, bounded work. The default timeout is ~300× the - * 5h #850 wedge shorter, yet far longer than any legitimate main-thread block. - * Opt out with `CODEGRAPH_NO_WATCHDOG=1`; tune with `CODEGRAPH_WATCHDOG_TIMEOUT_MS`. + * (off-thread) and the daemon's indexing shells out to a child process, so the + * daemon's main thread only ever does fast, bounded work. The default timeout + * is ~300× the 5h #850 wedge shorter, yet far longer than any legitimate + * main-thread block. Opt out with `CODEGRAPH_NO_WATCHDOG=1`; tune with + * `CODEGRAPH_WATCHDOG_TIMEOUT_MS`. + * + * **Disk-progress deferral (`progressPaths`).** The CLI `index`/`init` path is + * different: it runs the SQLite store on this thread, and one long synchronous + * statement on severely degraded storage can block the loop past the timeout + * with the process perfectly healthy (#1231: killed a valid index on a + * 150-IOPS disk). Heartbeat silence alone cannot tell that apart from a wedge — + * but the disk can: a wedged CPU loop makes no forward progress on the DB + * files, while a slow store advances them. When the caller supplies + * `progressPaths` (the SQLite DB + `-wal`), the child checks them at each + * silent timeout: size/mtime advanced ⇒ defer the kill and keep watching; + * unchanged ⇒ kill as before. Deferral is bounded by a hard cap + * (`PROGRESS_CAP_MULTIPLIER` × timeout) of continuous silence, so a wedge + * coinciding with unrelated file activity — or I/O hung beyond all reason — + * still dies. A true wedge with no disk progress dies at the base timeout, + * exactly as before. */ import * as fs from 'fs'; import * as os from 'os'; @@ -41,6 +57,14 @@ import { spawn, ChildProcess } from 'child_process'; /** Default: 60s — ~300× shorter than the 5h #850 wedge, far longer than any real main-thread block. */ export const DEFAULT_WATCHDOG_TIMEOUT_MS = 60_000; +/** + * Hard cap on disk-progress deferral: after this many timeouts' worth of + * CONTINUOUS heartbeat silence the process is killed even if the watched files + * keep advancing (a wedge coinciding with unrelated file writes, or I/O hung + * beyond any legitimate statement). 10× the 60s default ⇒ 10 minutes. + */ +export const PROGRESS_CAP_MULTIPLIER = 10; + /** `true` for `1/true/yes/on` (case-insensitive); `false` otherwise. */ function isEnvTruthy(raw: string | undefined): boolean { if (!raw) return false; @@ -85,31 +109,79 @@ const CHILD_SOURCE = ` const fs = require('fs'); const parentPid = Number(process.argv[1]); const timeoutMs = Number(process.argv[2]); +const capMs = Number(process.argv[3]); +const progressPaths = process.argv.slice(4); const secs = Math.round(timeoutMs / 1000); -const MSG = Buffer.from('[CodeGraph] Main thread unresponsive for ~' + secs + 's — killing the wedged process so a fresh one can start (#850). Disable with CODEGRAPH_NO_WATCHDOG=1.\\n'); -function kill() { - try { fs.writeSync(2, MSG); } catch (e) {} +function kill(extra) { + try { fs.writeSync(2, Buffer.from('[CodeGraph] Main thread unresponsive for ~' + secs + 's' + (extra || '') + ' — killing the wedged process so a fresh one can start (#850). Disable with CODEGRAPH_NO_WATCHDOG=1.\\n')); } catch (e) {} try { process.kill(parentPid, 'SIGKILL'); } catch (e) {} process.exit(0); } -let timer = setTimeout(kill, timeoutMs); -process.stdin.on('data', () => { clearTimeout(timer); timer = setTimeout(kill, timeoutMs); }); +// Fingerprint of the watched files (size + mtime). A change between checks is +// forward disk progress — a slow synchronous SQLite statement, not a wedge. +function snap() { + let s = ''; + for (const p of progressPaths) { + try { const st = fs.statSync(p); s += st.size + ':' + st.mtimeMs + ';'; } catch (e) { s += 'x;'; } + } + return s; +} +let lastSnap = progressPaths.length ? snap() : ''; +let lastSnapAt = Date.now(); +let silentSince = null; // start of the current continuous-silence episode +function onTimeout() { + if (!progressPaths.length) return kill(''); + const now = Date.now(); + if (silentSince === null) silentSince = now - timeoutMs; // silence began ~one timeout ago + const cur = snap(); + if (cur !== lastSnap && now - silentSince < capMs) { + // The event loop is blocked but the DB files are advancing: a legitimate + // long store on slow storage. Defer, re-baseline, keep watching. + lastSnap = cur; + timer = setTimeout(onTimeout, timeoutMs); + return; + } + kill(cur !== lastSnap ? ' despite ongoing disk activity (hard cap ' + Math.round(capMs / 1000) + 's reached)' : ''); +} +let timer = setTimeout(onTimeout, timeoutMs); +process.stdin.on('data', () => { + silentSince = null; + // Keep the baseline fresh while healthy (throttled — a stat per second). + if (progressPaths.length) { + const t = Date.now(); + if (t - lastSnapAt >= 1000) { lastSnap = snap(); lastSnapAt = t; } + } + clearTimeout(timer); timer = setTimeout(onTimeout, timeoutMs); +}); process.stdin.on('end', () => process.exit(0)); // parent closed the pipe (exited) -> no orphan process.stdin.on('error', () => process.exit(0)); // pipe broke -> parent gone process.stdin.resume(); `; +export interface WatchdogOptions { + /** + * Files whose size/mtime advancing counts as forward progress (the SQLite + * DB + `-wal` for an in-process indexer). With paths supplied, a silent + * timeout only kills when the files did NOT advance — see the header. Omit + * for pure heartbeat behavior (the daemon, whose main thread never runs + * long synchronous work). + */ + progressPaths?: string[]; +} + /** * Install the main-thread liveness watchdog for a long-lived process. Returns a * handle to stop it, or `null` when disabled or when the child can't be spawned * (degraded, never throws — a missing watchdog must never keep a process from * starting). */ -export function installMainThreadWatchdog(): WatchdogHandle | null { +export function installMainThreadWatchdog(options: WatchdogOptions = {}): WatchdogHandle | null { if (isEnvTruthy(process.env.CODEGRAPH_NO_WATCHDOG)) return null; const timeoutMs = parseWatchdogTimeoutMs(process.env.CODEGRAPH_WATCHDOG_TIMEOUT_MS); const checkMs = deriveCheckIntervalMs(timeoutMs); + const capMs = timeoutMs * PROGRESS_CAP_MULTIPLIER; + const progressPaths = options.progressPaths ?? []; let child: ChildProcess; try { @@ -118,7 +190,7 @@ export function installMainThreadWatchdog(): WatchdogHandle | null { // fd 2 so the kill notice lands wherever the parent logs (daemon.log). child = spawn( process.execPath, - ['-e', CHILD_SOURCE, String(process.pid), String(timeoutMs)], + ['-e', CHILD_SOURCE, String(process.pid), String(timeoutMs), String(capMs), ...progressPaths], { stdio: ['pipe', 'ignore', 'inherit'], windowsHide: true, @@ -155,7 +227,7 @@ export function installMainThreadWatchdog(): WatchdogHandle | null { child.unref(); try { (stdin as unknown as { unref?: () => void }).unref?.(); } catch { /* ignore */ } - debug(`armed (child pid ${child.pid ?? '?'}): timeoutMs=${timeoutMs} checkMs=${checkMs}`); + debug(`armed (child pid ${child.pid ?? '?'}): timeoutMs=${timeoutMs} checkMs=${checkMs} progressPaths=${progressPaths.length}`); let stopped = false; return {