diff --git a/docs/PROJECT_STATE.md b/docs/PROJECT_STATE.md index c1d907e8..1ca55efa 100644 --- a/docs/PROJECT_STATE.md +++ b/docs/PROJECT_STATE.md @@ -4,8 +4,47 @@ > to read **only this file** and continue immediately. Updated after every > milestone and every significant architectural step. -_Last updated: 2026-09-03 — M15 Increment 43: Engine analysis fingerprint identity coverage._ - +_Last updated: 2026-09-03 — M15 Increment 44: Signature B parent-side termination evidence._ + + +## M15 Increment 44 — Signature B parent-side termination evidence + +Signature B — a `packages/api` test-file subprocess dying with a bare `'test failed'`, no +assertion, no stack, none of its own tests reported — **remains unresolved, and no fix is proposed.** +What this increment changed is that the failure is no longer information-free. + +The previous increments instrumented the child and found silence: on three real captures no JS +lifecycle hook fired, not even Node's unconditional `exit` event. That ruled out `process.exit`, +uncaught exceptions and fatal unhandled rejections, and left the question of how the process actually +died on the other side of a boundary the child cannot report from. + +The parent could answer it the whole time. Node's runner attaches the child's `exitCode` and +`signal` to the `ERR_TEST_FAILURE` it throws, and the `spec` reporter discards both — `formatError` +replaces the error with `error.cause`, which is the bare string `'test failed'`. The built-in `tap` +reporter keeps them. Running `spec` to stdout and `tap` to a file at the same time recovers the exit +status with no custom reporter, no patched Node internals, and no change to what a human sees. + +Exit codes were measured on this platform rather than assumed: `process.abort()` gives `134`, +PowerShell `Stop-Process -Force` gives `4294967295`, NTSTATUS faults surface as raw unsigned values +such as `3221225477` (`0xC0000005`). **Exit code `1` identifies nothing** — an uncaught exception, +`process.exit(1)`, `taskkill /F` and `process.kill` all produce it with `signal: null`, since +Windows has no POSIX signals — so the correlator classifies it `inconclusive` rather than guessing. +Where it is ambiguous, the child log still narrows it: a child that reached `preload-installed` and +then logged nothing cannot have exited through `process.exit` or an uncaught exception, because both +leave a record and fire Node's `exit` event. + +`signature-b-correlate.cjs` joins the two sides on the test file path, which also yields the child +PID, and emits one record per failure with both views, the classification, and an explicit statement +of what the pair does and does not establish. `run-signature-b-pass.mjs` runs the pass under a +declared ceiling and stops at the first capture. + +A bounded pass of 20 runs produced 0 captures. That bounds the rate and proves +nothing: treating the historically observed ~1-in-5 as an independent per-run rate, zero captures in +20 runs has probability `(4/5)^20 ≈ 1.2%` — small, but bad luck is not excluded, and independence is +an assumption rather than something this data establishes. +The pass ran at 3084–3834 MB free of 16 GB where the historical captures happened at +roughly 2.5 GB free — consistent with the standing resource-contention hypothesis, and not evidence +for it. Nothing here establishes a cause. ## M15 Increment 43 — Engine analysis fingerprint identity coverage The two-layer engine cache identity is now pinned by tests rather than only by prose, and writing diff --git a/docs/ROADMAP.md b/docs/ROADMAP.md index edbd130a..7bce2f42 100644 --- a/docs/ROADMAP.md +++ b/docs/ROADMAP.md @@ -1349,7 +1349,7 @@ Debt observed during M14. Each states what is known, not what is planned; items - **The published capability document could omit a composed feature, and the client offered controls that could not work (RESOLVED in M15 Increment 24 / ADR-0132).** Left open by Increment 23 above. `capabilitiesView` (`packages/api/src/presenters.ts`) took a hand-written `Pick`, so a feature never added to it was invisible to `GET /v1/capabilities` and nothing complained. ADR-0131 judged that "a narrower failure than a 503 — the feature works for anyone who calls the route directly", and deferred it on the grounds that closing it meant first deciding which optional dependencies are user-facing capabilities. **Both halves of that were wrong.** The failure is narrower only when the client can still reach the feature, and a live instance already existed where it could not: `GET /v1/search` served three modes from two independently-gated dependency sets behind one published `search` flag, so a deployment running the Helm chart’s `search.semanticEnabled: false` advertised search while the client offered two mode buttons whose every request answered 503. And the judgement, while genuinely underivable, can be made **unskippable**, which was the property wanted. `semanticSearch` is now published from both of its dependencies, `Exclude[0] | NotAPublishedCapability>` must be `never` so a new optional dependency cannot compile until someone gives it a flag or records why it has none, and a behavioural guard requires every capability source to change what the document publishes — because a key can sit in that parameter unread, which the compile-time half cannot see. The mutation ledger lives in ADR-0132 and is not restated here. - **The search surface was not gated on `capabilities.search`, so an absolute kill switch still showed a search box (RESOLVED in M15 Increment 24 / ADR-0132 §5).** `SEARCH_ENABLED=0` — the chart's `search.enabled: false`, an absolute kill switch per ADR-0055 — leaves `searchRepository` unconstructed and `GET /v1/search` answering 503 on every mode, keyword included. The entry point was the persistent header form in `packages/web/index.html`, present on every page; being a `
` rather than an `a[data-route]`, `NAV_CAPABILITY_MAP` could not reach it, which is why the first pass at Increment 24 gated the semantic and hybrid *modes* and left keyword ungated — the same defect class one mode over. Raised by the Qodo review of PR #155. **Fixed in the same increment rather than deferred:** the form now ships `hidden` and is revealed by `applySearchCapability` only on an explicit `search: true`; the route renders an honest unavailable notice and issues no request; and keyword search waits for the capability answer, reversing this increment's own earlier latency decision, because knowing whether a request is pointless requires having asked. A markup-contract test pins the `hidden` attribute, since the gate depends on it and every other test passes without it. - **Clicking a search mode discarded text typed since the page loaded (RESOLVED in a follow-up to M15 Increment 24 / ADR-0132).** `createModeInput` in `packages/web/src/app/search-mount.ts` closed over the query captured when the route mounted, so `navigateToSearchMode` navigated with the old term and the remount reset the input to match it. Type a new term into the header field, click **Semantic** without pressing enter, and the typed text was gone with no indication it had been discarded. Pre-existing — the closure predated Increment 24 and was untouched by it — and found by the adversarial review of PR #155 while reviewing the capability gate wrapped around the same control. **Resolved:** the query is now a `() => string` read when a mode is chosen rather than a string captured when the selector renders, matching what `main.ts`'s submit handler already does, and falling back to the mounted query only where the document has no header input. Two regression tests, one of which fails against the exact pre-fix closure. -- **`startHarness` drew ports `fetch` refuses (RESOLVED in ADR-0140); the unexplained whole-file failure is still open.** Two signatures were filed here, deliberately not as one cause, and that judgement held. **Signature A is resolved.** WHATWG Fetch blocks eighty-two ports and undici enforces the list on the port number alone, before opening a socket — so `server.listen(0)` could bind, listen and answer raw TCP while `fetch` still refused, surfacing as `TypeError: fetch failed` / `Error: bad port` at the harness’s first request rather than at the listen that caused it. Whether it can happen at all is a property of the host’s dynamic port range: a typical Linux CI range (32768–60999) contains no blocked port, while the Windows range in use here (1024–15000) contains nineteen, which is the whole of "green on CI, flaky locally". The guard that already existed was incomplete in a way that still failed — its hand-observed set of eighteen ports was the spec list intersected with one machine’s range **minus `6679`** — and it retried unboundedly, had no behaviour on exhaustion, and had been copy-pasted into `auth-signin-schema.integration.test.ts`, so the missing port had to be found twice. `packages/api/test/listen.ts` now owns port acquisition for both sites: the spec-complete eighty-two ports (verified by sweeping all 65535 through the real `fetch` on Node v24.15.0), a bounded twenty attempts, each rejected listener closed before the next is asked for, a guarded `address()` read in place of the `as AddressInfo` cast, and an exhaustion error naming the attempts and rejected ports and nothing else. **Signature B is not resolved and was not folded in.** A file still fails with `'test failed'`, no assertion, no stack and none of its own tests reported. Twenty consecutive full runs gave five failures: on pre-fix code one signature A (`auth.test.js`) and three signature B; on post-fix code one signature B and no signature A. The port fix removes A and leaves B exactly where it was, which is the evidence that they are two defects. Four different files were hit (`move-explanation-route`, `tournament-commentary-route`, `bot-detection-analyze`, `anti-cheat-analysis`), sharing no import beyond `./helpers`; each died in 589–703 ms with no test of its own reporting and no stderr. Refuted with evidence: ephemeral-port exhaustion (113 sockets in TIME_WAIT against a 13977-port range), a `Promise.race` loser becoming an unhandled rejection (`race` subscribes to every promise, confirmed on v24.15.0), a throwing `after`/`afterEach` hook (the affected files use none), and a double `close()` rejecting (awaited in a `finally`, it would be attributed to that test with a stack). A second bounded pass — twelve more full runs under the TAP reporter with a preload recording `uncaughtException`, `unhandledRejection` and any non-zero exit — produced twelve clean runs and captured nothing at the time. **A follow-up increment (`claude/node-test-signature-b`) then captured the defect directly, three more times, on three files never previously implicated** (`rate-limit-atomicity`, `dependency-parity`, `studies-api`) — seven distinct files observed with this symptom to date. Occurrences across seven distinct files make a shared or cross-cutting path more plausible and make a defect confined to one test file less likely, but do not exclude file-specific inputs or lifecycle interactions. An instrumented preload (`packages/api/test/diagnostics/signature-b-preload.cjs`) hooking process-level events — `process.exit`, `process.abort`, `process.kill`, `uncaughtExceptionMonitor` (passively observing uncaught exceptions and fatal unhandled rejections), `warning`, `beforeExit`, and Node’s own unconditional `exit` — showed **none of the hooks active at the time fired** on any of the three historical captures (though `process.abort()` was not wrapped in those initial runs and is now covered for future occurrences). A synthetic `process.exit(1)`-before-registration fixture reproduces the identical silent shape; every other synthetic mechanism tried (a post-test async throw, an emitter `'error'` with its listener removed, a synchronous module-load throw, a delayed `SIGKILL`) prints a visibly different diagnostic line, stack, or partial test output that the real defect never shows. This narrows the investigated possibilities while leaving the root cause unresolved: the per-file child process (`node --test` spawns one per file, confirmed by distinct PIDs) was not terminated by `process.exit`, uncaught exceptions, or fatal unhandled rejections, and future runs with `process.abort` instrumentation will record whether abort was called through JS; an absent record narrows in-runtime JS termination but cannot alone prove external termination without corroborating child exit status/signal data or OS-level crash evidence (e.g. distinguishing an external kill or uncatchable signal from a native C++/V8 crash). The machine had roughly 2.5 GB of 15.7 GB RAM free at capture time with several other agents’ processes concurrently running, which is circumstantially consistent with resource contention, but no crash was recorded in the Windows Application or System event logs in that window, so the exact external trigger is still not established. No fix was invented — the forbidden responses (sleeps, whole-file retries, lowering concurrency) would only hide the unresolved root cause, whose origin is not yet established. See ADR-0140 §4. +- **`startHarness` drew ports `fetch` refuses (RESOLVED in ADR-0140); the unexplained whole-file failure is still open.** Two signatures were filed here, deliberately not as one cause, and that judgement held. **Signature A is resolved.** WHATWG Fetch blocks eighty-two ports and undici enforces the list on the port number alone, before opening a socket — so `server.listen(0)` could bind, listen and answer raw TCP while `fetch` still refused, surfacing as `TypeError: fetch failed` / `Error: bad port` at the harness’s first request rather than at the listen that caused it. Whether it can happen at all is a property of the host’s dynamic port range: a typical Linux CI range (32768–60999) contains no blocked port, while the Windows range in use here (1024–15000) contains nineteen, which is the whole of "green on CI, flaky locally". The guard that already existed was incomplete in a way that still failed — its hand-observed set of eighteen ports was the spec list intersected with one machine’s range **minus `6679`** — and it retried unboundedly, had no behaviour on exhaustion, and had been copy-pasted into `auth-signin-schema.integration.test.ts`, so the missing port had to be found twice. `packages/api/test/listen.ts` now owns port acquisition for both sites: the spec-complete eighty-two ports (verified by sweeping all 65535 through the real `fetch` on Node v24.15.0), a bounded twenty attempts, each rejected listener closed before the next is asked for, a guarded `address()` read in place of the `as AddressInfo` cast, and an exhaustion error naming the attempts and rejected ports and nothing else. **Signature B is not resolved and was not folded in.** A file still fails with `'test failed'`, no assertion, no stack and none of its own tests reported. Twenty consecutive full runs gave five failures: on pre-fix code one signature A (`auth.test.js`) and three signature B; on post-fix code one signature B and no signature A. The port fix removes A and leaves B exactly where it was, which is the evidence that they are two defects. Four different files were hit (`move-explanation-route`, `tournament-commentary-route`, `bot-detection-analyze`, `anti-cheat-analysis`), sharing no import beyond `./helpers`; each died in 589–703 ms with no test of its own reporting and no stderr. Refuted with evidence: ephemeral-port exhaustion (113 sockets in TIME_WAIT against a 13977-port range), a `Promise.race` loser becoming an unhandled rejection (`race` subscribes to every promise, confirmed on v24.15.0), a throwing `after`/`afterEach` hook (the affected files use none), and a double `close()` rejecting (awaited in a `finally`, it would be attributed to that test with a stack). A second bounded pass — twelve more full runs under the TAP reporter with a preload recording `uncaughtException`, `unhandledRejection` and any non-zero exit — produced twelve clean runs and captured nothing at the time. **A follow-up increment (`claude/node-test-signature-b`) then captured the defect directly, three more times, on three files never previously implicated** (`rate-limit-atomicity`, `dependency-parity`, `studies-api`) — seven distinct files observed with this symptom to date. Occurrences across seven distinct files make a shared or cross-cutting path more plausible and make a defect confined to one test file less likely, but do not exclude file-specific inputs or lifecycle interactions. An instrumented preload (`packages/api/test/diagnostics/signature-b-preload.cjs`) hooking process-level events — `process.exit`, `process.abort`, `process.kill`, `uncaughtExceptionMonitor` (passively observing uncaught exceptions and fatal unhandled rejections), `warning`, `beforeExit`, and Node’s own unconditional `exit` — showed **none of the hooks active at the time fired** on any of the three historical captures (though `process.abort()` was not wrapped in those initial runs and is now covered for future occurrences). A synthetic `process.exit(1)`-before-registration fixture reproduces the identical silent shape; every other synthetic mechanism tried (a post-test async throw, an emitter `'error'` with its listener removed, a synchronous module-load throw, a delayed `SIGKILL`) prints a visibly different diagnostic line, stack, or partial test output that the real defect never shows. This narrows the investigated possibilities while leaving the root cause unresolved: the per-file child process (`node --test` spawns one per file, confirmed by distinct PIDs) was not terminated by `process.exit`, uncaught exceptions, or fatal unhandled rejections, and future runs with `process.abort` instrumentation will record whether abort was called through JS; an absent record narrows in-runtime JS termination but cannot alone prove external termination without corroborating child exit status/signal data or OS-level crash evidence (e.g. distinguishing an external kill or uncatchable signal from a native C++/V8 crash). The machine had roughly 2.5 GB of 15.7 GB RAM free at capture time with several other agents’ processes concurrently running, which is circumstantially consistent with resource contention, but no crash was recorded in the Windows Application or System event logs in that window, so the exact external trigger is still not established. No fix was invented — the forbidden responses (sleeps, whole-file retries, lowering concurrency) would only hide the unresolved root cause, whose origin is not yet established. **A further increment then crossed the parent/child boundary the earlier work stopped at, and found the evidence had been there all along:** Node's runner attaches the child's `exitCode` and `signal` to the `ERR_TEST_FAILURE` it throws, and the `spec` reporter discards them — `formatError` replaces the error with `error.cause`, the bare string `'test failed'` — while the built-in `tap` reporter serializes them, so running `spec` to stdout and `tap` to a file recovers the exit status with no custom reporter and no patched internals. Exit codes were measured on this platform rather than assumed: `process.abort()` gives `134`, `Stop-Process -Force` gives `4294967295`, NTSTATUS faults surface as raw unsigned values such as `3221225477` (`0xC0000005`) — and `1` is produced alike by an uncaught exception, `process.exit(1)`, `taskkill /F` and `process.kill`, so it identifies nothing on its own and is classified `inconclusive`. `signature-b-correlate.cjs` joins the parent's TAP record to the child's JSONL log on the test file path (which also yields the child PID) and states what the pair does and does not establish; where the exit code is ambiguous, a child that reached `preload-installed` and then logged nothing still excludes `process.exit` and an uncaught exception, because both would have left a record and fired Node's `exit` event. A bounded pass of 20 runs under this instrumentation produced 0 captures — which bounds the rate and proves nothing: treating the historical ~1-in-5 as an independent per-run rate, zero captures in 20 runs has probability `(4/5)^20 ≈ 1.2%`, and independence is an assumption rather than an established fact; it ran at 3084–3834 MB free against roughly 2.5 GB at the historical captures, consistent with the resource-contention hypothesis but not evidence for it. **Signature B stays UNRESOLVED**; what changed is that the next occurrence is readable rather than silent. See ADR-0140 §4. - **`ApiServer.listen` registered no `'error'` handler, so a failed bind hung and raised an uncaught event (RESOLVED in ADR-0140 §5).** `packages/api/src/server.ts` resolved its promise from the `listening` callback only and built it with no reject path. A bind failing asynchronously (`EADDRINUSE`, `EMFILE`) left the promise pending forever and, with no `'error'` listener on the `http.Server`, was re-raised as an uncaught exception. Found while investigating ADR-0140 and independently raised by the Qodo review of PR #21. **Resolved in the same increment** rather than deferred, because ADR-0140 §2's bounded, diagnosable acquisition is not true without it — the retry can only report a bind error if the listener it is handed rejects. A one-shot `'error'` listener now rejects and is removed once listening, so later server errors keep their previous semantics rather than being swallowed by a `reject` on a settled promise. The regression test fails against the exact pre-fix code, through an uncaught `ERR_UNHANDLED_ERROR`. - **`main.ts`'s controller-disposal list is manual, untested, and silently incomplete when a section is added (RESOLVED in Increment 25 / ADR-0092).** `run()` in `packages/web/src/main.ts` disposes the previous route's controllers by name, and its own comment says doing so "is what makes re-bootstrapping safe" — but adding a section to `bootstrap` and forgetting to add it there compiles, passes every gate, and leaks. Increment 23 shipped exactly that omission for `LearningController` and it was caught in PR review, not by a test. `main.ts` has no test coverage of any kind, so no section's disposal is verified. A structural fix (bootstrap returning its disposables as a collection, or a type-level exhaustiveness check keyed off the result type) would make the next omission a compile error; it is a refactor across ~15 return sites and belongs in its own increment. **Resolved in Increment 25 (ADR-0092):** extracted `createLifecycle` run loop in `lifecycle.ts`, defined `BootstrappedDisposables` and `DisposableKey` driving `DISPOSABLE_TEARDOWN_MAP: Record` for compile-time exhaustiveness, normalised `.dispose()` verb across all disposables, and cascaded `GameController.stop()` to `gameSync.stop()`. - **`stepView` sends the answers to the learner (RESOLVED in Increment 29 / ADR-0095).** `packages/api/src/presenters.ts` emits `expectedSan` on a move step and `correctIndex` on a quiz step, and `GET /v1/lessons/:id/steps` is the route the learner's own lesson page calls. Increment 23 omits both from the client-side types (`packages/web/src/api/models.ts`), so the app cannot render or grade against them and a future edit that tries becomes a compile error — but the fields are still on the wire and readable in devtools. The authoring routes legitimately need them returned to the author, so the fix is a learner-scoped step view (or a caller-dependent projection), not a deletion: an API contract decision with its own ADR. Nothing rated or rewarded depends on step progress today, so this is a wart rather than a breach. **Resolved in Increment 29 (ADR-0095):** added `LearnerStepView` / `learnerStepView` in `packages/api/src/presenters.ts` omitting `expectedSan` and `correctIndex`. `GET /v1/lessons/:id/steps` and `GET /v1/steps/:id` now check course authorship via `repo.getLesson` / `repo.getCourse`, returning full `stepView` to the author and `learnerStepView` to learners and anonymous callers. Updated OpenAPI schema and web model comments. The first attempt resolved authorship with a separate `getLesson` + `getCourse` after the step read, which doubled both routes from 3 SQL queries to 6 because `listSteps` / `getStep` had already made those reads internally and discarded the course; caught in the PR #92 review and fixed by adding `getStepWithCourse` / `listStepsWithCourse` to `LearningRepository`, which return what was already loaded. Both routes now make exactly one repository call, pinned by a counting-proxy test. diff --git a/docs/adr/0140-harness-ephemeral-port-acquisition.md b/docs/adr/0140-harness-ephemeral-port-acquisition.md index 44a19d25..191ba903 100644 --- a/docs/adr/0140-harness-ephemeral-port-acquisition.md +++ b/docs/adr/0140-harness-ephemeral-port-acquisition.md @@ -268,6 +268,105 @@ whatever the root cause turns out to be. Signature B stays open and unresolved. preload is committed so the next occurrence — on this machine, in CI, or elsewhere — can be captured with selected termination and error path instrumentation rather than re-deriving it. +### Follow-up: the parent knew the exit status all along, and `spec` was discarding it + +The investigation above ends inside the child, because the child stops writing. This increment +crossed to the other side of the process boundary and found the missing evidence was never missing — +it was being thrown away by the reporter. + +Node's runner already computes it. `internal/test_runner/runner.js` waits on the child's `exit` +event and, when the child failed, builds the error the file-level failure is reported through: + +```js +if (code !== 0 || signal !== null) { + if (!err) { + const failureType = subtest.failedSubtests ? kSubtestsFailed : kTestCodeFailure; + err = ObjectAssign(new ERR_TEST_FAILURE('test failed', failureType), { + __proto__: null, exitCode: code, signal: signal, stack: undefined }); + } + throw err; +} +``` + +**The `spec` reporter discards `exitCode` and `signal`.** `formatError` in +`internal/test_runner/reporter/utils.js` does `const err = error.code === 'ERR_TEST_FAILURE' ? error.cause : error`, +and `cause` is the bare string `'test failed'` — so every own property of the error, the exit status +included, is dropped before anything is printed. That is the whole reason this failure has looked +information-free for three increments. **The built-in `tap` reporter does not discard them:** its +`jsToYaml` walks the error's own enumerable properties and skips only `cause` and `code`, so +`exitCode` and `signal` land in its YAML block. + +Both reporters can run at once, which is what makes this usable rather than a trade: + +```sh +node --require ./test/diagnostics/signature-b-preload.cjs \ + --test-reporter=spec --test-reporter-destination=stdout \ + --test-reporter=tap --test-reporter-destination= \ + --test --test-concurrency=1 "dist-test/test/**/*.test.js" +``` + +Human-facing stdout is unchanged, the exit status is captured to a file, no custom reporter is +written and no Node internal is patched — which matters, because the last attempt to observe this +system by patching `EventEmitter.prototype.emit` crashed the parent runner. The earlier TAP-only +pass recorded above would have shown these fields had it caught an occurrence; it captured nothing, +so nobody read them. + +**Exit codes were measured on this platform rather than assumed** (Windows 11, Node v24.15.0): + +| Mechanism | `exitCode` | `signal` | How it was measured | +|---|---|---|---| +| `process.exit(1)` before any test registers | `1` | `null` | run under the runner, read from the TAP block | +| `process.abort()` | `134` | `null` | same; also prints a native + JS stack to stderr | +| `taskkill /F /PID` | `1` | `null` | spawned a sleeper, killed it, read `child.on('exit')` | +| `Stop-Process -Force` | `4294967295` | `null` | same | +| `process.kill(pid)` | `1` | `null` | same | +| `STATUS_ACCESS_VIOLATION` | `3221225477` | `null` | not reproduced here; NTSTATUS `0xC0000005` surfaced as a raw unsigned 32-bit value | + +Two consequences follow, and the second is the one that keeps the analysis honest. + +- **A native fault or a V8 fatal error is now nameable as a candidate.** `134` and `0xC0000005` + name a specific mechanism — but naming is not proving. An exit status is a 32-bit integer the + terminating party chooses, and `TerminateProcess(h, 0xC0000005)` produces the same number as a + real access violation, so the status is the strongest candidate rather than proof. + `signature-b-correlate.cjs` reports these as `specific` rather than `conclusive`, and confirmation + has to come from the child log, the enumerated fatal stderr markers, or OS evidence. + **Membership of the `0xC0000000` range is not itself a native-fault finding**, and an earlier + draft of this section said otherwise: `STATUS_CONTROL_C_EXIT` (`0xC000013A`) is a console CTRL+C + and sits in the same range. Codes the measured table covers name a candidate; a value in the range + that it does not cover is reported `ntstatus-unmeasured` and non-specific, rather than assumed to + be a crash. +- **Exit code `1` identifies nothing.** An uncaught exception, `process.exit(1)`, `taskkill /F` and + `process.kill` all produce `1` with `signal: null`, because Windows has no POSIX signals and libuv + reports one only when the parent's own handle did the killing. Reading `1` as proof of an external + kill would be a wrong answer, and `signature-b-correlate.cjs` classifies it as `inconclusive`. + +What rescues `1` is the child-side log, which is why the two sides are correlated rather than read +separately: `process.exit(1)` and an uncaught exception both leave a record and both fire Node's +`exit` event, so a child that reached `preload-installed` and then logged **nothing** cannot have +died either way. `packages/api/test/diagnostics/signature-b-correlate.cjs` joins the parent's TAP +record to the child's JSONL log on the test file path — the preload records `testFile` on every +line, which also yields the child's PID — and emits one record per failure carrying both views, the +classification, and an explicit statement of what the pair does and does not establish. + +**Bounded pass: 20 runs, 0 captures.** Ceiling declared before starting at 20 full +`packages/api` runs or 45 minutes, stopping at the first capture; 20 runs at ~28s each +were executed and Signature B did not occur. That is not a fix and is not evidence of one. It bounds +the rate and nothing else: **treating the historically observed ~1-in-5 as an independent per-run +rate, zero captures in 20 runs has probability `(4/5)^20 ≈ 1.2%`** — small, but ordinary bad luck is +not excluded, and independence is an assumption here rather than something this data establishes. One difference from the capture conditions is +worth recording without being leaned on — this pass ran with 3084–3834 MB free of +16 GB, where the three historical captures happened at roughly 2.5 GB free with several other agents' +processes running. That is *consistent with* the standing resource-contention hypothesis and is not +evidence for it; nothing here establishes a causal link, and the hypothesis stays untested. + +**Signature B remains UNRESOLVED.** No fix is proposed and none is disguised: no sleep, no retry, no +lowered concurrency, no excluded file. What changed is that the next occurrence is readable. A +capture now yields the child's PID, which JS lifecycle paths it did or did not run, and the exit +status the parent observed. Whether that status names anything depends on the status: a mapped code +names a **candidate** mechanism, while a bare `1`, a signal — which names the signal that killed the +child but never the party that sent it — and any code outside the measured table are all reported +`specific: false` and name nothing on their own. + ## 5. `ApiServer.listen` rejects on a failed bind Raised by the Qodo review of PR #21 and **valid**. `packages/api/src/server.ts` diff --git a/packages/api/package.json b/packages/api/package.json index d330a438..37bf3112 100644 --- a/packages/api/package.json +++ b/packages/api/package.json @@ -25,6 +25,7 @@ "test": "tsc -p tsconfig.test.json && node --test --test-concurrency=1 \"dist-test/test/**/*.test.js\"", "test:analysis-smoke": "tsc -p tsconfig.test.json && node --test dist-test/test/analysis-stockfish-smoke.test.js dist-test/test/analysis-fairy-threecheck-smoke.test.js dist-test/test/analysis-real-stack.test.js", "test:diagnostics:abort": "tsc -p tsconfig.test.json && node --test dist-test/test/diagnostics/signature-b-preload-abort.diag.js", + "test:diagnostics:signature-b": "tsc -p tsconfig.test.json && node ./test/diagnostics/run-signature-b-pass.mjs", "lint": "tsc -p tsconfig.json --noEmit", "openapi": "node dist/scripts/generate-openapi.js", "reindex-search": "node dist/scripts/reindex-search.js", diff --git a/packages/api/test/diagnostics/run-signature-b-pass.mjs b/packages/api/test/diagnostics/run-signature-b-pass.mjs new file mode 100644 index 00000000..bd4b5fae --- /dev/null +++ b/packages/api/test/diagnostics/run-signature-b-pass.mjs @@ -0,0 +1,391 @@ +#!/usr/bin/env node +/** + * Bounded reproduction pass for the Signature B failure (ADR-0140 §4): a `packages/api` test-file + * subprocess that dies with a bare `'test failed'`, no assertion, no stack, and none of its own + * tests reported. + * + * Every run is instrumented on both sides of the process boundary at once: + * + * - **Child side** — `signature-b-preload.cjs` is `--require`d into each per-file child and records + * which JS lifecycle path, if any, the child took before dying. + * - **Parent side** — the built-in `tap` reporter writes to a file while `spec` keeps stdout. That + * pairing is the point: Node's runner attaches the child's `exitCode` and `signal` to the error it + * throws, `spec` discards them (its `formatError` replaces the error with `error.cause`, the bare + * string `'test failed'`), and `tap` serializes them into its YAML block. Running both recovers + * the exit status without a custom reporter, without patching Node internals, and without changing + * what a human sees on stdout. + * + * The pass is **bounded by construction** and stops at the first capture. The wall-clock ceiling is + * an absolute deadline enforced *during* a run, not merely consulted before starting another, and + * expiring it kills the whole process tree — `node:test` spawns one child per test file, so killing + * only the process this script started would leave workers behind on POSIX. It never retries a + * failed file and never reruns the suite to get a green result — those would hide the defect rather + * than explain it. + * + * Concurrency is **matched, not lowered**: each run passes the same `--test-concurrency=1` that + * `packages/api`'s own `npm test` passes, so the pass measures the configuration CI and developers + * actually run, which is the configuration under which every occurrence has been observed. Running + * it at Node's default parallelism would be a different experiment, not a stricter one. + * + * A pass that captures nothing proves nothing beyond "not observed in N runs", and the printed + * summary says so; a pass containing a run whose report could not be read says it is inconclusive + * instead. + * + * Usage, from `packages/api` (compile first: `npx tsc -p tsconfig.test.json`): + * + * node ./test/diagnostics/run-signature-b-pass.mjs \ + * [--runs 20] [--max-minutes 45] [--out ] [--target ] + */ + +import { spawn, spawnSync } from 'node:child_process'; +import { createRequire } from 'node:module'; +import { freemem, tmpdir, totalmem } from 'node:os'; +import fs from 'node:fs'; +import path from 'node:path'; +import { fileURLToPath } from 'node:url'; + +const HERE = path.dirname(fileURLToPath(import.meta.url)); +const API_DIR = path.resolve(HERE, '../..'); +const { correlate, parseTapFailures, readChildLogs } = createRequire(import.meta.url)('./signature-b-correlate.cjs'); + +/** Every option this script accepts, so one cannot be consumed as another's value. */ +const KNOWN_FLAGS = new Set(['runs', 'max-minutes', 'out', 'target']); + +/** Refuse before anything is created or spawned; a usage error must not leave artifacts behind. */ +function usageError(message) { + console.error(message); + process.exit(2); +} + +/** + * Read one option's value, rejecting an option that was given no value. + * + * `--out --target file` must be a usage error rather than a request to create a directory called + * `--target`, which would then silently write diagnostic artifacts somewhere nobody expects. + * + * @param {string} name + * @param {string|number} fallback + * @returns {string|number} + */ +const flag = (name, fallback) => { + const at = process.argv.indexOf(`--${name}`); + if (at === -1) return fallback; + const value = process.argv[at + 1]; + if (value === undefined) usageError(`--${name} requires a value`); + if (value.startsWith('--') && KNOWN_FLAGS.has(value.slice(2))) { + usageError(`--${name} requires a value; got the option ${value}`); + } + return value; +}; + +/** + * The only stderr lines a dying child produces that name its own cause. Node prints these itself, + * and they are what separates a V8 heap exhaustion from a JS `process.abort()` when both leave the + * same exit code 134. + */ +const FATAL_MARKERS = [ + 'FATAL ERROR:', + 'JavaScript heap out of memory', + '<--- Last few GCs --->', + '----- Native stack trace -----', + '----- JavaScript stack trace -----', +]; + +/** + * Record which fatal markers a run's stderr contained, and never the stderr itself. + * + * A whitelist rather than a redaction pass: the suite's own output can contain anything a test + * chose to print, so matching known markers is the only way to be sure a token, request body or + * connection string cannot reach the capture file. Presence is all the evidence is worth anyway — + * the marker names the mechanism, the surrounding text does not. + * + * @param {string | undefined} stderr + * @returns {string[]} markers present, in the order listed above + */ +function fatalMarkersIn(stderr) { + const text = String(stderr ?? ''); + return FATAL_MARKERS.filter((marker) => text.includes(marker)); +} + +/** + * A ceiling that does not describe a real experiment must stop the run, not shrink it. + * + * `--runs 0`, a negative value or a typo would otherwise execute nothing and still print that + * Signature B was not observed — an empty experiment presented as a clean pass, which is the exact + * dishonesty this whole diagnostic exists to avoid. + * + * @param {string} name + * @param {unknown} raw + * @param {number} fallback + * @returns {number} + */ +function positiveNumber(name, raw, fallback, { integer = false } = {}) { + if (raw === fallback) return fallback; + const value = Number(raw); + if (!Number.isFinite(value) || value <= 0) { + usageError(`--${name} must be a positive number; got ${JSON.stringify(raw)}`); + } + if (integer && !Number.isInteger(value)) { + usageError(`--${name} must be a whole number of runs; got ${JSON.stringify(raw)}`); + } + return value; +} + +// `--runs 1.5` would otherwise run twice, exceeding the ceiling the pass just declared. Minutes are +// a duration and are legitimately fractional, so the integer rule belongs to the count alone. +const maxRuns = positiveNumber('runs', flag('runs', 20), 20, { integer: true }); +const maxMs = positiveNumber('max-minutes', flag('max-minutes', 45), 45) * 60_000; +// The fallback is computed only when --out is absent: an argument is evaluated before the call, +// so an eager mkdtemp would create an unused directory on every run that supplies its own. +const outDir = flag('out', null) ?? fs.mkdtempSync(path.join(tmpdir(), 'sigb-pass-')); + +// What each run executes. The default is the whole compiled suite, which is what reproducing +// Signature B requires; `--target` exists so this script's own tests can point a run at one trivial +// file instead of launching a second copy of the suite against the same database. +const target = flag('target', 'dist-test/test/**/*.test.js'); + +/** + * Make the artifact directory owner-only, or refuse to write into it. + * + * `mkdirSync`'s `mode` applies only when the directory is created, so a `--out` that already exists + * keeps whatever permissions it had — and a captured `run.tap` holds raw suite output. Where + * POSIX permission bits are meaningful this narrows an existing directory to `0700` and verifies it + * took, refusing if it did not. **On Windows this guarantee is not offered**: `chmod` there sets + * only the read-only bit, ACLs are what actually govern access, and claiming a POSIX mode was + * enforced would be a false statement about the filesystem. + * + * @param {string} dir + */ +function ensurePrivateDirectory(dir) { + const existed = fs.existsSync(dir); + fs.mkdirSync(dir, { recursive: true, mode: 0o700 }); + if (process.platform === 'win32') { + if (existed) console.log('note: on Windows the artifact directory inherits its ACLs; POSIX modes are not enforced here.'); + return; + } + if (!existed) return; + const before = fs.statSync(dir).mode & 0o777; + if ((before & 0o077) === 0) return; + fs.chmodSync(dir, 0o700); + const after = fs.statSync(dir).mode & 0o777; + if ((after & 0o077) !== 0) { + usageError(`--out ${dir} is group/world accessible (mode ${after.toString(8)}) and could not be secured`); + } + console.log(`note: narrowed ${dir} from mode ${before.toString(8)} to 700 before writing artifacts.`); +} + +ensurePrivateDirectory(outDir); +console.log(`Signature B bounded pass — ceiling ${maxRuns} runs or ${maxMs / 60_000} minutes, stopping at first capture.`); +console.log(`Artifacts: ${outDir}\n`); + +/** + * Kill a run and everything it started, bounded, on either platform. + * + * This matters because `node:test` spawns one child process per test file, so the process this + * script starts is never the only one. Measured on Windows (Node v24.15.0): killing the runner + * leaves the per-file child already **gone**, because libuv puts spawned processes in a job object + * that terminates with the parent. POSIX offers no such guarantee — `SIGKILL` to a parent is not + * delivered to its children, which are reparented and keep running — so the group has to be killed + * explicitly. `taskkill /T` covers the Windows case anyway rather than relying on the job object. + * + * @param {import('node:child_process').ChildProcess} child + */ +function killTree(child) { + const pid = child.pid; + if (pid === undefined) return; + try { + if (process.platform === 'win32') { + spawnSync('taskkill', ['/F', '/T', '/PID', String(pid)], { stdio: 'ignore', timeout: 10_000 }); + } else { + // Spawned detached, so the child leads its own process group and the negated pid reaches + // every descendant in it, not just the runner. + process.kill(-pid, 'SIGKILL'); + } + } catch { + /* already gone, which is the outcome this wanted */ + } +} + +/** + * Execute one instrumented suite run under an absolute deadline. + * + * Asynchronous rather than `spawnSync` because the deadline must be able to act *while* a run is + * in flight — a hung `node --test` would otherwise block the loop past the declared ceiling — and + * because killing a tree requires a handle the synchronous API never yields. + * + * @param {string} tapPath + * @param {string} logDir + * @param {number} budgetMs + * @returns {Promise<{ status: number|null, signal: string|null, timedOut: boolean, error: Error|null, stderr: string }>} + */ +/** + * The run currently in flight, so an interrupted pass can take its process tree with it. + * + * Detaching the child is what makes the group killable on POSIX, and it is also what stops a + * terminal `SIGINT` reaching it: Ctrl-C goes to the foreground process group, which the detached + * runner is no longer in. Without these handlers, interrupting the pass would leave `node --test` + * and every per-file worker running against the suite database. + * + * @type {import('node:child_process').ChildProcess | null} + */ +let activeChild = null; + +for (const signal of ['SIGINT', 'SIGTERM']) { + process.on(signal, () => { + if (activeChild !== null) killTree(activeChild); + // 128 + signal number, the conventional shell encoding for "terminated by this signal". + process.exit(signal === 'SIGINT' ? 130 : 143); + }); +} + +function runOnce(tapPath, logDir, budgetMs) { + return new Promise((resolve) => { + const child = spawn( + process.execPath, + [ + '--require', './test/diagnostics/signature-b-preload.cjs', + '--test-reporter=spec', '--test-reporter-destination=stdout', + '--test-reporter=tap', `--test-reporter-destination=${tapPath}`, + '--test', '--test-concurrency=1', target, + ], + { + cwd: API_DIR, + env: { ...process.env, SIGB_LOG_DIR: logDir }, + // `spec` goes straight to this terminal, which is the whole point of running it alongside + // `tap`: the human-facing output must stay exactly what it would be without the diagnostic. + // Only stderr is captured, and only to test it for known fatal markers. + stdio: ['ignore', 'inherit', 'pipe'], + detached: process.platform !== 'win32', + }, + ); + + activeChild = child; + let stderr = ''; + let timedOut = false; + child.stderr?.on('data', (chunk) => { + // Bounded: only the tail can carry a fatal marker, and the suite's own output is unbounded. + stderr = `${stderr}${chunk}`.slice(-64 * 1024); + }); + + const deadline = setTimeout(() => { + timedOut = true; + killTree(child); + }, budgetMs); + + child.on('error', (error) => { + clearTimeout(deadline); + activeChild = null; + resolve({ status: null, signal: null, timedOut, error, stderr }); + }); + child.on('close', (status, signal) => { + clearTimeout(deadline); + activeChild = null; + resolve({ status, signal, timedOut, error: null, stderr }); + }); + }); +} + +const startedAt = Date.now(); +const runs = []; +let capture = null; + +for (let run = 1; run <= maxRuns; run++) { + const elapsed = Date.now() - startedAt; + if (elapsed >= maxMs) { + console.log(`ceiling reached: ${Math.round(elapsed / 1000)}s elapsed`); + break; + } + + const tapPath = path.join(outDir, `run${run}.tap`); + const logDir = path.join(outDir, `child-logs-run${run}`); + fs.mkdirSync(logDir, { recursive: true, mode: 0o700 }); + + const freeBefore = freemem(); + const startedRun = Date.now(); + const result = await runOnce(tapPath, logDir, Math.max(1, maxMs - elapsed)); + const durationMs = Date.now() - startedRun; + + // A run whose report cannot be read has not answered the question, and must not be filed next to + // the runs that did. Reporting it as "zero captures" would let a broken pass look like a quiet one. + let records = []; + let collectionError = result.error ? `${result.error.name}: ${result.error.message}` : null; + if (collectionError === null && result.timedOut) collectionError = 'run exceeded the wall-clock ceiling'; + if (collectionError === null) { + try { + records = correlate(parseTapFailures(fs.readFileSync(tapPath, 'utf8')), readChildLogs(logDir)); + } catch (error) { + collectionError = `${error.name}: ${error.message}`; + } + } + + const summary = { + run, + durationMs, + runnerExitCode: result.status, + // Set by this script's own deadline, never inferred from `signal`. A child that terminates + // itself by signal is not a run that ran out of time, and reporting it as one would misattribute + // the very kind of termination this diagnostic exists to identify. + timedOut: result.timedOut, + freeMemBeforeMb: Math.round(freeBefore / 1048576), + freeMemAfterMb: Math.round(freemem() / 1048576), + totalMemMb: Math.round(totalmem() / 1048576), + captures: records.length, + collectionError, + }; + runs.push(summary); + fs.writeFileSync(path.join(outDir, 'summary.json'), `${JSON.stringify({ runs }, null, 2)}\n`, { mode: 0o600 }); + console.log( + `run ${run}: ${Math.round(durationMs / 1000)}s runnerExit=${result.status} ` + + `captures=${records.length} freeMb ${summary.freeMemBeforeMb}->${summary.freeMemAfterMb}` + + (collectionError === null ? '' : ` COLLECTION FAILED: ${collectionError}`), + ); + + if (collectionError !== null) { + console.error(`\nRun ${run} produced no readable diagnostic result. Stopping rather than reporting a clean pass.`); + process.exitCode = 1; + break; + } + + if (records.length > 0) { + capture = { run, records, fatalMarkers: fatalMarkersIn(result.stderr) }; + fs.writeFileSync(path.join(outDir, 'capture.json'), `${JSON.stringify(capture, null, 2)}\n`, { mode: 0o600 }); + // The raw TAP has served its purpose the moment `capture.json` exists. It is a full transcript + // of whatever the suite printed, so keeping it past the normalised record retains arbitrary + // test output for no diagnostic gain; the child logs stay, being enumerated lifecycle events. + fs.rmSync(tapPath, { force: true }); + console.log(`\nCAPTURED on run ${run}:\n${records.map((r) => JSON.stringify(r, null, 2)).join('\n')}`); + console.log(`\nRaw TAP discarded; the normalised record is ${path.join(outDir, 'capture.json')}.`); + break; + } + + // A clean run's artifacts answer nothing and would otherwise grow without bound across the pass. + fs.rmSync(logDir, { recursive: true, force: true }); + fs.rmSync(tapPath, { force: true }); +} + +const minutes = Math.round((Date.now() - startedAt) / 60_000); +const unreadable = runs.filter((entry) => entry.collectionError !== null).length; +const readable = runs.length - unreadable; +console.log(`\n${runs.length} run(s), ${minutes} minute(s), ${capture ? 1 : 0} capture(s), ${unreadable} unreadable.`); + +// Only a pass that actually observed something may say the defect was not observed. Counting the +// runs that produced a readable report — rather than the runs that were started — covers an empty +// experiment and a wholly unreadable one with the same test, and neither is a clean result. +if (capture) { + // Only a record whose exit status names something may be described as naming something. An + // `unclassified` or `inconclusive` capture is still worth having, but saying it names a mechanism + // would overstate exactly the evidence this diagnostic exists to report precisely. + const named = capture.records.filter((record) => record.specific); + console.log( + named.length > 0 + ? `See capture.json. ${named.length} of ${capture.records.length} record(s) name a candidate mechanism; a candidate is not a cause.` + : 'See capture.json. No record names a mechanism — the exit status is one no measurement here identifies.', + ); +} else if (readable === 0) { + console.error('No run produced a readable result, so this pass observed nothing. It is not a clean result.'); + process.exitCode = 1; +} else if (unreadable > 0) { + console.log('This pass is inconclusive: at least one run produced no readable diagnostic result.'); +} else { + console.log('Signature B was not observed in this pass. That bounds its rate; it does not mean it is fixed.'); +} diff --git a/packages/api/test/diagnostics/signature-b-correlate.cjs b/packages/api/test/diagnostics/signature-b-correlate.cjs new file mode 100644 index 00000000..01fa009d --- /dev/null +++ b/packages/api/test/diagnostics/signature-b-correlate.cjs @@ -0,0 +1,415 @@ +'use strict'; +/** + * Correlates the PARENT-side view of a Signature B failure with the CHILD-side view, which is the + * observability boundary `docs/adr/0140-harness-ephemeral-port-acquisition.md` §4 stopped at. + * + * Signature B is a `packages/api` test-file subprocess dying with a bare `'test failed'`, no + * assertion, no stack, and none of that file's own tests reported. The child-side preload + * (`signature-b-preload.cjs`) established that on real captures no JS lifecycle hook fires at all — + * not even Node's unconditional `exit` event — which rules out `process.exit`, uncaught exceptions + * and fatal unhandled rejections, but cannot say how the process actually died. + * + * The parent knows. Node's runner already computes the child's exit status and attaches it to the + * error it throws (`internal/test_runner/runner.js`): + * + * err = ObjectAssign(new ERR_TEST_FAILURE('test failed', failureType), { + * __proto__: null, exitCode: code, signal: signal, stack: undefined }); + * + * The default `spec` reporter then throws that away: `formatError` in + * `internal/test_runner/reporter/utils.js` replaces the error with `error.cause`, which is the bare + * string `'test failed'`, so every own property including `exitCode` is discarded before printing. + * The built-in **TAP** reporter does not — `jsToYaml` walks the error's own enumerable properties + * and skips only `cause` and `code` — so `exitCode` and `signal` survive into its YAML block. That + * makes the exit status recoverable with no custom reporter and no patched internals, by running + * `spec` to stdout and `tap` to a file at the same time. See `npm run test:diagnostics:signature-b`. + * + * This module joins the two sides on the test file path, which the preload records for every child, + * and classifies the termination against exit codes verified on this platform (see + * {@link classifyTermination}). It deliberately reports `inconclusive` rather than guessing: exit + * code 1 has several possible causes and is not evidence of any one of them. + * + * Emits only enumerated fields — exit status, event kinds, PIDs, durations and test file paths. + * It never copies an error message, a TAP diagnostic body, stderr, or any environment value, so no + * token, request body or connection string can reach the output through it. + */ + +const fs = require('node:fs'); +const path = require('node:path'); + +/** Records kept per correlation run, so a pathological TAP file cannot produce an unbounded report. */ +const MAX_RECORDS = 200; + +/** + * A path with both separators normalised to `/`, so a capture taken on one platform can be read on + * another. `path.basename` and `path.normalize` use only the host's separator, so on Linux they + * return a Windows path unchanged and every comparison against it silently fails. + * + * @param {string} filePath + * @returns {string} + */ +function normalizePath(filePath) { + return String(filePath).replace(/\\/g, '/').replace(/^\.\//, ''); +} + +/** + * Last path segment, platform-independently. + * + * @param {string} filePath + * @returns {string} + */ +function fileKey(filePath) { + const segments = normalizePath(filePath).split('/'); + return segments[segments.length - 1] ?? ''; +} + +/** + * What an observed exit status *suggests*, keyed by the status the parent saw. + * + * Every code below was measured on this platform (Windows 11, Node v24.15.0) rather than assumed, + * with one labelled exception: `process.abort()` and `process.exit(1)` by running them under the + * test runner and reading the TAP block, and the external kills by spawning a sleeper and + * terminating it from outside. Windows has no POSIX signals — `signal` is `null` for every external + * kill and native fault — so the exit code is the only discriminator, and `1` does not discriminate + * at all. + * + * The exception is `0xC000013A`, which is taken from documented Windows console semantics rather + * than measured here. It is in the table because its absence was worse: it sits inside the + * `0xC0000000` range, and the range fallback used to call anything in that range a native-fault + * candidate, which for a console interrupt is simply wrong. + * + * `specific` says whether the status names a *particular* mechanism, not whether that mechanism is + * proven. Nothing here is proof: an exit status is a 32-bit integer the terminating party chooses, + * and any process can exit with 134 or with a value in the NTSTATUS range without a native fault + * having occurred. `TerminateProcess(h, 0xC0000005)` produces the same number as a real access + * violation. Corroboration has to come from outside the number — see {@link narrowFromChildEvidence}. + * + * @type {ReadonlyArray<{ code: number, id: string, meaning: string, specific: boolean }>} + */ +const EXIT_CODE_TABLE = [ + { code: 134, id: 'native-abort-or-v8-fatal', specific: true, + meaning: 'candidate: CRT/V8 abort(), a V8 fatal error such as heap OOM, or a native assertion; any process can also exit 134 deliberately' }, + { code: 3221225477, id: 'native-access-violation', specific: true, + meaning: 'candidate: STATUS_ACCESS_VIOLATION (0xC0000005); an external TerminateProcess may pass the same value' }, + { code: 3221226505, id: 'native-fast-fail', specific: true, + meaning: 'candidate: STATUS_STACK_BUFFER_OVERRUN (0xC0000409), __fastfail; an external kill may pass the same value' }, + { code: 3221225725, id: 'native-stack-overflow', specific: true, + meaning: 'candidate: STATUS_STACK_OVERFLOW (0xC00000FD); an external kill may pass the same value' }, + { code: 3221225540, id: 'job-object-quota', specific: true, + meaning: 'candidate: STATUS_QUOTA_EXCEEDED (0xC0000044), a job object or quota limit; an external kill may pass the same value' }, + { code: 3221225786, id: 'external-control-c', specific: true, + meaning: 'candidate: STATUS_CONTROL_C_EXIT (0xC000013A), a console CTRL+C or CTRL+BREAK — an external interrupt, not a native fault; documented rather than measured here, and an external kill may pass the same value' }, + { code: 4294967295, id: 'external-terminate-process', specific: true, + meaning: 'candidate: TerminateProcess with exit code -1, which is what PowerShell Stop-Process -Force produces' }, + { code: 1, id: 'inconclusive', specific: false, + meaning: 'exit code 1 is produced by an uncaught exception, process.exit(1), taskkill /F and process.kill alike' }, +]; + +/** + * Classify a parent-observed child termination. + * + * A non-null `signal` establishes that the child died by signal and nothing more. Node's exit + * contract names the signal that terminated the process, not the process that sent it, so an + * external `SIGKILL`, a self-sent signal and a runner cancellation are indistinguishable here. + * Naming a sender would be the same unsupported leap this module refuses to make for exit code 1. + * + * @param {{ exitCode: number | null, signal: string | null }} termination + * @returns {{ id: string, meaning: string, specific: boolean }} + */ +function classifyTermination({ exitCode, signal }) { + if (signal !== null && signal !== undefined) { + return { + id: 'signal-terminated', + meaning: `the child was terminated by ${signal}; the exit contract names the signal, not its sender, so the runner, the OS and an external process are all still possible`, + specific: false, + }; + } + const known = EXIT_CODE_TABLE.find((entry) => entry.code === exitCode); + if (known) return { id: known.id, meaning: known.meaning, specific: known.specific }; + if (typeof exitCode === 'number' && exitCode >= 0xc0000000) { + // Membership of the range is not a finding. A native fault produces a value here, but so does a + // console CTRL+C (`STATUS_CONTROL_C_EXIT`, in the table above), and an external TerminateProcess + // can pass any of them deliberately. An unmeasured value in the range therefore narrows the + // shape of the answer without naming a mechanism, and must not be reported as though it had. + return { + id: 'ntstatus-unmeasured', + meaning: `exit code ${exitCode} (0x${exitCode.toString(16)}) is an NTSTATUS value this table does not cover; a native fault is one candidate, but the range also carries non-fault statuses such as STATUS_CONTROL_C_EXIT, so the number alone names no mechanism`, + specific: false, + }; + } + return { id: 'unclassified', meaning: `exit code ${String(exitCode)} is not in the measured table`, specific: false }; +} + +/** + * Events that name *why* the process ended: a call the preload intercepted, or a fault it observed. + */ +const CAUSAL_KINDS = ['process.exit', 'process.abort', 'uncaughtExceptionMonitor']; + +/** + * Events that prove the process reached Node's shutdown path but say nothing about why. + * + * `exit` and `beforeExit` fire for any orderly termination. Treating them as causal would let a + * child that merely finished be reported as having explained itself. What they do establish is + * real and worth separating: neither fires for an external `TerminateProcess` or a native fault. + */ +const LIFECYCLE_KINDS = ['exit', 'beforeExit']; + +/** Every event the preload records that implies the child was still running JS. */ +const JS_EXIT_KINDS = [...CAUSAL_KINDS, ...LIFECYCLE_KINDS]; + +/** + * State the strongest claim the combined evidence supports, and no stronger. + * + * The child-side log is what makes an otherwise ambiguous exit code informative: `process.exit(1)` + * and an uncaught exception both log something and both fire Node's `exit` event, so a child that + * reached `preload-installed` and then logged nothing at all cannot have died either way. What + * remains — an external `TerminateProcess`, or a native path that bypasses JS entirely — is a + * narrowing, not an identification, and this returns it as such. + * + * @param {{ id: string, specific: boolean }} classification + * @param {readonly string[]} childKinds Event kinds the child logged, in order. + * @returns {{ narrowed: boolean, statement: string }} + */ +function narrowFromChildEvidence(classification, childKinds) { + const reachedPreload = childKinds.includes('preload-installed'); + const causal = CAUSAL_KINDS.find((kind) => childKinds.includes(kind)); + const lifecycle = LIFECYCLE_KINDS.some((kind) => childKinds.includes(kind)); + + if (!reachedPreload) { + return { narrowed: false, statement: 'the child never recorded preload-installed, so nothing is known about its JS lifecycle' }; + } + if (causal !== undefined) { + return { + narrowed: false, + statement: `the child logged ${causal}, which names the cause; the exit status only corroborates it`, + }; + } + if (lifecycle) { + // Worth stating separately rather than folding into either branch: reaching `exit` proves the + // child shut down through JS, which no external kill or native fault does — but no hook of ours + // fired, so nothing here says why it chose to exit. + return { + narrowed: true, + statement: + "the child reached Node's shutdown events without any hook naming a cause, which rules out an " + + 'external termination and a native fault — both bypass them — but does not say why it exited', + }; + } + if (classification.specific) { + return { + narrowed: true, + statement: + `the child ran no JS exit path, which excludes process.exit and an uncaught exception, and the exit status names ${classification.id} ` + + 'as the candidate mechanism — the status is a number the terminating party chose, so this is the strongest candidate rather than proof', + }; + } + return { + narrowed: true, + statement: + 'the child reached preload-installed and then ran no JS exit path at all, which excludes process.exit and an uncaught exception; ' + + 'an external TerminateProcess or a native path that bypasses JS remains, and the exit status alone does not choose between them', + }; +} + +/** + * Extract the file-level failures Node reports as its own bare fallback from a TAP report. + * + * Both conditions are required, and the second is the one that matters. Node writes + * `error: 'test failed'` for *any* file whose child exited non-zero, so a file containing an + * ordinary failing assertion carries it too — with `failureType: 'subtestsFailed'`, because the + * runner saw a subtest fail (`kSubtestsFailed`). Signature B is the other branch: no subtest + * failed, so the runner falls back to `kTestCodeFailure`. Matching on the message alone would + * report every ordinary regression as a capture and halt the pass on a false positive. + * + * @param {string} tapText + * @returns {Array<{ file: string, exitCode: number | null, signal: string | null, failureType: string | null, durationMs: number | null }>} + */ +function parseTapFailures(tapText) { + const blocks = String(tapText).matchAll(/^not ok \d+ - (.+?)$\r?\n\s*---\r?\n([\s\S]*?)^\s*\.\.\.$/gm); + const out = []; + for (const [, rawName, body] of blocks) { + if (!/^\s*error: 'test failed'\s*$/m.test(body)) continue; + if (!/^\s*failureType: 'testCodeFailure'\s*$/m.test(body)) continue; + if (out.length >= MAX_RECORDS) break; + const scalar = (key) => { + const found = new RegExp(`^\\s*${key}: (.+)$`, 'm').exec(body); + return found ? found[1].trim() : null; + }; + const exit = scalar('exitCode'); + const sig = scalar('signal'); + const dur = scalar('duration_ms'); + out.push({ + file: rawName.trim().replace(/\\\\/g, '\\'), + exitCode: exit === null || exit === '~' ? null : Number(exit), + signal: sig === null || sig === '~' ? null : sig.replace(/^'|'$/g, ''), + failureType: scalar('failureType')?.replace(/^'|'$/g, '') ?? null, + durationMs: dur === null ? null : Number(dur), + }); + } + return out; +} + +/** + * Read every child log the preload wrote, keyed by the test file each child was running. + * + * The preload records `testFile` on every line for children (it is `null` for the parent runner, + * which has no `NODE_TEST_CONTEXT`), so the join key is the file path and the PID comes with it. + * Malformed lines are skipped rather than throwing: a child killed mid-write can leave a partial + * final line, and losing that line must not lose the rest of the record. + * + * @param {string} logDir + * @returns {Map} keyed by the child's whole normalised path + */ +function readChildLogs(logDir) { + const byFile = new Map(); + let entries; + try { + entries = fs.readdirSync(logDir); + } catch { + return byFile; + } + for (const entry of entries) { + if (!entry.endsWith('.jsonl')) continue; + let text; + try { + text = fs.readFileSync(path.join(logDir, entry), 'utf8'); + } catch { + continue; + } + for (const line of text.split('\n')) { + if (line.trim() === '') continue; + let record; + try { + record = JSON.parse(line); + } catch { + continue; + } + if (typeof record.testFile !== 'string' || record.testFile === '') continue; + // Keyed on the child's whole path, not its basename. A suite run spans directories, and + // `foo/a.test.js` and `bar/a.test.js` are different files whose events must never be merged. + const key = normalizePath(record.testFile); + const existing = byFile.get(key) ?? { pid: null, kinds: [] }; + existing.pid = typeof record.pid === 'number' ? record.pid : existing.pid; + if (typeof record.kind === 'string') existing.kinds.push(record.kind); + byFile.set(key, existing); + } + } + return byFile; +} + +/** + * Find the child log belonging to one parent failure, or say that it cannot be told apart. + * + * The parent names the file as the runner received it, usually a relative path; the child records + * its own resolved `argv[1]`, an absolute one. Matching is therefore by path *suffix* rather than + * equality, which identifies `dist-test/test/foo/a.test.js` uniquely even when `bar/a.test.js` + * exists. Basename is only a fallback for a parent path too short to disambiguate, and when either + * step finds more than one candidate the answer is **ambiguous** rather than the first match: + * attaching one file's PID and lifecycle events to another file's failure would make the diagnostic + * assert something false, which is worse than reporting that it does not know. + * + * @param {ReturnType} childLogs + * @param {string} parentFile + * @returns {{ child: { pid: number | null, kinds: string[] } | null, ambiguous: boolean, candidates: number }} + */ +function matchChild(childLogs, parentFile) { + const wanted = normalizePath(parentFile); + const entries = [...childLogs.entries()]; + + const bySuffix = entries.filter(([key]) => key === wanted || key.endsWith(`/${wanted}`)); + if (bySuffix.length === 1) return { child: bySuffix[0][1], ambiguous: false, candidates: 1 }; + if (bySuffix.length > 1) return { child: null, ambiguous: true, candidates: bySuffix.length }; + + const base = fileKey(wanted); + const byBase = entries.filter(([key]) => fileKey(key) === base); + if (byBase.length === 1) return { child: byBase[0][1], ambiguous: false, candidates: 1 }; + if (byBase.length > 1) return { child: null, ambiguous: true, candidates: byBase.length }; + + return { child: null, ambiguous: false, candidates: 0 }; +} + +/** + * Join parent-observed failures to child-observed lifecycle evidence, one record per failure. + * + * Matching is by whole normalised path, not by basename. The parent names the file as the runner + * received it while the child records its own resolved `argv[1]`, so the child's key is the longer + * path and the parent's name is a suffix of it; a basename comparison is the fallback, not the rule. + * Basenames are *not* unique across the suite's compiled output, which is why a name matching more + * than one child is reported `ambiguous` rather than resolved to whichever came first. A failure + * with no matching child log is reported with `child.logFound: false` rather than being dropped, + * because "the child never wrote a log" is itself evidence. + * + * @param {ReturnType} failures + * @param {ReturnType} childLogs + * @returns {Array} + */ +function correlate(failures, childLogs) { + return failures.map((failure) => { + const match = matchChild(childLogs, failure.file); + const kinds = match.child?.kinds ?? []; + const classification = classifyTermination(failure); + const narrowing = narrowFromChildEvidence(classification, kinds); + return { + file: failure.file, + parent: { + exitCode: failure.exitCode, + signal: failure.signal, + failureType: failure.failureType, + durationMs: failure.durationMs, + }, + child: { + logFound: match.child !== null, + ambiguous: match.ambiguous, + candidates: match.candidates, + pid: match.child?.pid ?? null, + kinds, + }, + classification: classification.id, + meaning: classification.meaning, + specific: classification.specific, + narrowed: match.ambiguous ? false : narrowing.narrowed, + statement: match.ambiguous + ? `${match.candidates} child logs match this file's name and none matches its path, so no lifecycle evidence can be attributed to it without guessing` + : narrowing.statement, + }; + }); +} + +module.exports = { + EXIT_CODE_TABLE, + MAX_RECORDS, + classifyTermination, + correlate, + matchChild, + narrowFromChildEvidence, + normalizePath, + parseTapFailures, + readChildLogs, +}; + +if (require.main === module) { + const args = process.argv.slice(2); + const known = new Set(['--tap', '--child-logs']); + let usage = null; + // `--tap --child-logs dir` must be a usage error, not a request to read a file called + // "--child-logs". An option that swallows the next option produces a confident wrong answer. + const valueOf = (flag) => { + const at = args.indexOf(flag); + if (at === -1) return null; + const value = args[at + 1]; + if (value === undefined || known.has(value)) { + usage = `${flag} requires a value`; + return null; + } + return value; + }; + const tapPath = valueOf('--tap'); + const logDir = valueOf('--child-logs'); + if (usage !== null || tapPath === null || logDir === null) { + process.stderr.write(`${usage ?? 'usage'}: signature-b-correlate.cjs --tap --child-logs \n`); + process.exitCode = 2; + } else { + const records = correlate(parseTapFailures(fs.readFileSync(tapPath, 'utf8')), readChildLogs(logDir)); + for (const record of records) process.stdout.write(`${JSON.stringify(record)}\n`); + if (records.length === 0) process.stderr.write('no Signature B failures in this report\n'); + } +} diff --git a/packages/api/test/diagnostics/signature-b-correlate.test.ts b/packages/api/test/diagnostics/signature-b-correlate.test.ts new file mode 100644 index 00000000..06bde36b --- /dev/null +++ b/packages/api/test/diagnostics/signature-b-correlate.test.ts @@ -0,0 +1,722 @@ +import { test } from 'node:test'; +import assert from 'node:assert/strict'; +import { spawn, spawnSync } from 'node:child_process'; +import fs from 'node:fs'; +import os from 'node:os'; +import path from 'node:path'; + +const DIAGNOSTICS_DIR = path.resolve(__dirname, '../../../test/diagnostics'); +const CORRELATE_PATH = path.join(DIAGNOSTICS_DIR, 'signature-b-correlate.cjs'); +const PRELOAD_PATH = path.join(DIAGNOSTICS_DIR, 'signature-b-preload.cjs'); + +/** + * One record per parent-observed failure, exactly as `correlate` emits it. + * + * Declared once so the tests assert against the contract instead of each call site casting to its + * own guess of the shape. A field that moves or is dropped then fails to compile here, rather than + * silently passing every test that did not happen to name it. + */ +interface CorrelatedRecord { + file: string; + parent: { + exitCode: number | null; + signal: string | null; + failureType: string | null; + durationMs: number | null; + }; + child: { + logFound: boolean; + ambiguous: boolean; + candidates: number; + pid: number | null; + kinds: string[]; + }; + classification: string; + meaning: string; + specific: boolean; + narrowed: boolean; + statement: string; +} + +/* eslint-disable @typescript-eslint/no-var-requires */ +const correlator = require(CORRELATE_PATH) as { + EXIT_CODE_TABLE: ReadonlyArray<{ code: number; id: string; specific: boolean }>; + MAX_RECORDS: number; + classifyTermination(t: { exitCode: number | null; signal: string | null }): { + id: string; + meaning: string; + specific: boolean; + }; + correlate(failures: unknown[], childLogs: Map): CorrelatedRecord[]; + narrowFromChildEvidence( + c: { id: string; specific: boolean }, + kinds: readonly string[], + ): { narrowed: boolean; statement: string }; + parseTapFailures(tap: string): Array<{ + file: string; + exitCode: number | null; + signal: string | null; + failureType: string | null; + durationMs: number | null; + }>; + readChildLogs(dir: string): Map; + matchChild(logs: Map, file: string): { child: unknown; ambiguous: boolean; candidates: number }; + normalizePath(p: string): string; +}; + +/** A TAP block in the exact shape Node's built-in reporter emits for a file-level failure. */ +function tapFailure(file: string, exitCode: string, signal = '~', failureType = 'testCodeFailure'): string { + return [ + `# Subtest: ${file}`, + `not ok 1 - ${file}`, + ' ---', + ' duration_ms: 612.4', + " type: 'test'", + ` location: 'C:\\repo\\${file}:1:1'`, + ` failureType: '${failureType}'`, + ` exitCode: ${exitCode}`, + ` signal: ${signal}`, + " error: 'test failed'", + " code: 'ERR_TEST_FAILURE'", + ' ...', + ].join('\n'); +} + +test('correlator: reads the exit status the spec reporter discards out of a TAP block', () => { + const failures = correlator.parseTapFailures(tapFailure('studies-api.test.js', '3221225477')); + + assert.equal(failures.length, 1); + assert.equal(failures[0]?.exitCode, 3221225477, 'the NTSTATUS code survives as an unsigned integer'); + assert.equal(failures[0]?.signal, null, 'a YAML ~ is null, not the string "~"'); + assert.equal(failures[0]?.failureType, 'testCodeFailure'); +}); + +test('correlator: ignores a test that failed on its own assertion', () => { + const realFailure = [ + 'not ok 1 - some genuine test', + ' ---', + ' duration_ms: 3.1', + " error: 'Expected values to be strictly equal'", + ' ...', + ].join('\n'); + + assert.deepEqual(correlator.parseTapFailures(realFailure), [], 'only Node\'s bare fallback is Signature B'); +}); + +test('correlator: an ordinary failing assertion is not a Signature B capture', () => { + // Node writes `error: 'test failed'` for any file whose child exited non-zero, so a file holding + // an ordinary failing test carries the identical message — under `subtestsFailed`, because a + // subtest did fail. Matching the message alone would report every regression as a capture and + // halt the pass on a false positive. + const ordinary = tapFailure('has-a-failing-test.test.js', '1', '~', 'subtestsFailed'); + + assert.deepEqual(correlator.parseTapFailures(ordinary), [], 'only the no-subtest-failed branch is this defect'); + assert.equal(correlator.parseTapFailures(tapFailure('died.test.js', '1')).length, 1, 'testCodeFailure still counts'); +}); + +test('correlator: classifies every termination code that was measured on this platform', () => { + assert.equal(correlator.classifyTermination({ exitCode: 134, signal: null }).id, 'native-abort-or-v8-fatal'); + assert.equal(correlator.classifyTermination({ exitCode: 3221225477, signal: null }).id, 'native-access-violation'); + assert.equal(correlator.classifyTermination({ exitCode: 4294967295, signal: null }).id, 'external-terminate-process'); + assert.equal( + correlator.classifyTermination({ exitCode: 3221225786, signal: null }).id, + 'external-control-c', + '0xC000013A is STATUS_CONTROL_C_EXIT, a console interrupt — not a native fault', + ); +}); + +test('correlator: an unmeasured NTSTATUS code names no mechanism', () => { + // The range fallback used to report anything at or above 0xC0000000 as a native-fault candidate. + // STATUS_CONTROL_C_EXIT (0xC000013A) disproves that as a rule: it lives in the range and means a + // console CTRL+C. So membership narrows the shape of the answer and nothing more, and a value the + // measured table does not cover has to be reported non-specific. + const unmeasured = correlator.classifyTermination({ exitCode: 0xc0000022, signal: null }); + + assert.equal(unmeasured.id, 'ntstatus-unmeasured'); + assert.equal(unmeasured.specific, false, 'an unmeasured status in the range must not claim a mechanism'); + assert.match(unmeasured.meaning, /does not cover/); + assert.doesNotMatch(unmeasured.meaning, /^candidate:/, 'it names no candidate to lead with'); +}); + +test('correlator: an exit status names a candidate mechanism, never a proven one', () => { + // An exit status is a 32-bit integer the terminating party chooses. `TerminateProcess(h, + // 0xC0000005)` produces the same number as a real access violation, so treating the number as + // proof of a native fault would be an unsupported claim dressed as a measurement. + for (const exitCode of [134, 3221225477, 3221226505, 3221225725, 3221225540, 4294967295, 3221225786]) { + const classification = correlator.classifyTermination({ exitCode, signal: null }); + assert.equal(classification.specific, true, `${exitCode} names a specific mechanism`); + assert.match(classification.meaning, /candidate/, `${exitCode} must be described as a candidate`); + } + + assert.ok( + correlator.EXIT_CODE_TABLE.every((entry) => !('conclusive' in entry)), + 'no entry may claim to be conclusive from its status number alone', + ); +}); + +test('correlator: same-basename files in different directories are never merged', () => { + const logDir = fs.mkdtempSync(path.join(os.tmpdir(), 'sigb-collide-')); + try { + const lines = [ + { kind: 'start', pid: 111, testFile: 'C:\\r\\dist-test\\test\\foo\\a.test.js' }, + { kind: 'exit', pid: 111, testFile: 'C:\\r\\dist-test\\test\\foo\\a.test.js' }, + { kind: 'start', pid: 222, testFile: 'C:\\r\\dist-test\\test\\bar\\a.test.js' }, + { kind: 'preload-installed', pid: 222, testFile: 'C:\\r\\dist-test\\test\\bar\\a.test.js' }, + ]; + fs.writeFileSync(path.join(logDir, 'run-c.jsonl'), `${lines.map((l) => JSON.stringify(l)).join('\n')}\n`); + const logs = correlator.readChildLogs(logDir); + + const resolved = correlator.correlate( + correlator.parseTapFailures(tapFailure('dist-test/test/bar/a.test.js', '1')), + logs, + ); + assert.equal(resolved[0]?.child.pid, 222, 'the full path picks the right one of two same-named files'); + assert.equal(resolved[0]?.child.ambiguous, false); + assert.deepEqual(resolved[0]?.child.kinds, ['start', 'preload-installed']); + + // A parent path too short to disambiguate must be reported as ambiguous, never guessed. + const ambiguous = correlator.correlate( + correlator.parseTapFailures(tapFailure('a.test.js', '1')), + logs, + ); + assert.equal(ambiguous[0]?.child.ambiguous, true, 'two candidates is not an answer'); + assert.equal(ambiguous[0]?.child.pid, null, 'and no PID may be attributed'); + assert.equal(ambiguous[0]?.narrowed, false, 'evidence that is not this file\'s narrows nothing'); + assert.match(ambiguous[0]?.statement ?? '', /without guessing/); + } finally { + fs.rmSync(logDir, { recursive: true, force: true }); + } +}); + +test('correlator: an option given no value is a usage error, not a path', () => { + const run = (args: string[]): ReturnType => + spawnSync(process.execPath, [CORRELATE_PATH, ...args], { + encoding: 'utf8', + env: { ...process.env, NODE_TEST_CONTEXT: undefined }, + }); + + // `--tap --child-logs d` must not read a file literally called "--child-logs". + const swallowed = run(['--tap', '--child-logs', 'd']); + assert.notEqual(swallowed.status, 0); + assert.match(`${swallowed.stderr}`, /--tap requires a value/); + + const missing = run(['--tap']); + assert.notEqual(missing.status, 0); + assert.match(`${missing.stderr}`, /requires a value/); +}); + +test('correlator: names the signal that killed a child but never claims who sent it', () => { + // Node's exit contract reports the signal, not its sender, so an external SIGKILL on Linux is + // indistinguishable here from a runner cancellation. Attributing one would be the same + // unsupported leap this module refuses to make for exit code 1. + const classification = correlator.classifyTermination({ exitCode: null, signal: 'SIGKILL' }); + + assert.equal(classification.id, 'signal-terminated'); + assert.equal(classification.specific, false, 'the mechanism is known; the actor is not'); + assert.match(classification.meaning, /SIGKILL/); + assert.doesNotMatch(classification.meaning, /the test runner killed/, 'no sender may be named'); +}); + +test('correlator: refuses to identify exit code 1, which four different causes produce', () => { + const classification = correlator.classifyTermination({ exitCode: 1, signal: null }); + + assert.equal(classification.id, 'inconclusive'); + assert.equal(classification.specific, false, 'claiming a cause from exit code 1 would be the wrong answer'); +}); + +test('correlator: an unrun JS exit path narrows an inconclusive code without identifying it', () => { + const inconclusive = { id: 'inconclusive', specific: false }; + + const silent = correlator.narrowFromChildEvidence(inconclusive, ['start', 'preload-installed']); + assert.equal(silent.narrowed, true); + assert.match(silent.statement, /excludes process\.exit and an uncaught exception/); + + const exited = correlator.narrowFromChildEvidence(inconclusive, ['start', 'preload-installed', 'process.exit']); + assert.equal(exited.narrowed, false, 'a child whose own log names the cause explains itself'); + + const nothing = correlator.narrowFromChildEvidence(inconclusive, []); + assert.equal(nothing.narrowed, false, 'no child log is no evidence'); +}); + +test('correlator: a shutdown event is not a cause, and is not reported as one', () => { + // `exit` and `beforeExit` fire for any orderly termination, so treating them as causal would let + // a child that merely finished be reported as having explained itself. What they do establish is + // narrower and still useful: neither fires for an external kill or a native fault. + const inconclusive = { id: 'inconclusive', specific: false }; + + const named = correlator.narrowFromChildEvidence(inconclusive, ['preload-installed', 'process.exit', 'exit']); + assert.equal(named.narrowed, false, 'a hook that names the cause explains the child'); + assert.match(named.statement, /process\.exit, which names the cause/); + + const shutdownOnly = correlator.narrowFromChildEvidence(inconclusive, ['preload-installed', 'exit']); + assert.equal(shutdownOnly.narrowed, true, 'reaching shutdown is evidence, just not of a cause'); + assert.doesNotMatch(shutdownOnly.statement, /names the cause/, 'no cause may be claimed from a lifecycle event'); + assert.match(shutdownOnly.statement, /does not say why it exited/); + + const beforeOnly = correlator.narrowFromChildEvidence(inconclusive, ['preload-installed', 'beforeExit']); + assert.doesNotMatch(beforeOnly.statement, /names the cause/, 'beforeExit names nothing either'); +}); + +test('correlator: joins the parent record to the child that ran that file', () => { + const logDir = fs.mkdtempSync(path.join(os.tmpdir(), 'sigb-correlate-')); + try { + // The unrelated child is written FIRST on purpose: a correlator that took whichever log came + // to hand rather than the one for this file would report PID 9999, and ordering it the other + // way round would let that mistake pass unnoticed. + const lines = [ + { kind: 'start', pid: 9999, testFile: 'C:\\repo\\dist-test\\test\\other.test.js' }, + { kind: 'exit', pid: 9999, testFile: 'C:\\repo\\dist-test\\test\\other.test.js' }, + { kind: 'start', pid: 4242, testFile: 'C:\\repo\\dist-test\\test\\studies-api.test.js' }, + { kind: 'preload-installed', pid: 4242, testFile: 'C:\\repo\\dist-test\\test\\studies-api.test.js' }, + ]; + fs.writeFileSync(path.join(logDir, 'run-1.jsonl'), `${lines.map((l) => JSON.stringify(l)).join('\n')}\n`); + + const records = correlator.correlate( + correlator.parseTapFailures(tapFailure('dist-test/test/studies-api.test.js', '1')), + correlator.readChildLogs(logDir), + ); + + assert.equal(records.length, 1); + assert.equal(records[0]?.child.pid, 4242, 'the PID comes from the child that ran this file, not another'); + assert.deepEqual(records[0]?.child.kinds, ['start', 'preload-installed']); + assert.equal(records[0]?.parent.exitCode, 1); + assert.equal(records[0]?.classification, 'inconclusive'); + assert.equal(records[0]?.narrowed, true, 'silence on the child side is what makes exit code 1 informative'); + } finally { + fs.rmSync(logDir, { recursive: true, force: true }); + } +}); + +test('correlator: joins a capture taken on either platform, read on either platform', () => { + // A capture is taken on the developer machine and may be read anywhere, CI included. The host's + // own path helpers split only on the host's separator, so a Windows log read on Linux would keep + // its backslashes and match nothing — which is exactly how CI caught this. + const logDir = fs.mkdtempSync(path.join(os.tmpdir(), 'sigb-sep-')); + try { + const lines = [ + { kind: 'start', pid: 111, testFile: 'C:\\repo\\dist-test\\test\\windows-style.test.js' }, + { kind: 'start', pid: 222, testFile: '/home/runner/repo/dist-test/test/posix-style.test.js' }, + ]; + fs.writeFileSync(path.join(logDir, 'run-3.jsonl'), `${lines.map((l) => JSON.stringify(l)).join('\n')}\n`); + + const logs = correlator.readChildLogs(logDir); + + assert.deepEqual( + [...logs.keys()].sort(), + ['/home/runner/repo/dist-test/test/posix-style.test.js', 'C:/repo/dist-test/test/windows-style.test.js'].sort(), + 'both separators normalise to / so the key never depends on the reading platform', + ); + + const pidFor = (file: string): number | null => + correlator.correlate(correlator.parseTapFailures(tapFailure(file, '1')), logs)[0]?.child.pid ?? null; + + assert.equal(pidFor('dist-test/test/windows-style.test.js'), 111, 'a backslash-recorded child matches its parent'); + assert.equal(pidFor('dist-test/test/posix-style.test.js'), 222, 'so does a forward-slash one'); + } finally { + fs.rmSync(logDir, { recursive: true, force: true }); + } +}); + +test('correlator: a malformed trailing line does not discard the record before it', () => { + const logDir = fs.mkdtempSync(path.join(os.tmpdir(), 'sigb-correlate-')); + try { + const good = JSON.stringify({ kind: 'start', pid: 7, testFile: 'a.test.js' }); + fs.writeFileSync(path.join(logDir, 'run-2.jsonl'), `${good}\n{"kind":"preload-inst`); + + const logs = correlator.readChildLogs(logDir); + + assert.equal(logs.get('a.test.js')?.pid, 7, 'a child killed mid-write still yields what it managed to log'); + } finally { + fs.rmSync(logDir, { recursive: true, force: true }); + } +}); + +test('correlator: bounds how many records one report can produce', () => { + const many = Array.from({ length: correlator.MAX_RECORDS + 25 }, (_, i) => tapFailure(`f${i}.test.js`, '1')).join('\n'); + + assert.equal(correlator.parseTapFailures(many).length, correlator.MAX_RECORDS); +}); + +/** Runs the pass script and returns its result, isolated from this suite's own test context. */ +function runPass(args: string[], cwd?: string): ReturnType { + return spawnSync(process.execPath, [path.join(DIAGNOSTICS_DIR, 'run-signature-b-pass.mjs'), ...args], { + cwd: cwd ?? path.resolve(DIAGNOSTICS_DIR, '../..'), + encoding: 'utf8', + env: { ...process.env, NODE_TEST_CONTEXT: undefined }, + }); +} + +/** + * Read a worker pid once the file actually holds one. + * + * `existsSync` turns true when the worker creates the file, which can precede it writing the bytes. + * An empty read gives `Number('') === 0`, and pid 0 is not "no process" — `process.kill(0, ...)` + * addresses this test's *own* process group, so a naive read would have the test signalling itself + * and then reporting the worker as still alive. + * + * @returns the pid, or null if none appeared before the deadline + */ +async function readWorkerPid(pidFile: string, timeoutMs = 20_000): Promise { + const deadline = Date.now() + timeoutMs; + for (;;) { + try { + const pid = Number(fs.readFileSync(pidFile, 'utf8').trim()); + if (Number.isInteger(pid) && pid > 0) return pid; + } catch { + /* not written yet */ + } + if (Date.now() >= deadline) return null; + await new Promise((resolve) => setTimeout(resolve, 50)); + } +} + +/** + * Kill a pid outright, tolerating one that is already gone. + * + * Used from `finally` in the tests that deliberately start a long-sleeping worker: if their cleanup + * assertion fails, the worker they were complaining about would otherwise outlive the suite and + * interfere with whatever runs next. A test that leaks the process it is policing is worse than no + * test at all. + */ +function reap(pid: number | null): void { + if (pid === null) return; + try { + process.kill(pid, 'SIGKILL'); + } catch { + /* already gone, which is what the assertion wanted */ + } +} + +/** + * Wait for a pid to disappear, or give up. + * + * `process.kill(pid, 0)` sends no signal and throws ESRCH once the process is gone, but signal + * delivery and reaping are asynchronous — sampling once right after a kill can still see a process + * that is on its way out. Polling to a deadline tests the guarantee that actually matters ("it does + * not survive") without asserting anything about how fast the OS gets there. + */ +async function waitForExit(pid: number, timeoutMs = 15_000): Promise { + const deadline = Date.now() + timeoutMs; + for (;;) { + try { + process.kill(pid, 0); + } catch { + return true; + } + if (Date.now() >= deadline) return false; + await new Promise((resolve) => setTimeout(resolve, 50)); + } +} + +/** A test file that finishes immediately, so a pass over it costs a process start and nothing more. */ +function trivialTarget(dir: string): string { + const file = path.join(dir, 'noop.test.cjs'); + fs.writeFileSync(file, "require('node:test').test('noop', () => {});\n"); + return file; +} + +test('pass runner: --runs is a whole, finite, positive count', () => { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'sigb-runs-')); + try { + const target = trivialTarget(dir); + + // A fractional count is the one that matters: 1.5 passes a naive positive-number check and then + // executes runs 1 and 2, exceeding the ceiling the pass just declared to the reader. + for (const bad of ['1.5', '0', '-3', 'Infinity', 'twenty', '']) { + const result = runPass(['--runs', bad, '--target', target, '--out', path.join(dir, `r${bad || 'empty'}`)]); + assert.notEqual(result.status, 0, `--runs ${JSON.stringify(bad)} must be refused`); + assert.match(`${result.stderr}`, /must be a (positive number|whole number of runs)/, `--runs ${JSON.stringify(bad)} must say why`); + assert.doesNotMatch(`${result.stdout}`, /was not observed/, 'a refused ceiling must not report a clean pass'); + } + + for (const good of ['1', '2']) { + const out = path.join(dir, `ok${good}`); + const result = runPass(['--runs', good, '--target', target, '--out', out]); + assert.equal(result.status, 0, `--runs ${good} must be accepted`); + const summary = JSON.parse(fs.readFileSync(path.join(out, 'summary.json'), 'utf8')) as { runs: unknown[] }; + assert.equal(summary.runs.length, Number(good), `--runs ${good} must execute exactly ${good} run(s)`); + } + } finally { + fs.rmSync(dir, { recursive: true, force: true }); + } +}); + +test('pass runner: an option consumed as another option is a usage error', () => { + for (const args of [['--out', '--target', 'x'], ['--target', '--out'], ['--max-minutes']]) { + const result = runPass(args); + assert.notEqual(result.status, 0, `${args.join(' ')} must be refused`); + assert.match(`${result.stderr}`, /requires a value/); + } + assert.ok(!fs.existsSync(path.resolve(DIAGNOSTICS_DIR, '../..', '--target')), 'and must create no directory named after an option'); +}); + +test('pass runner: the ceiling kills the run and every process it started', async () => { + // Deterministic in both directions by a wide margin: the target blocks for 30s while the ceiling + // is 6s, which has to outlast two process starts — this script starts `node --test`, which then + // spawns the per-file worker that records its pid at load time. This is the one behaviour that + // needs a real timeout, because it is the process-tree cleanup being asserted: node:test spawns + // one child per file, and on POSIX a SIGKILL to the runner is not delivered to that child. + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'sigb-tree-')); + let workerPid: number | null = null; + try { + const pidFile = path.join(dir, 'child.pid'); + const target = path.join(dir, 'blocks.test.cjs'); + fs.writeFileSync( + target, + `require('node:fs').writeFileSync(${JSON.stringify(pidFile)}, String(process.pid));\n` + + "require('node:test').test('blocks', async () => {\n" + + ' await new Promise((r) => setTimeout(r, 30000));\n' + + '});\n', + ); + const out = path.join(dir, 'out'); + + const result = runPass(['--runs', '1', '--max-minutes', '0.1', '--target', target, '--out', out]); + + assert.notEqual(result.status, 0, 'a pass with no readable run must not exit successfully'); + const summary = JSON.parse(fs.readFileSync(path.join(out, 'summary.json'), 'utf8')) as { + runs: Array<{ timedOut: boolean; collectionError: string | null }>; + }; + assert.equal(summary.runs[0]?.timedOut, true, 'the deadline, not a signal, is what marks a run timed out'); + assert.match(`${summary.runs[0]?.collectionError}`, /ceiling/); + + workerPid = await readWorkerPid(pidFile); + assert.ok(workerPid !== null, 'the per-file child recorded its pid'); + assert.equal(await waitForExit(workerPid), true, 'the per-file child must not outlive the ceiling'); + // Proven gone, so there is nothing left to reap — and `waitForExit` only ever held the number. + // Passing a dead pid to `reap` would signal whatever the OS has since reused it for. + workerPid = null; + } finally { + reap(workerPid); + fs.rmSync(dir, { recursive: true, force: true }); + } +}); + +test('pass runner: a completed run is not reported as timed out', () => { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'sigb-nottimeout-')); + try { + const out = path.join(dir, 'out'); + const result = runPass(['--runs', '1', '--target', trivialTarget(dir), '--out', out]); + + assert.equal(result.status, 0); + const summary = JSON.parse(fs.readFileSync(path.join(out, 'summary.json'), 'utf8')) as { + runs: Array<{ timedOut: boolean; collectionError: string | null }>; + }; + assert.equal(summary.runs[0]?.timedOut, false, 'a run that finished inside its budget did not time out'); + assert.equal(summary.runs[0]?.collectionError, null); + } finally { + fs.rmSync(dir, { recursive: true, force: true }); + } +}); + +test('pass runner: interrupting the pass takes the detached test tree with it', { + skip: process.platform === 'win32' + ? 'SIGTERM on Windows terminates without running handlers, and libuv already reaps the tree there' + : false, +}, async () => { + // Detaching the run is what makes its group killable, and it is also what stops a terminal Ctrl-C + // reaching it: the runner is no longer in the foreground process group. Without the handlers this + // asserts, interrupting a pass would leave node --test and every per-file worker running against + // the suite database. + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'sigb-signal-')); + try { + const pidFile = path.join(dir, 'child.pid'); + const target = path.join(dir, 'blocks.test.cjs'); + fs.writeFileSync( + target, + `require('node:fs').writeFileSync(${JSON.stringify(pidFile)}, String(process.pid));\n` + + "require('node:test').test('blocks', async () => {\n" + + ' await new Promise((r) => setTimeout(r, 30000));\n' + + '});\n', + ); + + let workerPid: number | null = null; + const pass = spawn( + process.execPath, + [path.join(DIAGNOSTICS_DIR, 'run-signature-b-pass.mjs'), '--runs', '1', '--target', target, '--out', path.join(dir, 'out')], + { cwd: path.resolve(DIAGNOSTICS_DIR, '../..'), env: { ...process.env, NODE_TEST_CONTEXT: undefined }, stdio: 'ignore' }, + ); + + try { + // Wait for the worker to have written a usable pid, so the interrupt has something to clean + // up and the liveness probe addresses the worker rather than this process group. + workerPid = await readWorkerPid(pidFile); + assert.ok(workerPid !== null, 'the per-file worker started and recorded its pid'); + + pass.kill('SIGTERM'); + await new Promise((resolve) => pass.on('close', resolve)); + + assert.equal( + await waitForExit(workerPid), + true, + 'the detached per-file worker must not survive the interrupted pass', + ); + // Same reason as the ceiling test: once the pid is proven gone it belongs to nobody, and + // reaping it later could kill an unrelated process the OS gave that number to. + workerPid = null; + } finally { + // Two ways this test could leak the tree it started: the worker never appears, so the + // assertion throws before the interrupt is sent; or the cleanup being asserted did not happen, + // so the worker is still sleeping. Both are covered here rather than in the happy path. + pass.kill('SIGKILL'); + reap(workerPid); + } + } finally { + fs.rmSync(dir, { recursive: true, force: true }); + } +}); + +test('pass runner: a capture keeps the normalised record and discards the raw TAP', () => { + // The raw TAP is a full transcript of whatever the suite printed. Once `capture.json` holds the + // enumerated fields, keeping the transcript retains arbitrary test output for no diagnostic gain. + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'sigb-capture-')); + try { + const target = path.join(dir, 'dies.test.cjs'); + fs.writeFileSync(target, 'process.exit(3);\n'); + const out = path.join(dir, 'out'); + + const result = runPass(['--runs', '3', '--target', target, '--out', out]); + + assert.equal(result.status, 0); + const capture = JSON.parse(fs.readFileSync(path.join(out, 'capture.json'), 'utf8')) as { + run: number; + records: Array<{ parent: { exitCode: number | null } }>; + }; + assert.equal(capture.run, 1, 'the pass stops at the first capture'); + assert.equal(capture.records[0]?.parent.exitCode, 3, 'and the normalised record carries the exit status'); + + assert.ok(!fs.existsSync(path.join(out, 'run1.tap')), 'the raw TAP must not outlive the normalised record'); + assert.ok(fs.existsSync(path.join(out, 'child-logs-run1')), 'the child lifecycle log is enumerated and kept'); + } finally { + fs.rmSync(dir, { recursive: true, force: true }); + } +}); + +test('pass runner: an existing group-readable --out is secured or refused', { skip: process.platform === 'win32' ? 'POSIX permission bits are not meaningful on Windows; this guarantee is offered on POSIX only' : false }, () => { + // `mkdirSync`'s mode applies only when it creates the directory, so an existing `--out` keeps + // whatever permissions it had — and a captured run's artifacts would land in a shared directory. + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'sigb-perm-')); + try { + const out = path.join(dir, 'shared'); + fs.mkdirSync(out, { recursive: true }); + fs.chmodSync(out, 0o777); + + const result = runPass(['--runs', '1', '--target', trivialTarget(dir), '--out', out]); + + assert.equal(result.status, 0, 'a securable directory is narrowed rather than refused'); + assert.equal(fs.statSync(out).mode & 0o077, 0, 'and it is owner-only before anything is written into it'); + assert.match(`${result.stdout}`, /narrowed/, 'and the narrowing is stated rather than done silently'); + } finally { + fs.rmSync(dir, { recursive: true, force: true }); + } +}); + +test('pass runner: an experiment that runs nothing is refused, not reported clean', () => { + const runner = path.join(DIAGNOSTICS_DIR, 'run-signature-b-pass.mjs'); + const attempt = (runs: string): ReturnType => + spawnSync(process.execPath, [runner, '--runs', runs], { + cwd: path.resolve(DIAGNOSTICS_DIR, '../..'), + encoding: 'utf8', + env: { ...process.env, NODE_TEST_CONTEXT: undefined }, + }); + + for (const runs of ['0', '-3', 'twenty']) { + const result = attempt(runs); + assert.notEqual(result.status, 0, `--runs ${runs} must not exit successfully`); + assert.match(`${result.stderr}`, /must be a positive number/, `--runs ${runs} must say why`); + assert.doesNotMatch( + `${result.stdout}`, + /was not observed/, + 'an experiment that never ran must never claim the defect was not observed', + ); + } +}); + +test('pass runner: a pass whose every run was unreadable is refused, not reported clean', () => { + // The report is made unreadable by construction rather than by racing a clock: `run1.tap` is + // pre-created as a *directory*, so the reporter cannot write it and reading it back raises + // EISDIR. That is deterministic on every machine, needs no timeout, and leaves nothing running — + // a fixture that instead outlived a short ceiling would leak the test-file child the runner had + // already spawned, which survives being killed at one level up. + // + // `--target` points the nested run at one trivial file of this test's own making. Without it the + // run would launch a second copy of the whole API suite against the database the suite running + // this very test is already using. + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'sigb-target-')); + try { + const trivial = path.join(dir, 'noop.test.cjs'); + fs.writeFileSync(trivial, "require('node:test').test('noop', () => {});\n"); + const out = path.join(dir, 'out'); + fs.mkdirSync(path.join(out, 'run1.tap'), { recursive: true }); + + const result = spawnSync( + process.execPath, + [ + path.join(DIAGNOSTICS_DIR, 'run-signature-b-pass.mjs'), + '--runs', '1', + '--target', trivial, + '--out', out, + ], + { + cwd: path.resolve(DIAGNOSTICS_DIR, '../..'), + encoding: 'utf8', + env: { ...process.env, NODE_TEST_CONTEXT: undefined }, + }, + ); + + assert.notEqual(result.status, 0, 'an unreadable pass must not exit successfully'); + assert.doesNotMatch(`${result.stdout}`, /was not observed/, 'and must not claim the defect was not observed'); + assert.match(`${result.stderr}`, /observed nothing/, 'and must say the pass observed nothing'); + } finally { + fs.rmSync(dir, { recursive: true, force: true }); + } +}); + +test('correlator: captures a real child termination end to end through the parent reporter', () => { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'sigb-e2e-')); + try { + // Reproduces Signature B's exact shape: the child dies before registering a single test, so + // the runner has no subtest failure to report and falls back to the bare 'test failed'. + fs.writeFileSync(path.join(dir, 'dies.test.cjs'), 'process.exit(3);\n'); + const tapPath = path.join(dir, 'report.tap'); + const logDir = path.join(dir, 'child-logs'); + fs.mkdirSync(logDir, { recursive: true }); + + const run = spawnSync( + process.execPath, + [ + '--require', PRELOAD_PATH, + '--test-reporter=tap', `--test-reporter-destination=${tapPath}`, + '--test', 'dies.test.cjs', + ], + { + cwd: dir, + encoding: 'utf8', + // NODE_TEST_CONTEXT is set in this process because a test runner spawned it. Inheriting it + // would tell the nested Node it is already a test child, so it would never act as a runner. + env: { ...process.env, NODE_TEST_CONTEXT: undefined, SIGB_LOG_DIR: logDir }, + }, + ); + + assert.notEqual(run.status, 0, 'the runner must report the file as failed'); + + const records = correlator.correlate( + correlator.parseTapFailures(fs.readFileSync(tapPath, 'utf8')), + correlator.readChildLogs(logDir), + ); + + assert.equal(records.length, 1, 'the file-level failure is correlated'); + assert.equal( + records[0]?.parent.exitCode, + 3, + 'the exit code the spec reporter would have discarded is recovered from the parent', + ); + assert.equal(records[0]?.parent.signal, null, 'Windows reports no signal for a self-terminating child'); + assert.ok(typeof records[0]?.child.pid === 'number', 'the child that died is identified by PID'); + assert.ok( + records[0]?.child.kinds.includes('process.exit'), + 'and its own log agrees with the parent about how it went', + ); + } finally { + fs.rmSync(dir, { recursive: true, force: true }); + } +});