Recover daemon workers stalled by workspace Git pressure (#3033)

* fix(server): bound workspace git pipelines * fix(server): bound workspace git watcher setup * fix(server): recover unresponsive daemon workers * fix(server): tolerate transient daemon heartbeat delays A five-second watchdog threshold can replace a healthy worker during a short event-loop delay. Keep recovery bounded while allowing a 15-second heartbeat gap, and preserve process-level coverage for workers that ignore graceful termination. * test(server): normalize workspace fixture paths Workspace Git entry points resolve paths before invoking dependencies. Keep admission-control fixtures keyed by the same canonical paths so their assertions and deferred gates work on Windows. --------- Co-authored-by: Timi Ajiboye <trypio00@gmail.com> Co-authored-by: Mohamed Boudra <boudra.moha@gmail.com>
2026-08-09 03:01:34 +02:00
parent 3bca9b7a92
commit 01a1d3b2b6
9 changed files with 755 additions and 24 deletions
@@ -13,9 +13,11 @@ const supervisorPath = fileURLToPath(new URL("./supervisor.ts", import.meta.url)
 async function runSupervisorFixture(options: {
  workerSource: string;
  restartOnCrash?: boolean;
+  timeoutMs?: number;
 }): Promise<{
  code: number | null;
  signal: NodeJS.Signals | null;
+  elapsedMs: number;
  log: string;
  stdout: string;
  stderr: string;
@@ -47,6 +49,7 @@ async function runSupervisorFixture(options: {
    `,
  );

+  const startedAt = Date.now();
  const child = spawn(process.execPath, ["--import", "tsx", runnerPath], {
    cwd: repoRoot,
    env: { ...process.env },
@@ -71,7 +74,7 @@ async function runSupervisorFixture(options: {
    const timeout = setTimeout(() => {
      child.kill("SIGKILL");
      reject(new Error("supervisor fixture timed out"));
-    }, 10000);
+    }, options.timeoutMs ?? 10_000);

    child.on("error", (error) => {
      clearTimeout(timeout);
@@ -84,7 +87,7 @@ async function runSupervisorFixture(options: {
  });

  const log = await readFile(logPath, "utf8");
-  return { code, signal, log, stdout, stderr };
+  return { code, signal, elapsedMs: Date.now() - startedAt, log, stdout, stderr };
 }

 describe("supervisor durable logging", () => {
@@ -186,6 +189,152 @@ describe("supervisor durable logging", () => {
    expect(result.log).toContain('"workerPid":');
  });

+  test("keeps a worker alive while heartbeats continue", async () => {
+    const result = await runSupervisorFixture({
+      timeoutMs: 10_000,
+      workerSource: `
+        setInterval(() => {
+          process.send?.({ type: "paseo:worker-heartbeat" });
+        }, 250);
+        setTimeout(() => {
+          process.send?.({ type: "paseo:shutdown", reason: "healthy_heartbeat_test_complete" });
+        }, 6000);
+      `,
+    });
+
+    expect(result.code).toBe(0);
+    expect(result.signal).toBeNull();
+    expect(result.log).toContain('"reason":"healthy_heartbeat_test_complete"');
+    expect(result.log).not.toContain('"msg":"Worker heartbeat timed out; restarting worker"');
+  }, 10_000);
+
+  test("tolerates a transient seven-second heartbeat pause", async () => {
+    const result = await runSupervisorFixture({
+      timeoutMs: 10_000,
+      workerSource: `
+        import { existsSync, writeFileSync } from "node:fs";
+
+        const marker = process.argv[1] + ".started";
+        if (!existsSync(marker)) {
+          writeFileSync(marker, "started");
+          let heartbeatCount = 0;
+          const heartbeat = setInterval(() => {
+            process.send?.({ type: "paseo:worker-heartbeat" });
+            heartbeatCount += 1;
+            if (heartbeatCount === 3) clearInterval(heartbeat);
+          }, 100);
+          setTimeout(() => {
+            process.send?.({ type: "paseo:shutdown", reason: "heartbeat_pause_tolerated" });
+          }, 7_000);
+          setInterval(() => {}, 1_000);
+        } else {
+          process.send?.({ type: "paseo:shutdown", reason: "unexpected_heartbeat_restart" });
+          setInterval(() => {}, 1_000);
+        }
+      `,
+    });
+
+    expect(result.code).toBe(0);
+    expect(result.signal).toBeNull();
+    expect(result.log).toContain('"reason":"heartbeat_pause_tolerated"');
+    expect(result.log).not.toContain('"reason":"unexpected_heartbeat_restart"');
+    expect(result.log).not.toContain('"msg":"Worker heartbeat timed out; restarting worker"');
+  }, 10_000);
+
+  test.skipIf(isPlatform("win32"))(
+    "forces shutdown when a worker ignores SIGTERM",
+    async () => {
+      const result = await runSupervisorFixture({
+        timeoutMs: 15_000,
+        workerSource: `
+          process.on("SIGTERM", () => {});
+          process.send?.({ type: "paseo:shutdown", reason: "stalled_worker_shutdown" });
+          setInterval(() => {}, 1_000);
+        `,
+      });
+
+      expect(result.code).toBe(0);
+      expect(result.signal).toBeNull();
+      expect(result.log).toContain('"reason":"stalled_worker_shutdown"');
+      expect(result.log).toContain('"msg":"Worker did not exit after SIGTERM; forcing SIGKILL"');
+      expect(result.log).toContain('"signal":"SIGKILL"');
+    },
+    20_000,
+  );
+
+  // POSIX-only: the watchdog uses SIGKILL after its graceful shutdown window.
+  test.skipIf(isPlatform("win32"))(
+    "restarts a worker that stops heartbeating",
+    async () => {
+      const result = await runSupervisorFixture({
+        timeoutMs: 35_000,
+        workerSource: `
+          import { existsSync, writeFileSync } from "node:fs";
+
+          const marker = process.argv[1] + ".started";
+          if (!existsSync(marker)) {
+            writeFileSync(marker, "started");
+            let heartbeatCount = 0;
+            const heartbeat = setInterval(() => {
+              process.send?.({ type: "paseo:worker-heartbeat" });
+              heartbeatCount += 1;
+              if (heartbeatCount === 3) clearInterval(heartbeat);
+            }, 100);
+            process.on("SIGTERM", () => {});
+            setInterval(() => {}, 1000);
+          } else {
+            process.send?.({ type: "paseo:shutdown", reason: "watchdog_test_complete" });
+            setInterval(() => {}, 1000);
+          }
+        `,
+      });
+
+      expect(result.code).toBe(0);
+      expect(result.signal).toBeNull();
+      expect(result.log).toContain('"msg":"Worker heartbeat timed out; restarting worker"');
+      expect(result.log).toContain('"msg":"Worker did not exit after SIGTERM; forcing SIGKILL"');
+      expect(result.log).toContain('"signal":"SIGKILL"');
+    },
+    40_000,
+  );
+
+  test.skipIf(isPlatform("win32"))(
+    "restarts after worker exit while a descendant retains the worker stdio",
+    async () => {
+      const result = await runSupervisorFixture({
+        timeoutMs: 7_000,
+        workerSource: `
+          import { spawn } from "node:child_process";
+          import { existsSync, writeFileSync } from "node:fs";
+
+          const marker = process.argv[1] + ".started";
+          if (!existsSync(marker)) {
+            writeFileSync(marker, "started");
+            const descendant = spawn(
+              process.execPath,
+              ["-e", "process.on('SIGTERM', () => {}); setTimeout(() => process.exit(0), 4000)"],
+              { detached: true, stdio: ["ignore", "inherit", "inherit"] },
+            );
+            descendant.unref();
+            process.on("SIGTERM", () => process.exit(0));
+            process.send?.({ type: "paseo:restart", reason: "stdio_descendant" });
+            setInterval(() => {}, 1000);
+          } else {
+            process.send?.({ type: "paseo:shutdown", reason: "stdio_restart_complete" });
+            setInterval(() => {}, 1000);
+          }
+        `,
+      });
+
+      expect(result.code).toBe(0);
+      expect(result.signal).toBeNull();
+      expect(result.elapsedMs).toBeLessThan(2_500);
+      expect(result.log).toContain('"reason":"stdio_descendant"');
+      expect(result.log).toContain("Restarting worker");
+    },
+    7_000,
+  );
+
  // POSIX-only: Windows reports the worker self-kill as an exit code, not SIGKILL.
  test.skipIf(isPlatform("win32"))(
    "logs worker signal exits even when the worker cannot log",
@@ -2,6 +2,11 @@ import { fork, spawn, type ChildProcess } from "child_process";
 import { mkdirSync } from "node:fs";
 import path from "node:path";
 import { createStream as createRotatingFileStream } from "rotating-file-stream";
+import { signalProcessTree } from "../src/utils/tree-kill.js";
+
+const WORKER_HEARTBEAT_INTERVAL_MS = 1_000;
+const WORKER_HEARTBEAT_TIMEOUT_MS = 15_000;
+const WORKER_TERMINATION_GRACE_MS = 10_000;

 interface SupervisorLogFileOptions {
  path: string;
@@ -29,6 +34,10 @@ interface SupervisorHeartbeatMessage {
  type: "paseo:supervisor-heartbeat";
 }

+interface WorkerHeartbeatMessage {
+  type: "paseo:worker-heartbeat";
+}
+
 interface SupervisorOptions {
  name: string;
  startupMessage: string;
@@ -84,6 +93,15 @@ function parseLifecycleMessage(msg: unknown): WorkerLifecycleMessage | null {
  return null;
 }

+function isWorkerHeartbeatMessage(msg: unknown): msg is WorkerHeartbeatMessage {
+  return (
+    typeof msg === "object" &&
+    msg !== null &&
+    "type" in msg &&
+    (msg as { type?: unknown }).type === "paseo:worker-heartbeat"
+  );
+}
+
 function toRotatingFileStreamSize(size: string): string {
  const trimmed = size.trim();
  const match = trimmed.match(/^(\d+)\s*([bBkKmMgG])?$/);
@@ -120,6 +138,7 @@ export function runSupervisor(options: SupervisorOptions): SupervisorController
  let restarting = false;
  let shuttingDown = false;
  let exiting = false;
+  let forceKillTimer: NodeJS.Timeout | null = null;
  const logStream = createSupervisorLogStream(options.logFile);

  const writeDurableChunk = (chunk: string | Buffer): void => {
@@ -169,6 +188,40 @@ export function runSupervisor(options: SupervisorOptions): SupervisorController
      });
  };

+  const clearForceKillTimer = (): void => {
+    if (forceKillTimer) {
+      clearTimeout(forceKillTimer);
+      forceKillTimer = null;
+    }
+  };
+
+  const scheduleForceKill = (reason: string): void => {
+    if (!child) {
+      return;
+    }
+    const currentChild = child;
+    clearForceKillTimer();
+    forceKillTimer = setTimeout(() => {
+      forceKillTimer = null;
+      if (child !== currentChild) {
+        return;
+      }
+      writeLifecycleLog("Worker did not exit after SIGTERM; forcing SIGKILL", {
+        reason,
+        supervisorPid: process.pid,
+        workerPid: currentChild.pid ?? null,
+      });
+      void signalProcessTree(currentChild, "SIGKILL").catch((error) => {
+        writeLifecycleLog("Failed to force-kill worker process tree", {
+          error: error instanceof Error ? error.message : String(error),
+          supervisorPid: process.pid,
+          workerPid: currentChild.pid ?? null,
+        });
+      });
+    }, WORKER_TERMINATION_GRACE_MS);
+    forceKillTimer.unref();
+  };
+
  const spawnWorker = () => {
    let workerEntry: string;
    try {
@@ -197,6 +250,7 @@ export function runSupervisor(options: SupervisorOptions): SupervisorController
    }

    const currentChild = child;
+    let lastWorkerHeartbeatAt = Date.now();
    const heartbeat = setInterval(() => {
      const message: SupervisorHeartbeatMessage = { type: "paseo:supervisor-heartbeat" };
      if (currentChild.connected) {
@@ -210,9 +264,26 @@ export function runSupervisor(options: SupervisorOptions): SupervisorController
      } else {
        writeLifecycleLog("Worker heartbeat skipped because IPC channel is disconnected");
      }
-    }, 1000);
+    }, WORKER_HEARTBEAT_INTERVAL_MS);
    heartbeat.unref();

+    const workerWatchdog = setInterval(() => {
+      if (child !== currentChild || restarting || shuttingDown) {
+        return;
+      }
+      const heartbeatAgeMs = Date.now() - lastWorkerHeartbeatAt;
+      if (heartbeatAgeMs < WORKER_HEARTBEAT_TIMEOUT_MS) {
+        return;
+      }
+      writeLifecycleLog("Worker heartbeat timed out; restarting worker", {
+        heartbeatAgeMs,
+        supervisorPid: process.pid,
+        workerPid: currentChild.pid ?? null,
+      });
+      requestRestart("worker_heartbeat_timeout");
+    }, WORKER_HEARTBEAT_INTERVAL_MS);
+    workerWatchdog.unref();
+
    child.on("disconnect", () => {
      writeLifecycleLog("Worker IPC channel disconnected");
    });
@@ -228,6 +299,10 @@ export function runSupervisor(options: SupervisorOptions): SupervisorController
    });

    child.on("message", (msg: unknown) => {
+      if (isWorkerHeartbeatMessage(msg)) {
+        lastWorkerHeartbeatAt = Date.now();
+        return;
+      }
      const lifecycleMessage = parseLifecycleMessage(msg);
      if (!lifecycleMessage) {
        return;
@@ -256,8 +331,10 @@ export function runSupervisor(options: SupervisorOptions): SupervisorController
      requestRestart(reason);
    });

-    child.on("close", (code, signal) => {
+    child.on("exit", (code, signal) => {
      clearInterval(heartbeat);
+      clearInterval(workerWatchdog);
+      clearForceKillTimer();
      const exitDescriptor = describeExit(code, signal);
      writeLifecycleLog("Worker exited", { code, signal, exit: exitDescriptor });

@@ -308,6 +385,7 @@ export function runSupervisor(options: SupervisorOptions): SupervisorController
    writeLifecycleLog("Restart requested", { reason });
    log(`${reason}. Stopping worker for restart...`);
    signalWorker("SIGTERM", reason);
+    scheduleForceKill(reason);
  };

  const requestShutdown = (reason: string) => {
@@ -323,6 +401,7 @@ export function runSupervisor(options: SupervisorOptions): SupervisorController
      return;
    }
    signalWorker("SIGTERM", reason);
+    scheduleForceKill(reason);
  };

  const forwardSignal = (signal: NodeJS.Signals) => {