diff --git a/.changeset/proud-sloths-cheer.md b/.changeset/proud-sloths-cheer.md new file mode 100644 index 000000000..c72d65a92 --- /dev/null +++ b/.changeset/proud-sloths-cheer.md @@ -0,0 +1,5 @@ +--- +type: Fixed +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) diff --git a/bin/install.js b/bin/install.js index 62fa3da5a..c9311d08d 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 new file mode 100644 index 000000000..6f48de57d --- /dev/null +++ b/scripts/lib/ndjson-reporter.cjs @@ -0,0 +1,119 @@ +'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` 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: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 +// `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). 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 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 + // 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 ( + event.type === 'test:enqueue' || + event.type === 'test:dequeue' || + event.type === 'test:start' || + event.type === 'test:pass' || + event.type === 'test:fail' + ) { + const { file, name, nesting, testNumber } = event.data || {}; + const line = `${JSON.stringify({ + type: event.type, + file, + name, + nesting, + 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. + } + } + } + // 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/scripts/run-tests.cjs b/scripts/run-tests.cjs index 476ad6bf0..4541f80e7 100644 --- a/scripts/run-tests.cjs +++ b/scripts/run-tests.cjs @@ -35,8 +35,10 @@ // See docs/TESTING-SUITES.md for full grouping policy. 'use strict'; -const { readdirSync, readFileSync } = require('fs'); +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 { @@ -682,6 +684,117 @@ 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: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 +// 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 { + // The events file never existed — either GSD_RUN_TESTS_EVENTS_FILE never + // 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, 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, + anyDequeued: false, + readError: true, + }; + } + // 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; + 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; + if (evt.type === 'reporter:init') { + sawInitMarker = true; + continue; // not a test event — never tracked in inFlight, never proof a test ran + } + sawAnyEvent = true; + 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 = [...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, + }; +} + +// #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 +1073,83 @@ 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, 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 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-')); + // #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 + // 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`); + // 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. + // + // 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=${reporterSinkPath}`, + ]; + 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, { weightOf: fileWeightOf(), maxWeight: MAX_FILES_PER_CHUNK, @@ -970,9 +1159,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 +1203,107 @@ 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, + ...reporterArgs, + ...chunks[i], + ], { stdio: 'inherit', - env: { ...process.env }, + env: { ...process.env, GSD_RUN_TESTS_EVENTS_FILE: chunkEventsPath }, 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, + sawInitMarker, + anyDequeued, + readError, + } = analyzeChunkEvents(chunkEventsPath); + const inFlightMsg = inFlightFiles.length > 0 + ? `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).` + : 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 + ? `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 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 ` + + `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'); + 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 +1338,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. @@ -1098,6 +1384,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/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", diff --git a/tests/run-tests-harness.test.cjs b/tests/run-tests-harness.test.cjs index 100886070..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'); @@ -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'); @@ -814,6 +815,274 @@ 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', () => { + assert.strictEqual(successRun.status, 0, `expected a clean pass; STDERR:\n${successRun.stderr}`); + assert.match( + successRun.stderr, + /run-tests: chunk 1\/1 completed in \d+ms/, + `expected a per-chunk completion timing line; STDERR:\n${successRun.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', () => { + assert.strictEqual(successRun.status, 0, `expected a clean pass; STDERR:\n${successRun.stderr}`); + assert.deepStrictEqual( + eventsDirAfter, + eventsDirBefore, + `expected no leaked gsd-run-tests-events-* temp dir after a successful run; ` + + `before=${JSON.stringify(eventsDirBefore)} after=${JSON.stringify(eventsDirAfter)}`, + ); + }); + + // 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', () => { + assert.strictEqual(successRun.status, 0, `expected a clean pass; STDERR:\n${successRun.stderr}`); + assert.doesNotMatch( + successRun.stderr, + /EINVAL|invalid argument, fsync|WriteStream instance/i, + `expected no reporter-destination fsync crash; STDERR:\n${successRun.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 + // (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. + test('a chunk timeout names the file that was in flight when killed', () => { + assert.notStrictEqual( + timeoutRun.status, + 0, + `expected non-zero exit from a timed-out chunk; got status=${timeoutRun.status}\nSTDERR:\n${timeoutRun.stderr}`, + ); + assert.match( + 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${timeoutRun.stderr}`, + ); + }); + + // 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, 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'); + 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); + } + }); + + // 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 + // 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 + // control flow, or the exit code. + test('existing timeout diagnostic and abort behavior are unchanged', () => { + assert.notStrictEqual(timeoutRun.status, 0, `expected non-zero exit; STDERR:\n${timeoutRun.stderr}`); + assert.match( + timeoutRun.stderr, + /exceeded the per-chunk timeout/, + `expected the original timeout diagnostic wording to survive; STDERR:\n${timeoutRun.stderr}`, + ); + assert.match( + timeoutRun.stderr, + /run-tests: chunk 1\/1 was killed after \d+ms/, + `expected the new killed/elapsed line; STDERR:\n${timeoutRun.stderr}`, + ); + }); + }); }); // Pure partition contract for the shard selector (#1212). Imported directly @@ -2139,3 +2408,131 @@ 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'); + }); + + // 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); + }); +});