diff --git a/examples/app-showcase/test/fixtures/late-console-teardown/leaked-console.test.ts b/examples/app-showcase/test/fixtures/late-console-teardown/leaked-console.test.ts new file mode 100644 index 0000000000..74276ab83c --- /dev/null +++ b/examples/app-showcase/test/fixtures/late-console-teardown/leaked-console.test.ts @@ -0,0 +1,34 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * FIXTURE — not part of this app's suite. + * + * `vitest.config.ts` excludes `test/fixtures/**`, so a normal + * `pnpm --filter @objectstack/example-showcase test` never collects this file. + * It is run only by `test/vitest-console-teardown-race.test.ts`, which spawns + * vitest against THIS directory as its root (at which point the exclude no + * longer matches, because the path is relative to the root being used). + * + * WHAT IT REPRODUCES. The file passes its one assertion and then leaves a + * `console.log` rescheduling itself past the end of the file — the shape #9371 + * had (a messaging dispatcher that outlived its test file) and the shape any + * leaked timer, poll or fire-and-forget write has. In a worker whose console is + * intercepted, each of those logs is an `onUserConsoleLog` RPC whose promise + * vitest discards, so one landing inside the teardown window is rejected with + * `EnvironmentTeardownError` and nobody holds it — an unhandled rejection, and + * vitest fails a run on an unhandled error even with zero failed assertions. + * + * ⛔ Do not "fix" the leak here. The leak IS the instrument. + */ + +import { it, expect } from 'vitest'; + +it('passes, and leaves a console.log rescheduling past the end of the file', () => { + const tick = (): void => { + console.log('late log from a callback that outlived the test file'); + setImmediate(tick).unref?.(); + }; + setImmediate(tick).unref?.(); + + expect(1).toBe(1); +}); diff --git a/examples/app-showcase/test/fixtures/late-console-teardown/vitest.unguarded.config.ts b/examples/app-showcase/test/fixtures/late-console-teardown/vitest.unguarded.config.ts new file mode 100644 index 0000000000..9ca7db41f7 --- /dev/null +++ b/examples/app-showcase/test/fixtures/late-console-teardown/vitest.unguarded.config.ts @@ -0,0 +1,21 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * The ABLATION leg of `test/vitest-console-teardown-race.test.ts`. + * + * `disableConsoleIntercept: false` is vitest's own default, spelled out here + * rather than left implicit: this config exists to state that the ONE variable + * between the two legs is the guard, and to keep the leg honest if the default + * ever changes upstream. It deliberately does not extend the app's real config + * — the fixture imports nothing from the workspace, so the app's aliases and + * excludes cannot affect the measurement, and re-exporting a config that reads + * `__dirname` from a different directory would silently repoint them. + */ + +import { defineConfig } from 'vitest/config'; + +export default defineConfig({ + test: { + disableConsoleIntercept: false, + }, +}); diff --git a/examples/app-showcase/test/vitest-console-teardown-race.test.ts b/examples/app-showcase/test/vitest-console-teardown-race.test.ts new file mode 100644 index 0000000000..44c9592133 --- /dev/null +++ b/examples/app-showcase/test/vitest-console-teardown-race.test.ts @@ -0,0 +1,248 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * [#10293 / #10374] A green suite must not be reddened by a console.log that + * outlives its test file. + * + * THE DEFECT, read out of the installed vitest (4.1.10). The worker replaces + * `console` with one that forwards every write to the main thread over RPC, and + * `sendLog` in `packages/vitest/dist/chunks/console.*.js` DISCARDS the promise + * that forwarding returns. Teardown in `packages/vitest/dist/chunks/init.*.js` + * then runs `await rpcDone()` and, immediately after, a cleanup that calls + * `rpc.$rejectPendingCalls(...)` — and `rpcDone()` awaits a SNAPSHOT + * (`Array.from(promises)`) taken at the moment it is called. Any console RPC + * created after that snapshot is still pending when the rejection sweep runs, + * is rejected with `EnvironmentTeardownError`, and — because `sendLog` kept no + * reference — nobody handles it. vitest fails a run on an unhandled error even + * when no assertion failed, so the signature is a fully green suite exiting 1: + * + * Test Files 21 passed (21) + * Tests 342 passed (342) + * Errors 1 error + * EnvironmentTeardownError: [vitest-worker]: Closing rpc while + * "onUserConsoleLog" was pending + * + * That is what evicted PRs from the merge queue three times in one afternoon: + * the dequeue forces every speculative build behind the PR to rebuild. + * + * WHY IT READS AS LOAD-DEPENDENT. The window is exactly the duration of + * `rpcDone()` — the time to drain the RPC round-trips already in flight. Idle + * that is about a millisecond; on a saturated runner it is wide enough for a + * leaked timer, poll or fire-and-forget write to log inside it. Nothing about + * the code under test changes between the green run and the red one, which is + * why the two reproductions before this one both concluded "cannot reproduce". + * + * WHAT THIS PIN ASSERTS, and why it spawns vitest instead of asserting inline. + * The failure happens during worker teardown, i.e. strictly AFTER every test in + * the file has finished — no assertion inside the affected file can observe it, + * and the only visible symptom is the process exit code. So the pin drives a + * real vitest process over a fixture that deliberately leaks a logging callback + * (`test/fixtures/late-console-teardown/`) and reads the exit code: + * + * - the ABLATION leg runs it under vitest's defaults and requires the harm to + * still reproduce — a positive control, so this pin can never go quietly + * green because the fixture stopped provoking anything; + * - the GUARDED leg runs the SAME fixture under this app's real + * `vitest.config.ts` and requires exit 0. + * + * Delete `disableConsoleIntercept: true` from that config and the guarded leg + * turns red. Both legs also assert `Test Files 1 passed (1)`, because a run + * that collected NOTHING exits 0 too and would read as a pass. + * + * ⚠️ The ablation is a race, not a certainty: measured 8/10, 10/12 and 9/12 on + * an idle 4-vCPU container across three fixture shapes. It is therefore + * retried, and only the exhaustion of every attempt is a failure — reported as + * "the instrument stopped reproducing", never as "the guard broke". + * + * ⚠️ WHY THE CHILD'S OUTPUT IS NORMALISED BEFORE ANYTHING READS IT. Every + * predicate below is a substring of a REPORTER line, and vitest 4 decides both + * the colour and the reporter from the environment it finds itself in: + * `std-env`'s `isAgent` — true when `AI_AGENT`, `CLAUDECODE` and friends are + * set, i.e. in the shell an agent authors this from — makes it call + * tinyrainbow's `disableDefaultColors()` and select the `agent` reporter. A CI + * runner has none of those variables, so the SAME summary line arrives with + * escapes sitting BETWEEN `Test Files` and its count, and a regex written + * against the plain line matches in an agent shell and can never match in CI. + * Measured, on this pin's own first red: the anti-vacuity guard below refused + * to grade a run it could not read, and was right to. So the child is asked for + * plain bytes AND the captured text is stripped before it is read — the guard + * is never the thing that bends. + */ + +import { describe, it, expect } from 'vitest'; +import { spawnSync } from 'node:child_process'; +import { existsSync } from 'node:fs'; +import { stripVTControlCharacters } from 'node:util'; + +// `process.cwd()` is this package's established seed for its own files +// (`test/coverage.test.ts`, `test/inert-wirings.test.ts`) and the one the +// `types/node-shim.d.ts` surface is cut for. `import.meta.url` is NOT available +// here: this package compiles as CommonJS under `module: NodeNext`, so +// `tsc --noEmit` rejects it with TS1470. +const PACKAGE_ROOT = process.cwd(); + +const VITEST_BIN = `${PACKAGE_ROOT}/node_modules/.bin/vitest`; +const APP_CONFIG = `${PACKAGE_ROOT}/vitest.config.ts`; +const FIXTURE_ROOT = `${PACKAGE_ROOT}/test/fixtures/late-console-teardown`; +const ABLATION_CONFIG = `${FIXTURE_ROOT}/vitest.unguarded.config.ts`; + +/** The exact message vitest 4.1.10 rejects a pending console RPC with. */ +const TEARDOWN_ERROR = 'Closing rpc while "onUserConsoleLog" was pending'; + +/** Attempts allowed to the ablation leg before it is declared broken. */ +const ABLATION_ATTEMPTS = 8; +/** Repetitions of the guarded leg. A removed guard reproduces ~80% per run. */ +const GUARDED_REPETITIONS = 4; + +interface Leg { + readonly status: number | null; + /** The child's combined stdout+stderr, ALREADY stripped of ANSI escapes. */ + readonly output: string; + readonly reproduced: boolean; + readonly collectedOneFile: boolean; +} + +/** + * `-c` is resolved RELATIVE TO `--root`, so both paths are absolute here; a + * relative config path silently becomes `/` and the run dies in + * config loading rather than measuring anything. + * + * The child's environment drops vitest's own worker variables: this process IS + * a vitest worker, and leaking `VITEST_POOL_ID` / `VITEST_WORKER_ID` into a + * nested run makes the child believe it was spawned by a pool. + * + * It also pins the child to PLAIN, ENVIRONMENT-INDEPENDENT output, for the + * reason in this file's docblock: + * - `NO_COLOR` is the one switch tinyrainbow short-circuits on, ahead of + * every enabling condition, so it turns colour off wherever the child runs. + * `FORCE_COLOR` is DELETED rather than set to `'0'`, because tinyrainbow + * tests its PRESENCE (`'FORCE_COLOR' in env`) — the disabling spelling + * would have switched colour ON. + * - `--reporter=default` NAMES the reporter instead of letting vitest pick it + * from `isAgent`, which is how the author and CI came to read two different + * summary formats out of the same fixture. + * Then `stripVTControlCharacters` runs over the captured bytes anyway: belt and + * braces, so an escape arriving from some other source cannot quietly + * un-measure this pin the way one already did. + */ +function runFixture(config: string): Leg { + const env: Record = { ...process.env }; + for (const key of Object.keys(env)) { + if (key.startsWith('VITEST')) delete env[key]; + } + delete env.NODE_V8_COVERAGE; + delete env.FORCE_COLOR; + env.NO_COLOR = '1'; + + const result = spawnSync( + VITEST_BIN, + ['run', '-c', config, '--root', FIXTURE_ROOT, '--reporter=default'], + { + encoding: 'utf8', + timeout: 120_000, + env, + }, + ); + + const output = stripVTControlCharacters(`${result.stdout ?? ''}${result.stderr ?? ''}`); + return { + status: result.status, + output, + reproduced: output.includes(TEARDOWN_ERROR), + collectedOneFile: /Test Files\s+1 passed \(1\)/.test(output), + }; +} + +/** + * The anti-vacuity guards below grade the CHILD, whose output is captured and + * therefore never reaches the job log on its own. Saying only "measured + * nothing" leaves a CI-only failure undiagnosable from the log it fails in — + * measured, at the cost of one round trip. So every graded run names its exit + * status and shows the tail of what it actually wrote. + * + * Bounded at three runs and fifteen lines each: a leg can grade eight, and when + * they fail they fail the same way, so an unbounded dump buries the one thing + * being read in seven copies of itself. + */ +const DESCRIBED_RUNS = 3; + +function describeRuns(legs: readonly Leg[]): string { + const blocks = legs.slice(0, DESCRIBED_RUNS).map((leg, index) => { + const tail = leg.output.trimEnd().split('\n').slice(-15).join('\n'); + return ( + `\n--- child run ${index + 1}/${legs.length}: exit=${leg.status}, ` + + `collectedOneFile=${leg.collectedOneFile}, reproduced=${leg.reproduced}\n` + + `${tail === '' ? '(the child wrote nothing at all)' : tail}` + ); + }); + const elided = legs.length - blocks.length; + if (elided > 0) blocks.push(`\n--- ${elided} further run(s) not shown`); + return blocks.join('\n'); +} + +describe('[#10293] vitest console-forwarding teardown race', () => { + it('has a fixture and an ablation config to measure against', () => { + expect(existsSync(VITEST_BIN), `vitest binary missing at ${VITEST_BIN}`).toBe(true); + expect(existsSync(`${FIXTURE_ROOT}/leaked-console.test.ts`)).toBe(true); + expect(existsSync(ABLATION_CONFIG)).toBe(true); + }); + + it( + 'ABLATION: the fixture still reddens a green run under vitest defaults', + { timeout: 240_000 }, + () => { + const attempts: Leg[] = []; + for (let i = 0; i < ABLATION_ATTEMPTS; i++) { + const leg = runFixture(ABLATION_CONFIG); + attempts.push(leg); + if (leg.reproduced) break; + } + + // A run that collected no test file exits 0 and would read as "the harm + // is gone". Grade collection before grading the harm. + expect( + attempts.every((leg) => leg.collectedOneFile), + `the fixture was not collected — the ablation measured nothing. What the ` + + `child runs actually wrote:${describeRuns(attempts)}`, + ).toBe(true); + + const reproduced = attempts.find((leg) => leg.reproduced); + expect( + reproduced, + `the instrument stopped reproducing: ${attempts.length} attempts under vitest ` + + `defaults produced no "${TEARDOWN_ERROR}". Either vitest changed its console ` + + `forwarding (check sendLog/rpcDone in its dist chunks) or the fixture stopped ` + + `leaking. Do NOT relax the guarded leg on the strength of this.`, + ).toBeDefined(); + + // Every assertion in the fixture passed, and the run still failed. That + // conjunction is the whole defect. + expect(reproduced?.status).not.toBe(0); + expect(reproduced?.output).toContain('Tests 1 passed (1)'); + }, + ); + + it( + 'GUARDED: the same fixture exits 0 under this app’s real vitest config', + { timeout: 240_000 }, + () => { + const legs = Array.from({ length: GUARDED_REPETITIONS }, () => runFixture(APP_CONFIG)); + + expect( + legs.every((leg) => leg.collectedOneFile), + `the fixture was not collected under the app config — this leg measured ` + + `nothing. What the child runs actually wrote:${describeRuns(legs)}`, + ).toBe(true); + + const teardownErrors = legs.filter((leg) => leg.reproduced); + expect( + teardownErrors.length, + `${teardownErrors.length}/${legs.length} runs hit the teardown race under the app's ` + + `own config. If disableConsoleIntercept was removed from vitest.config.ts, restore ` + + `it — the docblock there explains why.\n${teardownErrors[0]?.output ?? ''}`, + ).toBe(0); + + expect(legs.map((leg) => leg.status)).toEqual(legs.map(() => 0)); + }, + ); +}); diff --git a/examples/app-showcase/types/node-shim.d.ts b/examples/app-showcase/types/node-shim.d.ts index 04fac89b2d..74d0858736 100644 --- a/examples/app-showcase/types/node-shim.d.ts +++ b/examples/app-showcase/types/node-shim.d.ts @@ -31,4 +31,33 @@ declare module 'node:path' { export function dirname(path: string): string; } -declare const process: { cwd(): string }; +// `test/vitest-console-teardown-race.test.ts` drives a real vitest process over +// a fixture, because the defect it pins (a console RPC rejected during worker +// teardown) is only observable as the child's EXIT CODE — it happens after every +// test in the file has finished, so no in-process assertion can see it. +// Narrowed to the synchronous form and to the three result members that pin +// reads: it must not grow into the whole `child_process` surface. +declare module 'node:child_process' { + export function spawnSync( + command: string, + args: readonly string[], + options: { + encoding: 'utf8'; + timeout?: number; + env?: Record; + }, + ): { status: number | null; stdout: string | null; stderr: string | null }; +} + +// Same pin, one member: it reads the child's reporter output, and vitest +// colourises that output on any machine `std-env` does not recognise as an +// agent shell. Stripping is delegated to the platform rather than to a +// hand-written escape regex, which would have to spell control characters in +// repo source (`pnpm check:nul-bytes`'s territory). +declare module 'node:util' { + export function stripVTControlCharacters(str: string): string; +} + +// `env` joins `cwd()` for the same pin: the nested run must NOT inherit this +// process's own `VITEST_*` variables, or the child believes a pool spawned it. +declare const process: { cwd(): string; env: Record }; diff --git a/examples/app-showcase/vitest.config.ts b/examples/app-showcase/vitest.config.ts index d677b284f6..3a1cb1f977 100644 --- a/examples/app-showcase/vitest.config.ts +++ b/examples/app-showcase/vitest.config.ts @@ -39,6 +39,64 @@ export default defineConfig({ ], }, test: { - exclude: [...configDefaults.exclude, '**/e2e/**'], + // `test/fixtures/**` holds the deliberately-broken inputs that + // `test/vitest-console-teardown-race.test.ts` spawns vitest against. They + // are `*.test.ts` on purpose — that pin runs them with vitest's DEFAULT + // include and this very config, only with the fixture directory as `root`, + // at which point this exclude no longer matches them (it is evaluated + // against the path relative to the root in use). Collecting them here + // instead would import a leaked-console-log fixture into the app's own + // suite, i.e. arm the exact flake the pin exists to keep disarmed. + exclude: [...configDefaults.exclude, '**/e2e/**', 'test/fixtures/**'], + + // ⛔ Do not remove without reading `test/vitest-console-teardown-race.test.ts` + // — that pin fails when this is off, and its ablation leg is what proves it. + // + // THE DEFECT (#10293, mechanism in #10374). vitest 4's worker replaces + // `console` with one that ships every write to the main thread over RPC. + // In `packages/vitest/dist/chunks/console.*.js`: + // + // state().rpc.onUserConsoleLog({ type, content, taskId, ... }); + // + // — the returned promise is DISCARDED. Teardown, in + // `packages/vitest/dist/chunks/init.*.js`, then does + // `await rpcDone()` followed by `$rejectPendingCalls(...)`, and `rpcDone()` + // awaits a SNAPSHOT (`Array.from(promises)`) taken when it is called. A + // console RPC created after that snapshot is still pending when + // `$rejectPendingCalls` runs, is rejected with `EnvironmentTeardownError`, + // and — because nobody kept the promise — surfaces as an UNHANDLED + // rejection. vitest fails a run on an unhandled error even when every + // assertion passed, so the observed signature is a green suite that exits + // 1: `Test Files 21 passed (21) / Tests 342 passed (342) / Errors 1 error`. + // Measured cost when it lands in the merge queue: the PR is dequeued and + // every speculative build behind it rebuilds. + // + // WHY THE WINDOW IS LOAD-DEPENDENT, which is why it reads as a flake: the + // window is the duration of `rpcDone()`, i.e. the time to complete the RPC + // round-trips already in flight. Idle that is ~1ms; on a saturated runner + // it is long enough for a leaked timer or poll to log inside it. Nothing + // about the code under test changes. + // + // WHY THIS SETTING AND NOT A QUIETER SUITE. Turning the interception off is + // vitest's own supported option, and it removes the MECHANISM rather than + // narrowing the trigger: with no RPC there is no pending call to reject, so + // no leak in any future test can redden a green run this way. It is also + // not a silencing: vitest's non-TTY default reporter sets + // `silent: 'passed-only'`, so today this app's console output from passing + // tests is discarded AFTER paying the round-trip. Written straight to the + // worker's stdout it is visible for the first time. Measured on this suite: + // 72 `onUserConsoleLog` calls per run — each carrying a batched buffer, so + // 285 lines — every one of them discarded before this change. That is the + // honest cost too: this app's share of a Test Core log grows by those 285 + // lines (~0.9% of a 31,839-line shard log), most of it `[Registry]` + // registration chatter. Quieting THAT is a separate question about + // `@objectstack/objectql`'s own default log level, not about this setting. + // + // WHAT IT COSTS. Console output loses vitest's `stdout | file > test` + // attribution header and its per-task buffering, so it interleaves in + // arrival order across forks — which is already how the bulk of this app's + // test output behaves, because ObjectQL's logger writes to `process.stdout` + // directly and never went through this path at all. + disableConsoleIntercept: true, }, });