golem15/msd-core
3
0
Fork 0
Code Issues Pull Requests Actions 1 Packages Projects Releases Wiki Activity

fix(#4012): a hang never emits the events I was listening for

Browse Source 
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
This commit is contained in:
sim
2026-08-28 19:52:57 -04:00
parent 444137e63a
commit bf8905fcc9
3 changed files with 191 additions and 36 deletions
Download Patch File Download Diff File Expand all files Collapse all files

26
scripts/lib/ndjson-reporter.cjs
View File

@@ -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'

94
scripts/run-tests.cjs
View File

@@ -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 ` +