Răsfoiți Sursa

fix(watchdog): don't kill a healthy index on degraded storage — require heartbeat silence AND no disk progress (#1231) (#1244)

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 <noreply@anthropic.com>
Colby Mchenry 1 lună în urmă
părinte
comite
edb9f2f14c

+ 3 - 0
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
 

+ 66 - 2
__tests__/liveness-watchdog.test.ts

@@ -57,11 +57,12 @@ describe('liveness watchdog (spawned, real watchdog process)', () => {
   function runChild(
     env: Record<string, string>,
     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<void> {
+    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' },

+ 10 - 4
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<IndexResult> => {
-        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.

+ 9 - 3
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.

+ 84 - 12
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 {