From fd661a14dfa1ba18cf043047fa7afce036c4cd04 Mon Sep 17 00:00:00 2001 From: Staff Engineer Date: Thu, 24 Sep 2026 11:39:28 +0000 Subject: [PATCH] test(crash-guard): let the startup watchdog report what it killed (BLO-36057) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The startup watchdog SIGKILLed the fixture and rejected immediately with a bare `fixture did not observe stderr backpressure`. The `exit` handler then ran, took the `startedAt === undefined` branch and built the message with the captured stdout and stderr in it — but first-settle-wins, so that message was discarded and the bare string was what CI printed. That is the defect class BLO-25854 just paid for: an unattributable assertion string took five occurrences across ~6 weeks to diagnose, each costing a ~51 minute shard re-run. #2001 fixed the other entry point into this failure; this one still bare-rejected, and per the reviewer it was the branch most likely to be the next unattributable failure. Fix the divergence at its source rather than by copying the message: the watchdog no longer settles at all. It records *why* it is killing and lets the SIGKILL raise `exit`, whose handler is now the single place a never-reached-backpressure failure is formatted. Two entry points, one formatter, so they cannot drift apart again. Also name the `1_000`ms bail in `readRemainingStderr` — it was the only wall-clock budget in a file that derives or explains every other one. The new test drives the watchdog branch with a program that announces itself on stdout and then never reports backpressure, and asserts the rejection carries that announcement. Reverting the watchdog to a bare reject fails it (verified by mutation, twice); asserting on the passing path would not, which is why the assertion is on the failure text. Co-Authored-By: Claude --- .../process-crash-guard-exit.test.ts | 104 ++++++++++++++++-- 1 file changed, 97 insertions(+), 7 deletions(-) diff --git a/server/src/__tests__/process-crash-guard-exit.test.ts b/server/src/__tests__/process-crash-guard-exit.test.ts index 0b2a080708ff..57d851852a0f 100644 --- a/server/src/__tests__/process-crash-guard-exit.test.ts +++ b/server/src/__tests__/process-crash-guard-exit.test.ts @@ -78,6 +78,17 @@ const STALLED_EXIT_DEADLINE_MS = 1_500; * measured on the same runners needs the same, and at 2s it had 500ms. */ const STALLED_EXIT_WATCHDOG_MS = STALLED_EXIT_DEADLINE_MS * 5; +/** + * How long `readRemainingStderr` waits for the dead child's stderr to reach `end` + * before reporting whatever it has so far. + * + * Unlike every other budget in this file it bounds only the gathering of *failure* + * context, so overrunning it costs detail in a message that is already failing — it + * can neither fail a passing run nor pass a failing one. Every caller runs after the + * child is gone, so `end` is due within a scheduler tick; a full second is slack for + * a loaded runner rather than an expectation about one. + */ +const STDERR_DRAIN_BAIL_MS = 1_000; interface CrashResult { code: number | null; @@ -158,7 +169,7 @@ function readRemainingStderr(stream: Readable): Promise { : out, ); }; - const bail = setTimeout(finish, 1_000); + const bail = setTimeout(finish, STDERR_DRAIN_BAIL_MS); stream.setEncoding("utf8"); stream.on("data", (chunk: string) => { out += chunk; @@ -169,19 +180,70 @@ function readRemainingStderr(stream: Readable): Promise { }); } -function runFixtureWithStalledStderr(): Promise { +/** + * What to spawn for a stalled-stderr run. Parameterised only so the diagnostic test + * below can drive the startup-watchdog branch with a program that never reports + * backpressure; the crash test uses PREFILL_RUN and is unaffected. + */ +interface StalledRun { + command: string; + args: string[]; + startupTimeoutMs: number; +} + +/** The real crash fixture: fills stderr, announces BACKPRESSURE, then crashes on ack. */ +const PREFILL_RUN: StalledRun = { + command: tsx, + args: [fixture, "throw", "0", "prefill-stderr"], + startupTimeoutMs: FIXTURE_STARTUP_TIMEOUT_MS, +}; + +const STARTUP_STALL_SENTINEL = "STARTUP_STALL_SENTINEL"; +/** + * Drives the startup-watchdog branch: announces itself on stdout, then stays alive + * without ever writing BACKPRESSURE, so the watchdog is the only thing that can end + * the run. Plain `node` rather than the fixture under `tsx` because the budget below + * has to clear process startup, and `node -e` boots in tens of milliseconds where a + * cold `tsx` compile is measured in seconds. + * + * 2_000ms is therefore ~50x the time the sentinel needs to reach us, and it bounds a + * diagnostic assertion rather than the thing under test: a runner slow enough to miss + * it would report `its stdout said: ` and fail loudly with the full context, + * which is precisely the property this test pins. It cannot fail silently or pass + * wrongly. + */ +const STARTUP_STALL_RUN: StalledRun = { + command: process.execPath, + args: ["-e", `process.stdout.write("${STARTUP_STALL_SENTINEL}\\n"); setInterval(() => {}, 1_000);`], + startupTimeoutMs: 2_000, +}; + +function runFixtureWithStalledStderr(run: StalledRun = PREFILL_RUN): Promise { return new Promise((resolve, reject) => { - const child = spawn(tsx, [fixture, "throw", "0", "prefill-stderr"], { + const child = spawn(run.command, run.args, { stdio: ["pipe", "pipe", "pipe"], }); child.stderr.pause(); let startedAt: number | undefined; let watchdog: NodeJS.Timeout | undefined; + /** + * Set by the startup watchdog so the `exit` handler can name which way this run + * failed. The watchdog deliberately does not reject: it only SIGKILLs, and the + * kill raises `exit`, whose handler is the single place a never-reached- + * backpressure failure is formatted. + * + * It used to reject here with a bare string, and because first-settle-wins that + * bare string beat the rich message the `exit` handler was already building — + * so the branch most likely to fail was the one branch with no context + * (BLO-36057). Recording the reason rather than reporting it is what makes the + * two entry points unable to drift apart again: there is only one formatter. + */ + let startupTimedOut = false; const startupWatchdog = setTimeout(() => { + startupTimedOut = true; child.kill("SIGKILL"); - reject(new Error("fixture did not observe stderr backpressure")); - }, FIXTURE_STARTUP_TIMEOUT_MS); + }, run.startupTimeoutMs); child.stdout.setEncoding("utf8"); // Captured for the failure path below. Once the fixture has deliberately filled @@ -190,7 +252,11 @@ function runFixtureWithStalledStderr(): Promise { let stdout = ""; child.stdout.on("data", (chunk: string) => { stdout += chunk; - if (startedAt !== undefined || !chunk.includes("BACKPRESSURE")) return; + // Keep accumulating after a SIGKILL — late bytes are context for the message + // below — but do not start the deadline off them: the child is already dead, + // so `stdin.end` would write to a closed pipe and the elapsed time would be + // measured against a corpse. + if (startupTimedOut || startedAt !== undefined || !chunk.includes("BACKPRESSURE")) return; clearTimeout(startupWatchdog); startedAt = Date.now(); watchdog = setTimeout(() => { @@ -214,7 +280,12 @@ function runFixtureWithStalledStderr(): Promise { .then((stderr) => { reject( new Error( - `fixture exited before reporting stderr backpressure ` + + `${ + startupTimedOut + ? `fixture did not report stderr backpressure within ${run.startupTimeoutMs}ms ` + + `(SIGKILLed by the startup watchdog)` + : "fixture exited before reporting stderr backpressure" + } ` + `(code=${code}, signal=${signal}); its stdout said: ${stdout.trim() || ""}; ` + `its stderr said: ${stderr.trim() || ""}`, ), @@ -268,6 +339,25 @@ describe("process crash guard — real process exit", () => { expect(elapsedMs).toBeLessThan(STALLED_EXIT_DEADLINE_MS); }); + /** + * Pins the diagnostic, not the guard: this is the branch BLO-36057 exists for. + * Before that fix the startup watchdog rejected with a bare + * `fixture did not observe stderr backpressure`, which beat the rich message the + * `exit` handler was concurrently building — the same unattributable-string defect + * that cost BLO-25854 five occurrences and ~51 minutes of CI per occurrence. + * + * Reverting the watchdog to a bare reject must fail this test; asserting on the + * passing path would not, which is why the assertion is on the failure text. + */ + it("carries the captured stdout into the startup-watchdog failure", async () => { + await expect(runFixtureWithStalledStderr(STARTUP_STALL_RUN)).rejects.toThrow( + new RegExp( + `did not report stderr backpressure within ${STARTUP_STALL_RUN.startupTimeoutMs}ms` + + `[\\s\\S]*its stdout said: ${STARTUP_STALL_SENTINEL}`, + ), + ); + }); + it("flushes one complete crash record for a strict unhandled rejection", async () => { const { code, stderr } = await runFixture("reject", PIPE_PRESSURE_BYTES, true);