import { mkdir, mkdtemp, readFile, writeFile } from "node:fs/promises"; import { tmpdir } from "node:os"; import path from "node:path"; import { fileURLToPath, pathToFileURL } from "node:url"; import { spawn } from "node:child_process"; import { describe, expect, test } from "vitest"; import { isPlatform } from "../src/test-utils/platform.js"; import { resolveSupervisorLogFile } from "./supervisor-log-config.js"; const repoRoot = path.resolve(fileURLToPath(new URL("../../..", import.meta.url))); const supervisorPath = fileURLToPath(new URL("./supervisor.ts", import.meta.url)); function isProcessRunning(pid: number): boolean { try { process.kill(pid, 0); return true; } catch { return false; } } async function runSupervisorFixture(options: { workerSource: string; restartOnCrash?: boolean; timeoutMs?: number; /** POSIX RLIMIT_FSIZE for the supervisor, in 512-byte blocks: writes past it fail like a full disk. */ fileSizeLimitBlocks?: number; /** Occupy the log path with a directory so the supervisor cannot open daemon.log. */ blockLogPath?: boolean; }): Promise<{ code: number | null; signal: NodeJS.Signals | null; elapsedMs: number; log: string; stdout: string; stderr: string; }> { const tempDir = await mkdtemp(path.join(tmpdir(), "paseo-supervisor-log-")); const logPath = path.join(tempDir, "daemon.log"); const workerPath = path.join(tempDir, "worker.mjs"); const runnerPath = path.join(tempDir, "runner.mjs"); if (options.blockLogPath) { await mkdir(logPath); } await writeFile( workerPath, `process.send?.({ type: "paseo:ready", listen: "fixture", serverId: "srv_fixture" });\n${options.workerSource}`, ); await writeFile( runnerPath, ` import { runSupervisor } from ${JSON.stringify(pathToFileURL(supervisorPath).href)}; runSupervisor({ name: "TestSupervisor", startupMessage: "starting fixture", resolveWorkerEntry: () => ${JSON.stringify(workerPath)}, workerArgs: [], workerEnv: process.env, workerExecArgv: [], restartOnCrash: ${JSON.stringify(options.restartOnCrash ?? false)}, logFile: { path: ${JSON.stringify(logPath)}, rotate: { maxSize: "1m", maxFiles: 2 }, }, }); `, ); const startedAt = Date.now(); const runnerArgs = [process.execPath, "--import", "tsx", runnerPath]; const [command, ...args] = options.fileSizeLimitBlocks === undefined ? runnerArgs : [ "/bin/sh", "-c", `ulimit -f ${options.fileSizeLimitBlocks} && exec "$@"`, "sh", ...runnerArgs, ]; const child = spawn(command, args, { cwd: repoRoot, env: { ...process.env }, stdio: ["ignore", "pipe", "pipe"], }); let stdout = ""; let stderr = ""; child.stdout.setEncoding("utf8"); child.stderr.setEncoding("utf8"); child.stdout.on("data", (chunk) => { stdout += chunk; }); child.stderr.on("data", (chunk) => { stderr += chunk; }); const { code, signal } = await new Promise<{ code: number | null; signal: NodeJS.Signals | null; }>((resolve, reject) => { const timeout = setTimeout(() => { child.kill("SIGKILL"); reject(new Error("supervisor fixture timed out")); }, options.timeoutMs ?? 10_000); child.on("error", (error) => { clearTimeout(timeout); reject(error); }); child.on("close", (exitCode, exitSignal) => { clearTimeout(timeout); resolve({ code: exitCode, signal: exitSignal }); }); }); const log = await readFile(logPath, "utf8"); return { code, signal, elapsedMs: Date.now() - startedAt, log, stdout, stderr }; } describe("supervisor durable logging", () => { test("resolves rotation defaults", () => { const paseoHome = path.join(path.sep, "tmp", "paseo-home"); const logFile = resolveSupervisorLogFile(paseoHome, {}, {}); expect(logFile).toEqual({ path: path.join(paseoHome, "daemon.log"), rotate: { maxSize: "10m", maxFiles: 3 }, }); }); test("lets persisted rotation override env rotation defaults", () => { const paseoHome = path.join(path.sep, "tmp", "paseo-home"); const logFile = resolveSupervisorLogFile( paseoHome, { log: { file: { path: "logs/daemon.log", rotate: { maxSize: "25m", maxFiles: 4 }, }, }, }, { PASEO_LOG_ROTATE_SIZE: "200m", PASEO_LOG_ROTATE_COUNT: "12", }, ); expect(logFile).toEqual({ path: path.resolve(paseoHome, "logs", "daemon.log"), rotate: { maxSize: "25m", maxFiles: 4 }, }); }); test("uses env rotation when persisted rotation is absent", () => { const paseoHome = path.join(path.sep, "tmp", "paseo-home"); const logFile = resolveSupervisorLogFile( paseoHome, {}, { PASEO_LOG_ROTATE_SIZE: "50m", PASEO_LOG_ROTATE_COUNT: "8", }, ); expect(logFile).toEqual({ path: path.join(paseoHome, "daemon.log"), rotate: { maxSize: "50m", maxFiles: 8 }, }); }); test("writes supervised worker stdout and stderr to daemon.log", async () => { const result = await runSupervisorFixture({ workerSource: ` process.stdout.write('{"level":30,"msg":"worker-json-stdout"}\\n'); process.stderr.write('{"level":50,"msg":"worker-json-stderr"}\\n'); process.exit(0); `, }); expect(result.code).toBe(0); expect(result.signal).toBeNull(); expect(result.log).toContain('"worker-json-stdout"'); expect(result.log).toContain('"worker-json-stderr"'); expect(result.stdout).toContain('"worker-json-stdout"'); expect(result.stderr).toContain('"worker-json-stderr"'); }); test("preserves raw non-JSON stdout and stderr lines", async () => { const result = await runSupervisorFixture({ workerSource: ` process.stdout.write('raw stdout line\\n'); process.stderr.write('raw stderr line\\n'); process.exit(0); `, }); expect(result.log).toContain("raw stdout line\n"); expect(result.log).toContain("raw stderr line\n"); }); test("logs the worker shutdown reason before requesting graceful shutdown", async () => { const result = await runSupervisorFixture({ workerSource: ` process.on("message", (message) => { if (message?.type === "paseo:graceful-shutdown") process.exit(0); }); process.send?.({ type: "paseo:shutdown", reason: "client_shutdown_rpc" }); setInterval(() => {}, 1000); `, }); expect(result.code).toBe(0); expect(result.signal).toBeNull(); expect(result.log).toContain('"msg":"Worker requested shutdown"'); expect(result.log).toContain('"reason":"client_shutdown_rpc"'); expect(result.log).toContain('"msg":"Supervisor requesting graceful worker shutdown"'); expect(result.log).toContain('"workerPid":'); }); test("lets the worker clean up its descendant before supervised shutdown", async () => { const result = await runSupervisorFixture({ workerSource: ` import { spawn } from "node:child_process"; const descendant = spawn( process.execPath, ["-e", "setInterval(() => {}, 1000)"], { detached: true, stdio: "ignore" }, ); descendant.unref(); process.stdout.write(\`DESCENDANT_PID=\${descendant.pid}\\n\`); process.on("message", (message) => { if (message?.type !== "paseo:graceful-shutdown") return; descendant.once("exit", () => { process.stdout.write("GRACEFUL_CLEANUP_RAN\\n"); process.exit(0); }); descendant.kill("SIGTERM"); }); process.send?.({ type: "paseo:shutdown", reason: "descendant_cleanup_probe" }); setInterval(() => {}, 1000); `, }); const descendantPid = Number.parseInt( result.stdout.match(/DESCENDANT_PID=(\d+)/)?.[1] ?? "", 10, ); expect(Number.isInteger(descendantPid)).toBe(true); const descendantSurvived = isProcessRunning(descendantPid); if (descendantSurvived) { process.kill(descendantPid, "SIGKILL"); } expect.soft(result.stdout).toContain("GRACEFUL_CLEANUP_RAN"); expect(descendantSurvived).toBe(false); }); test("does not restart a worker based on heartbeat absence", async () => { const result = await runSupervisorFixture({ timeoutMs: 20_000, workerSource: ` import { existsSync, writeFileSync } from "node:fs"; process.on("message", (message) => { if (message?.type === "paseo:graceful-shutdown") process.exit(0); }); const marker = process.argv[1] + ".started"; if (!existsSync(marker)) { writeFileSync(marker, "started"); setTimeout(() => { process.send?.({ type: "paseo:shutdown", reason: "silent_worker_test_complete" }); }, 16_000); setInterval(() => {}, 1_000); } else { process.send?.({ type: "paseo:shutdown", reason: "unexpected_silent_worker_restart" }); setInterval(() => {}, 1_000); } `, }); expect(result.code).toBe(0); expect(result.signal).toBeNull(); expect(result.log).toContain('"reason":"silent_worker_test_complete"'); expect(result.log).not.toContain('"reason":"unexpected_silent_worker_restart"'); expect(result.log).not.toContain('"msg":"Worker heartbeat timed out; restarting worker"'); }, 25_000); test("forces shutdown when a worker ignores the graceful shutdown request", async () => { const result = await runSupervisorFixture({ timeoutMs: 15_000, workerSource: ` 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 graceful shutdown request; forcing process tree kill"', ); }, 20_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"; process.on("message", (message) => { if (message?.type === "paseo:graceful-shutdown") process.exit(0); }); 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.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", async () => { const result = await runSupervisorFixture({ workerSource: ` process.kill(process.pid, "SIGKILL"); `, }); expect(result.code).toBe(1); expect(result.signal).toBeNull(); expect(result.log).toContain('"msg":"Worker exited"'); expect(result.log).toContain('"signal":"SIGKILL"'); expect(result.log).toContain("Supervisor exiting"); }, ); // POSIX-only: RLIMIT_FSIZE is how the test makes daemon.log writes fail. test.skipIf(isPlatform("win32"))( "keeps supervising the worker when daemon.log can no longer be written", async () => { const result = await runSupervisorFixture({ fileSizeLimitBlocks: 128, workerSource: ` process.on("message", (message) => { if (message?.type === "paseo:graceful-shutdown") process.exit(0); }); const line = '{"level":30,"msg":"' + "x".repeat(1000) + '"}\\n'; for (let i = 0; i < 200; i += 1) process.stdout.write(line); setTimeout(() => { process.send?.({ type: "paseo:shutdown", reason: "log_write_failure_probe" }); }, 1000); setInterval(() => {}, 1000); `, }); expect(result.stderr).not.toContain("Unhandled 'error' event"); expect(result.code).toBe(0); expect(result.signal).toBeNull(); }, ); test("resumes writing daemon.log once the log path is writable again", async () => { const result = await runSupervisorFixture({ blockLogPath: true, workerSource: ` import { rmdirSync } from "node:fs"; process.on("message", (message) => { if (message?.type === "paseo:graceful-shutdown") process.exit(0); }); process.stdout.write("line while daemon.log is blocked\\n"); setTimeout(() => { rmdirSync(process.argv[1].replace(/worker\\.mjs$/, "daemon.log")); process.stdout.write("line after daemon.log is writable\\n"); setTimeout(() => { process.send?.({ type: "paseo:shutdown", reason: "log_recovery_probe" }); }, 200); }, 500); setInterval(() => {}, 1000); `, }); expect(result.code).toBe(0); expect(result.log).toContain("line after daemon.log is writable\n"); expect(result.log).toContain('"reason":"log_recovery_probe"'); }); });