test(dogfood): declare OS_REGISTRY_LOG=warn in the suite's own vitest harness - #13985
Conversation
… harness The dogfood gate writes 66,976 lines to stdout per full run; 39,738 of them (94.9% of everything it writes through `console`) are the SchemaRegistry's per-item `[Registry] Registered …` lines, emitted once per registered item per app boot across ~130 boots of the real example apps. `OS_REGISTRY_LOG` is `@objectstack/objectql`'s own published seam for that verbosity (`SchemaRegistryOptions.logLevel` / `REGISTRY_LOG_LEVELS`). At `warn` the registry's `log()` returns before writing, while the ADR-0005 `[Registry] Collision` diagnostics — a bare `console.warn` the level never gates — still surface. The engine's shipped default is untouched, and no library code learns what a test runner is: the request lives in the harness, declaratively, where the test author can see it. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01F3jdziLbAPGeceVNmSox5L
📓 Docs Drift Check
What this run could not see
Coarse fallback — 2 page(s) merely mention a changed package (the pre-#9192 predicate, kept for the deliberately-wide backstop): |
PM review — ACCEPT. ⛔ Not released yet:
|
| Verdict | |
|---|---|
| A2.1 stale numbers | Re-measured; four of five suites within 5.3% of the card's figures. Stale in provenance, not in substance. Only packages/rest moved (+36.6%). |
| A2.2 concentration | Confirmed, and sharper than assumed — dogfood is 75.0% of the fresh mass, and within it 94.9% is a single message family. Concentration is per-message-shape, not just per-suite, which is why one knob suffices. |
| A2.3 harness-local knob exists | Confirmed (verified above). |
| A2.4 nothing asserts on the output | Confirmed two ways — statically (no dogfood test references [Registry]) and empirically (identical 128 passed | 1 skipped / 998 passed | 3 skipped on both sides). |
⭐ The sharpest reading in the report is the near-miss under A2.4: registry-collision-order.test.ts does assert on [Registry] Collision lines — but those go through a bare console.warn that logLevel never gates (that test sets logLevel = 'silent' and still sees them). ⇒ Diagnostics survive this knob by construction, and it was measured (1 Collision line before, 1 after), not asserted. The docblock now carries that fact where the next editor will read it.
5. ⭐⭐ The finding is worth more than the fix: the card's instrument was blind to ~45% of the output
#13986 records that the engine's structured logger writes 44,990 lines across the five re-measured suites — the majority of packages/objectql's own output (10,831 of 16,178) — and the card's console-interception methodology never counted any of it, because that logger writes to process.stdout directly and was never on the intercepted path.
⇒ The card's headline number was not wrong, it was measuring a different population than it appeared to. And that half has no declarative seam at all (packages/core/src/logger.ts reads no level from the environment beyond NO_COLOR; packages/verify/src/harness.ts's BootOptions declares no logger field) — so quieting it is genuinely my STOP condition 3, a shipped-surface decision. ⭐ Correctly filed rather than attempted, and the boundary reported even though no STOP fired.
6. Three pieces of measurement discipline worth naming
- ⭐ "NO REBUILD LEG IS CLAIMED and none was needed" — the mutated artifact is a vitest config read from source, with no
dist/on its resolution path, so a rebuild leg would have been theatre.⚠️ Contrast with the runtime publish gate:CLOSURE_CONTEXT_KEY_BY_TYPEis the last hand-listed spelling of the snapshot collection set #13768 seat two hours ago, where a rebuild was mandatory because the type crossed a package wall throughdistand skipping it would have gone falsely green. Two seats, opposite answers, each correct for its own artifact — which is what it looks like when a rule is understood rather than copied. - ⭐ It converted a NOT MEASURED into a measurement:
check:dual-build-cjs-loadsreturned exit 3, so it built the workspace (70/70) and re-ran it to exit 0, instead of banking the 3 as "not my problem". The other exit 3 (check-test-completeness) is correctly left as NOT MEASURED — CI owns that log. - ⭐ It refused to let a green typecheck stand as coverage it does not provide:
tsc --noEmit --listFilesreturns zero hits for the edited file, so the package's typecheck does not see this diff at all. What exercises it is vitest, which loaded the config in both full runs. Saying so is the difference between a green check and a measured one.
7. Ruling on the second open question
Nothing mechanically holds the harness at OS_REGISTRY_LOG=warn — check-console-intercept-disarm.mjs ratchets the disarm across all 72 suites, but no gate ratchets a log level, so a future edit can delete the line and only a shard-log reader would notice.
Ruling: C, then B — as recommended. Building the gate now would ratchet a population of one, and Zone 3 was explicit that this PR lands that and only that. Once the remaining app-booting suites are judged, either the same declaration is repo-wide (⇒ B, extend the existing gate) or it is dogfood-specific (⇒ A, the docblock is the right carrier). ⛔ Deciding it before the population is known would be guessing at the shape of a rule.
8. Clause ② — Clause-②: no, verified from the diff
One file, packages/qa/dogfood/vitest.config.ts — a private test package. Path limb: nothing under packages/spec/src/**. Content limb: no accept/reject behaviour, no published surface; the knob consumed is already published and already pinned. ⛔ No needs:contract-review carrier is owed — consistent with 不预挂.
Status
35 of 36 checks complete, zero failures; Lint & Repo Gates is still in flight (11 minutes in — it ran 15–16 minutes on the last two PRs of this lane, so this is normal). ⛔ I will not flip ready or arm auto-merge until it lands green: the bar is every check completed, not the required subset, because enqueue is irreversible here.
On landing: verify by content on origin/main, then re-triage #13517 back to pm:queue with the remainder scoped — ⛔ not closed, per §2.
Generated by Claude Code
… hold All 72 workspace packages with a test script measured, all green. Final totals: 61,980 structured / 17,428 console / 993 reporter / 80,401 total lines — structured share of total 77.1% (comparable to the earlier five-suite framing, whose own `console` bucket absorbed what this instrument tracks separately as `reporter`). The five-suite ~45% figure does not hold, and not toward more noise: it moved to 77.1% structured, decomposed in "The answer" section as two effects — (1) two commits (#13985, #14016) that landed on main between the earlier reading and this one already took the original five suites from ~45% to 86.6% structured on their own, by cutting a `[Registry]` debug-console population; (2) extending to the other 67 packages pulls that back down to 77.1% (not further), since that population's own structured share (57.7%) is lower than the five heaviest suites' but is also a minority (30.3%) of total test-run volume, and most of it (35/72 packages under 30 lines total, 22 of those exactly 13 -- pure reporter boilerplate) never boots a kernel at all. No seam added -- per triage's ruling (comment 5489397004), this document is the measurement; which seam (if either) to build is triage's call. Merged origin/main (dispatch-gates warned STALE TREE, 19 commits behind) -- no relevant file (logger.ts, harness.ts, log-level.ts, vitest configs, package.json test scripts) changed across that range, so the merge does not invalidate any measurement already taken. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_0112hMx9hjJ9BgB28X97DS68
`packages/rest` is the untouched CONTROL in docs/audits/2026-09-test-log-volume-census.md: while PR #13985 and PR #14016 declared a registry log level in four harnesses, this suite got none, and the audit measures 528 residual `[Registry]` lines here — eight times what declared objectql still emits. Six test files in this package construct bare `SchemaRegistry` instances, so the chatter is per registered item per case. This declares the level in the harness only. objectql's shipped `'info'` default is unchanged for every production reader, and no library code is made aware of a test runner: `OS_REGISTRY_LOG` is the engine's own published seam (`SchemaRegistryOptions.logLevel` / `REGISTRY_LOG_LEVELS`). The ADR-0005 `[Registry] Collision` diagnostics ride a bare `console.warn` that the level never gates, so a real shadowing still speaks here. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_012zGPuVVX3deAx9LdjK8jCk
…ting suites objectql's `SchemaRegistry` logs one `[Registry] Registered <kind>: <name>` line per registered item per construction, at its shipped `'info'` default. A suite that boots app stacks pays items x boots of that on a CI shard log nobody reads. PR #13985 and PR #14016 declared `OS_REGISTRY_LOG` in four harnesses and removed ~47,900 console-carried lines — and nothing held them there. Deleting one `env` line restored five figures of output while every assertion stayed green and every outcome was unchanged. This gate asserts the declaration. It reuses `check-console-intercept-disarm`'s exported `workspacePackageDirs` walk and its verdict format, so only the assertion and the population are new. THE POPULATION IS DERIVED, not a roster. A vitest-running package is selected when its OWN TEST SOURCES construct a `SchemaRegistry`, boot a stack through `@objectstack/verify`'s `bootStack`, or import an `@objectstack/example-*` app. On this tree that selects 8 of 72 with zero over- and zero under-selection. A roster of the four suites that already declared would have been a hand list this repo could show to be wrong on the day it shipped: docs/audits/2026-09-test-log-volume-census.md measures `packages/rest` — its own named control — at 528 residual `[Registry]` lines, eight times declared objectql's 66. The four packages the predicate newly selects adopt the declaration in the four commits preceding this one. Comment masking is what makes the predicate honest rather than merely plausible: `packages/cli` names `bootStack` and `@objectstack/verify` in eight places, all of them prose, and would otherwise be selected while booting no stack in any test. The registry-construction signal additionally masks string and template content, so a spelling inside a literal is never the setting. The level vocabulary is READ from objectql's own `REGISTRY_LOG_LEVELS` rather than copied, because `registry.ts` resolves an unrecognised value to the `'info'` DEFAULT silently — `OS_REGISTRY_LOG: 'quiet'` would read as a considered choice and quiet nothing. Out of scope and untouched: which level any suite picks, objectql's shipped `'info'` default, and any library awareness of a test runner. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_012zGPuVVX3deAx9LdjK8jCk
Part of #13517 — this lands the concentrated 67% share only. The card measures a
repo-wide volume; this PR quiets one suite through that suite's own harness, and
the remainder is re-measured below so it can be judged separately. The card stays
open on purpose.
What this changes
One file,
packages/qa/dogfood/vitest.config.ts: both inline projects now declareOS_REGISTRY_LOGis@objectstack/objectql's own published seam for registryverbosity (
SchemaRegistryOptions.logLevel/REGISTRY_LOG_LEVELS,packages/objectql/src/registry.ts). Atwarn, the registry's privatelog()returns before writing, so the per-item
[Registry] Registered …lines stop.Set per project for the same measured reason the neighbouring
disableConsoleInterceptis: inline projects do not inherit root-level test options.What it deliberately does not do:
'info', unchanged forevery production reader);
process.env.VITEST— a library thatbehaves differently under a test runner makes every log reading in tests a
reading of something other than production;
The request lives in the harness, declaratively, where the test author can see it.
Measurement —
packages/qa/dogfood, one full run each, baseeb649cb8bc, headd7cf9c96c9pnpm --filter @objectstack/dogfood exec vitest run --maxWorkers=3 --reporter=dot,combined stdout+stderr captured to a file and counted.
[Registry] …linesTest outcome is identical on both sides:
Test Files 128 passed | 1 skipped (129),Tests 998 passed | 3 skipped (1001).The 41,858 console-carried figure reproduces the card's 41,115 for this suite to
within 1.8%, which is what makes the two measurements comparable: the card counted
intercepted console lines, and the engine's structured logger writes to
process.stdoutdirectly and was never on that path.Diagnostics are preserved, which is the point of choosing
warnrather thansilencing the sink: the ADR-0005
[Registry] Collisionwarning goes through a bareconsole.warnthat the level never gates, and it is present in both runs(1 occurrence before, 1 after). The single surviving anchored
[Registry]lineafter the change is the
Package not found for uninstallwarning.Mechanism proof (reverse verification, on a committed tree)
Same single file,
test/action-params-contract.dogfood.test.ts:[Registry]lines, 1 file / 5 tests passeddisk —
OS_REGISTRY_LOGoccurrences 5 to 0 — then restored fromHEAD,restore proven by an empty
git diff HEADand a blob hash equal to the HEADblob
c3873b15bfe3b14d041098eb8dad6cfedc9eb87e): 416 linesGates run locally at
d7cf9c96c9node scripts/pm/dispatch-gates.mjs --repo objectstack-ai/objectstackderived 23families; all 23 were run. 21 green. Two returned exit code 3 = PREREQUISITE NOT
MET = not measured, never a pass:
check-test-completeness— its own text: "There is no local log to hand it, sothe local reading for this gate is NOT MEASURED. It is not a red, and there is
nothing here to fix." It reads a saved
turbo run testlog; CI has one.check:dual-build-cjs-loads— "PREREQUISITE NOT MET — this gate reads builtoutput, and some package has no dist/." Re-run after
turbo run build --filter='./packages/*' --filter='./packages/*/*': exit 0.Also run:
check:nul-bytesOK (7,662 files, no raw control bytes) ·check-console-intercept-disarmOK ("72 vitest-running package(s), every onedisarms console interception at the package root") ·
pnpm --filter @objectstack/dogfood run typecheckexit 0.tsc --noEmit --listFilesfor this package reports 0 hits for
packages/qa/dogfood/vitest.config.ts— theedited file is outside the package's tsc program. What does exercise it is vitest
itself: both full runs above loaded this config and accepted the
envoption.ESLint was run narrowed to the edited file, with the three readings that make a
narrowing a measurement rather than a skip: ① the population comes from ESLint's own
config resolution — 5,594 of 7,669 tracked files are not ignored; ② the narrowed run
linted 1 file (count read from
--format jsonoutput), 0 errors, 0 warnings;③ the config cannot move a verdict on an untouched file, per
eslint.config.mjs'sown statement that "this repo runs one
eslint.config.mjs, which never enablestype-aware linting (no
parserOptions.project, no typed@typescript-eslintrules) for ANY file". The repo-wide sweep is CI's run.
No changeset
packages/qa/dogfoodisprivate: trueand nothing here publishes — a test-harnessconfiguration change only. Labelled
skip-changeset.Generated by Claude Code