From 0abd137ec741410a22784e04cf47037a143e63a7 Mon Sep 17 00:00:00 2001 From: sim Date: Fri, 28 Aug 2026 19:10:54 -0400 Subject: [PATCH] fix(#4012): the events reporter has to survive SIGKILL MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The remote run proved the instrumentation did not work. Timing landed — "chunk 1/1 was killed after 2006ms" — but the in-flight-file naming produced nothing and fell through to the pre-existing generic message. The feature I wrote to diagnose a kill was itself destroyed by the kill. Root cause, confirmed rather than assumed. The reporter yielded strings, which node pipes into the --test-reporter-destination WriteStream. That stream BUFFERS. execFileSync's timeout sends SIGKILL, which is uncatchable and gives nothing a chance to flush, so the events sat in a buffer that died with the child. The parent's own timer reported correctly because it lives in the parent — which is exactly why half the feature looked fine. The reporter now writes each event with fs.appendFileSync, unbuffered and durable at the moment it happens, to a path passed through GSD_RUN_TESTS_EVENTS_FILE. Env vars do not count toward the Windows 32,767-char argv ceiling, so moving the path out of argv also REDUCES FIXED_OVERHEAD; the accounting moved with it rather than being left stale. The destination is now a fixed devNull sink that stays empty by design. Silence was the reason this was invisible for a whole run. Failing to read the events file now says so explicitly, and distinguishes a file that could not be read at all from one that exists but is empty — the generic fallback firing quietly is what let a broken feature look like a working one. A write is unbuffered but not atomic, so a kill can still interleave a partial line; the reader tolerates exactly one unparsable trailing line and reports the complete ones before it. The failing T1 was left red and untouched rather than weakened to pass. Three new unit tests cover the reader directly, with no subprocess, so the parsing half is verifiable without a full runner pass: missing file, existing-but-empty file, and a truncated final line. Also adds ndjson-reporter.cjs to GSD_SCRIPTS_LIB_FILES in bin/install.js — scripts/lib/ ships, and omitting it meant the file would install everywhere and orphan on uninstall. That single omission caused 4 of the 7 remote failures. Verification runs on the remote runner. Refs #4012 --- bin/install.js | 2 +- scripts/lib/ndjson-reporter.cjs | 60 ++++++++++++++++++----- scripts/run-tests.cjs | 84 +++++++++++++++++++++++--------- tests/run-tests-harness.test.cjs | 65 ++++++++++++++++++++++++ 4 files changed, 174 insertions(+), 37 deletions(-) diff --git a/bin/install.js b/bin/install.js index f83d232a5..4cbfc84a8 100755 --- a/bin/install.js +++ b/bin/install.js @@ -411,7 +411,7 @@ const GSD_CHANGESET_FILES = [ 'github-release-notes.cjs', 'lint.cjs', 'new.cjs', 'README.md', // documentation only — not user-authored ]; -const GSD_SCRIPTS_LIB_FILES = ['cli-exit.cjs', 'allowlist-ratchet.cjs', 'drift-scan.cjs', 'alias-drift-families.cjs', 'exit-code-registry.cjs']; +const GSD_SCRIPTS_LIB_FILES = ['cli-exit.cjs', 'allowlist-ratchet.cjs', 'drift-scan.cjs', 'alias-drift-families.cjs', 'exit-code-registry.cjs', 'ndjson-reporter.cjs']; /** * Resolve a runtime's shared-hooks directory name from its descriptor. diff --git a/scripts/lib/ndjson-reporter.cjs b/scripts/lib/ndjson-reporter.cjs index 0611f9917..fcc3f7663 100644 --- a/scripts/lib/ndjson-reporter.cjs +++ b/scripts/lib/ndjson-reporter.cjs @@ -7,34 +7,58 @@ // per #3597/#1051, to avoid the maxBuffer and live-output risks of piping — // so the parent process has no way to see WHICH file was executing when a // per-chunk timeout kills the child. This reporter runs ALONGSIDE the normal -// human reporter (a second `--test-reporter`/`--test-reporter-destination` -// pair on the same invocation, per Node's documented multi-reporter pairing) -// and appends one JSON object per line to its own destination file. On a +// human reporter (a second `--test-reporter` on the same invocation, per +// Node's documented multi-reporter pairing) and appends one JSON object per +// line to a path supplied via the GSD_RUN_TESTS_EVENTS_FILE env var. On a // timeout, run-tests.cjs reads that file back to name the file(s) still // in flight (a `test:start` with no matching `test:pass`/`test:fail`). // +// Durability, not `--test-reporter-destination` (#3889 root cause): a +// reporter that YIELDS strings has them piped by Node into a +// `fs.WriteStream` targeting the destination path, and that stream buffers. +// The parent's `execFileSync` timeout SIGKILLs the child on a hang, and +// SIGKILL is uncatchable and gives the process zero chance to flush — so a +// yield-based reporter can lose every event still sitting in the stream's +// buffer, which is exactly the case this feature exists to diagnose (proven +// live: a chunk killed at 2006ms produced a `killed after 2006ms` line from +// the TIMER, which lives in the parent, but zero usable events from the +// reporter, which lives in the child and never flushed). Writing each event +// with `fs.appendFileSync` — synchronous and unbuffered — makes it durable +// the instant it happens, before the process can be killed out from under +// it. The reporter therefore yields NOTHING; it is a pure side-effecting +// sink. Node still requires a `--test-reporter-destination` to pair with +// this `--test-reporter` (see run-tests.cjs's reporterArgsFor), but that +// destination is a throwaway sink that stays empty by design — the durable +// path is GSD_RUN_TESTS_EVENTS_FILE, not the destination Node manages. +// // Contract targeted: Node's "Custom reporters" contract // (https://nodejs.org/api/test.html#custom-reporters) — a reporter module's -// default export is a function receiving the test runner's event stream -// (an AsyncIterable of `{ type, data }` objects) and returning/yielding the -// reporter's output. This repo's `engines.node` requires >=24.0.0 -// (package.json), where this contract — including the CommonJS -// `async function*` form used here — has been stable since Node 20. +// default export is a function receiving the test runner's event stream (an +// AsyncIterable of `{ type, data }` objects) and returning an iterable (sync +// or async) of the reporter's output. This one intentionally emits no output +// (see the durability note above) — a plain `async function` that returns an +// empty array satisfies the contract without an `async function*` generator +// that would otherwise never `yield` (require-yield). This repo's +// `engines.node` requires >=24.0.0 (package.json), where this contract has +// been stable since Node 20. // // Kept intentionally tiny: only the three event types run-tests.cjs needs to // pair start/completion are handled; everything else (diagnostics, plans, -// coverage) is ignored so a truncated destination file (the process is -// SIGKILLed mid-write on timeout) never leaves more than one dangling -// unparsable trailing line. -module.exports = async function* ndjsonEventReporter(source) { +// coverage) is ignored so a truncated events file (the process is SIGKILLed +// mid-`appendFileSync` on timeout — an individual write is unbuffered but +// not atomic, so the OS can still interleave a partial write with the kill) +// never leaves more than one dangling unparsable trailing line. +module.exports = async function ndjsonEventReporter(source) { + const eventsPath = process.env.GSD_RUN_TESTS_EVENTS_FILE; for await (const event of source) { + if (!eventsPath) continue; // no destination configured — nothing to record if ( event.type === 'test:start' || event.type === 'test:pass' || event.type === 'test:fail' ) { const { file, name, nesting, testNumber } = event.data || {}; - yield `${JSON.stringify({ + const line = `${JSON.stringify({ type: event.type, file, name, @@ -42,6 +66,16 @@ module.exports = async function* ndjsonEventReporter(source) { testNumber, ts: Date.now(), })}\n`; + try { + require('fs').appendFileSync(eventsPath, line); + } catch { + // Best-effort: a write failure here (e.g. the events dir vanished) + // must never crash the test run this reporter is only observing. + } } } + // Intentionally empty: this reporter is a pure side-effecting sink (see the + // durability note above), never a source of reporter OUTPUT. Node still + // requires the exported function to return an iterable. + return []; }; diff --git a/scripts/run-tests.cjs b/scripts/run-tests.cjs index 0a039d780..83f715ccb 100644 --- a/scripts/run-tests.cjs +++ b/scripts/run-tests.cjs @@ -37,7 +37,7 @@ const { readdirSync, readFileSync, mkdtempSync, rmSync, unlinkSync } = require('fs'); const { join, basename } = require('path'); -const { tmpdir } = require('os'); +const { tmpdir, devNull } = require('os'); const { execFileSync } = require('child_process'); const { ExitError, runMain } = require('./lib/cli-exit.cjs'); const { @@ -701,7 +701,13 @@ function analyzeChunkEvents(eventsPath) { try { raw = readFileSync(eventsPath, 'utf8'); } catch { - return { files: [], staleMs: null, sawAnyEvent: false }; + // The events file never existed — either GSD_RUN_TESTS_EVENTS_FILE never + // resolved to a writable path, or the child was killed before the ndjson + // reporter's very first appendFileSync. Distinct from "file exists but + // has zero parseable events" (readError=false, sawAnyEvent=false) so the + // diagnostic below can say explicitly WHICH of the two happened, rather + // than silently collapsing both into "no in-flight file identified". + return { files: [], staleMs: null, sawAnyEvent: false, readError: true }; } const inFlight = new Map(); let lastTs = null; @@ -728,6 +734,7 @@ function analyzeChunkEvents(eventsPath) { files, staleMs: lastTs !== null ? Date.now() - lastTs : null, sawAnyEvent: lastTs !== null, + readError: false, }; } @@ -1030,31 +1037,55 @@ function main() { // #3889: a second, machine-readable reporter runs ALONGSIDE the normal // human one so a chunk timeout can name the file that was in flight (see - // scripts/lib/ndjson-reporter.cjs for the full contract writeup and - // its Node-docs citation). Passing --test-reporter at all replaces node's - // implicit default reporter entirely, so the human reporter must also be - // named explicitly, reproducing node's own default selection (spec on a - // TTY, tap otherwise) so visible stdout output is unchanged. + // scripts/lib/ndjson-reporter.cjs for the full contract writeup, its + // Node-docs citation, and — load-bearing — why it writes via + // `fs.appendFileSync` to a path passed through GSD_RUN_TESTS_EVENTS_FILE + // instead of yielding strings for Node to pipe through + // `--test-reporter-destination`: that destination is backed by an + // `fs.WriteStream`, which BUFFERS, and execFileSync's timeout SIGKILLs the + // child — uncatchable, zero chance to flush — so a yield-based reporter can + // lose every event still sitting in the stream's buffer, which is exactly + // the case this feature exists to diagnose (confirmed live: chunk killed at + // 2006ms produced a timer-based "killed after 2006ms" line — which lives in + // this parent process — but zero usable in-flight-file events from the + // reporter, which lives in the child and never flushed). Passing + // --test-reporter at all replaces node's implicit default reporter + // entirely, so the human reporter must also be named explicitly, + // reproducing node's own default selection (spec on a TTY, tap otherwise) + // so visible stdout output is unchanged. + // + // Node's documented multi-reporter contract requires EVERY --test-reporter + // to be paired with its own --test-reporter-destination, even though the + // ndjson reporter yields nothing and ignores its own destination — so the + // pairing still needs a sink argument. Pointed at the OS null device (a + // FIXED-length constant, unlike the old per-chunk events path) rather than + // a real file: it stays empty by design, since the durable write path is + // now the env var below, not this destination. // // One tmp dir for the whole run (not per-chunk) to avoid mkdtemp churn; - // each chunk gets its own destination file inside it so a diagnostic read - // never race with, or is polluted by, another chunk's events. Deleted on - // the success path; kept only long enough to read back on a timeout. + // each chunk gets its own events file inside it so a diagnostic read never + // races with, or is polluted by, another chunk's events. Deleted on the + // success path; kept only long enough to read back on a timeout. const eventsDir = mkdtempSync(join(tmpdir(), 'gsd-run-tests-events-')); const reporterModulePath = join(__dirname, 'lib', 'ndjson-reporter.cjs'); const humanReporter = process.stdout.isTTY ? 'spec' : 'tap'; - // Chunk index zero-padded to a fixed width: the destination path's length - // (and therefore FIXED_OVERHEAD below, computed once before chunking) must - // not depend on which chunk is running. 3 digits covers up to 999 chunks — - // this suite chunks into the tens, never close to that ceiling. + // Chunk index zero-padded to a fixed width so the events path's length is + // stable across chunks (kept for readability/debuggability; it no longer + // feeds FIXED_OVERHEAD since the path now travels via env, not argv). 3 + // digits covers up to 999 chunks — this suite chunks into the tens, never + // close to that ceiling. const eventsPathFor = (i) => join(eventsDir, `chunk-${String(i).padStart(3, '0')}.ndjson`); - const reporterArgsFor = (i) => [ + // Fixed argv for every chunk: the events path moved to the environment + // (GSD_RUN_TESTS_EVENTS_FILE, set per-chunk below in execFileSync's `env`), + // which does NOT count toward the Windows 32,767-char argv ceiling — only + // this fixed sink destination does. + const reporterArgs = [ `--test-reporter=${humanReporter}`, '--test-reporter-destination=stdout', `--test-reporter=${reporterModulePath}`, - `--test-reporter-destination=${eventsPathFor(i)}`, + `--test-reporter-destination=${devNull}`, ]; - const reporterOverhead = reporterArgsFor(0).reduce((sum, a) => sum + a.length + 1, 0); + const reporterOverhead = reporterArgs.reduce((sum, a) => sum + a.length + 1, 0); const FIXED_OVERHEAD = process.execPath.length + '--test'.length + concurrency.length + (forceExit ? '--test-force-exit'.length + 1 : 0) + reporterOverhead + 8; const chunks = packChunks(selected, { @@ -1119,12 +1150,12 @@ function main() { '--test', ...(forceExit ? ['--test-force-exit'] : []), concurrency, - ...reporterArgsFor(i), + ...reporterArgs, ...chunks[i], ], { stdio: 'inherit', - env: { ...process.env }, + env: { ...process.env, GSD_RUN_TESTS_EVENTS_FILE: chunkEventsPath }, timeout: chunkTimeoutMs, }, ); @@ -1155,7 +1186,7 @@ function main() { // this parent never saw the child's own stdout, so it cannot know // otherwise). Falls back to "no file identified" rather than // throwing when the reporter file is missing/empty/truncated. - const { files: inFlightFiles, staleMs, sawAnyEvent } = analyzeChunkEvents(chunkEventsPath); + const { files: inFlightFiles, staleMs, sawAnyEvent, readError } = analyzeChunkEvents(chunkEventsPath); const inFlightMsg = inFlightFiles.length > 0 ? `In flight when killed (test:start with no matching pass/fail): ` + `${inFlightFiles.map((f) => basename(f)).join(', ')} — last reporter event was ` + @@ -1167,9 +1198,15 @@ function main() { `event was ${staleMs !== null ? `${staleMs}ms` : 'an unknown time'} before this ` + `diagnostic); suspect a leaked handle outside any single test, or an ` + `after-tests hook.` - : `No reporter events were recorded before the kill — the companion reporter file ` + - `never received a test:start, so even the first file in this chunk may not have ` + - `begun executing (process/spawn startup stall, not a test hang).`; + : readError + ? `NO EVENTS COULD BE READ for this chunk — the companion reporter's events file ` + + `(GSD_RUN_TESTS_EVENTS_FILE) does not exist at all, so the child was killed ` + + `before the reporter wrote even one event (process/spawn startup stall, not a ` + + `test hang). This diagnostic could not identify an in-flight file.` + : `No reporter events were recorded before the kill — the companion reporter's ` + + `events file exists but is empty/unparseable, so even the first file in this ` + + `chunk may not have begun executing (process/spawn startup stall, not a test ` + + `hang). This diagnostic could not identify an in-flight file.`; const table = loadTestTimings(process.env.RUN_TESTS_TIMINGS_FILE || DEFAULT_TIMINGS_PATH); const ranked = rankChunkFilesByWeight(chunks[i], fileWeightOf(), table).join('\n'); @@ -1264,6 +1301,7 @@ module.exports = { loadTestTimings, makeFileWeigher, packChunks, + analyzeChunkEvents, DEFAULT_TIMINGS_PATH, // Exported so callers (tests/ci-test-scope.test.cjs) can assert the // suite-token resolution contract in-process rather than through a timed diff --git a/tests/run-tests-harness.test.cjs b/tests/run-tests-harness.test.cjs index a301c74d5..37a34417c 100644 --- a/tests/run-tests-harness.test.cjs +++ b/tests/run-tests-harness.test.cjs @@ -2228,3 +2228,68 @@ describe('chunk packing weights measured cost (#2456)', () => { }); }); }); + +// ─── analyzeChunkEvents (#3889 durability fix) ────────────────────────────── +// +// scripts/lib/ndjson-reporter.cjs now writes durably (fs.appendFileSync to a +// GSD_RUN_TESTS_EVENTS_FILE path) instead of yielding strings for Node to +// pipe through a buffered --test-reporter-destination WriteStream that a +// SIGKILL can wipe out before it flushes. These tests exercise the READER +// side (analyzeChunkEvents) directly against a hand-written events file, so +// they pin the reader's contract independently of whether the writer side +// managed to flush anything in a given subprocess run. +const { analyzeChunkEvents } = require('../scripts/run-tests.cjs'); + +describe('analyzeChunkEvents (#3889)', () => { + let tmpDir; + + beforeEach(() => { + tmpDir = createTempDir('gsd-3889-events-'); + }); + + afterEach(() => { + cleanup(tmpDir); + }); + + test('a missing events file is reported as an explicit read error, not silently as "no events"', () => { + const missingPath = path.join(tmpDir, 'does-not-exist.ndjson'); + const result = analyzeChunkEvents(missingPath); + assert.strictEqual(result.readError, true, 'a missing file must set readError=true'); + assert.strictEqual(result.sawAnyEvent, false); + assert.deepStrictEqual(result.files, []); + }); + + test('an existing-but-empty events file is distinguished from a missing one (readError=false)', () => { + const emptyPath = path.join(tmpDir, 'empty.ndjson'); + fs.writeFileSync(emptyPath, '', 'utf8'); + const result = analyzeChunkEvents(emptyPath); + assert.strictEqual(result.readError, false, 'an existing empty file must NOT be reported as a read error'); + assert.strictEqual(result.sawAnyEvent, false); + assert.deepStrictEqual(result.files, []); + }); + + test('a truncated final line does not crash the reader and earlier complete lines are still reported', () => { + const truncatedPath = path.join(tmpDir, 'truncated.ndjson'); + const complete = [ + JSON.stringify({ type: 'test:start', file: 'a.test.cjs', name: 'first', nesting: 0, testNumber: 1, ts: 1000 }), + JSON.stringify({ type: 'test:pass', file: 'a.test.cjs', name: 'first', nesting: 0, testNumber: 1, ts: 1010 }), + JSON.stringify({ type: 'test:start', file: 'b.test.cjs', name: 'hangs', nesting: 0, testNumber: 1, ts: 1020 }), + ].join('\n'); + // Simulate a SIGKILL mid-appendFileSync: the trailing line is cut off + // partway through a JSON object, exactly as an unbuffered but non-atomic + // write can be interrupted. + const truncatedTrailer = '\n{"type":"test:start","file":"c.test.cjs","name":"cut off mid-writ'; + fs.writeFileSync(truncatedPath, complete + truncatedTrailer, 'utf8'); + + const result = analyzeChunkEvents(truncatedPath); + assert.strictEqual(result.readError, false, 'a readable-but-truncated file must not be a read error'); + // The complete test:start (b.test.cjs) with no matching pass/fail is + // still identified as in-flight despite the unparsable trailing line. + assert.deepStrictEqual(result.files, ['b.test.cjs']); + // a.test.cjs completed (start+pass), so it must NOT show as in-flight. + assert.ok(!result.files.includes('a.test.cjs')); + // c.test.cjs never parsed (truncated line), so it cannot appear either. + assert.ok(!result.files.includes('c.test.cjs')); + assert.strictEqual(result.sawAnyEvent, true, 'the complete lines before the truncation must still count as events'); + }); +});