From 88b91131437265c3950bc0e5363802a43da63bae Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 25 Aug 2026 16:25:40 +0000 Subject: [PATCH 1/3] docs(runtime): state the expected-read-refusal capture's real pass-through asymmetry MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The module header claimed, of both channels, that anything the capture does not recognise is forwarded to the real console. That holds for `captureDriver` (its non-matching branch calls `console` directly) and not for `captureEngine` (its non-matching branch calls the engine's own kernel-derived logger, which drops an `error` frame whenever the configured level ranks above `error` — `fatal` or `silent`). Documentation only: no sink, predicate, count or assertion changes, and no consuming fixture becomes loud. A new pin measures both directions of the asymmetry on a real kernel so the prose cannot rot unnoticed. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01HbG3rGVLjZStHQxHDtzJdJ --- ...ad-refusal-noise.channel-asymmetry.test.ts | 231 ++++++++++++++++++ .../src/expected-read-refusal-noise.ts | 75 +++++- 2 files changed, 301 insertions(+), 5 deletions(-) create mode 100644 packages/runtime/src/expected-read-refusal-noise.channel-asymmetry.test.ts diff --git a/packages/runtime/src/expected-read-refusal-noise.channel-asymmetry.test.ts b/packages/runtime/src/expected-read-refusal-noise.channel-asymmetry.test.ts new file mode 100644 index 0000000000..c60b2be731 --- /dev/null +++ b/packages/runtime/src/expected-read-refusal-noise.channel-asymmetry.test.ts @@ -0,0 +1,231 @@ +// 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] Pay the first transform of these dist-resolved workspace deps at +// MODULE LOAD, not inside a clocked `it()` body — see +// `scripts/check-test-source-alias.mjs` (the clocked-window rule). +import '@objectstack/objectql'; +import '@objectstack/driver-sqlite-wasm'; + +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 { + 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('objectql')); + + const data = kernel.getService<{ find(o: string): Promise }>('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, + ); +}); diff --git a/packages/runtime/src/expected-read-refusal-noise.ts b/packages/runtime/src/expected-read-refusal-noise.ts index d506e10494..e3fc865371 100644 --- a/packages/runtime/src/expected-read-refusal-noise.ts +++ b/packages/runtime/src/expected-read-refusal-noise.ts @@ -54,16 +54,44 @@ * * 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`). Several + * consumers of this capture boot with `logger: { level: 'silent' }`, and + * in those an unrecognised ENGINE frame is dropped rather than logged. + * + * ⇒ 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. + * — 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 * console side-effect only. @@ -138,6 +166,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 +250,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 }).logger; (engine as { logger: unknown }).logger = new Proxy(base, { @@ -474,9 +536,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 From 5f21451fc3679a01b72bde27ca913b09fc101d5c Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 25 Aug 2026 16:44:03 +0000 Subject: [PATCH 2/3] test(runtime): pin the expected-read-refusal capture's per-channel pass-through loudness Boots a real lean kernel (ObjectQL + sqlite-wasm) at four logger levels and counts what each channel's pass-through puts in front of a reader: level driver pass-through engine pass-through info 1 1 error 1 1 fatal 1 0 silent 1 0 plus a recognised-pair case proving the withholding/counting half is unchanged. Comment-only edits elsewhere in the module; this is what keeps those sentences from rotting unmeasured. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01HbG3rGVLjZStHQxHDtzJdJ --- ...expected-read-refusal-noise.channel-asymmetry.test.ts | 9 ++++----- packages/runtime/src/expected-read-refusal-noise.ts | 6 ++++-- 2 files changed, 8 insertions(+), 7 deletions(-) diff --git a/packages/runtime/src/expected-read-refusal-noise.channel-asymmetry.test.ts b/packages/runtime/src/expected-read-refusal-noise.channel-asymmetry.test.ts index c60b2be731..2ae7ab20ea 100644 --- a/packages/runtime/src/expected-read-refusal-noise.channel-asymmetry.test.ts +++ b/packages/runtime/src/expected-read-refusal-noise.channel-asymmetry.test.ts @@ -58,11 +58,10 @@ import { type ExpectedReadRefusalCapture, } from './expected-read-refusal-noise.js'; -// [#10126] Pay the first transform of these dist-resolved workspace deps at -// MODULE LOAD, not inside a clocked `it()` body — see -// `scripts/check-test-source-alias.mjs` (the clocked-window rule). -import '@objectstack/objectql'; -import '@objectstack/driver-sqlite-wasm'; +// [#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; diff --git a/packages/runtime/src/expected-read-refusal-noise.ts b/packages/runtime/src/expected-read-refusal-noise.ts index e3fc865371..468154b009 100644 --- a/packages/runtime/src/expected-read-refusal-noise.ts +++ b/packages/runtime/src/expected-read-refusal-noise.ts @@ -93,8 +93,10 @@ * (see the asymmetry note above, and {@link captureExpectedReadRefusals}'s * `captureEngine`). * - * ⛔ Nothing here reads or relaxes a fixture's own assertions. This is the - * console side-effect only. + * ⛔ 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 * From f811e755a6258e968041f50a8c2f72015a689e35 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 25 Aug 2026 16:51:13 +0000 Subject: [PATCH 3/3] docs(runtime): say that the engine channel's loudness is per-fixture, not uniform Measured on origin/main: only 3 of the 19 fixtures that carry captureExpectedReadRefusals construct their kernel with `logger: { level: 'silent' }`; the other 16 leave it at the default `info`, where an unrecognised engine frame IS logged. The header now says so, so the silent-fixture case is not read as the rule for all of them. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01HbG3rGVLjZStHQxHDtzJdJ --- packages/runtime/src/expected-read-refusal-noise.ts | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/packages/runtime/src/expected-read-refusal-noise.ts b/packages/runtime/src/expected-read-refusal-noise.ts index 468154b009..da3af9238f 100644 --- a/packages/runtime/src/expected-read-refusal-noise.ts +++ b/packages/runtime/src/expected-read-refusal-noise.ts @@ -70,9 +70,15 @@ * 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`). Several - * consumers of this capture boot with `logger: { level: 'silent' }`, and - * in those an unrecognised ENGINE frame is dropped rather than logged. + * 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