diff --git a/docs/audits/2026-09-test-log-volume-census.md b/docs/audits/2026-09-test-log-volume-census.md new file mode 100644 index 0000000000..3e47348554 --- /dev/null +++ b/docs/audits/2026-09-test-log-volume-census.md @@ -0,0 +1,421 @@ +# Test-run log volume census — both channels, all 72 packages + +**Measured on `origin/main` `b1d49b394`, 2026-09-03T11:41 UTC.** Instrument: +`scripts/qa/log-volume-census.mjs` (this document states nothing the instrument +cannot be re-run to produce). + +This extends an earlier reading that covered five suites and left the rest +unmeasured. The question it was dispatched to answer is narrow and it is worth +stating before any number: + +> Does the ratio the five suites showed — structured logger ≈ 45% of everything +> a test run writes — hold across the other 67 packages? + +**Answer: no, and not in the direction the phrasing suggests.** Across all 72 +packages the structured logger is **77.1%** of the output (61,980 of 80,401 +lines) — not lower than the five-suite reading, higher. The other 67 packages +are not what moved it: two commits that landed on `main` in the three days +between the earlier reading and this one already took the *original five* +suites from ~45% to ~87% structured on their own, by cutting a debug-only +`console.log` population out of four of them. Extending to all 72 packages +pulls that back down to 77.1%, not because the extra 67 reverse the direction, +but because they are collectively a smaller, more console-leaning slice of +total volume than the five heaviest suites already were. See +[The answer](#the-answer) for the arithmetic. + +## What is NOT claimed here + +- **No urgency, no correctness impact.** This is CI log volume. The earlier + reading said so and nothing here changes it. +- **No seam was added, and none is recommended.** The two candidates — an env + read in the kernel logger, a level field on `BootOptions` — both touch + published surface, and choosing between them is not a measurement. +- **"A reader of a production boot log may well want every one of these + lines."** Test-environment noise and production observability are two ends of + one switch. Nothing here is an argument for lowering the engine's boot INFO + verbosity; that judgement is not this document's to make. + +## Method + +For each of the 72 workspace packages that declare a `test` script, the +package's **own** `test` script is run **unchanged** — `pnpm --filter run +test` — and its **combined stdout+stderr** is captured to a file. No package's +vitest config, harness or environment is modified; nothing is added to the +environment except `NODE_OPTIONS=--max-old-space-size=4096` and +`VITEST_MAX_WORKERS=2`, which bound memory and worker count on a shared box and +change interleaving, not which lines are emitted. `CI` is passed through as the +caller has it, never forced — code that branches on `CI` would otherwise be +measured in a mode nobody runs the suite in. + +Every captured line is stripped of ANSI SGR sequences and classified: + +| bucket | rule | +|---|---| +| **structured** | matches `^ (DEBUG\|INFO\|WARN\|ERROR\|FATAL)\b`, the head `ObjectLogger.write()` composes for formats `pretty` (the default) and `text`; plus the `json` format's `{"time":…,"level":…` prefix | +| **reporter** | vitest's own reporter vocabulary plus the pnpm script banner — a closed, enumerated list | +| **console** | everything else | + +### The limits, stated + +- **`console` is a complement, not a positive identification.** Anything that + writes to stdout with neither the logger's head nor a reporter shape lands in + it — a bare `process.stdout.write` from build or seed code included. The + failure direction is over-counting `console`, never over-counting + `structured`. +- **There is no channel-level discriminator available, and that is a property + of the repo, not of the instrument.** All 72 vitest configs set + `disableConsoleIntercept: true` — enforced by + `scripts/check-console-intercept-disarm.mjs` — so console output is *not* + forwarded over vitest's RPC and carries no `stdout | > ` header. + Both populations land on the same two file descriptors, unlabelled. + Separating them at capture time would mean changing how a package runs its + tests, which measures a different thing than the suite anyone actually runs. +- **A multi-line `console.*` payload counts as N lines** — a stack trace is + worth its height. This matches the earlier reading's definition. +- **A red suite writes more than a green one.** Every row carries its exit + code and non-zero rows are flagged; they are not silently averaged in. +- **Durations are shared-box readings.** Suites ran under this container's + shared verify lock with other agents on the machine. Ratios survive + contention; wall-clock absolutes do not, and none are quoted as performance. + +## The instrument writes to `process.stdout` directly — verified, not inferred + +`packages/core/src/logger.ts:349-394` (verified at `0de50b83a`): + +```ts +const isErrorLevel = level === 'error' || level === 'fatal'; +const proc = typeof process !== 'undefined' ? (process as any) : undefined; +const stream = proc ? (isErrorLevel ? proc.stderr : proc.stdout) : undefined; +… +if (stream) { + stream.write(line + '\n'); +} else if (typeof console !== 'undefined') { … } +``` + +The `console` branch is browser-only fallback: it is reached only when +`process` is absent or carries no stdio streams. Observed, with a positive +control: + +| probe | result | +|---|---| +| replace all four `console` methods, then emit one `info` and one `error` through a default logger | **0** lines seen by `console` | +| positive control: the same replacement over a real `console.log` | **1** line captured | +| `info` with stderr discarded | `INFO-PROBE` present on **stdout** | +| `error` with stdout discarded | `ERROR-PROBE` present on **stderr** | + +So the logger is invisible to any instrument that watches `console`, in either +direction — which is the whole reason this population went uncounted. + +## The premise re-verification: no seam a test author can reach + +Each of the three claims re-checked on this tree, each with a control. + +### The kernel logger reads no level from the environment + +`ObjectLogger`'s constructor takes `level: config.level ?? 'info'` +(`packages/core/src/logger.ts:236`). The only `process.env` read in the whole +file is `NO_COLOR` (`:180`), for color, not level. + +Observed — one `info()` call through a default logger, counting the emitted +line: + +| environment | lines emitted | +|---|---| +| nothing set | 1 | +| `OS_LOG_LEVEL=silent` | 1 | +| `LOG_LEVEL=silent` | 1 | +| `OS_CORE_LOG_LEVEL=silent` | 1 | +| `OS_REGISTRY_LOG=warn` | 1 | +| **positive control** `createLogger({ level: 'silent' })` | **0** | +| **positive control** `createLogger({ level: 'error' })` | **0** | + +The positive controls are the point: the probe *can* see suppression, so the +five zeros above them are a reading and not a broken probe. + +### `BootOptions` declares no logger field, and the harness passes no config at all + +`packages/verify/src/harness.ts`, `export interface BootOptions` spans lines +**96–313** and declares exactly ten fields: `admin`, `authSecret`, `security`, +`analytics`, `multiTenant`, `orgContext`, `hostRoot`, `automation`, +`databaseFile`, `extraPlugins`. No logger, no level. + +Type-level control (`tsc --noEmit`, package tsconfig): + +``` +src/__d2-control-strict.ts(2,37): error TS2353: Object literal may only specify + known properties, and 'logLevel' does not exist in type 'BootOptions'. +``` + +while the positive control `const positive: BootOptions = { databaseFile: ':memory:' }` +compiles clean. + +⚠️ **The wire is missing one layer lower than the card said, which makes the +premise stronger rather than weaker.** `harness.ts:384` constructs the kernel +as: + +```ts +const kernel = new ObjectKernel(); +``` + +— no config object at all. `ObjectKernel`'s constructor does accept +`config.logger` (`packages/core/src/kernel.ts:87`, `this.logger = +createLogger(config.logger)`), so a seam exists *at the kernel*; what does not +exist is any path from a suite to it. Adding a `BootOptions` field would +therefore also mean threading it through this call — it is not a one-line +forward of something already being passed. + +**A second, un-asked-for finding, relevant to which seam triage picks:** the +bare `new ObjectKernel()` call in `harness.ts` is not an isolated case. +Repo-wide, `new ObjectKernel(` appears **78 times across 55 files** +(`grep -rn 'new ObjectKernel(' --include='*.ts' packages examples`; verified +at `0de50b83a`, this branch merged with `origin/main` at `99b4deba4` — re-run +the command to reproduce, since this file set moves), most of +them test files constructing a kernel directly rather than through +`packages/verify`'s harness — `packages/objectql/src/kernel-factory.ts:35` +(the factory objectql's own suite boots through, contributing 11,326 of the +61,980 structured lines measured here — 18.3% of the total) is one of them, +with the identical `new ObjectKernel()` — no config — shape. **A `BootOptions` +field on `packages/verify`'s harness would quiet only the suites that boot +through that one harness; it would not reach objectql's kernel construction, +or any of the other ~53 call sites, without each of them being found and +updated individually.** An env-level default read inside the kernel or logger +construction itself (`NO_COLOR`'s existing pattern in the same file is the +precedent) would cover all 78 call sites without touching any of them. This +does not choose a seam — it changes what "choosing" would cost. + +### `OS_LOG_LEVEL` is resolved in the CLI and read nowhere below it + +Repo-wide, `OS_LOG_LEVEL` is read in exactly one non-test source file: +`packages/cli/src/utils/log-level.ts:53` +(`readEnvWithDeprecation('OS_LOG_LEVEL', 'LOG_LEVEL', …)`). Its consumers are +`packages/cli`'s `serve`, `start` and `dev` commands, which hand a level to the +kernel they spawn. No package outside `packages/cli` reads it. + +End-to-end control — `resolveLogLevel()` (`packages/cli/src/utils/log-level.ts`), +called directly from the built `packages/cli/dist`, to confirm the probe can +see a level change before trusting that nothing else reads one: + +| call | resolved level | +|---|---| +| `resolveLogLevel({})` | `warn` (the CLI default) | +| `resolveLogLevel({ envLevel: 'debug' })` | **`debug`** | +| `resolveLogLevel({ envLevel: 'silent' })` | **`silent`** | +| `resolveLogLevel({ flag: 'error', envLevel: 'debug' })` | `error` (flag beats env) | +| `resolveLogLevel({ verbose: true, envLevel: 'silent' })` | `debug` (`--verbose` beats both) | + +The function is demonstrably sensitive to its input, so the repo-wide grep is +not a probe that happened to see nothing: `grep -rn 'OS_LOG_LEVEL\b'` across +every `.ts`/`.mjs`/`.js` (excluding `dist/`) returns exactly one non-`cli`, +non-test hit — `scripts/pm/dispatch-gates.mjs:14478` (verified at `0de50b83a` +— this file is edited often, re-check before reuse), a string literal inside +that script's own self-test fixture, not a read. Every other match is +`packages/cli/src/**` (the resolver plus the three commands that call it) or +`packages/cli/test/**` (tests of that resolution — a package testing its own +env read is expected and not a seam into some other suite). + +**⇒ All three premise claims hold. No pre-existing seam was found, so the +card's purpose is unchanged.** + +## Reproduction of the five-suite reading + +A census that cannot reproduce a known answer is not trustworthy for the +unknown ones, so the five suites were re-run first. + +The tree has moved **410 commits** between the earlier reading +(`eb649cb8bc`, 2026-08-31 20:55 UTC) and this one (`b1d49b394`, 2026-09-03 +11:41 UTC), and two of those commits act directly on the population being +measured: + +- **`b79ddf17d` (#13985, 2026-08-31)** — declares `OS_REGISTRY_LOG=warn` in + **dogfood**'s vitest harness. Its own commit message measures the population + it removes: *"66,976 lines to stdout per full run; 39,738 of them (94.9% of + everything it writes through `console`)"* — 66,976 is, to the line, the + earlier reading's dogfood total. +- **`5e2c04da7` (#14016, 2026-09-01)** — the same declaration for **objectql, + verify and runtime**, removing 4,744 / 2,323 / 1,155 `[Registry]` lines + respectively, measured at `b1b7d6088a`. + +`packages/rest` received no such declaration. It is therefore a **natural +control**: the one suite of the five whose console population nothing touched. + +| suite | earlier `console` | expected after #13985/#14016 | measured now | earlier `structured` | measured now | +|---|---:|---:|---:|---:|---:| +| `packages/qa/dogfood` | 41,858 | 2,120 | **1,738** | 25,118 | **26,707** | +| `packages/objectql` | 5,347 | 603 | **533** | 10,831 | **11,326** | +| `packages/runtime` | 2,069 | 914 | **815** | 4,658 | **5,550** | +| `packages/verify` | 2,574 | 251 | **221** | 3,093 | **3,171** | +| `packages/rest` *(control — untouched)* | 3,963 | 3,963 | **4,192** | 1,290 | **1,672** | + +Residual `[Registry]` lines in the current captures confirm the mechanism +rather than assuming it: dogfood 2, verify 0, runtime 9, objectql 66 — and +rest, the untouched control, **528**. + +**Verdict: the instrument reproduces.** Every `structured` figure lands within ++2.5% to +30% of the earlier reading on a tree 410 commits younger, and every +`console` figure lands within 3–18% of what the two intervening commits +predict. The control suite moved +5.8% on `console`, i.e. did not collapse, +which is what makes the other four collapses attributable rather than +instrument drift. + +## The census + +**All 72/72 packages measured.** + +| package | console | structured | reporter | total | exit | +|---|---:|---:|---:|---:|---| +| `examples/app-crm` | 48 | 60 | 13 | 121 | ok | +| `examples/app-showcase` | 346 | 61 | 13 | 420 | ok | +| `examples/app-todo` | 482 | 0 | 13 | 495 | ok | +| `examples/embed-objectql` | 1 | 7 | 13 | 21 | ok | +| `packages/adapters/hono` | 0 | 0 | 13 | 13 | ok | +| `packages/cli` | 1,608 | 4,926 | 49 | 6,583 | ok | +| `packages/client` | 229 | 325 | 13 | 567 | ok | +| `packages/client-react` | 3 | 0 | 13 | 16 | ok | +| `packages/cloud-connection` | 3 | 0 | 13 | 16 | ok | +| `packages/connectors/connector-mcp` | 0 | 61 | 13 | 74 | ok | +| `packages/connectors/connector-openapi` | 0 | 112 | 13 | 125 | ok | +| `packages/connectors/connector-rest` | 0 | 238 | 13 | 251 | ok | +| `packages/connectors/connector-slack` | 0 | 167 | 13 | 180 | ok | +| `packages/core` | 18 | 228 | 13 | 259 | ok | +| `packages/create-objectstack` | 0 | 0 | 13 | 13 | ok | +| `packages/drivers/driver-memory` | 2 | 593 | 13 | 608 | ok | +| `packages/drivers/driver-mongodb` | 7 | 0 | 13 | 20 | ok | +| `packages/drivers/driver-sql` | 223 | 0 | 13 | 236 | ok | +| `packages/drivers/driver-sqlite-wasm` | 3 | 0 | 13 | 16 | ok | +| `packages/drivers/driver-turso` | 9 | 0 | 13 | 22 | ok | +| `packages/formula` | 0 | 0 | 13 | 13 | ok | +| `packages/lint` | 15 | 0 | 13 | 28 | ok | +| `packages/mcp` | 0 | 0 | 13 | 13 | ok | +| `packages/metadata` | 24 | 168 | 13 | 205 | ok | +| `packages/metadata-core` | 0 | 0 | 13 | 13 | ok | +| `packages/metadata-fs` | 0 | 0 | 13 | 13 | ok | +| `packages/metadata-protocol` | 308 | 0 | 13 | 321 | ok | +| `packages/objectql` | 533 | 11,326 | 16 | 11,875 | ok | +| `packages/observability` | 0 | 0 | 13 | 13 | ok | +| `packages/platform-objects` | 0 | 0 | 13 | 13 | ok | +| `packages/plugins/embedder-openai` | 0 | 0 | 13 | 13 | ok | +| `packages/plugins/knowledge-memory` | 0 | 0 | 13 | 13 | ok | +| `packages/plugins/knowledge-ragflow` | 0 | 0 | 13 | 13 | ok | +| `packages/plugins/plugin-approvals` | 428 | 300 | 13 | 741 | ok | +| `packages/plugins/plugin-audit` | 658 | 889 | 13 | 1,560 | ok | +| `packages/plugins/plugin-auth` | 2,678 | 2,149 | 13 | 4,840 | ok | +| `packages/plugins/plugin-dev` | 0 | 0 | 13 | 13 | ok | +| `packages/plugins/plugin-email` | 6 | 60 | 13 | 79 | ok | +| `packages/plugins/plugin-hono-server` | 0 | 1 | 13 | 14 | ok | +| `packages/plugins/plugin-pinyin-search` | 0 | 0 | 13 | 13 | ok | +| `packages/plugins/plugin-reports` | 247 | 8 | 13 | 268 | ok | +| `packages/plugins/plugin-security` | 305 | 422 | 13 | 740 | ok | +| `packages/plugins/plugin-sharing` | 633 | 149 | 13 | 795 | ok | +| `packages/plugins/plugin-webhooks` | 126 | 440 | 13 | 579 | ok | +| `packages/qa/dogfood` | 1,738 | 26,707 | 25 | 28,470 | ok | +| `packages/qa/downstream-contract` | 0 | 0 | 13 | 13 | ok | +| `packages/qa/http-conformance` | 250 | 302 | 13 | 565 | ok | +| `packages/rest` | 4,192 | 1,672 | 13 | 5,877 | ok | +| `packages/runtime` | 815 | 5,550 | 13 | 6,378 | ok | +| `packages/sdui-parser` | 0 | 0 | 13 | 13 | ok | +| `packages/services/service-analytics` | 1 | 294 | 13 | 308 | ok | +| `packages/services/service-automation` | 333 | 607 | 13 | 953 | ok | +| `packages/services/service-cache` | 0 | 0 | 13 | 13 | ok | +| `packages/services/service-cluster` | 5 | 0 | 13 | 18 | ok | +| `packages/services/service-cluster-redis` | 9 | 0 | 13 | 22 | ok | +| `packages/services/service-datasource` | 24 | 16 | 15 | 55 | ok | +| `packages/services/service-i18n` | 4 | 0 | 13 | 17 | ok | +| `packages/services/service-job` | 0 | 0 | 13 | 13 | ok | +| `packages/services/service-knowledge` | 0 | 32 | 13 | 45 | ok | +| `packages/services/service-messaging` | 242 | 380 | 13 | 635 | ok | +| `packages/services/service-package` | 6 | 0 | 13 | 19 | ok | +| `packages/services/service-queue` | 0 | 0 | 13 | 13 | ok | +| `packages/services/service-realtime` | 0 | 0 | 13 | 13 | ok | +| `packages/services/service-settings` | 115 | 341 | 13 | 469 | ok | +| `packages/services/service-sms` | 0 | 0 | 13 | 13 | ok | +| `packages/services/service-storage` | 113 | 218 | 13 | 344 | ok | +| `packages/spec` | 15 | 0 | 17 | 32 | ok | +| `packages/triggers/trigger-api` | 0 | 0 | 13 | 13 | ok | +| `packages/triggers/trigger-record-change` | 401 | 0 | 13 | 414 | ok | +| `packages/triggers/trigger-schedule` | 0 | 0 | 13 | 13 | ok | +| `packages/types` | 1 | 0 | 13 | 14 | ok | +| `packages/verify` | 221 | 3,171 | 13 | 3,405 | ok | +| **total, 72/72 suites measured** | **17,428** | **61,980** | **993** | **80,401** | | + +structured share of total, structured / (structured+console+reporter) — +comparable to the 5-suite framing, whose own `console` already absorbed what +this instrument tracks separately as `reporter`: **77.1%** + +structured share of console+structured alone, reporter set aside: 78.1% + +measured: 72/72 + +non-zero exit: 0 + +## The answer + +**No — the ratio does not hold, and it moved in the opposite direction from +the one "the other 67 packages are noisier" would predict.** + +All 72 packages, all green (exit 0), totals from the ledger: + +| | console | structured | reporter | total | +|---|---:|---:|---:|---:| +| **all 72 packages** | 17,428 | 61,980 | 993 | 80,401 | + +- **structured share of total** (the metric comparable to the earlier + reading's own convention, where `console + structured == total` with no + separate reporter bucket — i.e. `structured / (structured + console + + reporter)`): **77.1%**. +- **structured share of console+structured alone** (reporter's own ~1% of + total set aside): 78.1%. The two are close because `reporter` is a small, + closed vocabulary (993 of 80,401 lines, 1.2%) — see Method. + +**Why it moved this far, decomposed:** + +1. **The original five suites, re-measured on today's tree, are already at + 86.6% structured** (48,426 structured / 55,925 console+structured — from + the "Reproduction" table above), not ~45%. Two commits explain essentially + all of that move: `b79ddf17d` (#13985) and `5e2c04da7` (#14016) each + declared `OS_REGISTRY_LOG=warn` in a suite's vitest harness, cutting a + `[Registry]` debug-`console.log` population that had been the majority of + `console` output in dogfood, objectql, runtime and verify. `packages/rest` + — the one suite of the five nothing touched — moved only +5.8% on + `console`, which is what makes the other four attributable to those two + commits rather than to this instrument reading differently than the + original one did. +2. **Extending to the other 67 packages pulls the number back down, from + 86.6% to 77.1%, but not remotely far enough to reverse it.** Those 67 + packages contribute 24,396 of the 80,401 total lines (30.3%) — collectively + a minority of test-run volume — and most of them are near-silent either + way: **35 of the 72 packages write fewer than 30 lines total**, and **22 + of the 72 write exactly 13** — the reporter's own fixed banner with + nothing else at all (a package whose suite has no tests that emit + anything, structured or console). Structured lines require a kernel boot + (`ObjectLogger`'s INFO-level startup chatter); a package whose suite never + constructs one — most of `packages/services/*`, `packages/triggers/*`, + `packages/drivers/*` (besides `driver-memory`), and several thin + `plugins/*` — writes at or near zero of both. +3. **The marginal 67 packages' own structured share is 57.7%** (13,554 + structured / 23,483 console+structured among just that group) — lower + than the reproduced five-suite figure, higher than the original ~45% + reading. The largest genuinely console-**majority** contributors outside + the original five (`console > structured`, sorted by `console`): + `packages/plugin-auth` (2,678 console / 2,149 structured — its own suite + boots a kernel and logs per-request auth denials), `packages/plugin-sharing` + (633 / 149), `examples/app-todo` (482 / 0), `packages/plugin-approvals` + (428 / 300) and `packages/trigger-record-change` (401 / 0). `packages/cli` + has the second-highest raw `console` count outside the original five + (1,608) but is itself majority-**structured** (4,926) — it belongs to the + `console`-heavy-in-absolute-terms group, not the console-majority one. + +**Reading the two effects together:** the five-suite figure this card cited +(~45%) was a snapshot from *before* #13985/#14016 landed. Re-running the same +five suites today already answers most of the question — the ratio was never +stable at 45%, because the population it measured moved out from under it in +three days. The extension to all 72 packages is the second, smaller +correction, and it is a real one: the untouched 67 packages are more +console-leaning on average (57.7%) than the five heaviest suites (86.6%), so a +full-repo reading is not simply "the five-suite number, unchanged." But at no +point does the combined population cross back toward parity, let alone toward +`console` being the majority — it stays firmly structured-dominated (77.1%) +throughout. + +**No seam was added.** Per triage's ruling, this document is the measurement +only; which of the two candidate seams (if either) to build is triage's call, +made with this table in hand. diff --git a/scripts/qa/log-volume-census.mjs b/scripts/qa/log-volume-census.mjs new file mode 100644 index 0000000000..b43d9a6104 --- /dev/null +++ b/scripts/qa/log-volume-census.mjs @@ -0,0 +1,301 @@ +#!/usr/bin/env node +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * log-volume-census -- how many lines does each package's test suite write, and + * WHICH WRITER wrote them? + * + * node scripts/qa/log-volume-census.mjs --list + * node scripts/qa/log-volume-census.mjs --run --budget 300 + * node scripts/qa/log-volume-census.mjs --run --only @objectstack/rest + * node scripts/qa/log-volume-census.mjs --report + * node scripts/qa/log-volume-census.mjs --report --json + * node scripts/qa/log-volume-census.mjs --classify + * + * ## The population, and why counting it needed an instrument + * + * A test run's stdout carries at least three writers, and they are NOT + * distinguishable by file descriptor: + * + * 1. the engine's STRUCTURED LOGGER -- `ObjectLogger.write()` in + * `packages/core/src/logger.ts`, which composes ` …` and + * calls `process.stdout.write` (`process.stderr` for error/fatal) DIRECTLY; + * 2. `console.*` from application, plugin and test code; + * 3. vitest's own reporter, plus the `pnpm`/script banner around it. + * + * ⚠️ The obvious discriminator -- "was it forwarded through vitest's console + * RPC?" -- does not exist in this repo. All 72 vitest configs set + * `disableConsoleIntercept: true`, enforced by + * `scripts/check-console-intercept-disarm.mjs`, so console output is NOT + * intercepted and carries no `stdout | > ` header. Both (1) and + * (2) land on the same two file descriptors, unlabelled. Capture-time + * separation would mean changing how a package runs its tests, which would + * measure a different thing than the suite anyone actually runs. + * + * So the discriminator is LINE SHAPE, anchored on the one writer whose output + * format is fixed in source: the structured logger. Everything the logger did + * not write is then split into the reporter's own bounded, enumerable + * vocabulary and the remainder. The remainder is reported as `console` -- and + * is a COMPLEMENT, not a positive identification. Anything that writes to + * stdout without the logger's head and without a reporter shape (a bare + * `process.stdout.write` from build or seed code, for instance) lands in it. + * That is stated at every output site rather than left for a reader to + * discover. + * + * ## Why the complement is the right shape anyway + * + * It is also the definition the measurement this extends used: in that table + * `console + structured == total` in all five rows, exactly. Keeping the same + * definition is what makes the two tables comparable. This one additionally + * breaks out the reporter bucket, which that table folded into `console`, so + * both numbers can be read from one run. + * + * ## What a reading is NOT + * + * - NOT a wall-clock claim. Suites here run under a shared verify lock on a + * box with other agents on it; durations are recorded for triage, never as + * performance figures. + * - NOT invariant across worker counts in ORDER, only in COUNT. Interleaving + * changes with `VITEST_MAX_WORKERS`; which lines get emitted does not. + * - NOT meaningful for a RED suite without saying so. A failing suite prints + * stack traces the green one does not, so every record carries its exit code + * and the report flags non-zero rows. + */ + +import { execFileSync, spawnSync } from 'node:child_process'; +import fs from 'node:fs'; +import path from 'node:path'; +import { fileURLToPath } from 'node:url'; +import { isEntrypoint } from '../invoked-as.mjs'; + +const REPO_ROOT = path.resolve(path.dirname(fileURLToPath(import.meta.url)), '..', '..'); +const DEFAULT_STATE_DIR = process.env.OS_LOG_CENSUS_DIR || '/tmp/os-log-volume-census'; + +/** SGR escape sequences. The logger colors its head when the stream is a TTY. */ +const ANSI = /\x1b\[[0-9;]*m/g; + +/** + * `ObjectLogger.write()`, formats `pretty` (the default) and `text`, compose + * `${new Date().toISOString()} ${level.toUpperCase()}` as the head of every + * line. `pretty` follows it with a space, `text` with ` | `. Anchored on the + * timestamp so no other writer can collide by accident. + */ +const STRUCTURED_PRETTY = /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z (?:\| )?(DEBUG|INFO|WARN|ERROR|FATAL)\b/; + +/** Format `json`: `JSON.stringify({ time, level, … })` -- key order is fixed by the literal. */ +const STRUCTURED_JSON = /^\{"time":"\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z","level":"(debug|info|warn|error|fatal)"/; + +/** + * vitest's reporter vocabulary plus the pnpm/script banner. Deliberately a + * closed list: a shape that is not here is counted as `console`, so the + * failure direction is over-counting console, never over-counting structured. + */ +const REPORTER = [ + /^\s*$/, // blank separator lines the reporter emits between blocks + /^> /, // npm/pnpm script echo: `> @objectstack/rest@17.2.0 test …` + /^\s*RUN\s+v\d/, // ` RUN v4.1.10 /path` + /^\s*(?:✓|×|❯|·|↓)\s/, // per-file / per-test result lines + /^\s*Test Files\s+/, + /^\s*Tests\s+\d/, + /^\s*Start at\s+/, + /^\s*Duration\s+/, + /^\s*Errors\s+\d/, + /^\s*Snapshots\s+/, + /^\s*Coverage /, + /^\s*(?:stdout|stderr) \| /, // present only if some config ever re-arms interception + /^\s*[-─═]{10,}\s*$/, // rules the reporter draws + /^\s*(?:Failed Tests|Unhandled Errors)\s+\d/, + /^\s*(?:FAIL|PASS)\s+/, + /^\s*⎯{3,}/, // vitest failure block separators +]; + +function isReporter(line) { + return REPORTER.some((re) => re.test(line)); +} + +/** + * Classify one captured combined-stdout+stderr log. + * Returns counts plus the level histogram of the structured population. + */ +export function classify(text) { + const counts = { total: 0, structured: 0, reporter: 0, console: 0 }; + const levels = { DEBUG: 0, INFO: 0, WARN: 0, ERROR: 0, FATAL: 0 }; + // A trailing newline must not manufacture an empty final line. + const body = text.endsWith('\n') ? text.slice(0, -1) : text; + if (body.length === 0) return { ...counts, levels }; + for (const raw of body.split('\n')) { + const line = raw.replace(ANSI, ''); + counts.total += 1; + const m = STRUCTURED_PRETTY.exec(line); + if (m) { + counts.structured += 1; + levels[m[1]] += 1; + continue; + } + const j = STRUCTURED_JSON.exec(line); + if (j) { + counts.structured += 1; + levels[j[1].toUpperCase()] += 1; + continue; + } + if (isReporter(line)) counts.reporter += 1; + else counts.console += 1; + } + return { ...counts, levels }; +} + +/** Every workspace package that declares a `test` script, minus the root. */ +export function listPackages(repoRoot = REPO_ROOT) { + const out = execFileSync('pnpm', ['-r', 'list', '--depth', '-1', '--json'], { + cwd: repoRoot, + maxBuffer: 1 << 28, + encoding: 'utf8', + }); + const rows = []; + for (const entry of JSON.parse(out)) { + if (!entry.path || path.resolve(entry.path) === path.resolve(repoRoot)) continue; + const manifest = path.join(entry.path, 'package.json'); + if (!fs.existsSync(manifest)) continue; + const pkg = JSON.parse(fs.readFileSync(manifest, 'utf8')); + if (!pkg.scripts || !pkg.scripts.test) continue; + rows.push({ + name: pkg.name, + dir: path.relative(repoRoot, entry.path), + script: pkg.scripts.test, + }); + } + rows.sort((a, b) => a.dir.localeCompare(b.dir)); + return rows; +} + +function ledgerPath(stateDir) { + return path.join(stateDir, 'ledger.json'); +} + +function readLedger(stateDir) { + const file = ledgerPath(stateDir); + if (!fs.existsSync(file)) return {}; + return JSON.parse(fs.readFileSync(file, 'utf8')); +} + +function writeLedger(stateDir, ledger) { + fs.mkdirSync(stateDir, { recursive: true }); + fs.writeFileSync(ledgerPath(stateDir), JSON.stringify(ledger, null, 1) + '\n'); +} + +/** + * Run ONE package's own `test` script, unchanged, capturing combined + * stdout+stderr. Nothing about how the package runs its tests is altered: the + * only environment this adds is a memory ceiling and a worker cap, both of + * which bound resource use on a shared box without changing which lines are + * emitted. ⚠️ Nothing else: `CI` in particular is passed through as the + * caller has it and never forced, because code that branches on `CI` would + * then be measured in a mode no one runs the suite in. + */ +export function runPackage(pkg, stateDir, repoRoot = REPO_ROOT) { + const logFile = path.join(stateDir, 'logs', `${pkg.name.replace(/[^\w.-]/g, '_')}.log`); + fs.mkdirSync(path.dirname(logFile), { recursive: true }); + const started = Date.now(); + const res = spawnSync('pnpm', ['--filter', pkg.name, 'run', 'test'], { + cwd: repoRoot, + encoding: 'utf8', + maxBuffer: 1 << 30, + env: { + ...process.env, + NODE_OPTIONS: `${process.env.NODE_OPTIONS || ''} --max-old-space-size=4096`.trim(), + VITEST_MAX_WORKERS: process.env.VITEST_MAX_WORKERS || '2', + }, + }); + const text = (res.stdout || '') + (res.stderr || ''); + fs.writeFileSync(logFile, text); + return { + ...classify(text), + exitCode: res.status === null ? -1 : res.status, + signal: res.signal || null, + seconds: Math.round((Date.now() - started) / 1000), + logFile, + measuredAt: new Date().toISOString(), + }; +} + +function fmt(n) { + return String(n).replace(/\B(?=(\d{3})+(?!\d))/g, ','); +} + +function report(stateDir, asJson) { + const ledger = readLedger(stateDir); + const all = listPackages(); + if (asJson) { + process.stdout.write(JSON.stringify({ ledger, packages: all.map((p) => p.name) }, null, 1) + '\n'); + return 0; + } + const rows = all.map((p) => ({ pkg: p, rec: ledger[p.name] })); + const measured = rows.filter((r) => r.rec); + const missing = rows.filter((r) => !r.rec); + const tot = { total: 0, structured: 0, reporter: 0, console: 0 }; + console.log('| package | console | structured | reporter | total | exit |'); + console.log('|---|---:|---:|---:|---:|---|'); + for (const { pkg, rec } of measured) { + for (const k of Object.keys(tot)) tot[k] += rec[k]; + console.log( + `| \`${pkg.dir}\` | ${fmt(rec.console)} | ${fmt(rec.structured)} | ${fmt(rec.reporter)} | ${fmt(rec.total)} | ${rec.exitCode === 0 ? 'ok' : '⚠ ' + rec.exitCode} |`, + ); + } + console.log( + `| **total, ${measured.length} suites** | **${fmt(tot.console)}** | **${fmt(tot.structured)}** | **${fmt(tot.reporter)}** | **${fmt(tot.total)}** | |`, + ); + console.log(''); + console.log(`structured share of total: ${((tot.structured / tot.total) * 100).toFixed(1)}%`); + console.log(`NOT MEASURED: ${missing.length}${missing.length ? ' — ' + missing.map((m) => m.pkg.dir).join(', ') : ''}`); + console.log(''); + console.log('`console` is a COMPLEMENT (total - structured - reporter), not a positive identification.'); + return 0; +} + +function main(argv) { + const stateDir = DEFAULT_STATE_DIR; + if (argv.includes('--list')) { + for (const p of listPackages()) console.log(`${p.name}\t${p.dir}\t${p.script}`); + return 0; + } + const classifyAt = argv.indexOf('--classify'); + if (classifyAt !== -1) { + const file = argv[classifyAt + 1]; + if (!file) { + console.error('--classify needs a file'); + return 2; + } + console.log(JSON.stringify(classify(fs.readFileSync(file, 'utf8')), null, 1)); + return 0; + } + if (argv.includes('--report')) return report(stateDir, argv.includes('--json')); + if (argv.includes('--run')) { + const budgetAt = argv.indexOf('--budget'); + const budget = budgetAt === -1 ? Infinity : Number(argv[budgetAt + 1]) * 1000; + const onlyAt = argv.indexOf('--only'); + const only = onlyAt === -1 ? null : argv[onlyAt + 1]; + const ledger = readLedger(stateDir); + const deadline = Date.now() + budget; + let ran = 0; + for (const pkg of listPackages()) { + if (only && pkg.name !== only) continue; + if (!only && ledger[pkg.name]) continue; + if (!only && Date.now() >= deadline) break; + process.stderr.write(`census: running ${pkg.name} …\n`); + const rec = runPackage(pkg, stateDir); + ledger[pkg.name] = rec; + writeLedger(stateDir, ledger); + ran += 1; + process.stderr.write( + `census: ${pkg.name} exit=${rec.exitCode} total=${rec.total} structured=${rec.structured} console=${rec.console} reporter=${rec.reporter} ${rec.seconds}s\n`, + ); + } + const remaining = listPackages().filter((p) => !ledger[p.name]).length; + console.log(`census: ran ${ran} this pass · ${remaining} still unmeasured · ledger ${ledgerPath(stateDir)}`); + return 0; + } + console.error('usage: --list | --run [--budget S] [--only PKG] | --report [--json] | --classify FILE'); + return 2; +} + +if (isEntrypoint(import.meta.url)) process.exit(main(process.argv.slice(2)));