diff --git a/CHANGELOG.md b/CHANGELOG.md index 10351b1f..a82672ed 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,6 +11,46 @@ split, begin at v1.0.0 — see [VERSIONING.md](VERSIONING.md) for exactly what ## [Unreleased] +### Added + +- **Event-loop watchdog: a server whose main thread gets stuck no longer hangs + silently until someone restarts it.** One synchronous loop (catastrophic + regex backtracking, a conversion that never terminates) blocks the single + thread that serves every request, so every URL stops answering at once, with + nothing in the logs. `dune dev` and `dune serve` now run a small watchdog + Worker that expects a heartbeat from the main thread every second. After 15 + seconds of silence (`DUNE_WATCHDOG_TIMEOUT_MS`; 2 minutes until the server is + up, `DUNE_WATCHDOG_STARTUP_TIMEOUT_MS`, so a large site's initial indexing + can't put a supervised process into a kill/restart loop) it writes a report + to `/.dune/hangs/` naming the requests that were in flight (path + segments longer than 24 characters are cut, so tokens in URLs don't land in + it; the newest 20 reports are kept; plus a native stack sample on macOS), logs + the same lines to stderr, and SIGKILLs the process so a supervisor (systemd + `Restart=`; the `dune dev` wrapper exits 137) sees a dead process instead of + a zombie. The kill always happens: writing the report is abandoned after 5 + seconds. `DUNE_WATCHDOG=warn` reports without killing and is chosen + automatically when the process runs under `--inspect`/`--inspect-brk` (a + breakpoint pauses only the main thread); `DUNE_WATCHDOG=off` disables it. A + process that is suspended and resumed (laptop sleep, Ctrl-Z) is not mistaken + for a hang: the stall clock is monotonic and the Worker discards a gap in its + own ticks. It kills with SIGKILL rather than `Deno.exit()` because an exit + requested from a Worker only ends the Worker — the spinning main thread + carries on. +- **Telling the watchdog about legitimately synchronous work.** The watchdog + can't tell an infinite loop from a long computation, only whether the loop is + making progress. `@dune/core/watchdog` exports two functions for code that + blocks on purpose: `watchdogProgress()`, called per item inside a long + synchronous loop (counts as a heartbeat; rate-limited, so cheap), and + `watchdogGrace(ms, reason)`, a declared busy window for a single long native + call (capped at 10 minutes, nests, expires on its own, logged each time). A + loop that calls `watchdogProgress()` on every iteration of an unbounded loop + looks alive forever; use it only where the loop has a natural end. Measured + on a 4,474-page site: startup indexing and the search build never held the + event loop for over a second, so none of Dune's own loops needed either call. +- The main thread also logs `[dune] event loop was blocked for ~N.Ns` whenever + it was held for over a second, which shows a creeping problem before it + becomes a hang. + ### Fixed - **Co-located audio and video could not seek, and would not play in diff --git a/deno.json b/deno.json index da4f135c..b4877555 100644 --- a/deno.json +++ b/deno.json @@ -54,7 +54,8 @@ "./i18n": "./src/i18n/rtl.ts", "./api": "./src/api/handlers.ts", "./bootstrap": "./src/runtime/bootstrap.ts", - "./fresh-app": "./src/runtime/server.ts" + "./fresh-app": "./src/runtime/server.ts", + "./watchdog": "./src/runtime/watchdog.ts" }, "imports": { "@dune/plugin-admin": "jsr:@dune/plugin-admin@^3.0", diff --git a/src/cli/dev.ts b/src/cli/dev.ts index cd8e23f4..81e309b5 100644 --- a/src/cli/dev.ts +++ b/src/cli/dev.ts @@ -22,6 +22,7 @@ import { materializeRemoteIslands } from "./remote-islands.ts"; import { checkLockfileStaleness } from "./lockfile.ts"; import { resolveContentDirPath } from "../content/content-root.ts"; import { registerEsbuildWorkerCleanup } from "./esbuild-cleanup.ts"; +import { startWatchdog } from "../runtime/watchdog.ts"; export interface DevOptions { port?: number; @@ -36,6 +37,11 @@ export async function devCommand(root: string, options: DevOptions = {}) { // invalidate any relative paths computed against the original cwd. root = resolve(root); + // A server whose event loop is stuck can't answer anything, log anything or + // be stopped gracefully; see runtime/watchdog.ts. Dev has no graceful-exit + // path to hook (Ctrl-C / --watch restarts end the process), so no stop(). + const watchdog = startWatchdog({ root, label: "dune dev" }); + registerEsbuildWorkerCleanup(); // ── Lockfile staleness check (advisory in dev) ─────────────────────────── @@ -61,6 +67,7 @@ export async function devCommand(root: string, options: DevOptions = {}) { await manager.init(root, { port, debug, dev: true }); console.log(`\n 🌐 http://localhost:${port} (${manager.siteCount()} sites)\n`); Deno.serve({ port, handler: (req, info) => manager.handle(req, info) }); + watchdog.ready(); return; } @@ -207,6 +214,8 @@ export async function devCommand(root: string, options: DevOptions = {}) { const { app, notifyReload } = await createDuneApp(ctx, { root, port, debug, dev: true }); // Wire the content watcher's notifyReload reference now that the app is built. notifyContentReload = notifyReload; + // Startup is over: from here on the normal (short) stall limit applies. + watchdog.ready(); return app; }, { port }); } diff --git a/src/cli/serve.ts b/src/cli/serve.ts index 05ae1691..af7f8e6c 100644 --- a/src/cli/serve.ts +++ b/src/cli/serve.ts @@ -32,6 +32,7 @@ import type { Scheduler, ScheduledAction } from "../workflow/mod.ts"; import { resolveContentDirPath } from "../content/content-root.ts"; import { createEmailClient, createEmailProvider } from "../email/mod.ts"; import { checkLockfileStaleness } from "./lockfile.ts"; +import { startWatchdog } from "../runtime/watchdog.ts"; export interface ServeOptions { port?: number; @@ -106,6 +107,10 @@ export async function serveCommand(root: string, options: ServeOptions = {}) { // path and we Deno.chdir() later, which would invalidate relative paths. root = resolve(root); + // See runtime/watchdog.ts. Its Worker can't be unref'd, so both graceful- + // shutdown paths below stop it explicitly or the process would never exit. + const watchdog = startWatchdog({ root, label: "dune serve" }); + // ── Lockfile staleness check ───────────────────────────────────────────── if (await checkLockfileStaleness(root)) { if (frozen) { @@ -170,9 +175,11 @@ export async function serveCommand(root: string, options: ServeOptions = {}) { }, ); + watchdog.ready(); await server.finished; await drainInFlight(() => inFlight, drainDeadlineMs); cleanup(); + watchdog.stop(); console.log("[dune] shutdown complete"); return; } @@ -374,6 +381,7 @@ export async function serveCommand(root: string, options: ServeOptions = {}) { }, ); + watchdog.ready(); await server.finished; // Safety-net drain poll — in normal operation inFlight is already 0 here @@ -387,5 +395,6 @@ export async function serveCommand(root: string, options: ServeOptions = {}) { // flush step is required here. cleanup(); + watchdog.stop(); console.log("[dune] shutdown complete"); } diff --git a/src/runtime/server.ts b/src/runtime/server.ts index 99764266..cb9343af 100644 --- a/src/runtime/server.ts +++ b/src/runtime/server.ts @@ -19,6 +19,7 @@ import { mountPlugins } from "../plugins/loader.ts"; import { mountDuneAuth } from "../auth/mount.ts"; import { getUser, USER_HEADER } from "../auth/types.ts"; import { isAdminPath, withSecurityHeaders } from "../cli/serve-utils.ts"; +import { trackRequest } from "./watchdog.ts"; import { duneRoutes } from "../routing/routes.ts"; import { buildPluginClientBundles } from "../cli/client-bundles.ts"; import { createApiHandler } from "../api/handlers.ts"; @@ -346,6 +347,17 @@ export async function createDuneApp( return fc.next(); }); + // 0a. Tell the event-loop watchdog which requests are in flight, so a hang + // report can name the one that never finished. No-op without a watchdog. + app.use(async (fc) => { + const done = trackRequest(fc.req.method, fc.url.pathname); + try { + return await fc.next(); + } finally { + done(); + } + }); + // 0b. Standard security headers on EVERY response, whichever route family // produced it — plugin publicRoutes, plugin mount() routes, /api/*, /health, // sitemap and feeds, static files. They used to be applied by wrapping diff --git a/src/runtime/watchdog.ts b/src/runtime/watchdog.ts new file mode 100644 index 00000000..4c86edef --- /dev/null +++ b/src/runtime/watchdog.ts @@ -0,0 +1,397 @@ +/** + * Event-loop watchdog. + * + * A synchronous loop (catastrophic regex backtracking, a conversion that never + * terminates) blocks the one thread that serves every request, so one bad + * request takes the whole site down — silently, with nothing in the logs, and + * only a restart clears it. A blocked thread can't rescue itself, so the check + * runs on a separate one: the main thread posts a heartbeat to a Worker every + * second, and the Worker acts when the heartbeats stop. + * + * What it does on a stall (`DUNE_WATCHDOG`): + * - `exit` (default): write a report (plus a native stack sample where + * `sample` exists) to `/.dune/hangs/`, then SIGKILL the process so a + * supervisor (systemd `Restart=`, the `dune dev` wrapper's exit) sees a + * dead process instead of a zombie. SIGKILL, not `Deno.exit()`: an exit + * requested from a worker only ends the worker; the spinning main thread + * carries on. The kill always happens: writing the report is raced against + * a timeout. + * - `warn`: same report, no kill. Used automatically when an inspector flag + * (`--inspect`, `--inspect-brk`, ...) is present, because a breakpoint + * pauses only the main thread and would otherwise look like a hang. + * - `off`: nothing starts. + * + * It measures a lack of *progress*, not of idleness, and it cannot tell an + * infinite loop from a long computation by looking at the thread. Work that is + * legitimately synchronous says so: + * - `watchdogProgress()`, called per item inside a long synchronous loop, + * counts as a heartbeat (rate-limited, so calling it 10k times is cheap). + * It only protects loops that call it: an unbounded loop that calls it on + * every iteration looks alive forever. Most indexing/compile loops are + * async and yield anyway; only genuinely synchronous ones need it. + * - `watchdogGrace(ms, reason)` declares an expected-busy window for work + * where per-item progress can't be reported (one long native call). It is + * capped, auto-expires, nests, and is logged when used. + * + * Two further guards against false kills: the stall clock is monotonic + * (`performance.now()`), and the Worker treats a tick of its own that ran + * late as "the whole process was suspended" (laptop sleep, Ctrl-Z / SIGSTOP) + * and resets rather than fires. Until the server reports `ready()` the limit + * is the much longer startup limit, so a big site's initial indexing can't + * put a supervised process into a kill/restart loop. + * + * The main thread also logs a one-line warning when its own timer ran over a + * second late, which makes a creeping problem visible before it becomes a + * hang. + * + * @module + */ + +export type WatchdogMode = "exit" | "warn" | "off"; + +export interface WatchdogOptions { + /** Site root; reports go to `/.dune/hangs/`. */ + root: string; + /** What to do on a stall. Default: `DUNE_WATCHDOG` env, else `exit` (`warn` under an inspector). */ + mode?: WatchdogMode; + /** Heartbeat silence that counts as a stall once ready. Default: `DUNE_WATCHDOG_TIMEOUT_MS` env, else 15000. */ + stallMs?: number; + /** The limit before `ready()` is called. Default: `DUNE_WATCHDOG_STARTUP_TIMEOUT_MS` env, else 120000. */ + startupStallMs?: number; + /** Heartbeat period. Default 1000; tests shorten it. */ + heartbeatMs?: number; + /** Event-loop delay (over the expected tick) that logs a warning. Default 1000. */ + lagWarnMs?: number; + /** Shown in the report and log line, e.g. `dev` / `serve`. */ + label?: string; + /** How long writing the report may take before the kill goes ahead anyway. Default 5000; tests shorten it. */ + reportTimeoutMs?: number; +} + +export interface Watchdog { + /** The server is up: switch from the startup limit to the normal one. */ + ready(): void; + stop(): void; +} + +const DEFAULT_STALL_MS = 15_000; +const DEFAULT_STARTUP_STALL_MS = 120_000; +const DEFAULT_HEARTBEAT_MS = 1_000; +const DEFAULT_LAG_WARN_MS = 1_000; +/** `watchdogProgress()` posts at most this often. */ +const PROGRESS_MIN_INTERVAL_MS = 250; +/** No grace window may be longer than this, whatever the caller asks. */ +export const MAX_GRACE_MS = 10 * 60_000; +/** Reports kept in `.dune/hangs/`; older ones are deleted. */ +const MAX_REPORTS = 20; +/** Writing the report must not be able to stop the kill. */ +const REPORT_TIMEOUT_MS = 5_000; + +// The running watchdog's Worker, so request middleware can report to it. +let activeWorker: Worker | null = null; +let nextId = 0; +let lastProgressPost = 0; + +/** + * Hide anything token-shaped before a request path goes into a report: any + * path segment longer than 24 characters is cut to its first six. + */ +export function maskPath(path: string): string { + return path.split("/").map((seg) => (seg.length > 24 ? `${seg.slice(0, 6)}…` : seg)).join("/"); +} + +/** + * Record a request as in flight; call the returned function when it + * finishes. A stall report then lists what was running, which is usually + * the answer to "what hung?" — the native stack sample has no JS frames. A + * no-op when no watchdog is running. + */ +export function trackRequest(method: string, path: string): () => void { + const worker = activeWorker; + if (!worker) return () => {}; + const id = ++nextId; + worker.postMessage({ type: "req+", id, desc: `${method} ${maskPath(path)}` }); + return () => worker.postMessage({ type: "req-", id }); +} + +/** + * Report progress from inside a long synchronous loop: counts as a heartbeat. + * Cheap and rate-limited; a no-op when no watchdog is running. Call it once + * per item, never in a loop that has no natural end. + */ +export function watchdogProgress(): void { + const worker = activeWorker; + if (!worker) return; + const now = performance.now(); + if (now - lastProgressPost < PROGRESS_MIN_INTERVAL_MS) return; + lastProgressPost = now; + worker.postMessage({ type: "beat" }); +} + +/** + * Declare that the process is expected to be busy for up to `ms` (capped at + * `MAX_GRACE_MS`): the stall check pauses until the returned function is + * called or the window expires, whichever is first. Windows nest. Use it only + * for work that cannot report progress per item; it is logged each time. + */ +export function watchdogGrace(ms: number, reason: string): () => void { + const worker = activeWorker; + if (!worker) return () => {}; + const capped = Math.max(0, Math.min(ms, MAX_GRACE_MS)); + const id = ++nextId; + console.warn(`[dune] watchdog: grace for "${reason}" (up to ${Math.round(capped / 1000)}s)`); + worker.postMessage({ type: "grace+", id, ms: capped }); + return () => worker.postMessage({ type: "grace-", id }); +} + +/** Parse `DUNE_WATCHDOG`; anything unrecognised falls back to the default. */ +export function parseWatchdogMode(value: string | undefined): WatchdogMode { + const v = value?.trim().toLowerCase(); + return v === "off" || v === "warn" || v === "exit" ? v : "exit"; +} + +function parseMs(value: string | undefined, fallback: number): number { + const n = Number(value); + return Number.isFinite(n) && n >= 1000 ? n : fallback; +} + +/** Was this process started with an inspector flag? (`Deno.args` only has script args, so ask `ps`.) */ +export function inspectorAttached(): boolean { + if (Deno.build.os === "windows") return false; + try { + const out = new Deno.Command("ps", { + args: ["-o", "args=", "-p", String(Deno.pid)], + stdout: "piped", + stderr: "null", + }).outputSync(); + return /(^|\s)--inspect(-brk|-wait)?([=\s]|$)/.test(new TextDecoder().decode(out.stdout)); + } catch { + return false; + } +} + +// Runs in the Worker. Kept as a string so it works from any module origin +// (jsr:/https: included), where a relative worker URL would not. +const WORKER_SOURCE = ` +let cfg = null; +let last = performance.now(); +let lastTick = performance.now(); +let fired = false; +let ready = false; +const TICK_MS = 500; +const inflight = new Map(); // id -> { desc, since } +const graces = new Map(); // id -> expiry (performance.now() ms) +const pad = (n) => String(n).padStart(2, "0"); +const sleep = (ms) => new Promise((r) => setTimeout(r, ms)); + +async function prune(dir) { + try { + const names = []; + for await (const e of Deno.readDir(dir)) if (/^hang-.*\\.txt$/.test(e.name) && !e.name.endsWith(".sample.txt")) names.push(e.name); + names.sort(); + for (const n of names.slice(0, Math.max(0, names.length - cfg.maxReports))) { + const base = n.slice(0, -4); + await Deno.remove(dir + "/" + n).catch(() => {}); + await Deno.remove(dir + "/" + base + ".sample.txt").catch(() => {}); + } + } catch { /* retention is best effort */ } +} + +async function report(silentMs) { + const now = new Date(); + const stamp = now.getFullYear() + pad(now.getMonth() + 1) + pad(now.getDate()) + + "-" + pad(now.getHours()) + pad(now.getMinutes()) + pad(now.getSeconds()); + const dir = cfg.root + "/.dune/hangs"; + const base = dir + "/hang-" + stamp + "-" + cfg.pid; + const lines = [ + "Dune event-loop watchdog report", + "time: " + now.toISOString(), + "pid: " + cfg.pid, + "command: " + cfg.label, + "root: " + cfg.root, + "deno: " + Deno.version.deno, + "uptime: " + Math.round((performance.now() - cfg.startedAt) / 1000) + "s", + "phase: " + (ready ? "serving" : "startup"), + "stalled: main thread silent for " + Math.round(silentMs / 1000) + "s (limit " + + Math.round(limit() / 1000) + "s)", + "action: " + (cfg.mode === "exit" ? "SIGKILL" : "none (DUNE_WATCHDOG=warn)"), + ]; + const nowMs = performance.now(); + const pending = [...inflight.values()].sort((a, b) => a.since - b.since); + lines.push("in-flight requests: " + pending.length); + for (const r of pending.slice(0, 20)) { + lines.push(" " + r.desc + " (" + Math.round((nowMs - r.since) / 1000) + "s)"); + } + let sampled = false; + try { + await Deno.mkdir(dir, { recursive: true }); + if (Deno.build.os === "darwin") { + // 'sample' ships with macOS; it reads the stuck thread's native stack. + const out = await new Deno.Command("sample", { + args: [String(cfg.pid), "1", "-file", base + ".sample.txt"], + stdout: "null", + stderr: "null", + }).output(); + sampled = out.success; + } + if (sampled) lines.push("sample: " + base + ".sample.txt"); + else lines.push("sample: unavailable on this platform; run 'eu-stack -p " + cfg.pid + "' or 'gdb -p " + cfg.pid + "' next time before killing"); + await Deno.writeTextFile(base + ".txt", lines.join("\\n") + "\\n"); + lines.push("report: " + base + ".txt"); + await prune(dir); + } catch (err) { + lines.push("report: could not be written (" + err + ")"); + } + return lines; +} + +function limit() { + return ready ? cfg.stallMs : cfg.startupStallMs; +} + +function graceActive(t) { + for (const [id, expiry] of graces) { + if (expiry <= t) graces.delete(id); + } + return graces.size > 0; +} + +async function onStall(silent) { + console.error("[dune] watchdog: the main thread has not responded for " + + Math.round(silent / 1000) + "s (event loop blocked)"); + // The kill must not depend on the report: a hung 'sample', a slow or + // network filesystem, or a failing mkdir would otherwise leave the process + // running forever. + const lines = await Promise.race([report(silent), sleep(cfg.reportTimeoutMs).then(() => null)]); + if (lines === null) { + console.error("[dune] watchdog: the report did not finish within " + Math.round(cfg.reportTimeoutMs / 1000) + "s"); + } else { + for (const l of lines.filter((l) => /^(in-flight| [A-Z]+ |sample|report)/.test(l))) { + console.error("[dune] watchdog: " + l.trim()); + } + } + if (cfg.mode === "exit") { + console.error("[dune] watchdog: killing pid " + cfg.pid + " so it can be restarted"); + try { + Deno.kill(cfg.pid, "SIGKILL"); + return; + } catch (err) { + // Typically a missing --allow-run. Say so, and fall back to reporting + // only: silently never firing again would be the worst outcome. + console.error("[dune] watchdog: could not kill pid " + cfg.pid + " (" + err + "); " + + "continuing in warn mode"); + cfg.mode = "warn"; + } + } + fired = false; // keep watching, and report again if it stays stuck + last = performance.now(); +} + +self.onmessage = (e) => { + const msg = e.data; + if (msg.type === "init") { + cfg = msg; + last = lastTick = performance.now(); + setInterval(() => { + const t = performance.now(); + const gap = t - lastTick; + lastTick = t; + // Our own timer ran far later than scheduled: the whole process was + // suspended (sleep, SIGSTOP/Ctrl-Z). The main thread could not have + // beaten us to the next heartbeat, so forget the gap. + if (gap > TICK_MS * 2) { last = t; return; } + const silent = t - last; + if (fired || silent < limit() || graceActive(t)) return; + fired = true; + onStall(silent); + }, TICK_MS); + } else if (msg.type === "beat") { + last = performance.now(); + } else if (msg.type === "ready") { + ready = true; + last = performance.now(); + } else if (msg.type === "req+") { + inflight.set(msg.id, { desc: msg.desc, since: performance.now() }); + } else if (msg.type === "req-") { + inflight.delete(msg.id); + } else if (msg.type === "grace+") { + graces.set(msg.id, performance.now() + msg.ms); + } else if (msg.type === "grace-") { + graces.delete(msg.id); + last = performance.now(); + } +}; +`; + +/** + * Start the watchdog for this process. Returns a handle whose `stop()` ends + * it; a no-op handle when the mode is `off`. + */ +export function startWatchdog(opts: WatchdogOptions): Watchdog { + let mode = opts.mode ?? parseWatchdogMode(Deno.env.get("DUNE_WATCHDOG")); + if (mode === "off") return { ready() {}, stop() {} }; + if (mode === "exit" && opts.mode === undefined && Deno.env.get("DUNE_WATCHDOG") === undefined && inspectorAttached()) { + console.warn("[dune] watchdog: inspector detected, reporting stalls instead of killing (DUNE_WATCHDOG=warn)"); + mode = "warn"; + } + + const stallMs = opts.stallMs ?? parseMs(Deno.env.get("DUNE_WATCHDOG_TIMEOUT_MS"), DEFAULT_STALL_MS); + const startupStallMs = Math.max( + stallMs, + opts.startupStallMs ?? parseMs(Deno.env.get("DUNE_WATCHDOG_STARTUP_TIMEOUT_MS"), DEFAULT_STARTUP_STALL_MS), + ); + const heartbeatMs = opts.heartbeatMs ?? DEFAULT_HEARTBEAT_MS; + const lagWarnMs = opts.lagWarnMs ?? DEFAULT_LAG_WARN_MS; + + const url = URL.createObjectURL( + new Blob([WORKER_SOURCE], { type: "application/javascript" }), + ); + const worker = new Worker(url, { type: "module" }); + URL.revokeObjectURL(url); + activeWorker = worker; + worker.postMessage({ + type: "init", + mode, + stallMs, + startupStallMs, + root: opts.root, + pid: Deno.pid, + label: opts.label ?? "dune", + startedAt: performance.now(), + maxReports: MAX_REPORTS, + reportTimeoutMs: opts.reportTimeoutMs ?? REPORT_TIMEOUT_MS, + }); + + let expected = performance.now() + heartbeatMs; + const timer = setInterval(() => { + const now = performance.now(); + const lag = now - expected; + expected = now + heartbeatMs; + worker.postMessage({ type: "beat" }); + if (lag >= lagWarnMs) { + console.warn(`[dune] event loop was blocked for ~${(lag / 1000).toFixed(1)}s`); + } + }, heartbeatMs); + // The heartbeat must not be what keeps a finished process alive. + Deno.unrefTimer(timer); + + let stopped = false; + const stop = () => { + if (stopped) return; + stopped = true; + if (activeWorker === worker) activeWorker = null; + clearInterval(timer); + worker.terminate(); + }; + // Unlike a timer, a Worker cannot be unref'd: it keeps the process alive + // until terminated. Every normal exit path (`dune serve`'s graceful + // shutdown) must therefore call stop(); signal-driven and Deno.exit() + // exits end the process regardless. 'unload' is a best-effort backstop. + globalThis.addEventListener("unload", stop); + return { + ready: () => { + if (!stopped) worker.postMessage({ type: "ready" }); + }, + stop, + }; +} diff --git a/tests/runtime/watchdog_test.ts b/tests/runtime/watchdog_test.ts new file mode 100644 index 00000000..dfabeee0 --- /dev/null +++ b/tests/runtime/watchdog_test.ts @@ -0,0 +1,468 @@ +/** + * Tests for the event-loop watchdog (src/runtime/watchdog.ts). + * + * The behaviour under test is a process killing itself while its main thread + * is stuck in a loop, so every case runs a real child `deno` process and + * inspects how it ended. + */ + +import { assert, assertEquals, assertStringIncludes } from "https://deno.land/std@0.224.0/assert/mod.ts"; +import { join } from "@std/path"; +import { maskPath, parseWatchdogMode } from "../../src/runtime/watchdog.ts"; + +const WATCHDOG_URL = new URL("../../src/runtime/watchdog.ts", import.meta.url).href; +const CHILD_DEADLINE_MS = 25_000; +const noSanitize = { sanitizeOps: false, sanitizeResources: false }; +const unixOnly = { ...noSanitize, ignore: Deno.build.os === "windows" }; + +interface ChildResult { + code: number; + signal: Deno.Signal | null; + stdout: string; + stderr: string; + timedOut: boolean; +} + +interface ChildOptions { + env?: Record; + /** Extra args to `deno run` (permissions, inspector flags). Default: `-A`. */ + denoArgs?: string[]; +} + +/** Run `body` as a module that has already started a watchdog configured by `opts`. */ +async function runChild(root: string, opts: string, body: string, extra: ChildOptions = {}): Promise { + const script = join(root, "child.ts"); + await Deno.writeTextFile( + script, + `import { startWatchdog, watchdogProgress, watchdogGrace } from ${JSON.stringify(WATCHDOG_URL)};\n` + + `const wd = startWatchdog({ root: ${JSON.stringify(root)}, ${opts} });\n${body}\n`, + ); + const child = new Deno.Command(Deno.execPath(), { + args: ["run", ...(extra.denoArgs ?? ["-A"]), script], + env: extra.env, + stdout: "piped", + stderr: "piped", + }).spawn(); + return await finish(child); +} + +async function finish(child: Deno.ChildProcess): Promise { + let timedOut = false; + const killer = setTimeout(() => { + timedOut = true; + try { + child.kill("SIGKILL"); + } catch { /* already gone */ } + }, CHILD_DEADLINE_MS); + const out = await child.output(); + clearTimeout(killer); + const dec = new TextDecoder(); + return { + code: out.code, + signal: out.signal, + stdout: dec.decode(out.stdout), + stderr: dec.decode(out.stderr), + timedOut, + }; +} + +async function withRoot(fn: (root: string) => Promise): Promise { + const root = await Deno.makeTempDir({ prefix: "dune_test_watchdog_" }); + try { + await fn(root); + } finally { + await Deno.remove(root, { recursive: true }).catch(() => {}); + } +} + +async function reports(root: string): Promise { + try { + const names: string[] = []; + for await (const e of Deno.readDir(join(root, ".dune", "hangs"))) names.push(e.name); + return names.sort(); + } catch { + return []; + } +} + +const mainReports = (names: string[]) => names.filter((f) => /^hang-.*\.txt$/.test(f) && !f.endsWith(".sample.txt")); + +/** Busy-wait `ms` of wall time. */ +const SPIN = (ms: number) => `{ const t = Date.now(); while (Date.now() - t < ${ms}) {} }`; + +// ── units ──────────────────────────────────────────────────────────────────── + +Deno.test("parseWatchdogMode: accepts the three modes, defaults anything else to exit", () => { + assertEquals(parseWatchdogMode("off"), "off"); + assertEquals(parseWatchdogMode("WARN"), "warn"); + assertEquals(parseWatchdogMode(" exit "), "exit"); + assertEquals(parseWatchdogMode(undefined), "exit"); + assertEquals(parseWatchdogMode("nonsense"), "exit"); +}); + +Deno.test("maskPath: short segments are kept, token-sized ones are cut", () => { + assertEquals(maskPath("/blog/my-first-post/"), "/blog/my-first-post/"); + assertEquals(maskPath("/auth/verify/0123456789abcdef0123456789abcdef"), "/auth/verify/012345…"); + assertEquals(maskPath("/a/b"), "/a/b"); +}); + +// ── the kill ───────────────────────────────────────────────────────────────── + +Deno.test( + "watchdog (exit): a main thread stuck in a loop is SIGKILLed, with a report written first", + noSanitize, + async () => { + await withRoot(async (root) => { + const r = await runChild( + root, + `mode: "exit", stallMs: 1500, startupStallMs: 1500, heartbeatMs: 100`, + `import { trackRequest } from ${JSON.stringify(WATCHDOG_URL)};\n` + + `trackRequest("GET", "/fine")();\n` + + `trackRequest("GET", "/stuck/0123456789abcdef0123456789abcdef");\n` + + `setTimeout(() => { console.log("spinning"); while (true) {} }, 300);\n` + + `Deno.serve({ port: 0, onListen: () => {} }, () => new Response("ok"));`, + ); + assert(!r.timedOut, "child was still running at the deadline — the watchdog did not fire"); + assertEquals(r.signal, "SIGKILL"); + assertStringIncludes(r.stderr, "event loop blocked"); + const files = mainReports(await reports(root)); + assert(files.length > 0, `no report in ${await reports(root)}`); + const report = await Deno.readTextFile(join(root, ".dune", "hangs", files[0])); + assertStringIncludes(report, "main thread silent for"); + assertStringIncludes(report, "action: SIGKILL"); + assertStringIncludes(report, "GET /stuck/"); + assert(!report.includes("0123456789abcdef0123456789abcdef"), "a token-sized path segment must be masked"); + assert(!report.includes("GET /fine"), "a finished request must not be listed"); + }); + }, +); + +Deno.test( + "watchdog (warn): reports a stall but leaves the process alone", + noSanitize, + async () => { + await withRoot(async (root) => { + // Block for ~2.5s (past the 1.5s limit), then carry on and exit normally. + const r = await runChild( + root, + `mode: "warn", stallMs: 1500, startupStallMs: 1500, heartbeatMs: 100`, + `setTimeout(async () => {\n` + + ` ${SPIN(2500)}\n` + + ` // Let the report (and macOS 'sample') finish before stopping.\n` + + ` for (let i = 0; i < 100; i++) {\n` + + ` try { for await (const e of Deno.readDir(${JSON.stringify(root)} + "/.dune/hangs")) if (e.name.endsWith(".txt") && !e.name.endsWith(".sample.txt")) { wd.stop(); Deno.exit(0); } } catch {}\n` + + ` await new Promise((r) => setTimeout(r, 100));\n` + + ` }\n` + + ` wd.stop();\n` + + `}, 300);`, + ); + assert(!r.timedOut); + assertEquals(r.code, 0); + assertEquals(r.signal, null); + assertStringIncludes(r.stderr, "event loop blocked"); + assert((await reports(root)).length > 0, "expected a report file"); + }); + }, +); + +Deno.test( + "watchdog: a briefly blocked loop under the limit is not reported, but the lag is logged", + noSanitize, + async () => { + await withRoot(async (root) => { + const r = await runChild( + root, + `mode: "exit", stallMs: 5000, heartbeatMs: 100, lagWarnMs: 500`, + `setTimeout(() => { ${SPIN(900)} }, 300);\n` + `setTimeout(() => wd.stop(), 1500);`, + ); + assert(!r.timedOut); + assertEquals(r.code, 0); + assertStringIncludes(r.stderr, "event loop was blocked for"); + assertEquals((await reports(root)).length, 0); + }); + }, +); + +Deno.test( + "watchdog: after stop(), a finished process exits on its own", + noSanitize, + async () => { + await withRoot(async (root) => { + // A Worker can't be unref'd, so stop() is the contract: once it has + // been called (as `dune serve`'s shutdown does) nothing of the + // watchdog may hold the process open. + const r = await runChild(root, `mode: "exit", heartbeatMs: 100`, `setTimeout(() => wd.stop(), 300);`); + assert(!r.timedOut, "process lingered after its work was done"); + assertEquals(r.code, 0); + }); + }, +); + +Deno.test( + "watchdog (off): starts nothing and the process exits normally", + noSanitize, + async () => { + await withRoot(async (root) => { + const r = await runChild(root, `mode: "off"`, `console.log("done");`); + assert(!r.timedOut); + assertEquals(r.code, 0); + assertStringIncludes(r.stdout, "done"); + }); + }, +); + +// ── not killing what shouldn't be killed ───────────────────────────────────── + +Deno.test( + "watchdog: a process suspended and resumed (laptop sleep, Ctrl-Z) is not mistaken for a hang", + unixOnly, + async () => { + await withRoot(async (root) => { + const script = join(root, "child.ts"); + await Deno.writeTextFile( + script, + `import { startWatchdog } from ${JSON.stringify(WATCHDOG_URL)};\n` + + `const wd = startWatchdog({ root: ${JSON.stringify(root)}, mode: "exit", stallMs: 1500, startupStallMs: 1500, heartbeatMs: 100 });\n` + + `wd.ready();\nconsole.log("ready");\nsetTimeout(() => wd.stop(), 7000);\n`, + ); + const child = new Deno.Command(Deno.execPath(), { args: ["run", "-A", script], stdout: "piped", stderr: "piped" }).spawn(); + // Wait until the watchdog is running, then freeze the whole process well past the limit. + const reader = child.stdout.getReader(); + const first = await reader.read(); + assertStringIncludes(new TextDecoder().decode(first.value), "ready"); + reader.releaseLock(); + await new Promise((r) => setTimeout(r, 400)); + Deno.kill(child.pid, "SIGSTOP"); + await new Promise((r) => setTimeout(r, 3500)); + Deno.kill(child.pid, "SIGCONT"); + const r = await finish(child); + assert(!r.timedOut); + assertEquals(r.signal, null, `was killed after resume:\n${r.stderr}`); + assertEquals(r.code, 0); + assertEquals((await reports(root)).length, 0, "no report for a pause"); + }); + }, +); + +Deno.test( + "watchdog: until ready() the long startup limit applies; after it, the normal one", + noSanitize, + async () => { + await withRoot(async (root) => { + // 2.5s of blocking during startup is over the 1.5s normal limit but under the 6s startup limit. + const startup = await runChild( + root, + `mode: "exit", stallMs: 1500, startupStallMs: 6000, heartbeatMs: 100`, + `setTimeout(() => { ${SPIN(2500)} wd.stop(); }, 300);`, + ); + assert(!startup.timedOut); + assertEquals(startup.signal, null, `killed during startup:\n${startup.stderr}`); + assertEquals(startup.code, 0); + + // The same block after ready() is a stall. + const serving = await runChild( + root, + `mode: "exit", stallMs: 1500, startupStallMs: 6000, heartbeatMs: 100`, + `wd.ready();\nsetTimeout(() => { while (true) {} }, 300);`, + ); + assert(!serving.timedOut); + assertEquals(serving.signal, "SIGKILL"); + }); + }, +); + +Deno.test( + "watchdogProgress: a synchronous loop that keeps reporting progress survives, one that doesn't is killed", + noSanitize, + async () => { + await withRoot(async (root) => { + const alive = await runChild( + root, + `mode: "exit", stallMs: 1500, startupStallMs: 1500, heartbeatMs: 100`, + `wd.ready();\nsetTimeout(() => { const t = Date.now(); while (Date.now() - t < 3500) { watchdogProgress(); } wd.stop(); }, 300);`, + ); + assert(!alive.timedOut); + assertEquals(alive.signal, null, `a loop reporting progress was killed:\n${alive.stderr}`); + assertEquals(alive.code, 0); + + const stuck = await runChild( + root, + `mode: "exit", stallMs: 1500, startupStallMs: 1500, heartbeatMs: 100`, + `wd.ready();\nsetTimeout(() => { while (true) {} }, 300);`, + ); + assertEquals(stuck.signal, "SIGKILL"); + }); + }, +); + +Deno.test( + "watchdogGrace: protects a declared busy window, is logged, and expires on its own", + noSanitize, + async () => { + await withRoot(async (root) => { + const within = await runChild( + root, + `mode: "exit", stallMs: 1500, startupStallMs: 1500, heartbeatMs: 100`, + `wd.ready();\nsetTimeout(() => { const release = watchdogGrace(10000, "test import"); ${SPIN(3500)} release(); wd.stop(); }, 300);`, + ); + assert(!within.timedOut); + assertEquals(within.signal, null, `killed inside its grace window:\n${within.stderr}`); + assertStringIncludes(within.stderr, 'grace for "test import"'); + + // A 1s window followed by a loop that never ends: the window must lapse and the kill follow. + const expired = await runChild( + root, + `mode: "exit", stallMs: 1500, startupStallMs: 1500, heartbeatMs: 100`, + `wd.ready();\nsetTimeout(() => { watchdogGrace(1000, "short"); while (true) {} }, 300);`, + ); + assert(!expired.timedOut, "grace never expired"); + assertEquals(expired.signal, "SIGKILL"); + }); + }, +); + +Deno.test( + "watchdog: nested grace windows are refcounted — releasing one leaves the other in force", + noSanitize, + async () => { + await withRoot(async (root) => { + const r = await runChild( + root, + `mode: "exit", stallMs: 1500, startupStallMs: 1500, heartbeatMs: 100`, + `wd.ready();\nsetTimeout(() => {\n` + + ` const outer = watchdogGrace(10000, "outer");\n` + + ` const inner = watchdogGrace(10000, "inner");\n` + + ` inner();\n` + + ` ${SPIN(3000)}\n` + + ` outer(); wd.stop();\n` + + `}, 300);`, + ); + assert(!r.timedOut); + assertEquals(r.signal, null, `outer window should still have protected the loop:\n${r.stderr}`); + }); + }, +); + +Deno.test( + "watchdog: under an inspector it reports instead of killing, since a breakpoint pauses only the main thread", + unixOnly, + async () => { + await withRoot(async (root) => { + const env = Deno.env.toObject(); + delete env.DUNE_WATCHDOG; + const r = await runChild( + root, + `stallMs: 1500, startupStallMs: 1500, heartbeatMs: 100`, // no mode option and no DUNE_WATCHDOG: the default applies + `wd.ready();\nsetTimeout(() => { ${SPIN(2500)} setTimeout(() => wd.stop(), 1500); }, 300);`, + { denoArgs: ["-A", "--inspect=127.0.0.1:19349"], env }, + ); + assert(!r.timedOut); + assertEquals(r.signal, null, `was killed under an inspector:\n${r.stderr}`); + assertEquals(r.code, 0); + assertStringIncludes(r.stderr, "inspector detected"); + assertStringIncludes(r.stderr, "event loop blocked"); + }); + }, +); + +// ── the kill must always happen, and say so when it can't ──────────────────── + +Deno.test( + "watchdog: the kill goes ahead even when writing the report hangs (a stuck 'sample')", + { ...noSanitize, ignore: Deno.build.os !== "darwin" }, + async () => { + await withRoot(async (root) => { + const bin = join(root, "fakebin"); + await Deno.mkdir(bin); + await Deno.writeTextFile(join(bin, "sample"), "#!/bin/sh\nsleep 60\n"); + await Deno.chmod(join(bin, "sample"), 0o755); + const r = await runChild( + root, + `mode: "exit", stallMs: 1500, startupStallMs: 1500, heartbeatMs: 100, reportTimeoutMs: 1000`, + `wd.ready();\nsetTimeout(() => { while (true) {} }, 300);`, + { env: { ...Deno.env.toObject(), PATH: `${bin}:${Deno.env.get("PATH")}` } }, + ); + assert(!r.timedOut, "a hung report prevented the kill"); + assertEquals(r.signal, "SIGKILL"); + assertStringIncludes(r.stderr, "did not finish"); + }); + }, +); + +// ── bookkeeping ────────────────────────────────────────────────────────────── + +Deno.test( + "watchdog: old reports are pruned so .dune/hangs/ can't grow without bound", + noSanitize, + async () => { + await withRoot(async (root) => { + const dir = join(root, ".dune", "hangs"); + await Deno.mkdir(dir, { recursive: true }); + for (let i = 0; i < 24; i++) { + const stamp = `20200101-0000${String(i).padStart(2, "0")}-1`; + await Deno.writeTextFile(join(dir, `hang-${stamp}.txt`), "old\n"); + await Deno.writeTextFile(join(dir, `hang-${stamp}.sample.txt`), "old sample\n"); + } + const r = await runChild( + root, + `mode: "warn", stallMs: 1500, startupStallMs: 1500, heartbeatMs: 100`, + `wd.ready();\nsetTimeout(async () => {\n` + + ` ${SPIN(2500)}\n` + + ` for (let i = 0; i < 100; i++) {\n` + + ` let n = 0; for await (const e of Deno.readDir(${JSON.stringify(dir)})) if (/^hang-2026|^hang-20[3-9]/.test(e.name) && e.name.endsWith(".txt") && !e.name.endsWith(".sample.txt")) n++;\n` + + ` if (n > 0) { await new Promise((r) => setTimeout(r, 500)); break; }\n` + + ` await new Promise((r) => setTimeout(r, 100));\n` + + ` }\n` + + ` wd.stop();\n` + + `}, 300);`, + ); + assert(!r.timedOut); + const names = await reports(root); + assertEquals(mainReports(names).length, 20, `expected 20 reports kept, got ${mainReports(names).length}`); + assertEquals(names.filter((n) => n.endsWith(".sample.txt")).length <= 20, true, "pruned reports take their samples with them"); + }); + }, +); + +// ── what the supervisor and the dune dev wrapper see ───────────────────────── + +Deno.test( + "watchdog: a wrapper around a killed process exits non-zero, and a child that reads stdin (like esbuild) does not outlive it", + unixOnly, + async () => { + await withRoot(async (root) => { + const forward = new URL("../../src/cli/forward-signals.ts", import.meta.url).href; + const pidFile = join(root, "grandchild.pid"); + await Deno.writeTextFile( + join(root, "server.ts"), + `import { startWatchdog } from ${JSON.stringify(WATCHDOG_URL)};\n` + + `const wd = startWatchdog({ root: ${JSON.stringify(root)}, mode: "exit", stallMs: 1500, startupStallMs: 1500, heartbeatMs: 100 });\n` + + `wd.ready();\n` + + // Stands in for the esbuild service: exits when its stdin closes (the parent died). + `const g = new Deno.Command(Deno.execPath(), { args: ["eval", "await Deno.stdin.read(new Uint8Array(1))"], stdin: "piped", stdout: "null", stderr: "null" }).spawn();\n` + + `await Deno.writeTextFile(${JSON.stringify(pidFile)}, String(g.pid));\n` + + `setTimeout(() => { while (true) {} }, 400);\n`, + ); + // Same shape as the dune re-exec wrapper (src/cli/reexec.ts). + await Deno.writeTextFile( + join(root, "wrapper.ts"), + `import { waitForwardingSignals } from ${JSON.stringify(forward)};\n` + + `const child = new Deno.Command(Deno.execPath(), { args: ["run", "-A", ${JSON.stringify(join(root, "server.ts"))}], stdout: "null", stderr: "null" }).spawn();\n` + + `const status = await waitForwardingSignals(child);\nDeno.exit(status.code);\n`, + ); + const wrapper = new Deno.Command(Deno.execPath(), { args: ["run", "-A", join(root, "wrapper.ts")], stdout: "piped", stderr: "piped" }).spawn(); + const r = await finish(wrapper); + assert(!r.timedOut, "the wrapper never saw its child die"); + assertEquals(r.code, 137, "the wrapper must exit non-zero so a supervisor sees a failure"); + + const gpid = Number(await Deno.readTextFile(pidFile)); + let alive = true; + for (let i = 0; i < 30 && alive; i++) { + await new Promise((res) => setTimeout(res, 100)); + const ps = await new Deno.Command("ps", { args: ["-p", String(gpid)], stdout: "null", stderr: "null" }).output(); + alive = ps.success; + } + assertEquals(alive, false, "a child reading the parent's stdin should end when the parent is SIGKILLed"); + }); + }, +);