diff --git a/scripts/lib/ndjson-reporter.cjs b/scripts/lib/ndjson-reporter.cjs index a06e03cd6..6f48de57d 100644 --- a/scripts/lib/ndjson-reporter.cjs +++ b/scripts/lib/ndjson-reporter.cjs @@ -11,7 +11,7 @@ // 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`). +// in flight (a `test:dequeue` 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 @@ -49,12 +49,22 @@ // repo's `engines.node` requires >=24.0.0 (package.json), where both // contracts have 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 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. +// Kept intentionally tiny: only the five event types run-tests.cjs needs are +// handled — `test:enqueue`/`test:dequeue` (emitted by the RUNNER as it queues +// and begins each spawned test-file child, independent of whether anything +// inside that file ever completes) plus `test:start`/`test:pass`/`test:fail` +// (emitted per-subtest, once the child reports it). `test:dequeue` is the +// event that actually means "in flight": a subtest inside a file that hangs +// forever never reaches `test:start`/`test:pass`/`test:fail` at all, because +// node:test only surfaces those to the parent once the child COMPLETES that +// test — a hang, by definition, never completes. Recording `test:dequeue` +// closes that gap: it fires the moment the runner begins the file, so a +// killed hang still leaves a durable "this file was running" record. +// Everything else (diagnostics, plans, 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; // #3889: an init marker, written as this reporter's FIRST action — before @@ -77,6 +87,8 @@ module.exports = async function ndjsonEventReporter(source) { for await (const event of source) { if (!eventsPath) continue; // no destination configured — nothing to record if ( + event.type === 'test:enqueue' || + event.type === 'test:dequeue' || event.type === 'test:start' || event.type === 'test:pass' || event.type === 'test:fail' diff --git a/scripts/run-tests.cjs b/scripts/run-tests.cjs index ff2863c63..4541f80e7 100644 --- a/scripts/run-tests.cjs +++ b/scripts/run-tests.cjs @@ -685,11 +685,22 @@ function selectExplicitFiles(allFiles, filesValue, filesFrom) { } // #3889: reads back the ndjson companion reporter's destination file for one -// chunk and reduces it to "which file(s) were in flight" — a `test:start` -// with no matching `test:pass`/`test:fail` in the same file. Matched by -// (file, nesting, testNumber) when testNumber is present (assigned once at -// start and echoed on completion, per node:test), falling back to -// (file, name) for older/odd event shapes. +// chunk and reduces it to "which file(s) were in flight" — a `test:dequeue` +// with no matching `test:pass`/`test:fail` FOR THE SAME FILE. `test:dequeue` +// is emitted by the RUNNER the moment it begins a spawned test-file child, +// independent of whether anything inside that file ever completes — it is +// the correct "in flight" signal precisely BECAUSE a hang never completes. +// `test:start`/`test:pass`/`test:fail` are per-SUBTEST events that node:test +// only surfaces to the parent once the child reports that subtest, which +// happens on completion — a subtest that hangs forever inside `new +// Promise(() => {})` never reports `test:start` either, so those three event +// types alone can NEVER see a genuine hang (this was the root cause of the +// feature never working: the three original event types are precisely the +// ones a hang guarantees are never emitted). `test:start` is still tracked +// here as a SECONDARY in-flight signal (a file can legitimately produce +// both), never as the primary one. Tracked per FILE, not per (file, nesting, +// testNumber) — dequeue/enqueue are file-level events with no subtest +// identity, so file is the only key both event families share. // // Tolerant of a destination file that is missing (reporter never flushed // anything before the kill) or whose last line is truncated mid-write (the @@ -708,12 +719,23 @@ function analyzeChunkEvents(eventsPath) { // FIRST action, before any test can run, so its absence pins the failure // to reporter load/resolution, not to the tests). Distinct from "file // exists but only the init marker was written" (readError=false, - // sawInitMarker=true, sawAnyEvent=false) so the diagnostic below can say + // sawInitMarker=true, anyDequeued=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, sawInitMarker: false, readError: true }; + return { + files: [], + staleMs: null, + sawAnyEvent: false, + sawInitMarker: false, + anyDequeued: false, + readError: true, + }; } - const inFlight = new Map(); + // Map preserves insertion order; re-`set`ting an existing key moves it to + // the END, so iterating this map's keys yields "most recently + // dequeued/started" LAST — reversed below to report most-recent-first. + const dequeuedAt = new Map(); // file -> last dequeue/start ts seen + const terminated = new Set(); // files with an observed test:pass/test:fail let lastTs = null; let sawInitMarker = false; let sawAnyEvent = false; @@ -731,21 +753,25 @@ function analyzeChunkEvents(eventsPath) { continue; // not a test event — never tracked in inFlight, never proof a test ran } sawAnyEvent = true; - const key = evt.testNumber !== undefined - ? `${evt.file}::${evt.nesting}::${evt.testNumber}` - : `${evt.file}::${evt.name}`; - if (evt.type === 'test:start') { - inFlight.set(key, evt.file); - } else { - inFlight.delete(key); + if (!evt.file) continue; // defensive: every recorded type carries `file` + if (evt.type === 'test:dequeue' || evt.type === 'test:start') { + dequeuedAt.delete(evt.file); // move to most-recent position + dequeuedAt.set(evt.file, evt.ts); + terminated.delete(evt.file); // a re-dequeue (retry) puts it back in flight + } else if (evt.type === 'test:pass' || evt.type === 'test:fail') { + terminated.add(evt.file); } + // test:enqueue is intentionally NOT a start signal here: "enqueued" means + // "queued to run", not "running" — test:dequeue is the runner actually + // picking the file up, which is the moment that matters for "in flight". } - const files = [...new Set([...inFlight.values()].filter(Boolean))]; + const files = [...dequeuedAt.keys()].filter((f) => !terminated.has(f)).reverse(); return { files, staleMs: lastTs !== null ? Date.now() - lastTs : null, sawAnyEvent, sawInitMarker, + anyDequeued: dequeuedAt.size > 0, readError: false, }; } @@ -1222,16 +1248,23 @@ 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, sawInitMarker, readError } = analyzeChunkEvents(chunkEventsPath); + const { + files: inFlightFiles, + staleMs, + sawInitMarker, + anyDequeued, + readError, + } = analyzeChunkEvents(chunkEventsPath); const inFlightMsg = inFlightFiles.length > 0 - ? `In flight when killed (test:start with no matching pass/fail): ` + + ? `In flight when killed (test:dequeue with no matching pass/fail): ` + `${inFlightFiles.map((f) => basename(f)).join(', ')} — last reporter event was ` + `${staleMs !== null ? `${staleMs}ms` : 'an unknown time'} before this diagnostic ` + `(small = output kept flowing until the kill = slow; large = it stopped early = hang).` - : sawAnyEvent - ? `No file was in flight when killed — every started test in this chunk already ` + - `completed, so the CHILD PROCESS itself hung after its last test (last reporter ` + - `event was ${staleMs !== null ? `${staleMs}ms` : 'an unknown time'} before this ` + + : anyDequeued + ? `No file was in flight when killed — every file the runner dequeued in this ` + + `chunk already terminated (test:pass/test:fail seen for each), so the CHILD ` + + `PROCESS itself hung after its last test finished (last reporter 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.` : readError @@ -1243,13 +1276,16 @@ function main() { `reporter function was ever invoked (process/spawn startup stall). This ` + `diagnostic could not identify an in-flight file.` : sawInitMarker - ? `THE REPORTER LOADED BUT RECORDED NO TEST EVENTS — the events file contains ` + - `only the reporter's own \`reporter:init\` marker, so the reporter module ` + - `was invoked and ran, but no \`test:start\` for any file in this chunk ` + - `reached it before the kill. Two possible causes, NOT distinguished by this ` + - `diagnostic: node --test itself stalled before dispatching any test file, or ` + - `the first file in this chunk hung/stalled before its first test began. This ` + - `diagnostic could not identify an in-flight file.` + ? `THE REPORTER LOADED BUT THE RUNNER NEVER DEQUEUED A SINGLE FILE — the events ` + + `file contains only the reporter's own \`reporter:init\` marker (and possibly ` + + `\`test:enqueue\` events with no matching \`test:dequeue\`), so the reporter ` + + `module was invoked and ran, but node's test runner never began executing any ` + + `file in this chunk before the kill. This is a genuinely surprising state — ` + + `\`test:dequeue\` fires the instant the runner starts a file, independent of ` + + `whether anything inside it ever completes. Two possible causes, NOT ` + + `distinguished by this diagnostic: node --test itself stalled before ` + + `dispatching any test file, or process/spawn startup stalled. 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 (no \`reporter:init\` marker and ` + `no test events), so even the reporter's first appendFileSync may not have ` + diff --git a/tests/run-tests-harness.test.cjs b/tests/run-tests-harness.test.cjs index 57b582aea..9a2eb529c 100644 --- a/tests/run-tests-harness.test.cjs +++ b/tests/run-tests-harness.test.cjs @@ -951,6 +951,50 @@ test('hangs forever', () => new Promise(() => {})); } }); + // Regression (#3889 root cause): a hang inside a test body NEVER produces + // a `test:start`/`test:pass`/`test:fail` for that subtest (node:test only + // surfaces those to the parent once the child reports completion), so + // those three event types alone can never see a hang. `test:enqueue` and + // `test:dequeue` are emitted by the RUNNER as it queues/begins a file, + // independent of completion — this pins that the reporter now records + // both, verbatim, for exactly the "enqueue then dequeue, then nothing" + // shape a real hang produces. + test('the reporter records test:enqueue and test:dequeue for the hang shape (enqueue, dequeue, nothing else)', async () => { + const reporter = require('../scripts/lib/ndjson-reporter.cjs'); + const eventsFile = path.join(tmpDir, 'ndjson-reporter-hang-shape.ndjson'); + const savedEventsFile = process.env.GSD_RUN_TESTS_EVENTS_FILE; + process.env.GSD_RUN_TESTS_EVENTS_FILE = eventsFile; + try { + async function* hangShapeEvents() { + yield { type: 'test:enqueue', data: { file: 'hangs.test.cjs', name: 'hangs.test.cjs', nesting: 0 } }; + yield { type: 'test:dequeue', data: { file: 'hangs.test.cjs', name: 'hangs.test.cjs', nesting: 0 } }; + // Never yields test:start/test:pass/test:fail — this IS the hang. + } + const result = await reporter(hangShapeEvents()); + assert.strictEqual(result ?? null, null); + const rawContent = fs.readFileSync(eventsFile, 'utf8'); + const lines = splitLines(rawContent.trim()).filter((l) => l.length > 0); + assert.strictEqual( + lines.length, + 3, + `expected exactly 3 NDJSON lines (init marker + enqueue + dequeue); got:\n${lines.join('\n')}`, + ); + const [init, enqueue, dequeue] = lines.map((l) => JSON.parse(l)); + assert.strictEqual(init.type, 'reporter:init'); + assert.strictEqual(enqueue.type, 'test:enqueue'); + assert.strictEqual(enqueue.file, 'hangs.test.cjs'); + assert.strictEqual(dequeue.type, 'test:dequeue'); + assert.strictEqual(dequeue.file, 'hangs.test.cjs'); + } finally { + if (savedEventsFile === undefined) { + delete process.env.GSD_RUN_TESTS_EVENTS_FILE; + } else { + process.env.GSD_RUN_TESTS_EVENTS_FILE = savedEventsFile; + } + cleanup(eventsFile); + } + }); + // #3889: the init marker is the reporter's FIRST action, written before // the `for await` loop even begins — so it must land even when the // source event stream yields ZERO events (e.g. the child is killed @@ -2402,4 +2446,67 @@ describe('analyzeChunkEvents (#3889)', () => { assert.ok(!result.files.includes('c.test.cjs')); assert.strictEqual(result.sawAnyEvent, true, 'the complete lines before the truncation must still count as events'); }); + + // Regression (#3889 root cause): test:start/test:pass/test:fail are the + // exact three event types a genuine hang guarantees are never emitted — + // node:test only surfaces a subtest event to the parent once the child + // reports it, which happens on completion. test:dequeue is the RUNNER's + // own "began this file" signal and fires independent of completion; these + // four cases pin analyzeChunkEvents' dequeue-based in-flight rule directly + // against the synthetic event shapes a real hang, and a real finish, produce. + test('a dequeued file with no terminal event is reported as in flight', () => { + const eventsPath = path.join(tmpDir, 'dequeue-only.ndjson'); + const lines = [ + JSON.stringify({ type: 'reporter:init', ts: 900 }), + JSON.stringify({ type: 'test:enqueue', file: 'a.test.cjs', ts: 1000 }), + JSON.stringify({ type: 'test:dequeue', file: 'a.test.cjs', ts: 1010 }), + ].join('\n'); + fs.writeFileSync(eventsPath, lines, 'utf8'); + + const result = analyzeChunkEvents(eventsPath); + assert.deepStrictEqual(result.files, ['a.test.cjs']); + assert.strictEqual(result.anyDequeued, true); + assert.strictEqual(result.sawInitMarker, true); + }); + + test('a dequeued file that also terminates reports nothing in flight (all files finished)', () => { + const eventsPath = path.join(tmpDir, 'dequeue-then-pass.ndjson'); + const lines = [ + JSON.stringify({ type: 'reporter:init', ts: 900 }), + JSON.stringify({ type: 'test:enqueue', file: 'a.test.cjs', ts: 1000 }), + JSON.stringify({ type: 'test:dequeue', file: 'a.test.cjs', ts: 1010 }), + JSON.stringify({ type: 'test:pass', file: 'a.test.cjs', ts: 1020 }), + ].join('\n'); + fs.writeFileSync(eventsPath, lines, 'utf8'); + + const result = analyzeChunkEvents(eventsPath); + assert.deepStrictEqual(result.files, [], 'a terminated file must not show as in flight'); + assert.strictEqual(result.anyDequeued, true, 'the file WAS dequeued — "all files finished" is a distinct state from "nothing ran"'); + }); + + test('one terminated file followed by a second dequeued-but-unterminated file reports only the second', () => { + const eventsPath = path.join(tmpDir, 'two-files.ndjson'); + const lines = [ + JSON.stringify({ type: 'reporter:init', ts: 900 }), + JSON.stringify({ type: 'test:dequeue', file: 'a.test.cjs', ts: 1000 }), + JSON.stringify({ type: 'test:pass', file: 'a.test.cjs', ts: 1010 }), + JSON.stringify({ type: 'test:dequeue', file: 'b.test.cjs', ts: 1020 }), + ].join('\n'); + fs.writeFileSync(eventsPath, lines, 'utf8'); + + const result = analyzeChunkEvents(eventsPath); + assert.deepStrictEqual(result.files, ['b.test.cjs']); + assert.ok(!result.files.includes('a.test.cjs')); + }); + + test('an init marker with no dequeue at all is distinguished (anyDequeued=false) from "all finished"', () => { + const eventsPath = path.join(tmpDir, 'init-only.ndjson'); + fs.writeFileSync(eventsPath, JSON.stringify({ type: 'reporter:init', ts: 900 }), 'utf8'); + + const result = analyzeChunkEvents(eventsPath); + assert.deepStrictEqual(result.files, []); + assert.strictEqual(result.anyDequeued, false); + assert.strictEqual(result.sawInitMarker, true); + assert.strictEqual(result.sawAnyEvent, false); + }); });