test(showcase): disarm the vitest console-forwarding teardown race that reddens a green suite (#10293, #10374)

[claude]

Fixes#10293
Part of #10374

A fully green @objectstack/example-showcase run can still exit 1. This makes that structurally impossible for this app, and pins it with a reproduction that fails without the change.

The defect, read out of the installed vitest (4.1.10)

The worker replaces console with one that ships every write to the main thread over RPC, and sendLog in packages/vitest/dist/chunks/console.*.jsdiscards the returned promise. Teardown in packages/vitest/dist/chunks/init.*.js then runs await rpcDone() and immediately after a cleanup calling rpc.$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 the rejection sweep runs, is rejected with EnvironmentTeardownError, and because nobody kept the promise it surfaces as an unhandled rejection. Vitest fails a run on an unhandled error even when every assertion passed:

Test Files 21 passed (21)
Tests 342 passed (342)
Errors 1 error
EnvironmentTeardownError: [vitest-worker]: Closing rpc while "onUserConsoleLog" was pending

The window is exactly the duration of rpcDone() — about a millisecond idle, wide enough on a saturated runner for a leaked timer or poll to log inside it. That is the whole of this flake's load-dependence; nothing about the code under test changes. It dequeued three merge-queue PRs in one afternoon, each cascade forcing every speculative build behind it to rebuild.

The change

disableConsoleIntercept: true in examples/app-showcase/vitest.config.ts — vitest's own supported option. With no RPC there is no pending call to reject, so no future leak in any test in this app can redden a green run this way. It removes the mechanism rather than narrowing one trigger.

It is not a silencing. Vitest's non-TTY default reporter sets silent: 'passed-only', so this app's console output from passing tests is discarded today after paying the round-trip. Written straight to the worker's stdout it becomes visible for the first time. Measured: 72 onUserConsoleLog calls per run, each carrying a batched buffer, so the visible log grows by 285 lines (about 0.9% of a 31,839-line Test Core shard log), most of it [Registry] registration chatter. That is the honest cost, and it is recorded in the config docblock. Quieting the registry itself is a separate question about @objectstack/objectql's default log level.

Failing-then-passing evidence

The failure happens during worker teardown, strictly after every test in the file has finished, so no in-process assertion can see it — the only symptom is the child's exit code. test/vitest-console-teardown-race.test.ts therefore drives real vitest processes over test/fixtures/late-console-teardown/, a fixture that passes its one assertion and leaves a console.log rescheduling past the end of the file:

• ablation leg — the same fixture under vitest's defaults, which must still reproduce the harm. A positive control, so the pin can never go quietly green because the fixture stopped provoking anything.
• guarded leg — the same fixture under this app's realvitest.config.ts, which must exit 0.

Both legs assert Test Files 1 passed (1), because a run that collected nothing also exits 0 and would read as a pass.

Measured on an idle 4-vCPU container:

leg	result
fixture under vitest defaults, standalone	8/10, 10/12 and 9/12 runs red across three fixture shapes
disableConsoleIntercept: true, standalone	10/10 green
pin with the guard removed from the config	3/3 pin runs red, 4/4 guarded repetitions hit the race each time
pin with the guard restored	green

The ablation was run against the committed tree and confirmed on disk before each leg (guard-line count 1 to 0, then back to 1; git diff --stat showing exactly the one deletion), not inferred from an editor's exit code.

Two things in the brief that the tree falsified

1. The named file is not a console logger.test/approval-resume-relation-expand.test.ts contains zeroconsole.* calls. The [Registry] ... lines around it in the CI log come from packages/objectql/src/registry.ts — product code — not from the test. And "RPC pressure" is not the driver: the whole suite emits 72 console RPCs per run, not hundreds per file.
2. The live suite no longer reproduces it on main. Under finding: any late console.* in a vitest worker can fail a fully green suite — the #9371 amplifier is upstream and still live #10374's own recipe — 4 concurrent full showcase suites, 3 rounds, 4 vCPU — the suite came back 12/12 green with this guard removed, matching the earlier investigation's 13/13. The specific trigger behind the three CI sightings is most plausibly the messaging dispatcher leak repaired in fix(service-messaging): stop the delivery dispatchers on the kernel's own teardown hook (#9371) #10375, which merged at 18:08Z on 2026-08-20, after the last sighting at 16:39Z. So this change is a structural defence for the package where the flake fired three times, not the repair of a currently-firing failure. It is filed that way deliberately rather than claimed as a reproduction of the live incident.

On the repo-wide half, and on --detectAsyncLeaks

#10374 is general: any package is exposed. Closing it means 73 vitest test tasks (40 with a config, 33 without), which is a diff across every lane and outside this card's surface — so it is left open and the rollout shape is proposed in the report instead.

Its graded scope was to evaluate wiring vitest --detectAsyncLeaks. Measured here: showcase wall time 21s to 40s (about 1.9x), and its four findings on this suite are never-settled Promise.race timeout guards in ObjectKernel that emit no console output and therefore cannot cause this defect. Recorded as #10604. It is a detector for a different class, so it is not wired here.

Follow-up (d88f4445d1): the pin read the child through coloured prose

Test Core and Test Core (1/6) went red on b13c4fad07, both from this PR's own new test and both from its anti-vacuity guard, which refused to grade a nested run it could not see:

x ABLATION: the fixture still reddens a green run under vitest defaults
AssertionError: the fixture was not collected - the ablation measured nothing
x GUARDED: the same fixture exits 0 under this app's real vitest config
AssertionError: the fixture was not collected under the app config - this leg measured nothing

The guard was right; the collection probe was wrong.runFixture() detected collection by scraping the child's human reporter output for Test Files 1 passed (1), and vitest 4 decides both the colour and the reporter of that output from the environment it finds itself in. std-env's isAgent - true when AI_AGENT / CLAUDECODE are set, i.e. in the shell this was authored from - makes vitest call tinyrainbow's disableDefaultColors() (vitest/dist/chunks/cac.*.js) and select the agent reporter instead of default. A CI runner has neither variable, so the identical summary line arrives coloured, with escapes sitting betweenTest Files and its count (escapes written here as ESC):

ESC[2m Test Files ESC[22m ESC[1mESC[32m1 passed ESC[39mESC[22mESC[90m (1)ESC[39m

The regex matches for the author and can never match on CI. Two further predicates over the same text carried the identical fragility: the ablation leg's Tests 1 passed (1) assertion (equally unmatchable), and output.includes(TEARDOWN_ERROR), which survived only because no escape happens to land inside that phrase - which is why the ablation broke after one attempt on CI rather than exhausting eight.

It is not FORCE_COLOR. Measured in this container: FORCE_COLOR=1, CI=true, GITHUB_ACTIONS=true and even --color all leave the child's summary plain in an agent shell, because disableDefaultColors() runs after every one of them. The reproduction is unsetting the agent variables - the only difference that matters - after which both legs fail locally with the exact CI assertion text at the exact CI line numbers (143 and 170).

The repair, all inside runFixture() and its guards:

• ask the child for plain bytes: NO_COLOR=1, the one condition tinyrainbow short-circuits on ahead of every enabling one, and deleteFORCE_COLOR rather than set it to '0', because tinyrainbow tests its presence and the disabling spelling would have switched colour on;
• name the reporter (--reporter=default) instead of letting isAgent pick it, so one summary format reaches the author and CI alike;
• strip ANSI from the captured bytes with stripVTControlCharacters before anything reads them - one boundary, so all three predicates are fixed at once rather than one regex at a time;
• print each graded child's exit status and the tail of its output in the guard's message. The child's output is captured and never reaches the job log on its own, and that absence is precisely what made a CI-only failure cost a round trip.

Measured, before and after, in both environments:

run	result
before, CI-shaped env (agent variables unset)	both legs red, same two assertion messages, same lines 143/170
after, CI-shaped env	Tests 3 passed (3)
after, CI-shaped env plus FORCE_COLOR=1	Tests 3 passed (3)
after, ordinary agent shell	Tests 3 passed (3)

Positive control, so this is not the measurement being switched off: the fixture was renamed out of the child's include glob, and both guards still refused - now naming the cause in the message, No test files found, exiting with code 1. Restored and confirmed byte-identical by sha256, not by an editor's exit code. The ablation leg still reproduces EnvironmentTeardownError (that assertion sits inside the now-green leg) and the guarded leg is still clean across all 4 repetitions.

Verification

Union re-derived with node scripts/pm/dispatch-gates.mjs (no paths passed) and re-run at d88f4445d1, the final commit - all green, each read from the gate's own verdict line rather than from a piped $?:

check:nul-bytes · check:cross-package-test-inputs · check:test-source-alias · check:type-source-resolution · check:query-options-erasure · check:type-check-coverage · check:type-check-debt (--self-test plus --re-measure: "33 ledger entr(ies) re-measured in 272.2s, 1924 raw tsc error(s) total, none above its recorded number") · check:engine-double-contract · check:where-matcher · pnpm --filter @objectstack/example-showcase typecheck (tsc --noEmit, exit 0).

Suite, in both shapes: Test Files 24 passed (24) / Tests 364 passed (364) in the ordinary shell, and the same 24/364 under the CI-shaped environment (agent variables unset, CI=true, GITHUB_ACTIONS=true) that reproduces the red. Heavy runs were serialised through scripts/pm/os-verify-lock.sh; both suite runs reported VERDICT command-exit 0.

No changeset: pnpm check:empty-changeset refuses an empty-frontmatter changeset and routes an examples/-and-tests-only PR to the skip-changeset label instead, since an all-empty pending set makes changesets/action return green without creating a version PR.

---

Generated by Claude Code

---

Generated by Claude Code

[os-zhuang]

PM triage of the red CI — the guard is right, the probe is wrong. Fix dispatched.

Test Core and Test Core (1/6) are red on b13c4fad07. Diagnosed against the full job log (13,310 lines pulled from logs_url, not a tail window). 26 of 29 checks are green; the rest of the showcase suite is fine (Test Files 1 failed | 23 passed (24), Tests 2 failed | 362 passed (364)).

⚠️ First, the trap in this log — for whoever reads it next

It carries dozens of ERROR Find operation failed {"object":"sys_organization" …} lines with the driver's no-verdict wrapper. That is not the failure. It is the exact noise signature #10293 originally adopted as its flake fingerprint, falsified on that thread and traced to passing@objectstack/runtime tests. It appears in green runs too. Anyone grepping this log for a cause will hit it first and it will mislead them.

The actual failure

Both failing legs are this PR's own new test, and both fail on its anti-vacuity guard, not on the behaviour under test:

× ABLATION: the fixture still reddens a green run under vitest defaults
AssertionError: the fixture was not collected — the ablation measured nothing
× GUARDED: the same fixture exits 0 under this app's real vitest config
AssertionError: the fixture was not collected under the app config — this leg measured nothing

⭐ The guard did its job. It refused to grade a run that collected zero files, which is precisely the "a green over a population of nothing" failure this whole family of cards is about. ⛔ It must not be weakened to get to green — it is the only thing standing between this PR and a test that passes while measuring nothing.

Root cause — measured, not reasoned

runFixture() detects collection by scraping the child's human-readable reporter output:

collectedOneFile: /TestFiles\s+1passed\(1\)/.test(output),

That regex cannot match a colorized summary. The raw bytes of a Test Files line in this very job log:

^[[2m Test Files ^[[22m ^[[1m^[[32m23 passed^[[39m^[[22m^[[90m (24)^[[39m

ANSI escapes sit betweenTest Files and the count, and between passed and (1). Checked directly: the regex returns False against the raw line and True only after stripping escapes. 1,694 lines in this log carry escapes, so color is being forced here even through pipes — and runFixture copies process.env wholesale into the child (deleting only VITEST* and NODE_V8_COVERAGE), so the child inherits it and colorizes into the spawnSync pipe. Locally, with color off, the same regex matches. That is the whole local-green / CI-red asymmetry.

Two consequences worth naming beyond the one-line fix:

1. Every other scrape in the file has the same fragility — output.includes(TEARDOWN_ERROR) and the 'Tests 1 passed (1)' assertion are load-bearing in the ablation leg and will break the same way. The instrument should read a machine-readable result rather than a reporter's prose. This is doubly true given finding: any late console.* in a vitest worker can fail a fully green suite — the #9371 amplifier is upstream and still live #10374's own finding that vitest 4's non-TTY default reporter is MinimalReporter with silent: 'passed-only' — the child's reporter in CI is not necessarily the one you see locally.
2. ⭐ The guard is correct but not diagnosable. It says "measured nothing" and prints no child output, so this failure could not be diagnosed from CI alone — which is what cost the round trip. The child's exit status and output tail belong in that message.

Fix dispatched with instructions to reproduce locally under FORCE_COLOR=1 first, and to prove afterwards that the ablation still reproduces the EnvironmentTeardownError and the guarded leg stays clean — i.e. that the measurement was repaired rather than disabled.

---

Generated by Claude Code

[os-zhuang]

PM review — ACCEPT, arming. My hypothesis was right about the mechanism and wrong about the trigger, and the correction matters.

Head d88f4445d1, 30/30 checks green, 0 failing, 0 running (latest run per check name), up from 26/29 with two red. Test Files 24 passed (24) / Tests 364 passed (364).

⭐ The correction to my diagnosis

I told you the child colorizes because it inherits FORCE_COLOR. You measured that and it is false: in this container FORCE_COLOR=1, CI=true, GITHUB_ACTIONS=true, and even --color allall leave the child's summary plain. The real switch is std-env's isAgent — true when AI_AGENT / CLAUDECODE are set, i.e. inside an agent shell — which makes vitest 4.1.10 call tinyrainbow's disableDefaultColors() (vitest/dist/chunks/cac.*.js, if (isAgent) disableDefaultColors()) and select the agent reporter instead of default. A CI runner has neither variable, so color is on there and off here.

That inverts the whole picture: it is not that CI turns color on, it is that every agent shell in this fleet turns it off — so this class of bug is invisible to every one of us locally, by construction, and only ever appears on a runner. ⭐ And it explains a detail I had no account for: why the CI ablation broke after one attempt (1625 ms, one cold child) rather than exhausting all eight — includes(TEARDOWN_ERROR) is true on both raw and stripped bytes because no escape lands inside that phrase, so the loop breaks on the first leg and the collection guard then fails it.

⭐ And my suggested fallback would have made it worse. I proposed setting FORCE_COLOR=0; you found tinyrainbow tests the variable's presence, so FORCE_COLOR=0 would have switched color on. Deleting it, as you did, is the correct move. That is the kind of thing I would have shipped and then re-debugged at the next red.

Reproducing the CI red locally by unsetting the agent variables (env -u AI_AGENT -u CLAUDECODE -u CLAUDE_CODE CI=true GITHUB_ACTIONS=true) and getting the identical assertion text at the identical line numbers is the proof I asked for. A fix never seen failing is a hypothesis; this one was seen failing.

What earns the ACCEPT

• ⛔ The guard was not weakened, which was the one thing that would have cost this PR its value. All four repairs sit inside runFixture and its two guards: NO_COLOR=1, deleting FORCE_COLOR, --reporter=default so reporter choice stops depending on isAgent, and stripVTControlCharacters at the one capture boundary.
• ⭐ Fixed at the boundary, so all three fragile predicates die together — not just the one that failed. includes(TEARDOWN_ERROR) and the 'Tests 1 passed (1)' assertion were the same bug waiting for a different day.
• Proof the measurement was repaired, not disabled — the ablation leg's expect(reproduced).toBeDefined(), .not.toBe(0) and toContain('Tests 1 passed (1)') are all inside the now-green leg, so EnvironmentTeardownError is still reproduced; the guarded leg still asserts [0,0,0,0] across all four repetitions. That is the difference between green and correct.
• ⭐ The positive control is the right one: renaming the fixture out of the child's include glob, and showing both guards still refuse — now naming the cause (No test files found, exiting with code 1, each child's exit status, the include/exclude globs). Restored and verified byte-identical by sha256, not by an editor's exit code.
• Green under three environments — CI-shaped, CI-shaped plusFORCE_COLOR=1, and an ordinary agent shell — so the fix does not merely trade one environment's green for another's.
• check:type-check-debtrefused rather than mis-measuring (missing closure member), and you resolved the refusal by building it rather than bypassing it. Correct handling of a gate that distinguishes "cannot measure" from "measured clean" — the exact distinction this PR's own guard is about.

Why this one mattered

This is the P1: Test Core (3/3) → @objectstack/example-showcase#test dying at the ELIFECYCLE layer, dequeuing the PR and forcing every speculative build behind it to rebuild — measured at ~20 minutes added to every queued PR per cascade, three occurrences in one afternoon. It got there past two dead ends the card itself pointed at (the Acquire connection error signature, which appears in green runs; and pool sizing, structurally closed by knex pinning better-sqlite3 to pool {min:1,max:1} with each :memory: connection its own database), and the fix rests on #10374's reading of the actual vitest source rather than on the card's guess.

---

Generated by Claude Code