From 8497833a15189b557e230c1995c8d01c80d58808 Mon Sep 17 00:00:00 2001 From: sim Date: Fri, 28 Aug 2026 18:50:55 -0400 Subject: [PATCH 1/9] fix(#4012): a killed chunk now names the file that was hanging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The per-chunk timeout fired correctly but reported almost nothing, so every diagnosis cost a CI round-trip. run-tests.cjs logged chunk START only — no timestamp, no duration, no end line — then on a kill printed all ~55 basenames and asked the operator to work out whether output kept flowing (slow) or stopped early (hang). It could not name the in-flight file because the child is spawned with stdio inherit, deliberately, per #3597/#1051. Three additions. Per-chunk elapsed timing on every path, not just failures, so drift toward the cap is visible before it becomes a kill. Every timing number in the investigation behind this had to be reconstructed by hand from GitHub log timestamps. A second, machine-readable reporter running ALONGSIDE the human one, writing NDJSON to its own file. On a kill that file is read back and the files with a test:start and no matching completion are named, with the staleness of the last event, so "stopped 480s ago at X" reads differently from "still emitting at kill". stdio stays inherit and nothing is piped or tee'd — the maxBuffer and live-output risks that shaped the original design are untouched. Ranking of the killed chunk's files by known weight, flagging any absent from tests/test-timings.json, since an unweighted file is an unknown quantity. Two details that are correct rather than lucky. Passing --test-reporter at all replaces node's implicit default, so the human reporter is now named explicitly and reproduces node's own selection (spec on a TTY, tap otherwise) — visible output is unchanged. And the destination path's chunk index is zero-padded to a fixed width because FIXED_OVERHEAD is computed ONCE before chunking; a variable-length path would have silently mis-accounted the Windows 32,767-char argv ceiling and reintroduced #3597. The reporter flags are added to FIXED_OVERHEAD exactly as --test-force-exit is. The multi-reporter pairing and the stream.compose reporter contract were confirmed against Node's v24 documentation, not recalled — the first draft carried them as an unverified assumption and said so. Also corrects a stale comment claiming the 600s cap sits "below the 20m job cap". The lane is sharded 3x at timeout-minutes: 45; the windows shards were at 19m when chunk 1/5 was killed on b351c83e0 and c3e667df3. The per-chunk cap is now the binding constraint, and the old silent-cancel model leads to the wrong conclusion. Verification runs on the remote runner. Closes #4012 --- .changeset/proud-sloths-cheer.md | 5 + scripts/lib/ndjson-reporter.cjs | 47 ++++++++ scripts/run-tests.cjs | 186 +++++++++++++++++++++++++++++-- tests/run-tests-harness.test.cjs | 89 +++++++++++++++ 4 files changed, 317 insertions(+), 10 deletions(-) create mode 100644 .changeset/proud-sloths-cheer.md create mode 100644 scripts/lib/ndjson-reporter.cjs diff --git a/.changeset/proud-sloths-cheer.md b/.changeset/proud-sloths-cheer.md new file mode 100644 index 000000000..af15ab35f --- /dev/null +++ b/.changeset/proud-sloths-cheer.md @@ -0,0 +1,5 @@ +--- +type: Fixed +pr: 0 +--- +**A killed test chunk now names the file that was hanging.** `scripts/run-tests.cjs` logged only chunk starts, so a chunk killed at the 600s cap printed ~55 basenames and left the operator to guess which one hung — and every timing figure had to be reconstructed from CI log timestamps. It now emits per-chunk elapsed time on every path, names the files still in flight on a kill with how stale the last event is (hang vs. merely slow), and ranks the chunk by known weight, flagging files missing from the timings table. (#4012) diff --git a/scripts/lib/ndjson-reporter.cjs b/scripts/lib/ndjson-reporter.cjs new file mode 100644 index 000000000..0611f9917 --- /dev/null +++ b/scripts/lib/ndjson-reporter.cjs @@ -0,0 +1,47 @@ +'use strict'; + +// Machine-readable companion reporter for scripts/run-tests.cjs (#3889). +// +// node:test's built-in reporters (spec/tap) are human-formatted and +// scripts/run-tests.cjs spawns the child with `stdio: 'inherit'` — by design, +// 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 +// 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`). +// +// 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. +// +// 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) { + for await (const event of source) { + if ( + event.type === 'test:start' || + event.type === 'test:pass' || + event.type === 'test:fail' + ) { + const { file, name, nesting, testNumber } = event.data || {}; + yield `${JSON.stringify({ + type: event.type, + file, + name, + nesting, + testNumber, + ts: Date.now(), + })}\n`; + } + } +}; diff --git a/scripts/run-tests.cjs b/scripts/run-tests.cjs index 476ad6bf0..0a039d780 100644 --- a/scripts/run-tests.cjs +++ b/scripts/run-tests.cjs @@ -35,8 +35,9 @@ // See docs/TESTING-SUITES.md for full grouping policy. 'use strict'; -const { readdirSync, readFileSync } = require('fs'); +const { readdirSync, readFileSync, mkdtempSync, rmSync, unlinkSync } = require('fs'); const { join, basename } = require('path'); +const { tmpdir } = require('os'); const { execFileSync } = require('child_process'); const { ExitError, runMain } = require('./lib/cli-exit.cjs'); const { @@ -682,6 +683,73 @@ function selectExplicitFiles(allFiles, filesValue, filesFrom) { return { files: [...new Set(selected)] }; } +// #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. +// +// Tolerant of a destination file that is missing (reporter never flushed +// anything before the kill) or whose last line is truncated mid-write (the +// child is SIGKILLed, not given a chance to finish a buffered write) — both +// degrade to "no in-flight file identified" rather than throwing, since this +// is a best-effort diagnostic layered on top of, never a precondition for, +// the timeout it explains. +function analyzeChunkEvents(eventsPath) { + let raw; + try { + raw = readFileSync(eventsPath, 'utf8'); + } catch { + return { files: [], staleMs: null, sawAnyEvent: false }; + } + const inFlight = new Map(); + let lastTs = null; + for (const line of raw.split('\n')) { + if (line.trim() === '') continue; + let evt; + try { + evt = JSON.parse(line); + } catch { + continue; // truncated trailing line from a mid-write kill + } + if (typeof evt.ts === 'number') lastTs = evt.ts; + 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); + } + } + const files = [...new Set([...inFlight.values()].filter(Boolean))]; + return { + files, + staleMs: lastTs !== null ? Date.now() - lastTs : null, + sawAnyEvent: lastTs !== null, + }; +} + +// #3889: ranks a killed chunk's files heaviest-first using the same weigher +// the packer used to build the chunk, and flags any file the timings table +// has no measurement for at all (as opposed to one that IS measured but +// happens to be cheap) — an unmeasured file is an unknown quantity, not a +// known-light one, and the table itself is advisory/stale (see the +// loadTestTimings header), so this is presented as a hint, never a verdict. +function rankChunkFilesByWeight(files, weightOf, timingsTable) { + return [...files] + .map((f) => ({ base: basename(f), weight: weightOf(f) })) + .sort((a, b) => b.weight - a.weight) + .map(({ base, weight }, idx) => { + const measured = timingsTable ? Object.hasOwn(timingsTable.timings, base) : false; + return ` ${idx + 1}. ${base} (weight=${weight.toFixed(2)}${ + measured ? '' : ', UNMEASURED — absent from tests/test-timings.json (table is advisory' + + ' and stale; treat this file as an unknown cost, not a cheap one)' + })`; + }); +} + function main() { const args = process.argv.slice(2); const parsed = parseArgs(args); @@ -960,7 +1028,35 @@ function main() { const nodeMajor = Number(process.versions.node.split('.')[0]); const forceExit = nodeMajor >= 22 && !process.env.RUN_TESTS_NO_FORCE_EXIT; - const FIXED_OVERHEAD = process.execPath.length + '--test'.length + concurrency.length + (forceExit ? '--test-force-exit'.length + 1 : 0) + 8; + // #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. + // + // 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. + 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. + const eventsPathFor = (i) => join(eventsDir, `chunk-${String(i).padStart(3, '0')}.ndjson`); + const reporterArgsFor = (i) => [ + `--test-reporter=${humanReporter}`, + '--test-reporter-destination=stdout', + `--test-reporter=${reporterModulePath}`, + `--test-reporter-destination=${eventsPathFor(i)}`, + ]; + const reporterOverhead = reporterArgsFor(0).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, { weightOf: fileWeightOf(), maxWeight: MAX_FILES_PER_CHUNK, @@ -970,9 +1066,20 @@ function main() { // A chunk that still hangs (a leak the backstop somehow misses, or a wedged // subprocess) must fail loudly rather than silently burn the job's wall-clock - // budget until the CI runner cancels the whole job. Default 10 min per chunk: - // well above a healthy chunk (~4-5 min on the windows lane) but below the 20m - // job cap. Operator/test override via RUN_TESTS_CHUNK_TIMEOUT_MS. + // budget. Default 10 min per chunk. Operator/test override via + // RUN_TESTS_CHUNK_TIMEOUT_MS. + // + // Correction: this used to be justified as "below the 20m job cap" — that is + // stale. The full-test lane is now SHARDED 3x with `timeout-minutes: 45` in + // .github/workflows/test.yml, and that budget is asserted by + // tests/ci-test-job-timeout-budget.test.cjs. Consequence: the 600s + // per-chunk cap below is now the BINDING constraint, not the job cap. + // Evidence (measured 2026-08-28): windows shards ran 19m+ while every macos + // shard had already finished — nowhere near 45m — yet chunk 1/5 was killed + // at 600s on two separate runs (b351c83e0, c3e667df3), presenting as + // "# fail 0" with exit 1. Do not reason about a modern chunk kill using the + // old 20m silent-cancel model; they are different failure modes with + // different evidence. const chunkTimeoutMs = positiveNumberEnv(process.env.RUN_TESTS_CHUNK_TIMEOUT_MS, 600000); // #2665: snapshot GSD's install footprint in every LIVE runtime config dir @@ -1003,32 +1110,80 @@ function main() { if (chunks.length > 1) { console.error(`run-tests: chunk ${i + 1}/${chunks.length} — ${chunks[i].length} files`); } + const chunkEventsPath = eventsPathFor(i); + const chunkStartedAt = process.hrtime.bigint(); try { execFileSync( process.execPath, - ['--test', ...(forceExit ? ['--test-force-exit'] : []), concurrency, ...chunks[i]], + [ + '--test', + ...(forceExit ? ['--test-force-exit'] : []), + concurrency, + ...reporterArgsFor(i), + ...chunks[i], + ], { stdio: 'inherit', env: { ...process.env }, timeout: chunkTimeoutMs, }, ); + const elapsedMs = Number(process.hrtime.bigint() - chunkStartedAt) / 1e6; + console.error( + `run-tests: chunk ${i + 1}/${chunks.length} completed in ${elapsedMs.toFixed(0)}ms`, + ); + // Success path only (#3889): the events file has served its purpose — + // delete it now rather than let it accumulate across a multi-chunk run. + try { + unlinkSync(chunkEventsPath); + } catch { + // Best-effort; a missing/already-gone file is not an error here. + } } catch (err) { + const elapsedMs = Number(process.hrtime.bigint() - chunkStartedAt) / 1e6; // When the per-chunk timeout fires, execFileSync kills the child and // surfaces it as err.code === 'ETIMEDOUT' (POSIX) and/or err.killed === true // (platform-dependent). Check both so detection holds on Windows and POSIX. const timedOut = err.killed === true || err.code === 'ETIMEDOUT'; + console.error( + `run-tests: chunk ${i + 1}/${chunks.length} ${timedOut ? 'was killed' : 'failed'} ` + + `after ${elapsedMs.toFixed(0)}ms`, + ); if (timedOut) { + // #3889: name the file(s) in flight when the kill fired, using the + // ndjson companion reporter's destination file (stdio:'inherit' means + // 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 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 ` + + `${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 ` + + `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).`; + + const table = loadTestTimings(process.env.RUN_TESTS_TIMINGS_FILE || DEFAULT_TIMINGS_PATH); + const ranked = rankChunkFilesByWeight(chunks[i], fileWeightOf(), table).join('\n'); + console.error( `run-tests: chunk ${i + 1}/${chunks.length} exceeded the per-chunk timeout ` + `of ${chunkTimeoutMs}ms and was killed. Two possible causes: (1) a test leaks ` + `an open handle (un-terminated Worker, un-killed child process, or ref'd timer) ` + `so node --test never exits — but --test-force-exit already guards that, so if it ` + `is enabled suspect (2) the chunk is legitimately too slow for the budget (too ` + - `many/too-heavy files packed together). Check whether output kept flowing until ` + - `the kill (slow) vs stopped early (hang) before assuming a leak. Files: ${chunks[i] - .map(f => f.split(/[\\/]/).pop()) - .join(' ')}`, + `many/too-heavy files packed together).\n${inFlightMsg}\n` + + `Files in this chunk, heaviest-first by measured weight ` + + `(table last regenerated 2026-08-07; real Windows cost runs ~2.2x the recorded ` + + `figure, so treat every number as a floor):\n${ranked}`, ); } const code = err.status || 1; @@ -1063,6 +1218,17 @@ function main() { // and the first non-zero exit is reported at the end. } } + // #3889: sweep any events file the per-chunk success path didn't already + // delete (a timeout diagnostic read one but left it on disk; an aborted + // run may leave more that were never opened). All diagnostics that needed + // these files have already been printed above, so this is unconditional — + // best-effort, since a failure to remove a tmp dir must never mask the + // real chunk-loop exit code. + try { + rmSync(eventsDir, { recursive: true, force: true }); + } catch { + // Non-fatal: an orphaned OS tmp dir is a cosmetic leak, not a test result. + } // #2665: post-suite hermeticity check. Runs even when tests failed — a leaked // global install is worth reporting alongside the failure that hid it, and // suppressing it on red would hide it exactly when the suite is least trusted. diff --git a/tests/run-tests-harness.test.cjs b/tests/run-tests-harness.test.cjs index 100886070..a301c74d5 100644 --- a/tests/run-tests-harness.test.cjs +++ b/tests/run-tests-harness.test.cjs @@ -814,6 +814,95 @@ test('noop', () => {}); ); }); }); + + describe('chunk-timeout instrumentation (#3889)', () => { + // T2: per-chunk elapsed timing appears on the normal SUCCESS path, not + // only when something goes wrong — this is what makes "which chunk is + // drifting toward the cap" readable across ordinary green runs. + test('a successful chunk prints its elapsed time', () => { + seed(tmpDir, ['a.test.cjs']); + const r = runHarness(tmpDir, []); + assert.strictEqual(r.status, 0, `expected a clean pass; STDERR:\n${r.stderr}`); + assert.match( + r.stderr, + /run-tests: chunk 1\/1 completed in \d+ms/, + `expected a per-chunk completion timing line; STDERR:\n${r.stderr}`, + ); + }); + + // T3: the ndjson companion reporter's destination file is a temp + // artifact of the instrumentation, not a product output — it must not + // survive a successful run. Assert against the OS temp root's own + // "gsd-run-tests-events-*" prefix (scripts/run-tests.cjs's mkdtemp + // prefix) rather than any run-tests-owned directory, since that IS the + // leak surface being guarded. + test('the ndjson reporter temp dir is cleaned up after a successful run', () => { + seed(tmpDir, ['a.test.cjs']); + const before = fs.readdirSync(require('os').tmpdir()) + .filter((n) => n.startsWith('gsd-run-tests-events-')); + const r = runHarness(tmpDir, []); + assert.strictEqual(r.status, 0, `expected a clean pass; STDERR:\n${r.stderr}`); + const after = fs.readdirSync(require('os').tmpdir()) + .filter((n) => n.startsWith('gsd-run-tests-events-')); + assert.deepStrictEqual( + after, + before, + `expected no leaked gsd-run-tests-events-* temp dir after a successful run; ` + + `before=${JSON.stringify(before)} after=${JSON.stringify(after)}`, + ); + }); + + // T1: on a chunk timeout, the diagnostic must NAME the file that was + // still executing — not merely list every file the chunk contained (the + // pre-instrumentation behavior). A test that hangs INSIDE its own body + // (never resolving) keeps its test:start event unmatched by any + // test:pass/test:fail in the ndjson companion reporter's output, which + // is exactly the signal the diagnostic reads back on timeout. + const HANGS_FOREVER_BODY = `'use strict'; +const { test } = require('node:test'); +test('hangs forever', () => new Promise(() => {})); +`; + test('a chunk timeout names the file that was in flight when killed', () => { + fs.writeFileSync(path.join(tmpDir, 'hangs.test.cjs'), HANGS_FOREVER_BODY, 'utf8'); + const r = runHarness(tmpDir, [], { + RUN_TESTS_NO_FORCE_EXIT: '1', + RUN_TESTS_CHUNK_TIMEOUT_MS: '2000', + }); + assert.notStrictEqual( + r.status, + 0, + `expected non-zero exit from a timed-out chunk; got status=${r.status}\nSTDERR:\n${r.stderr}`, + ); + assert.match( + r.stderr, + /In flight when killed.*hangs\.test\.cjs/s, + `expected the diagnostic to NAME the in-flight file, not just list the chunk; STDERR:\n${r.stderr}`, + ); + }); + + // T4: the pre-existing timeout / abort / force-exit behavior (#1051) + // still holds with the reporter instrumentation wired in — the new + // --test-reporter flags must not change detection, the abort-on-timeout + // control flow, or the exit code. + test('existing timeout diagnostic and abort behavior are unchanged', () => { + fs.writeFileSync(path.join(tmpDir, 'hangs.test.cjs'), HANGS_FOREVER_BODY, 'utf8'); + const r = runHarness(tmpDir, [], { + RUN_TESTS_NO_FORCE_EXIT: '1', + RUN_TESTS_CHUNK_TIMEOUT_MS: '2000', + }); + assert.notStrictEqual(r.status, 0, `expected non-zero exit; STDERR:\n${r.stderr}`); + assert.match( + r.stderr, + /exceeded the per-chunk timeout/, + `expected the original timeout diagnostic wording to survive; STDERR:\n${r.stderr}`, + ); + assert.match( + r.stderr, + /run-tests: chunk 1\/1 was killed after \d+ms/, + `expected the new killed/elapsed line; STDERR:\n${r.stderr}`, + ); + }); + }); }); // Pure partition contract for the shard selector (#1212). Imported directly From 11c24ce97325b5a216b5fae8f16f48ead80358b6 Mon Sep 17 00:00:00 2001 From: sim Date: Fri, 28 Aug 2026 18:58:05 -0400 Subject: [PATCH 2/9] chore(#4012): regenerate the 19 install-tree goldens MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit scripts/ ships, so a new file under scripts/lib/ moves every install-tree golden. The remote runner caught this as 26 failures across all 19 runtimes. My fault in the dispatch: I limited the implementation's verification to build:lib and lint:ci and left regen:derived out. Both of those passed, which is precisely why a green local gate is not a substitute for the runner — the goldens are only exercised there. One line per golden: scripts/lib/ndjson-reporter.cjs joining the shipped tree. Refs #4012 --- tests/fixtures/install-tree/antigravity.json | 1 + tests/fixtures/install-tree/augment.json | 1 + tests/fixtures/install-tree/claude-local.json | 3 ++- tests/fixtures/install-tree/claude.json | 1 + tests/fixtures/install-tree/cline.json | 1 + tests/fixtures/install-tree/codebuddy.json | 1 + tests/fixtures/install-tree/codex.json | 3 ++- tests/fixtures/install-tree/copilot.json | 1 + tests/fixtures/install-tree/cursor.json | 1 + tests/fixtures/install-tree/hermes.json | 1 + tests/fixtures/install-tree/kilo.json | 1 + tests/fixtures/install-tree/kimi-code.json | 1 + tests/fixtures/install-tree/kimi.json | 1 + tests/fixtures/install-tree/opencode.json | 1 + tests/fixtures/install-tree/pi.json | 3 ++- tests/fixtures/install-tree/qwen.json | 1 + tests/fixtures/install-tree/trae.json | 1 + tests/fixtures/install-tree/windsurf.json | 3 ++- tests/fixtures/install-tree/zcode.json | 1 + 19 files changed, 23 insertions(+), 4 deletions(-) diff --git a/tests/fixtures/install-tree/antigravity.json b/tests/fixtures/install-tree/antigravity.json index ff646f413..0b6ec95e5 100644 --- a/tests/fixtures/install-tree/antigravity.json +++ b/tests/fixtures/install-tree/antigravity.json @@ -433,6 +433,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-add-tests/SKILL.md", "skills/gsd-ai-integration-phase/SKILL.md", "skills/gsd-audit-fix/SKILL.md", diff --git a/tests/fixtures/install-tree/augment.json b/tests/fixtures/install-tree/augment.json index 92e060da9..33ef834fe 100644 --- a/tests/fixtures/install-tree/augment.json +++ b/tests/fixtures/install-tree/augment.json @@ -503,6 +503,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-ns-context/SKILL.md", "skills/gsd-ns-context/skills/docs-update/SKILL.md", "skills/gsd-ns-context/skills/extract-learnings/SKILL.md", diff --git a/tests/fixtures/install-tree/claude-local.json b/tests/fixtures/install-tree/claude-local.json index 23e4ffa1b..d180006de 100644 --- a/tests/fixtures/install-tree/claude-local.json +++ b/tests/fixtures/install-tree/claude-local.json @@ -502,5 +502,6 @@ "scripts/lib/allowlist-ratchet.cjs", "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", - "scripts/lib/exit-code-registry.cjs" + "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs" ] diff --git a/tests/fixtures/install-tree/claude.json b/tests/fixtures/install-tree/claude.json index 72ac7de4d..e4d4d20c8 100644 --- a/tests/fixtures/install-tree/claude.json +++ b/tests/fixtures/install-tree/claude.json @@ -432,6 +432,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-add-tests/SKILL.md", "skills/gsd-ai-integration-phase/SKILL.md", "skills/gsd-audit-fix/SKILL.md", diff --git a/tests/fixtures/install-tree/cline.json b/tests/fixtures/install-tree/cline.json index e644569c7..9061cad27 100644 --- a/tests/fixtures/install-tree/cline.json +++ b/tests/fixtures/install-tree/cline.json @@ -395,6 +395,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-ns-context/SKILL.md", "skills/gsd-ns-context/skills/docs-update/SKILL.md", "skills/gsd-ns-context/skills/extract-learnings/SKILL.md", diff --git a/tests/fixtures/install-tree/codebuddy.json b/tests/fixtures/install-tree/codebuddy.json index 451de0a20..80033205e 100644 --- a/tests/fixtures/install-tree/codebuddy.json +++ b/tests/fixtures/install-tree/codebuddy.json @@ -503,6 +503,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-add-tests/SKILL.md", "skills/gsd-ai-integration-phase/SKILL.md", "skills/gsd-audit-fix/SKILL.md", diff --git a/tests/fixtures/install-tree/codex.json b/tests/fixtures/install-tree/codex.json index 1a9deb7fc..33d634a39 100644 --- a/tests/fixtures/install-tree/codex.json +++ b/tests/fixtures/install-tree/codex.json @@ -433,5 +433,6 @@ "scripts/lib/allowlist-ratchet.cjs", "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", - "scripts/lib/exit-code-registry.cjs" + "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs" ] diff --git a/tests/fixtures/install-tree/copilot.json b/tests/fixtures/install-tree/copilot.json index 9a5a81d2d..a2dfc0a36 100644 --- a/tests/fixtures/install-tree/copilot.json +++ b/tests/fixtures/install-tree/copilot.json @@ -395,6 +395,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-add-tests/SKILL.md", "skills/gsd-ai-integration-phase/SKILL.md", "skills/gsd-audit-fix/SKILL.md", diff --git a/tests/fixtures/install-tree/cursor.json b/tests/fixtures/install-tree/cursor.json index 04021fb09..5f4870a96 100644 --- a/tests/fixtures/install-tree/cursor.json +++ b/tests/fixtures/install-tree/cursor.json @@ -406,6 +406,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-add-tests/SKILL.md", "skills/gsd-ai-integration-phase/SKILL.md", "skills/gsd-audit-fix/SKILL.md", diff --git a/tests/fixtures/install-tree/hermes.json b/tests/fixtures/install-tree/hermes.json index 9dbaaf556..9243a9537 100644 --- a/tests/fixtures/install-tree/hermes.json +++ b/tests/fixtures/install-tree/hermes.json @@ -432,6 +432,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd/DESCRIPTION.md", "skills/gsd/gsd-ns-context/SKILL.md", "skills/gsd/gsd-ns-context/skills/docs-update/SKILL.md", diff --git a/tests/fixtures/install-tree/kilo.json b/tests/fixtures/install-tree/kilo.json index 5dba68c68..d447453d7 100644 --- a/tests/fixtures/install-tree/kilo.json +++ b/tests/fixtures/install-tree/kilo.json @@ -506,6 +506,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-add-tests/SKILL.md", "skills/gsd-ai-integration-phase/SKILL.md", "skills/gsd-audit-fix/SKILL.md", diff --git a/tests/fixtures/install-tree/kimi-code.json b/tests/fixtures/install-tree/kimi-code.json index 9cc5918ec..9cd3a0c33 100644 --- a/tests/fixtures/install-tree/kimi-code.json +++ b/tests/fixtures/install-tree/kimi-code.json @@ -433,6 +433,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-add-tests/SKILL.md", "skills/gsd-ai-integration-phase/SKILL.md", "skills/gsd-audit-fix/SKILL.md", diff --git a/tests/fixtures/install-tree/kimi.json b/tests/fixtures/install-tree/kimi.json index 12301f844..8de8044da 100644 --- a/tests/fixtures/install-tree/kimi.json +++ b/tests/fixtures/install-tree/kimi.json @@ -430,6 +430,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-add-tests/SKILL.md", "skills/gsd-ai-integration-phase/SKILL.md", "skills/gsd-audit-fix/SKILL.md", diff --git a/tests/fixtures/install-tree/opencode.json b/tests/fixtures/install-tree/opencode.json index 4a06d99f2..b49094e86 100644 --- a/tests/fixtures/install-tree/opencode.json +++ b/tests/fixtures/install-tree/opencode.json @@ -506,6 +506,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-add-tests/SKILL.md", "skills/gsd-ai-integration-phase/SKILL.md", "skills/gsd-audit-fix/SKILL.md", diff --git a/tests/fixtures/install-tree/pi.json b/tests/fixtures/install-tree/pi.json index b8334ecc4..a178f40e4 100644 --- a/tests/fixtures/install-tree/pi.json +++ b/tests/fixtures/install-tree/pi.json @@ -398,5 +398,6 @@ "scripts/lib/allowlist-ratchet.cjs", "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", - "scripts/lib/exit-code-registry.cjs" + "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs" ] diff --git a/tests/fixtures/install-tree/qwen.json b/tests/fixtures/install-tree/qwen.json index 10c88e76d..323ed882c 100644 --- a/tests/fixtures/install-tree/qwen.json +++ b/tests/fixtures/install-tree/qwen.json @@ -432,6 +432,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-ns-context/SKILL.md", "skills/gsd-ns-context/skills/docs-update/SKILL.md", "skills/gsd-ns-context/skills/extract-learnings/SKILL.md", diff --git a/tests/fixtures/install-tree/trae.json b/tests/fixtures/install-tree/trae.json index 40e159155..027c10f81 100644 --- a/tests/fixtures/install-tree/trae.json +++ b/tests/fixtures/install-tree/trae.json @@ -393,6 +393,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-ns-context/SKILL.md", "skills/gsd-ns-context/skills/docs-update/SKILL.md", "skills/gsd-ns-context/skills/extract-learnings/SKILL.md", diff --git a/tests/fixtures/install-tree/windsurf.json b/tests/fixtures/install-tree/windsurf.json index 5cdaa1497..a6716c4e1 100644 --- a/tests/fixtures/install-tree/windsurf.json +++ b/tests/fixtures/install-tree/windsurf.json @@ -395,5 +395,6 @@ "scripts/lib/allowlist-ratchet.cjs", "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", - "scripts/lib/exit-code-registry.cjs" + "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs" ] diff --git a/tests/fixtures/install-tree/zcode.json b/tests/fixtures/install-tree/zcode.json index bc0bb4d56..943441131 100644 --- a/tests/fixtures/install-tree/zcode.json +++ b/tests/fixtures/install-tree/zcode.json @@ -464,6 +464,7 @@ "scripts/lib/cli-exit.cjs", "scripts/lib/drift-scan.cjs", "scripts/lib/exit-code-registry.cjs", + "scripts/lib/ndjson-reporter.cjs", "skills/gsd-ns-context/SKILL.md", "skills/gsd-ns-context/skills/docs-update/SKILL.md", "skills/gsd-ns-context/skills/extract-learnings/SKILL.md", From 0abd137ec741410a22784e04cf47037a143e63a7 Mon Sep 17 00:00:00 2001 From: sim Date: Fri, 28 Aug 2026 19:10:54 -0400 Subject: [PATCH 3/9] 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'); + }); +}); From 7f2af286392573faa2ad3c086cc7f91c9b1e6875 Mon Sep 17 00:00:00 2001 From: sim Date: Fri, 28 Aug 2026 19:20:11 -0400 Subject: [PATCH 4/9] fix(#4012): the reporter sink must be a regular file, not devNull MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Third failure on this feature, and this one broke everything rather than just the diagnostic: 43 failures across every run-tests.cjs invocation. Error: EINVAL: invalid argument, fsync Emitted 'error' event on WriteStream instance Node opens a WriteStream for a --test-reporter-destination and FSYNCS it on close. fsync on /dev/null is EINVAL — it is a character device, not a regular file. So os.devNull is not a usable reporter destination at all, and every chunk crashed on exit. The sink only ever needed to be a regular file that stays empty, since the reporter writes its real output through appendFileSync to the path in GSD_RUN_TESTS_EVENTS_FILE. It is now one fixed file inside the existing events dir, pre-created rather than relying on the stream's create-on-open, and left empty by design. One sink for the whole run, not per chunk, so its path length stays constant — reporterOverhead feeds FIXED_OVERHEAD, which is computed once before chunking, and a variable-length path would silently mis-account the Windows argv ceiling. The comment that named devNull now says why the destination must be a regular file, so this does not get re-optimized back into the same crash. Reaching for devNull was the mistake: it looks like the obviously correct way to discard output, and it is, for a pipe or an fd — but not for something Node is going to fsync. Each of the three failures on this feature was a different edge of the same assumption, that a reporter destination behaves like ordinary output. The regression test asserts the closest externally observable consequence — a normal run must not surface the EINVAL/fsync text. The argv construction lives inside main() with no exported seam, and the sink is swept before a test could stat it; adding a seam purely to assert that is left out rather than reshaping production code for the test. Stated plainly rather than implied. The failing T1 is untouched and still red. Verification runs on the remote runner. Refs #4012 --- scripts/run-tests.cjs | 19 ++++++++++++++++--- tests/run-tests-harness.test.cjs | 25 +++++++++++++++++++++++++ 2 files changed, 41 insertions(+), 3 deletions(-) diff --git a/scripts/run-tests.cjs b/scripts/run-tests.cjs index 83f715ccb..2828dc205 100644 --- a/scripts/run-tests.cjs +++ b/scripts/run-tests.cjs @@ -35,9 +35,9 @@ // See docs/TESTING-SUITES.md for full grouping policy. 'use strict'; -const { readdirSync, readFileSync, mkdtempSync, rmSync, unlinkSync } = require('fs'); +const { readdirSync, readFileSync, mkdtempSync, rmSync, unlinkSync, writeFileSync } = require('fs'); const { join, basename } = require('path'); -const { tmpdir, devNull } = require('os'); +const { tmpdir } = require('os'); const { execFileSync } = require('child_process'); const { ExitError, runMain } = require('./lib/cli-exit.cjs'); const { @@ -1079,11 +1079,24 @@ function main() { // (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. + // + // The ndjson reporter yields nothing and ignores its own destination — the + // durable write path is GSD_RUN_TESTS_EVENTS_FILE above — but Node still + // opens this destination as a real fs.WriteStream and fsyncs it on close, + // so it MUST be a regular file. os.devNull (a character device on every + // platform) fails that fsync with EINVAL, crashing every chunk, not just + // the timeout path (confirmed live: 43/43 chunk failures, "EINVAL: invalid + // argument, fsync" on WriteStream close). Do not re-point this at devNull — + // it is the ONE destination flavor this feature cannot use. Pre-created + // once, alongside eventsDir, so it stays empty and its path length is + // identical across every chunk (see FIXED_OVERHEAD below). + const reporterSinkPath = join(eventsDir, 'reporter-sink.txt'); + writeFileSync(reporterSinkPath, ''); const reporterArgs = [ `--test-reporter=${humanReporter}`, '--test-reporter-destination=stdout', `--test-reporter=${reporterModulePath}`, - `--test-reporter-destination=${devNull}`, + `--test-reporter-destination=${reporterSinkPath}`, ]; const reporterOverhead = reporterArgs.reduce((sum, a) => sum + a.length + 1, 0); diff --git a/tests/run-tests-harness.test.cjs b/tests/run-tests-harness.test.cjs index 37a34417c..68d856bfc 100644 --- a/tests/run-tests-harness.test.cjs +++ b/tests/run-tests-harness.test.cjs @@ -852,6 +852,31 @@ test('noop', () => {}); ); }); + // T5 (regression): the human reporter's --test-reporter-destination + // pairing must be a regular file, not os.devNull. devNull is a character + // device; Node opens the reporter destination as an fs.WriteStream and + // fsyncs it on close, and fsync on a character device fails with EINVAL + // — surfaced as "Emitted 'error' event on WriteStream instance" / + // "EINVAL: invalid argument, fsync", which crashed EVERY chunk on the + // real remote run this regresses (43/43 failures), not only the timeout + // path. The argv construction lives entirely inside main() with no + // exported seam to unit-test directly (see NOTES), so this asserts the + // closest real, externally-observable consequence: a normal successful + // run must not surface that error text, and must still complete and + // exit 0 — both of which a reintroduced devNull destination would break + // on any platform where fsync(devNull) actually returns EINVAL (this + // suite's own bench platform, historically). + test('a successful run never surfaces the devNull fsync/EINVAL reporter crash', () => { + seed(tmpDir, ['a.test.cjs']); + const r = runHarness(tmpDir, []); + assert.strictEqual(r.status, 0, `expected a clean pass; STDERR:\n${r.stderr}`); + assert.doesNotMatch( + r.stderr, + /EINVAL|invalid argument, fsync|WriteStream instance/i, + `expected no reporter-destination fsync crash; STDERR:\n${r.stderr}`, + ); + }); + // T1: on a chunk timeout, the diagnostic must NAME the file that was // still executing — not merely list every file the chunk contained (the // pre-instrumentation behavior). A test that hangs INSIDE its own body From 5504724d7a85024b84398d227180ce38cb3b55dd Mon Sep 17 00:00:00 2001 From: sim Date: Fri, 28 Aug 2026 19:29:51 -0400 Subject: [PATCH 5/9] fix(#4012): the reporter body must return nully, not an iterable MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Fourth failure on this feature, and this one was caused by the previous fix's lint workaround. TypeError [ERR_INVALID_RETURN_VALUE]: Expected nully to be returned from the "body" function but got an instance of Array. When stream.compose is given an async FUNCTION as the body, that function must return nully. The reporter ended with 'return []' under a comment asserting Node "still requires the exported function to return an iterable" — exactly backwards, and the direct cause of 41 failures across every run-tests.cjs invocation. That return existed only to dodge ESLint's require-yield after the previous commit converted async function* to async function. A lint workaround became a runtime crash, and the comment written to justify it stated the opposite of the contract. Both are now corrected to what the runtime actually does. Verified by EXECUTION rather than by reading: composing the real reporter against a fake event stream completes with no error and leaves both handled events durably on disk, with the ignored event type skipped. The failing form was reproduced the same way first, so the diagnosis is not inferred from the stack trace alone. The new unit test requires the reporter directly and asserts the returned value is nully — the assertion that would have caught this before it reached the runner — plus the exact NDJSON written. No subprocess, so this half of the feature is verifiable without a full runner pass, which matters because every defect in this feature so far has only been observable remotely. T1 remains untouched and red. Verification runs on the remote runner. Refs #4012 --- scripts/lib/ndjson-reporter.cjs | 31 ++++++++++++++-------- tests/run-tests-harness.test.cjs | 45 ++++++++++++++++++++++++++++++++ 2 files changed, 65 insertions(+), 11 deletions(-) diff --git a/scripts/lib/ndjson-reporter.cjs b/scripts/lib/ndjson-reporter.cjs index fcc3f7663..dba6c2348 100644 --- a/scripts/lib/ndjson-reporter.cjs +++ b/scripts/lib/ndjson-reporter.cjs @@ -34,13 +34,20 @@ // 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 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. +// AsyncIterable of `{ type, data }` objects). Node feeds that function to +// `stream.compose` as the stream's "body". When the body is an async +// FUNCTION (not an `async function*` generator), `stream.compose`'s own +// contract (https://nodejs.org/api/stream.html#streamcomposestreams) +// requires it to return nully (undefined/null) — returning anything else, +// including an array, throws `ERR_INVALID_RETURN_VALUE` ("Expected nully to +// be returned from the 'body' function but got an instance of Array") +// exactly once the promise resolves. Verified directly against +// `stream.compose` in this repo's Node: calling it with a body that +// `return`s `[]` reproduces that same TypeError. A generator form +// (`async function*`) is the one that yields an iterable; the plain +// `async function` form used here is the one that must return nully. This +// 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, @@ -74,8 +81,10 @@ module.exports = async function ndjsonEventReporter(source) { } } } - // 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 []; + // Falls through to an implicit `return undefined` (nully): this reporter is + // a pure side-effecting sink (see the durability note above), never a + // source of reporter OUTPUT, and `stream.compose` requires its async + // FUNCTION body to return nully — returning an iterable (e.g. `[]`) here + // raises `ERR_INVALID_RETURN_VALUE` (observed live: this exact `return []` + // crashed every chunk on the real remote run this regresses). }; diff --git a/tests/run-tests-harness.test.cjs b/tests/run-tests-harness.test.cjs index 68d856bfc..7b4d42ddf 100644 --- a/tests/run-tests-harness.test.cjs +++ b/tests/run-tests-harness.test.cjs @@ -24,6 +24,7 @@ const path = require('path'); const { runNode } = require('./helpers/process-seam.cjs'); const { toLegacyResult } = require('./helpers/git-fixture.cjs'); const { createTempDir, cleanup, CONFIG_LOCATION_ENV_KEYS } = require('./helpers.cjs'); +const { splitLines } = require('../gsd-core/bin/lib/text-lines.cjs'); const HARNESS = path.join(__dirname, '..', 'scripts', 'run-tests.cjs'); @@ -905,6 +906,50 @@ test('hangs forever', () => new Promise(() => {})); ); }); + // Regression (#3889 recurrence): the reporter module itself, called + // directly with no subprocess, must return nully — this is the exact + // contract violation (`return []`) that crashed every chunk on the real + // remote run this file regresses ("Expected nully to be returned from + // the 'body' function but got an instance of Array", thrown by + // node:stream's `compose` when its async-function body returns an + // iterable instead of undefined/null). Also pins the NDJSON side effect: + // only the two handled event types are appended, verbatim, one per line. + test('the reporter returns nully and appends only the handled event types as NDJSON', async () => { + const reporter = require('../scripts/lib/ndjson-reporter.cjs'); + const eventsFile = path.join(tmpDir, 'ndjson-reporter-events.ndjson'); + const savedEventsFile = process.env.GSD_RUN_TESTS_EVENTS_FILE; + process.env.GSD_RUN_TESTS_EVENTS_FILE = eventsFile; + try { + async function* fakeEvents() { + yield { type: 'test:start', data: { file: 'a.test.cjs', name: 't', nesting: 0, testNumber: 1 } }; + yield { type: 'test:diagnostic', data: { message: 'ignored' } }; + yield { type: 'test:pass', data: { file: 'a.test.cjs', name: 't', nesting: 0, testNumber: 1 } }; + } + const result = await reporter(fakeEvents()); + assert.strictEqual( + result ?? null, + null, + `expected the reporter to return nully (undefined/null) per stream.compose's ` + + `async-function body contract; got ${JSON.stringify(result)}`, + ); + const rawContent = fs.readFileSync(eventsFile, 'utf8'); + const lines = splitLines(rawContent.trim()).filter((l) => l.length > 0); + assert.strictEqual(lines.length, 2, `expected exactly 2 NDJSON lines; got:\n${lines.join('\n')}`); + const [start, pass] = lines.map((l) => JSON.parse(l)); + assert.strictEqual(start.type, 'test:start'); + assert.strictEqual(start.file, 'a.test.cjs'); + assert.strictEqual(pass.type, 'test:pass'); + assert.strictEqual(pass.file, 'a.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); + } + }); + // T4: the pre-existing timeout / abort / force-exit behavior (#1051) // still holds with the reporter instrumentation wired in — the new // --test-reporter flags must not change detection, the abort-on-timeout From 444137e63abbfe1a6df350bc568325000e8a0006 Mon Sep 17 00:00:00 2001 From: sim Date: Fri, 28 Aug 2026 19:41:32 -0400 Subject: [PATCH 6/9] fix(#4012): make the artifact say whether the reporter ever loaded MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Down to 3 remote failures, all one chain. The explicit no-events reporting is working — the diagnostic now states the events file does not exist, instead of silently printing the generic message. But it then ASSERTED a cause: "the child was killed before the reporter wrote even one event (process/spawn startup stall, not a test hang)". That was a guess dressed as a finding, and the fixture contradicts it: it starts a real test, so test:start should fire in milliseconds against a 2000ms budget. Two hypotheses remained and I could not separate them locally, because the local test runner is hook-blocked here: either the custom reporter never LOADS in the child, or it loads and no event reaches it before the SIGKILL. Rather than guess a third time, the artifact now answers it. The reporter appends a reporter:init line as its first action, before consuming anything, so the file's contents discriminate: absent means the reporter never loaded; init-only means it loaded and saw no test events; init plus events means it works. The diagnostic has a branch for each and, where the cause is genuinely unresolved, names both possibilities instead of picking one. Also passes the reporter as a file:// URL via pathToFileURL. Node documents the --test-reporter value as an import()-style specifier, and a bare absolute path is not a portable one — notably on Windows. That is a correctness fix whichever hypothesis holds, and it is a live candidate for the first. FIXED_OVERHEAD is derived by reducing over the actual argv strings, so the longer URL is accounted automatically. Verified by execution, not assumption: composing the reporter against an EMPTY event stream writes exactly one line, the init marker. That is the whole point of the marker, so it is pinned by a test rather than left to inspection. T1 stays red and untouched. Verification runs on the remote runner. Refs #4012 --- scripts/lib/ndjson-reporter.cjs | 17 ++++++++ scripts/run-tests.cjs | 68 ++++++++++++++++++++++++-------- tests/run-tests-harness.test.cjs | 44 ++++++++++++++++++++- 3 files changed, 110 insertions(+), 19 deletions(-) diff --git a/scripts/lib/ndjson-reporter.cjs b/scripts/lib/ndjson-reporter.cjs index dba6c2348..a06e03cd6 100644 --- a/scripts/lib/ndjson-reporter.cjs +++ b/scripts/lib/ndjson-reporter.cjs @@ -57,6 +57,23 @@ // 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 + // the `for await` loop even begins consuming the event stream — so the + // events file's mere existence (and its exact contents) can distinguish + // "the reporter module never loaded in the child at all" (file absent) + // from "it loaded fine but no test:start reached it before the kill" + // (file contains only this one line) from "it's working" (file contains + // more than this line). Same appendFileSync durability rationale as every + // other write in this file: synchronous and unbuffered, so it survives an + // uncatchable SIGKILL landing a moment later. + if (eventsPath) { + try { + require('fs').appendFileSync(eventsPath, `${JSON.stringify({ type: 'reporter:init', ts: Date.now() })}\n`); + } catch { + // Best-effort, same as every other write below — must never crash the + // test run this reporter is only observing. + } + } for await (const event of source) { if (!eventsPath) continue; // no destination configured — nothing to record if ( diff --git a/scripts/run-tests.cjs b/scripts/run-tests.cjs index 2828dc205..ff2863c63 100644 --- a/scripts/run-tests.cjs +++ b/scripts/run-tests.cjs @@ -38,6 +38,7 @@ const { readdirSync, readFileSync, mkdtempSync, rmSync, unlinkSync, writeFileSync } = require('fs'); const { join, basename } = require('path'); const { tmpdir } = require('os'); +const { pathToFileURL } = require('url'); const { execFileSync } = require('child_process'); const { ExitError, runMain } = require('./lib/cli-exit.cjs'); const { @@ -702,15 +703,20 @@ function analyzeChunkEvents(eventsPath) { raw = readFileSync(eventsPath, 'utf8'); } catch { // 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 }; + // resolved to a writable path, or the reporter module never loaded in the + // child at all (the `reporter:init` marker below is the reporter's very + // 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 + // 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 }; } const inFlight = new Map(); let lastTs = null; + let sawInitMarker = false; + let sawAnyEvent = false; for (const line of raw.split('\n')) { if (line.trim() === '') continue; let evt; @@ -720,6 +726,11 @@ function analyzeChunkEvents(eventsPath) { continue; // truncated trailing line from a mid-write kill } if (typeof evt.ts === 'number') lastTs = evt.ts; + if (evt.type === 'reporter:init') { + sawInitMarker = true; + 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}`; @@ -733,7 +744,8 @@ function analyzeChunkEvents(eventsPath) { return { files, staleMs: lastTs !== null ? Date.now() - lastTs : null, - sawAnyEvent: lastTs !== null, + sawAnyEvent, + sawInitMarker, readError: false, }; } @@ -1067,7 +1079,18 @@ function main() { // 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'); + // #3889: Node documents `--test-reporter`'s value as "a string similar to + // those used in import() statements" (https://nodejs.org/api/test.html#--test-reporter), + // NOT a bare filesystem path — a bare absolute path is not a portable + // import specifier (notably on Windows, where `C:\...` is not valid + // import()able syntax). Converting through pathToFileURL is the fix that + // hardens reporter resolution against a possible root cause of #3889: the + // events file never being created at all because the reporter module + // itself never loaded in the child. This makes the resulting string + // LONGER than the bare path, which is why reporterOverhead/FIXED_OVERHEAD + // below are derived from the final reporterArgs strings, not a literal + // constant — they must reflect whatever this line actually produces. + const reporterModulePath = pathToFileURL(join(__dirname, 'lib', 'ndjson-reporter.cjs')).href; const humanReporter = process.stdout.isTTY ? 'spec' : 'tap'; // 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 @@ -1199,7 +1222,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, readError } = analyzeChunkEvents(chunkEventsPath); + const { files: inFlightFiles, staleMs, sawAnyEvent, sawInitMarker, 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 ` + @@ -1212,14 +1235,25 @@ function main() { `diagnostic); suspect a leaked handle outside any single test, or an ` + `after-tests hook.` : 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.`; + ? `THE EVENTS FILE DOES NOT EXIST for this chunk — not even the reporter's own ` + + `\`reporter:init\` marker, which is the reporter module's first action before ` + + `it reads a single test event. Two possible causes, NOT distinguished by this ` + + `diagnostic: the ndjson reporter module never loaded in the child at all ` + + `(--test-reporter resolution failure), or the child was killed before the ` + + `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.` + : `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 ` + + `completed. 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'); diff --git a/tests/run-tests-harness.test.cjs b/tests/run-tests-harness.test.cjs index 7b4d42ddf..57b582aea 100644 --- a/tests/run-tests-harness.test.cjs +++ b/tests/run-tests-harness.test.cjs @@ -934,8 +934,9 @@ test('hangs forever', () => new Promise(() => {})); ); const rawContent = fs.readFileSync(eventsFile, 'utf8'); const lines = splitLines(rawContent.trim()).filter((l) => l.length > 0); - assert.strictEqual(lines.length, 2, `expected exactly 2 NDJSON lines; got:\n${lines.join('\n')}`); - const [start, pass] = lines.map((l) => JSON.parse(l)); + assert.strictEqual(lines.length, 3, `expected exactly 3 NDJSON lines (init marker + 2 handled events); got:\n${lines.join('\n')}`); + const [init, start, pass] = lines.map((l) => JSON.parse(l)); + assert.strictEqual(init.type, 'reporter:init'); assert.strictEqual(start.type, 'test:start'); assert.strictEqual(start.file, 'a.test.cjs'); assert.strictEqual(pass.type, 'test:pass'); @@ -950,6 +951,45 @@ test('hangs forever', () => new Promise(() => {})); } }); + // #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 + // before node:test emits anything). This pins the marker's whole + // purpose: its presence alone proves the reporter module loaded and was + // invoked, independent of whether any test ever started. + test('the reporter writes only the init marker when the source yields zero events', async () => { + const reporter = require('../scripts/lib/ndjson-reporter.cjs'); + const eventsFile = path.join(tmpDir, 'ndjson-reporter-init-only.ndjson'); + const savedEventsFile = process.env.GSD_RUN_TESTS_EVENTS_FILE; + process.env.GSD_RUN_TESTS_EVENTS_FILE = eventsFile; + try { + async function* emptyEvents() {} + const result = await reporter(emptyEvents()); + assert.strictEqual( + result ?? null, + null, + `expected the reporter to return nully even with zero source events; got ${JSON.stringify(result)}`, + ); + const rawContent = fs.readFileSync(eventsFile, 'utf8'); + const lines = splitLines(rawContent.trim()).filter((l) => l.length > 0); + assert.strictEqual( + lines.length, + 1, + `expected exactly 1 NDJSON line (the init marker only); got:\n${lines.join('\n')}`, + ); + const [init] = lines.map((l) => JSON.parse(l)); + assert.strictEqual(init.type, 'reporter:init'); + assert.strictEqual(typeof init.ts, 'number'); + } finally { + if (savedEventsFile === undefined) { + delete process.env.GSD_RUN_TESTS_EVENTS_FILE; + } else { + process.env.GSD_RUN_TESTS_EVENTS_FILE = savedEventsFile; + } + cleanup(eventsFile); + } + }); + // T4: the pre-existing timeout / abort / force-exit behavior (#1051) // still holds with the reporter instrumentation wired in — the new // --test-reporter flags must not change detection, the abort-on-timeout From bf8905fcc98bea8303965a5b60e0060d3196b5ad Mon Sep 17 00:00:00 2001 From: sim Date: Fri, 28 Aug 2026 19:52:57 -0400 Subject: [PATCH 7/9] fix(#4012): a hang never emits the events I was listening for MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The init marker settled it. The diagnostic reported "THE REPORTER LOADED BUT RECORDED NO TEST EVENTS — the events file contains only the reporter's own reporter:init marker", which refutes the reporter-never-loaded hypothesis and leaves exactly one explanation. The runner spawns a child process per test file and surfaces a subtest's test:start / test:pass / test:fail to the parent's reporter only once the child REPORTS that test — which happens when it completes. The fixture hangs forever, so it never completes, so it never reports. I had recorded exactly those three event types: the precise set that a hang guarantees you will never see. The feature could not have worked for the case it was built for. test:enqueue and test:dequeue are emitted by the runner as it queues and begins each file, independent of anything inside finishing. test:dequeue is what actually means "in flight", and it is now the primary signal, with test:start kept as a secondary one. A file is in flight when it has been dequeued and has no terminal event. The four branches now describe states that are all real: the events file absent (reporter never loaded); the init marker alone (the runner dequeued nothing at all — genuinely surprising now rather than the expected outcome); everything dequeued and terminated (the files finished and the process hung afterwards, a handle leak); and one or more dequeued-but-unterminated files, named, which is the case this whole feature exists to report. Verified against the exact shape the real hang produces, by executing analyzeChunkEvents on a synthetic events file: init + enqueue + dequeue with no terminal event reports hangs.test.cjs as in flight, and appending a test:pass clears it. Four more unit tests cover the ordering and multi-file cases with no subprocess, so this logic is now checkable without a runner round-trip — which matters, because every defect in this feature so far was visible only remotely. T1 is untouched and should now pass for the right reason. Verification runs on the remote runner. Refs #4012 --- scripts/lib/ndjson-reporter.cjs | 26 ++++++-- scripts/run-tests.cjs | 94 ++++++++++++++++++--------- tests/run-tests-harness.test.cjs | 107 +++++++++++++++++++++++++++++++ 3 files changed, 191 insertions(+), 36 deletions(-) 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); + }); }); From d1d6c82a0fcf155ef4b84c30b8b196dd2817e211 Mon Sep 17 00:00:00 2001 From: sim Date: Fri, 28 Aug 2026 20:00:09 -0400 Subject: [PATCH 8/9] chore(#4012): backfill changeset pr number to 4015 --- .changeset/proud-sloths-cheer.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.changeset/proud-sloths-cheer.md b/.changeset/proud-sloths-cheer.md index af15ab35f..c72d65a92 100644 --- a/.changeset/proud-sloths-cheer.md +++ b/.changeset/proud-sloths-cheer.md @@ -1,5 +1,5 @@ --- type: Fixed -pr: 0 +pr: 4015 --- **A killed test chunk now names the file that was hanging.** `scripts/run-tests.cjs` logged only chunk starts, so a chunk killed at the 600s cap printed ~55 basenames and left the operator to guess which one hung — and every timing figure had to be reconstructed from CI log timestamps. It now emits per-chunk elapsed time on every path, names the files still in flight on a kill with how stale the last event is (hang vs. merely slow), and ranks the chunk by known weight, flagging files missing from the timings table. (#4012) From c1a2c33886ed4e0d394a09e1828f42fb8018b29b Mon Sep 17 00:00:00 2001 From: sim Date: Sat, 29 Aug 2026 01:01:36 -0400 Subject: [PATCH 9/9] perf(#4012): two subprocess spawns, not five MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit My instrumentation suite tipped ubuntu shard 1/3 over its 15-minute job cap. Measured, not guessed: baseline on next (c8f08b61f) passed that shard in 14m21s — 39 seconds of headroom — and the chunk-timeout instrumentation suite I added costs 31,621ms, about 80% of what was left. The job ran 15m09s and GitHub reported the cap as a cancel, which failed the required-tests rollup. Cause is spawn count, not test content. The suite booted scripts/run-tests.cjs five separate times — three success-path, two timeout-path — and each boot globs the suite and spawns node --test children before any assertion runs. The direct-require tests beside it cost milliseconds. Now two spawns: one success run backing the elapsed-timing, temp-dir-non-leak and no-EINVAL assertions, and one timeout run backing the in-flight-file naming and the diagnostic wording. Every assertion is kept verbatim; only the per-assertion subprocess boot is gone. Modelling per-boot overhead from the measured total puts the saving around 18s, but that is an estimate derived from one data point, not a measurement — the real number comes from CI. The chunk timeout stays at 2000ms. It is already the lowest value used anywhere in this file, and lowering it further would race a loaded CI box that has to boot node --test, register the hang, and observe the kill inside the window. Worth recording separately: that lane has 39 seconds of margin on next, so it is one cliff away from this happening to whoever adds the next test. The per-chunk timing this PR adds is what made the attribution possible at all — chunk 1/5 alone is 263s of a 900s budget, which was previously invisible. Verification runs on the remote runner. Refs #4012 --- tests/run-tests-harness.test.cjs | 114 +++++++++++++++++++------------ 1 file changed, 70 insertions(+), 44 deletions(-) diff --git a/tests/run-tests-harness.test.cjs b/tests/run-tests-harness.test.cjs index 9a2eb529c..aeadca169 100644 --- a/tests/run-tests-harness.test.cjs +++ b/tests/run-tests-harness.test.cjs @@ -16,7 +16,7 @@ 'use strict'; -const { describe, test, beforeEach, afterEach } = require('node:test'); +const { describe, test, before, after, beforeEach, afterEach } = require('node:test'); const assert = require('node:assert/strict'); const fs = require('fs'); const path = require('path'); @@ -817,17 +817,65 @@ test('noop', () => {}); }); describe('chunk-timeout instrumentation (#3889)', () => { + // Consolidation (CI cost, #4015): this describe block used to spawn the + // harness once PER assertion group (3 success-path runs + 2 timeout-path + // runs = 5 subprocess boots). Each boot is expensive — run-tests.cjs + // starts, globs the suite, then spawns `node --test` children — so on a + // CI shard already within ~39s of its 15-minute cap, paying for 5 boots + // to check facts that all hold against the SAME run is wasted spend. + // Below, exactly ONE successful run and ONE timed-out run are captured + // once (via `before`) and every assertion group below reads from those + // captured results instead of spawning its own. This is the whole + // savings — no assertion is weakened or removed. + const HANGS_FOREVER_BODY = `'use strict'; +const { test } = require('node:test'); +test('hangs forever', () => new Promise(() => {})); +`; + + let successDir; + let successRun; + let eventsDirBefore; + let eventsDirAfter; + let timeoutDir; + let timeoutRun; + + before(() => { + // Single SUCCESS-path run, reused by T2/T3/T5 below. + successDir = createTempDir('gsd-3889-success-'); + seed(successDir, ['a.test.cjs']); + eventsDirBefore = fs.readdirSync(require('os').tmpdir()) + .filter((n) => n.startsWith('gsd-run-tests-events-')); + successRun = runHarness(successDir, []); + eventsDirAfter = fs.readdirSync(require('os').tmpdir()) + .filter((n) => n.startsWith('gsd-run-tests-events-')); + + // Single TIMEOUT-path run, reused by T1/T4 below. 2000ms is kept — + // it is already the smallest value this suite used anywhere for the + // per-chunk timeout, and going lower risks flaking on a loaded CI + // box that has to boot node --test, register the hang, and observe + // the kill inside the window. + timeoutDir = createTempDir('gsd-3889-timeout-'); + fs.writeFileSync(path.join(timeoutDir, 'hangs.test.cjs'), HANGS_FOREVER_BODY, 'utf8'); + timeoutRun = runHarness(timeoutDir, [], { + RUN_TESTS_NO_FORCE_EXIT: '1', + RUN_TESTS_CHUNK_TIMEOUT_MS: '2000', + }); + }); + + after(() => { + cleanup(successDir); + cleanup(timeoutDir); + }); + // T2: per-chunk elapsed timing appears on the normal SUCCESS path, not // only when something goes wrong — this is what makes "which chunk is // drifting toward the cap" readable across ordinary green runs. test('a successful chunk prints its elapsed time', () => { - seed(tmpDir, ['a.test.cjs']); - const r = runHarness(tmpDir, []); - assert.strictEqual(r.status, 0, `expected a clean pass; STDERR:\n${r.stderr}`); + assert.strictEqual(successRun.status, 0, `expected a clean pass; STDERR:\n${successRun.stderr}`); assert.match( - r.stderr, + successRun.stderr, /run-tests: chunk 1\/1 completed in \d+ms/, - `expected a per-chunk completion timing line; STDERR:\n${r.stderr}`, + `expected a per-chunk completion timing line; STDERR:\n${successRun.stderr}`, ); }); @@ -838,18 +886,12 @@ test('noop', () => {}); // prefix) rather than any run-tests-owned directory, since that IS the // leak surface being guarded. test('the ndjson reporter temp dir is cleaned up after a successful run', () => { - seed(tmpDir, ['a.test.cjs']); - const before = fs.readdirSync(require('os').tmpdir()) - .filter((n) => n.startsWith('gsd-run-tests-events-')); - const r = runHarness(tmpDir, []); - assert.strictEqual(r.status, 0, `expected a clean pass; STDERR:\n${r.stderr}`); - const after = fs.readdirSync(require('os').tmpdir()) - .filter((n) => n.startsWith('gsd-run-tests-events-')); + assert.strictEqual(successRun.status, 0, `expected a clean pass; STDERR:\n${successRun.stderr}`); assert.deepStrictEqual( - after, - before, + eventsDirAfter, + eventsDirBefore, `expected no leaked gsd-run-tests-events-* temp dir after a successful run; ` + - `before=${JSON.stringify(before)} after=${JSON.stringify(after)}`, + `before=${JSON.stringify(eventsDirBefore)} after=${JSON.stringify(eventsDirAfter)}`, ); }); @@ -868,13 +910,11 @@ test('noop', () => {}); // on any platform where fsync(devNull) actually returns EINVAL (this // suite's own bench platform, historically). test('a successful run never surfaces the devNull fsync/EINVAL reporter crash', () => { - seed(tmpDir, ['a.test.cjs']); - const r = runHarness(tmpDir, []); - assert.strictEqual(r.status, 0, `expected a clean pass; STDERR:\n${r.stderr}`); + assert.strictEqual(successRun.status, 0, `expected a clean pass; STDERR:\n${successRun.stderr}`); assert.doesNotMatch( - r.stderr, + successRun.stderr, /EINVAL|invalid argument, fsync|WriteStream instance/i, - `expected no reporter-destination fsync crash; STDERR:\n${r.stderr}`, + `expected no reporter-destination fsync crash; STDERR:\n${successRun.stderr}`, ); }); @@ -884,25 +924,16 @@ test('noop', () => {}); // (never resolving) keeps its test:start event unmatched by any // test:pass/test:fail in the ndjson companion reporter's output, which // is exactly the signal the diagnostic reads back on timeout. - const HANGS_FOREVER_BODY = `'use strict'; -const { test } = require('node:test'); -test('hangs forever', () => new Promise(() => {})); -`; test('a chunk timeout names the file that was in flight when killed', () => { - fs.writeFileSync(path.join(tmpDir, 'hangs.test.cjs'), HANGS_FOREVER_BODY, 'utf8'); - const r = runHarness(tmpDir, [], { - RUN_TESTS_NO_FORCE_EXIT: '1', - RUN_TESTS_CHUNK_TIMEOUT_MS: '2000', - }); assert.notStrictEqual( - r.status, + timeoutRun.status, 0, - `expected non-zero exit from a timed-out chunk; got status=${r.status}\nSTDERR:\n${r.stderr}`, + `expected non-zero exit from a timed-out chunk; got status=${timeoutRun.status}\nSTDERR:\n${timeoutRun.stderr}`, ); assert.match( - r.stderr, + timeoutRun.stderr, /In flight when killed.*hangs\.test\.cjs/s, - `expected the diagnostic to NAME the in-flight file, not just list the chunk; STDERR:\n${r.stderr}`, + `expected the diagnostic to NAME the in-flight file, not just list the chunk; STDERR:\n${timeoutRun.stderr}`, ); }); @@ -1039,21 +1070,16 @@ test('hangs forever', () => new Promise(() => {})); // --test-reporter flags must not change detection, the abort-on-timeout // control flow, or the exit code. test('existing timeout diagnostic and abort behavior are unchanged', () => { - fs.writeFileSync(path.join(tmpDir, 'hangs.test.cjs'), HANGS_FOREVER_BODY, 'utf8'); - const r = runHarness(tmpDir, [], { - RUN_TESTS_NO_FORCE_EXIT: '1', - RUN_TESTS_CHUNK_TIMEOUT_MS: '2000', - }); - assert.notStrictEqual(r.status, 0, `expected non-zero exit; STDERR:\n${r.stderr}`); + assert.notStrictEqual(timeoutRun.status, 0, `expected non-zero exit; STDERR:\n${timeoutRun.stderr}`); assert.match( - r.stderr, + timeoutRun.stderr, /exceeded the per-chunk timeout/, - `expected the original timeout diagnostic wording to survive; STDERR:\n${r.stderr}`, + `expected the original timeout diagnostic wording to survive; STDERR:\n${timeoutRun.stderr}`, ); assert.match( - r.stderr, + timeoutRun.stderr, /run-tests: chunk 1\/1 was killed after \d+ms/, - `expected the new killed/elapsed line; STDERR:\n${r.stderr}`, + `expected the new killed/elapsed line; STDERR:\n${timeoutRun.stderr}`, ); }); });