Skip to content

finding: the engine's structured logger writes ~45k lines per test run that the console-chatter measurement never counted, and no declarative seam exists to quiet it #13986

Description

@zhuangjianguo

Found while re-measuring the console-chatter card (related to #13517 — that card is about the console population and is not addressed or superseded here).

The measurement

Re-measuring on origin/main eb649cb8bc, capturing each suite's combined stdout+stderr and classifying every line, produced a population the earlier measurement could not see. That one counted intercepted console linesconsole.* calls forwarded over vitest's RPC. The engine's structured logger writes to process.stdout directly, so it was never on that path and was never counted, in either direction.

Lines per full suite run, classified:

suite console-carried structured logger (TIMESTAMP LEVEL message) total stdout
packages/qa/dogfood 41,858 25,118 66,976
packages/objectql 5,347 10,831 16,178
packages/runtime 2,069 4,658 6,727
packages/verify 2,574 3,093 5,667
packages/rest 3,963 1,290 5,253
total, 5 suites 55,811 44,990 100,802

So the structured logger is ~45% of what these five suites actually write, and in packages/objectql it is the majority of the suite's output (10,831 of 16,178). The five suites here are the top of the console distribution; the remaining 67 packages were not re-run in this pass, so 44,990 is a floor for the repo, not the repo total.

The dominant shapes are engine lifecycle INFO at boot — Loading plugin: NAME (1,578 in dogfood), Plugin registered: NAME (1,585), Plugin loaded: NAME (1,466), Service 'NAME' … (840), the [security] seeding summaries (672+) — emitted once per boot, in suites that boot real apps many times.

Why this is not the same question as the console chatter

The console half has a declarative answer that already exists: OS_REGISTRY_LOG is @objectstack/objectql's own published seam (SchemaRegistryOptions.logLevel / REGISTRY_LOG_LEVELS), so a suite can ask for quiet from its own harness without anything shipped changing.

The structured-logger half has no equivalent seam:

  • packages/core/src/logger.ts reads no level from the environment — grepping process.env in it finds only NO_COLOR. The level is whatever the kernel's constructor was handed.
  • packages/verify/src/harness.ts's BootOptions (:97) declares no logger or log-level field, so the in-process harness the dogfood and verify suites boot through cannot pass one either.
  • packages/cli does have OS_LOG_LEVEL (src/utils/log-level.ts), but it is resolved in the CLI and handed to the kernel it spawns. Nothing reads it below that.

So quieting this population is not a configuration change a test author can make today — it needs a seam to exist first, either an env read in the kernel logger or a level field on BootOptions. Both are shipped-surface decisions, which is why this is filed as an observation rather than attempted.

Not claimed here

  • No urgency. Same cost shape as the console half: CI log volume, not correctness.
  • No recommendation on which seam is right, or whether the engine's boot-time INFO verbosity is correct as shipped. A reader of a production boot log may well want every one of these lines; that is exactly the judgement this observation is handing over rather than making.
  • Whether the same ratio holds across the other 67 packages is unmeasured.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions