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'); + }); +});