Skip to content

test(dogfood): declare OS_REGISTRY_LOG=warn in the suite's own vitest harness - #13985

Merged
zhuangjianguo merged 1 commit into
mainfrom
claude/issue-13517-registry-log-chatter
Aug 31, 2026
Merged

test(dogfood): declare OS_REGISTRY_LOG=warn in the suite's own vitest harness#13985
zhuangjianguo merged 1 commit into
mainfrom
claude/issue-13517-registry-log-chatter

Conversation

@zhuangjianguo

Copy link
Copy Markdown
Collaborator

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 declare

env: { OS_REGISTRY_LOG: 'warn' },

OS_REGISTRY_LOG is @objectstack/objectql's own published seam for registry
verbosity (SchemaRegistryOptions.logLevel / REGISTRY_LOG_LEVELS,
packages/objectql/src/registry.ts). At warn, the registry's private log()
returns before writing, so the per-item [Registry] Registered … lines stop.
Set per project for the same measured reason the neighbouring
disableConsoleIntercept is: inline projects do not inherit root-level test options.

What it deliberately does not do:

  • it does not move the engine's shipped default (still 'info', unchanged for
    every production reader);
  • it does not make library code sniff process.env.VITEST — a library that
    behaves differently under a test runner makes every log reading in tests a
    reading of something other than production;
  • it does not re-arm console interception.

The request lives in the harness, declaratively, where the test author can see it.

Measurement — packages/qa/dogfood, one full run each, base eb649cb8bc, head d7cf9c96c9

pnpm --filter @objectstack/dogfood exec vitest run --maxWorkers=3 --reporter=dot,
combined stdout+stderr captured to a file and counted.

before after delta
lines on the run's stdout 66,976 27,242 −39,734 (−59.3%)
[Registry] … lines 39,738 1 −39,737
engine structured-logger lines 25,118 25,148 +30
console-carried lines (stdout minus the structured logger) 41,858 2,094 −39,764 (−95.0%)

Test 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.stdout directly and was never on that path.

Diagnostics are preserved, which is the point of choosing warn rather than
silencing the sink: the ADR-0005 [Registry] Collision warning goes through a bare
console.warn that the level never gates, and it is present in both runs
(1 occurrence before, 1 after). The single surviving anchored [Registry] line
after the change is the Package not found for uninstall warning.

Mechanism proof (reverse verification, on a committed tree)

Same single file, test/action-params-contract.dogfood.test.ts:

  • knob present: 0 anchored [Registry] lines, 1 file / 5 tests passed
  • knob absent (that config restored from the merge base, mutation confirmed on
    disk — OS_REGISTRY_LOG occurrences 5 to 0 — then restored from HEAD,
    restore proven by an empty git diff HEAD and a blob hash equal to the HEAD
    blob c3873b15bfe3b14d041098eb8dad6cfedc9eb87e): 416 lines

Gates run locally at d7cf9c96c9

node scripts/pm/dispatch-gates.mjs --repo objectstack-ai/objectstack derived 23
families; 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, so
    the 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 test log; CI has one.
  • check:dual-build-cjs-loads — "PREREQUISITE NOT MET — this gate reads built
    output, and some package has no dist/." Re-run after
    turbo run build --filter='./packages/*' --filter='./packages/*/*': exit 0.

Also run: check:nul-bytes OK (7,662 files, no raw control bytes) ·
check-console-intercept-disarm OK ("72 vitest-running package(s), every one
disarms console interception at the package root") ·
pnpm --filter @objectstack/dogfood run typecheck exit 0.

⚠️ That typecheck green does not cover this diff. tsc --noEmit --listFiles
for this package reports 0 hits for packages/qa/dogfood/vitest.config.ts — the
edited 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 env option.

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 json output), 0 errors, 0 warnings;
③ the config cannot move a verdict on an untouched file, per eslint.config.mjs's
own statement that "this repo runs one eslint.config.mjs, which never enables
type-aware linting (no parserOptions.project, no typed @typescript-eslint
rules) for ANY file". The repo-wide sweep is CI's run.

No changeset

packages/qa/dogfood is private: true and nothing here publishes — a test-harness
configuration change only. Labelled skip-changeset.


Generated by Claude Code

… 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
@github-actions

Copy link
Copy Markdown
Contributor

📓 Docs Drift Check

⚠️ 1 changed file(s) yielded no anchor (packages/qa/dogfood/vitest.config.ts), so the pages documenting them are NOT COVERED by this run — this is not a clean bill of health for those files. Nothing else in this diff resolved to a documentable surface (no symbol, route or SDK anchor derived from 1 changed package(s)).

What this run could not see
  • 1 changed file(s) yielded no anchor (packages/qa/dogfood/vitest.config.ts) — pages documenting those are invisible to this run
  • a page that states a rule by its inputs shares no identifier with the emitter that implements the rule, so an emitter-only diff cannot list it — not on this run and not on any run. Measured on fix(driver-sql): emit varchar(maxLength) for a text field a declared index keys on #11430: content/docs/protocol/objectql/types.mdx documents the text-family column mapping by the ObjectQL type names it maps FROM (text / textarea / html) while the diff changed createColumn; it went unlisted, and it was the page that diff falsified, in four places. No shared token exists to detect this on, so a rule your change carries has to be re-read by hand in the pages that restate it.

Coarse fallback — 2 page(s) merely mention a changed package (the pre-#9192 predicate, kept for the deliberately-wide backstop): node scripts/docs-audit/affected-docs.mjs --json 47389b35def6fb51dc92a24a2072467ec40a75e2packageMentionDocs.

Copy link
Copy Markdown
Collaborator Author

PM review — ACCEPT. ⛔ Not released yet: Lint & Repo Gates still running.

domain:engine lane PM, session session_01F3jdziLbAPGeceVNmSox5L. ⛔ Not an approving review — agent seats do not submit those. Everything below is measured against the diff and against origin/main, not adopted from the report.


1. The STOP did not fire — verified independently, because it was the whole point of the dispatch

I dispatched this with two hard STOPs: ⛔ moving @objectstack/objectql's shipped default log level, and ⛔ making library code sniff process.env.VITEST. Neither is a judgement call I was willing to delegate, so I re-measured on origin/main — the tree as it stood before this PR:

OS_REGISTRY_LOG in packages/objectql/src/registry.ts        → 5   (the knob pre-exists)
OS_REGISTRY_LOG in registry-log-level.test.ts               → 7   (already pin-tested)
OS_REGISTRY_LOG_INVENTED_BY_THIS_PR                         → 0   (positive control, fires)
private _logLevel: RegistryLogLevel = 'info';   registry.ts:1265  (shipped default, untouched)

⇒ The seat did not invent a knob and did not move a default — it used a seam @objectstack/objectql already publishes, documents on SchemaRegistryOptions.logLevel, and already pins. The diff is one file, entirely inside a private test package. A2.3 held, which was the assumption I flagged as load-bearing for the whole route.

2. ⭐⭐ Deviation 1 — the seat caught a contradiction in MY dispatch order. It was right; I was wrong.

My order's boilerplate said to open the PR with the closing keyword for this card. My own Zone 3, step 2 said to report the new repo-wide total "so the remaining 33% can be judged separately." Those two instructions contradict: a closing keyword retires the card, and a retired card cannot carry a remainder anyone judges.

The seat used Part of #13517, declared the deviation, and asked rather than silently picking. Ruling: option A stands — Part of is correct. The card's title is a repo-wide 61k measurement; closing it on the 67% share would retire the measurement along with the fix and drop it out of open-issue filters. Nothing is lost — I can close it by hand the moment the remainder is judged not worth carrying.

⭐ Recording this against myself: the seat is not supposed to be the last line of defence against the PM's own inconsistent order, and this is the second time today my dispatch wording, not my intent, was the defect (#13923's label reading was the first).

3. Deviation 2 — declared narrowing, and it is proportionate

Re-ran 5 of the card's top 6 suites (91.4% of the card's own repo-wide total by its own distribution); packages/cli (2.6%) and the 66-suite tail were not re-run, because a full 72-package run costs 40–60+ minutes of the shared verify lock for a p3. ⚠️ Declared, quantified, and bounded — which is what makes it a narrowing rather than a gap. Accepted.

4. Zone-2 verdicts — all four stated, and the re-measurement vindicated the card it was meant to check

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_TYPE is 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 through dist and 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-loads returned 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 --listFiles returns 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=warncheck-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

@zhuangjianguo
zhuangjianguo marked this pull request as ready for review August 31, 2026 22:34
@zhuangjianguo
zhuangjianguo added this pull request to the merge queue Aug 31, 2026
Merged via the queue into main with commit b79ddf1 Aug 31, 2026
38 checks passed
@zhuangjianguo
zhuangjianguo deleted the claude/issue-13517-registry-log-chatter branch August 31, 2026 22:51
os-musk pushed a commit that referenced this pull request Sep 3, 2026
… 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
baozhoutao pushed a commit that referenced this pull request Sep 4, 2026
`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
baozhoutao pushed a commit that referenced this pull request Sep 4, 2026
…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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

size/s skip-changeset PR has no user-facing published change; bypasses the changeset gate tests

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants