docs(runtime): state the expected-read-refusal capture's real per-channel pass-through loudness

packages/runtime/src/expected-read-refusal-noise.channel-asymmetry.test.ts

@@ -0,0 +1,230 @@
+// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license.
+//
+// #11569 — the two captures in `expected-read-refusal-noise.ts` do NOT have the
+// same PASS-THROUGH loudness, and this file is the measurement that says so.
+//
+// ## What is pinned, and why prose alone would not have been enough
+//
+// That module's header used to claim, of both channels, that "anything it does
+// not recognise still reaches the log". It holds on the driver channel and not
+// on the engine channel:
+//
+// * `captureDriver` installs a sink whose non-matching branch calls
+// `console.warn` / `console.error` DIRECTLY, so an unrecognised driver
+// refusal is loud no matter how the kernel's logger is configured;
+// * `captureEngine` installs a Proxy whose non-matching branch calls
+// `target.error(...)` — `target` being the engine's own logger, which the
+// kernel built from its `logger` config and handed over BY REFERENCE. So
+// the pass-through is subject to that logger's level: `ObjectLogger.write`
+// returns early unless `LEVEL_ORDER.error >= LEVEL_ORDER[config.level]`,
+// which is false for `fatal` and for `silent`.
+//
+// The correction #11569 ruled is a documentation one — no behaviour moves, no
+// consuming fixture goes loud. This file is what keeps that documentation
+// HONEST: the sentences in the module header are now claims about a measured
+// threshold, and a change to either sink (or to `ObjectLogger.isEnabled`) that
+// invalidates one of them turns this red instead of leaving prose behind that
+// nobody re-measures.
+//
+// ⭐ Every case here is GREEN both before and after #11569's edit — the edit
+// changed comments only. These are regression guards on the behaviour the new
+// prose describes, never red-before evidence for it.
+//
+// ## The instrument, and its deliberate limits
+//
+// The engine pass-through's destination under `environment: 'node'` is
+// `process.stderr` (`ObjectLogger.write` prefers the process streams and only
+// falls back to `console` where they are absent — the same finding the sibling
+// module's #11571 block records). So the engine channel is counted by patching
+// `process.stderr.write`, and the driver channel by spying `console.warn`.
+//
+// ⛔ That patch is an INSTRUMENT here, not a capture mechanism: it is installed
+// around one probe kernel's lifetime and removed in a `finally`, which is a
+// different thing from the file-scoped `process.stderr` capture #11571 refuses
+// on blast-radius grounds. It also covers `bootstrap()` and `shutdown()` on
+// purpose — boot-time fail-soft reads of this lean composition would otherwise
+// print the very noise `expected-read-refusal-noise.ts` exists to withhold, and
+// a probe that measures noise by emitting some is not one.
+
+import { describe, it, expect } from 'vitest';
+import type { LogLevel } from '@objectstack/spec/system';
+import { ObjectKernel } from '@objectstack/core';
+import { ObjectQLPlugin } from '@objectstack/objectql';
+import { SqliteWasmDriver } from '@objectstack/driver-sqlite-wasm';
+
+import { DriverPlugin } from './driver-plugin.js';
+import {
+ captureExpectedReadRefusals,
+ type ExpectedReadRefusalCapture,
+} from './expected-read-refusal-noise.js';
+
+// [#10126] Both dist-resolved workspace deps above are STATIC imports, so their
+// first transform is already paid at module load rather than inside a clocked
+// `it()` body — no bare re-import is needed here (see
+// `scripts/check-test-source-alias.mjs`, the clocked-window rule).
+
+const BOOT_TIMEOUT = 60_000;
+
+/** Read by the probe, and DECLARED to the capture: the recognised pair. */
+const DECLARED_TABLE = 'probe_11569_declared';
+/** Read by the probe, and NOT declared: the unrecognised pair. */
+const UNDECLARED_TABLE = 'probe_11569_undeclared';
+
+interface Readout {
+ /** Did the read reject at all? A silent success would invalidate everything. */
+ readonly rejected: boolean;
+ /** `console.warn` lines naming the driver's refusal envelope for `table`. */
+ readonly driverPassThrough: number;
+ /** `process.stderr` lines carrying the engine's `Find operation failed`. */
+ readonly enginePassThrough: number;
+ /** What the capture withheld and counted, per channel. */
+ readonly withheldRefusals: number;
+ readonly withheldEngineFrames: number;
+ readonly silentChannels: readonly string[];
+}
+
+/**
+ * Boot a lean real kernel at `level`, read `table` through the real engine and
+ * the real sqlite driver, and count what each channel's PASS-THROUGH put in
+ * front of a reader.
+ *
+ * `declared` is what the capture was told to expect, so the caller chooses
+ * whether the resulting pair is recognised (`declared` contains `table`) or
+ * not.
+ */
+async function probeRead(
+ level: LogLevel,
+ table: string,
+ declared: readonly string[],
+): Promise<Readout> {
+ const warnings: string[] = [];
+ const stderr: string[] = [];
+
+ const realWarn = console.warn;
+ const realError = console.error;
+ const realWrite = process.stderr.write.bind(process.stderr);
+
+ console.warn = (...args: unknown[]): void => {
+ warnings.push(args.map((a) => String(a)).join(' '));
+ };
+ console.error = (...args: unknown[]): void => {
+ warnings.push(args.map((a) => String(a)).join(' '));
+ };
+ (process.stderr as { write: unknown }).write = (chunk: unknown): boolean => {
+ stderr.push(String(chunk));
+ return true;
+ };
+
+ let capture: ExpectedReadRefusalCapture | undefined;
+ let rejected = false;
+ let kernel: ObjectKernel | undefined;
+ try {
+ kernel = new ObjectKernel({ logger: { level } });
+ const driver = new SqliteWasmDriver({ filename: ':memory:' });
+ capture = captureExpectedReadRefusals(declared);
+ // ⛔ Before the driver runs any statement — the idiom the capture's own
+ // doc comment names.
+ capture.captureDriver(driver);
+ await kernel.use(new DriverPlugin(driver));
+ await kernel.use(new ObjectQLPlugin());
+ await kernel.bootstrap();
+ capture.captureEngine(kernel.getService<unknown>('objectql'));
+
+ const data = kernel.getService<{ find(o: string): Promise<unknown[]> }>('data');
+ try {
+ await data.find(table);
+ } catch {
+ rejected = true;
+ }
+ } finally {
+ try {
+ await kernel?.shutdown();
+ } catch {
+ /* the probe's verdict does not depend on a clean teardown */
+ }
+ (process.stderr as { write: unknown }).write = realWrite;
+ console.warn = realWarn;
+ console.error = realError;
+ }
+
+ return {
+ rejected,
+ driverPassThrough: warnings.filter((l) => l.includes(`refused a read on '${table}'`)).length,
+ enginePassThrough: stderr.filter((l) => l.includes('Find operation failed')).length,
+ withheldRefusals: capture?.totalRefusals() ?? -1,
+ withheldEngineFrames: capture?.totalEngineFrames() ?? -1,
+ silentChannels: capture?.silentChannels() ?? ['probe never built a capture'],
+ };
+}
+
+describe('#11569 expected-read-refusal-noise: the two channels are not equally loud on pass-through', () => {
+ it(
+ 'engine pass-through: a level ABOVE `error` (silent) drops the frame, while the driver stays loud',
+ async () => {
+ const seen = await probeRead('silent', UNDECLARED_TABLE, [DECLARED_TABLE]);
+
+ // The read really did fail — otherwise "no frame appeared" would be a
+ // statement about a read that never refused.
+ expect(seen.rejected).toBe(true);
+ // Nothing was recognised: this is the PASS-THROUGH path on both channels.
+ expect(seen.withheldRefusals).toBe(0);
+ expect(seen.withheldEngineFrames).toBe(0);
+
+ // The driver's pass-through goes to `console` directly — loud.
+ expect(seen.driverPassThrough).toBeGreaterThanOrEqual(1);
+ // The engine's pass-through goes to the kernel-derived logger — dropped.
+ expect(seen.enginePassThrough).toBe(0);
+ },
+ BOOT_TIMEOUT,
+ );
+
+ it(
+ 'engine pass-through: the SAME unrecognised read is loud at `error` — the instrument produces a positive',
+ async () => {
+ const seen = await probeRead('error', UNDECLARED_TABLE, [DECLARED_TABLE]);
+
+ expect(seen.rejected).toBe(true);
+ expect(seen.withheldEngineFrames).toBe(0);
+ expect(seen.driverPassThrough).toBeGreaterThanOrEqual(1);
+ // ⭐ The negative above is a real measurement and not a broken probe:
+ // the identical read on the identical composition DOES reach the log
+ // when the kernel's level admits `error`.
+ expect(seen.enginePassThrough).toBeGreaterThanOrEqual(1);
+ },
+ BOOT_TIMEOUT,
+ );
+
+ it(
+ 'engine pass-through: the condition is the LEVEL THRESHOLD, not the word `silent` — `fatal` drops it too',
+ async () => {
+ // `ObjectLogger.isEnabled` compares rank: `error` (3) is admitted only
+ // while the configured level is `debug`/`info`/`warn`/`error`. `fatal`
+ // (4) and `silent` (5) both refuse it, so a fixture that floats its
+ // kernel to `fatal` is just as blind as one at `silent`.
+ const seen = await probeRead('fatal', UNDECLARED_TABLE, [DECLARED_TABLE]);
+
+ expect(seen.rejected).toBe(true);
+ expect(seen.driverPassThrough).toBeGreaterThanOrEqual(1);
+ expect(seen.enginePassThrough).toBe(0);
+ },
+ BOOT_TIMEOUT,
+ );
+
+ it(
+ 'the surviving half is untouched: a RECOGNISED pair is still withheld on both channels and counted',
+ async () => {
+ const seen = await probeRead('silent', DECLARED_TABLE, [DECLARED_TABLE]);
+
+ expect(seen.rejected).toBe(true);
+ // Withheld, on both channels, and COUNTED — a capture nobody asserts is
+ // a mute, and this is the assertion.
+ expect(seen.withheldRefusals).toBeGreaterThanOrEqual(1);
+ expect(seen.withheldEngineFrames).toBeGreaterThanOrEqual(1);
+ expect([...seen.silentChannels]).toEqual([]);
+ // …and neither channel put anything in front of a reader.
+ expect(seen.driverPassThrough).toBe(0);
+ expect(seen.enginePassThrough).toBe(0);
+ },
+ BOOT_TIMEOUT,
+ );
+});

packages/runtime/src/expected-read-refusal-noise.ts

@@ -54,19 +54,55 @@
  * * it withholds ONLY the expected fault — the line must name one of the
  * caller's declared tables AND carry that same table's `no such table`
  * reason. Any other table, any other reason, any other level and any other
- * logger method is forwarded to the real console untouched;
+ * logger method is forwarded untouched to the sink that would have
+ * received it;
  * * it COUNTS what it withheld, per table and per channel, and the caller
  * asserts those counts. A capture nobody asserts is a mute.
  *
+ * ⚠️ [#11569] "Forwarded untouched" is NOT the same as "loud", and the two
+ * channels differ on exactly that point. Measured, not inferred (pinned by
+ * `expected-read-refusal-noise.channel-asymmetry.test.ts`):
+ *
+ * * `captureDriver`'s pass-through calls `console.warn` / `console.error`
+ * DIRECTLY, so an unrecognised driver refusal reaches a reader whatever
+ * the kernel's log level is;
+ * * `captureEngine`'s pass-through calls the ENGINE'S OWN logger — the one
+ * the kernel built from its `logger` config and handed over by reference
+ * — so it inherits that logger's level. `ObjectLogger.write` returns
+ * early unless `error` is enabled, which it is not whenever the
+ * configured level ranks ABOVE `error` (`fatal`, `silent`).
+ *
+ * ⇒ So the engine channel's loudness is the CALLER'S, not this module's, and
+ * it is not uniform across this capture's consumers: the ones that boot
+ * `new ObjectKernel({ logger: { level: 'silent' } })` see an unrecognised
+ * ENGINE frame nowhere at all, while the ones that leave the kernel at its
+ * default (`info`) still see it. ⛔ Do not read the silent-fixture case as the
+ * rule for all of them, and do not read a quiet engine channel in one fixture
+ * as evidence about another.
+ *
+ * ⇒ Read the guarantee per channel: the DRIVER channel is pinned in both
+ * directions (withheld-when-expected, loud-when-not); the ENGINE channel is
+ * pinned in one (withheld-when-expected, counted, asserted) and is only as
+ * loud as the fixture's own kernel logger in the other. The driver half of the
+ * same fault stays loud, which is where this class of fault can still be
+ * picked up.
+ *
  * ⛔ The engine gate is deliberately the narrowest of the two: a frame is
  * withheld only when it sits directly above a driver refusal this capture
  * already recognised ({@link ExpectedReadRefusalCapture.pending}). A
  * `DATABASE_ERROR` on one of the same tables arising from any OTHER cause is
  * not recognised by the driver sink, so its frame is not withheld here either
- * — it reaches the log with both halves intact.
- *
- * ⛔ Nothing here reads or relaxes a fixture's own assertions. This is the
- * console side-effect only.
+ * — this capture never swallows it. Its DRIVER half reaches the log intact,
+ * on the direct console sink above. Its ENGINE half is handed back to the
+ * engine's own logger, so whether a reader sees it is that logger's decision
+ * and not this module's — under `logger: { level: 'silent' }` it is dropped
+ * (see the asymmetry note above, and {@link captureExpectedReadRefusals}'s
+ * `captureEngine`).
+ *
+ * ⛔ Nothing here reads or relaxes a fixture's own assertions. This is the LOG
+ * side-effect only — and "the log" means `console` on the driver channel and
+ * the engine's own logger on the engine channel, which is the whole of the
+ * asymmetry above.
  *
  * ## Why a shared module rather than a copy per fixture
  *
@@ -138,6 +174,11 @@ export interface ExpectedReadRefusalCapture {
  * method resolves to the engine's own. ⛔ Call it before the expected reads
  * happen; the engine's logger is a private field with no setter, which is
  * the same access `engine-readonly-when-parent.test.ts` established.
+ *
+ * ⚠️ [#11569] Its PASS-THROUGH is quieter than
+ * {@link ExpectedReadRefusalCapture.captureDriver}'s: an unrecognised frame
+ * goes to the engine's own logger and is dropped under a kernel configured
+ * above `error`. The implementation carries the full note.
  */
  captureEngine(engine: unknown): void;
 }
@@ -217,6 +258,35 @@ export function captureExpectedReadRefusals(
  (driver as { logger: unknown }).logger = sink;
  },
 
+ /**
+ * ⚠️ [#11569] Where a NON-matching frame actually goes, and why it is not
+ * the same place `captureDriver`'s goes.
+ *
+ * The fall-through below is `target.error(msg, err, meta)` — `target` is
+ * the ENGINE'S OWN logger, i.e. the `ObjectLogger` the kernel built from
+ * its `logger` config and handed to the engine by reference
+ * (`core/src/kernel.ts` → `hostContext.logger`). So the pass-through
+ * inherits that logger's level: `ObjectLogger.write` returns early unless
+ * `error` is enabled, and it is not whenever the configured level ranks
+ * above `error` — `fatal` or `silent`. Fixtures that boot with
+ * `logger: { level: 'silent' }` therefore see an unrecognised engine frame
+ * NOWHERE. `captureDriver`'s sink, by contrast, calls `console` directly
+ * and is loud regardless. Both directions are pinned in
+ * `expected-read-refusal-noise.channel-asymmetry.test.ts`.
+ *
+ * ⛔ Deliberately NOT "repaired" by pointing this branch at `console`:
+ * that makes every consuming fixture — including two in another lane's
+ * packages — newly loud on a channel they expect to be quiet, to recover a
+ * diagnosis no test has yet been shown to have lost. Ruled a DOCUMENTED
+ * limit rather than a defect (#11569); a loud-channel mechanism gets its
+ * own card if an unrecognised engine frame ever actually costs one.
+ *
+ * ⛔ What this does NOT weaken: a RECOGNISED frame is still withheld here,
+ * still counted per table, and still asserted through
+ * {@link ExpectedReadRefusalCapture.silentChannels} — that half is a pin,
+ * and the driver channel carrying the same fault stays loud in both
+ * directions.
+ */
  captureEngine(engine: unknown): void {
  const base = (engine as { logger: Record<string, any> }).logger;
  (engine as { logger: unknown }).logger = new Proxy(base, {
@@ -474,9 +544,12 @@ export function captureExpectedCrossFieldRefusalNoise(
  * is process-global and sits in the path of everything the worker writes —
  * the reporter's own diagnostics included — for as long as it is installed.
  * Twenty-one invariant per-boot frames that carry no per-test signal do not
- * buy a third capture mechanism of that reach, and #11569 (this module's
- * engine pass-through already lands in a silenced logger) means the two
- * mechanisms here want repairing before a third is stacked on them.
+ * buy a third capture mechanism of that reach. #11569 — this module's engine
+ * pass-through lands in the engine's own logger, and is therefore dropped
+ * under exactly the `level: 'silent'` fixtures this section is about — was
+ * ruled a DOCUMENTED limit of the two mechanisms above rather than a repair to
+ * make (see the file header), so it is one more reason not to stack a third
+ * on top of them, and not a repair this section is waiting on.
  *
  * ⛔ Nor is the repair a predicate pointed at `kernel.logger`: the kernel takes
  * a logger CONFIG, builds its own and hands it to the plugin loader and the