diff --git a/.changeset/migrate-plan-missing-table-log-level.md b/.changeset/migrate-plan-missing-table-log-level.md new file mode 100644 index 0000000000..24ed2f4e39 --- /dev/null +++ b/.changeset/migrate-plan-missing-table-log-level.md @@ -0,0 +1,58 @@ +--- +"@objectstack/objectql": patch +--- + +fix(objectql): stop reporting "the table does not exist yet" as an ERROR with a stack trace (#13273) + +`ObjectQL.find` logged every read failure identically: `ERROR Find operation +failed`, carrying the driver's fault as a stack. That merged two different +facts — **"this table has not been created yet"** and **"this read failed"** — +onto one channel, at the level reserved for the second. + +Measured on `os migrate plan --database-url file:`, +which is the ordinary first run and exactly the run the command exists to +describe: **five** ERROR records with full stack traces, out of a command that +exits 0 and prints a correct plan. Every one of them is a boot-path probe whose +caller already treats a missing table as a normal answer and says so in its own +code — `readMigrationFlagVerified` (`sys_migration`), +`ObjectStoreActionActivationStore.probe` (`sys_metadata_activation`), +`readAuthoredTranslationLayer` and `ObjectQLPlugin`'s authored-hook / +authored-action re-syncs (`sys_metadata`, which report `authoredRows: 0` and +carry on). An `error` channel that fires on a routine state is what trains +operators to skim `error`. + +**What changed:** the read path now picks the level from the CAUSE. A failure +that positively identifies as "relation does not exist" — asked through the +shared `isMissingTableError` predicate (`@objectstack/metadata/errors`), never a +hand-rolled code test — is logged at `debug` with a +`reason: 'table-not-provisioned'` meta and no stack. Everything else is +unchanged: `error`, with the Error and its stack. + +**⛔ What did not change**, and is pinned: + +- **The throw.** Both branches rethrow the driver's envelope byte-identically, + so no caller's control flow, `catch` or error envelope moves. This is a log + level and nothing else. +- **Every genuinely failed read.** A connection drop, a timeout, a permission + denial, an unclassified fault — and, through the predicate's `excludes`, + Postgres' `column "x" of relation "y" does not exist`, which contains a legal + missing-table phrase but is a column fault on a table that exists — all stay + loud. Measured end to end on the same command: against a database whose + `sys_metadata` exists but lacks the column being filtered on, three ERROR + records with stacks remain in the same run in which the two still-absent + tables stay quiet; against a file that is not a database at all + (`SQLITE_NOTADB`), all five stay loud and the command exits 1. +- **The driver's own refusal envelope.** `[sql-driver] DATABASE_ERROR — the + backend refused a read on '' … no such table:
` still goes to + `warn` on every one of these reads. It is deliberately the surviving loud + half: the class remains visible to an operator, without a duplicate and + without a stack. +- **The write verbs.** `insert` / `update` / `delete` keep their unconditional + `error` — a write to a table that does not exist is not a normal answer for + any caller, and nothing landed. + +User-visible: `os migrate plan` (and any first boot against an unprovisioned +database) no longer prints these stack traces. Fixtures that captured this frame +on the `error` channel should read `debug` as well; the shared +`expected-read-refusal-noise` helper in `@objectstack/runtime`'s test tree +already does. diff --git a/packages/objectql/src/engine-file-hydrate-outage.test.ts b/packages/objectql/src/engine-file-hydrate-outage.test.ts index c996b8dc1b..f0f34fa215 100644 --- a/packages/objectql/src/engine-file-hydrate-outage.test.ts +++ b/packages/objectql/src/engine-file-hydrate-outage.test.ts @@ -13,12 +13,15 @@ * * ONE CORRECTION to the issue body, measured rather than assumed: the catch is * zero-output, but the PATH is not literally silent. The generic read handler - * one frame up already logs `error: 'Find operation failed' { object: - * 'sys_file' }` before rethrowing into this catch. That line is untouched here, - * and `the pre-existing generic line cannot tell the two apart` below pins why - * it does not satisfy the acceptance: it is byte-identical for the benign and - * the non-benign failure, and it describes the sub-read only — never the parent - * object, the fields left un-hydrated, or the consequence. + * one frame up already logs `'Find operation failed' { object: 'sys_file' }` + * before rethrowing into this catch. That line is untouched here, and the + * `the generic line separates the two causes but still cannot name the loss` + * block below pins why it does not satisfy the acceptance: it describes the + * sub-read only — never the parent object, the fields left un-hydrated, or the + * consequence. ⚠️ [#13273] That block was rewritten when the generic frame + * stopped being `error` for every cause: it is `debug` for the benign + * "table was never provisioned" class now, and `error` for everything else. + * The consequence gap this file exists to close is unchanged either way. * * The pass-through itself is correct and is NOT what this fixes. A file-metadata * read that fails must not take down the record read that asked for it, so @@ -279,16 +282,26 @@ describe('sys_file hydrate read fault — distinguishable from "no file" (#6116) * #6116's body says the seam logs nothing. Measured on `origin/main` that is * true of the CATCH, but not of the whole path: the generic read handler one * frame up (`engine.ts`, `'Find operation failed'`) already reports the - * failed `sys_file` sub-read at `error` before rethrowing into this catch. - * That line is real and this fix neither removes nor duplicates it. + * failed `sys_file` sub-read before rethrowing into this catch. That line is + * real and this fix neither removes nor duplicates it. * - * It cannot be the discriminator the acceptance asks for, for two reasons - * pinned below: it is emitted IDENTICALLY for the benign and the non-benign - * failure, and it describes the sub-read only — never the parent object, - * the fields left un-hydrated, or the consequence that those bare ids will - * read downstream as "this record has no file". + * ⚠️ [#13273] What HAS moved since #6116, and why this block was rewritten + * rather than deleted. That generic frame used to be `error` for every cause + * — which is what made it useless as a discriminator, and is the sentence + * this block used to pin. `engine.ts` now asks `isMissingTableError` and puts + * the benign class on `debug`, so the two causes no longer produce the same + * line. The re-pinned facts below are therefore: + * + * 1. the generic frame DOES now separate the two causes by channel — the + * benign read leaves the `error` channel empty (#13273's own acceptance, + * re-measured from this file's fake driver); + * 2. and it STILL does not satisfy #6116's acceptance, because on the + * outage branch it describes the sub-read only — never the parent + * object, the fields left un-hydrated, or the consequence that those + * bare ids will read downstream as "this record has no file". That gap + * is what the seam's own `warn` closes, and it is unchanged. */ - describe('the pre-existing generic line cannot tell the two apart', () => { + describe('the generic line separates the two causes but still cannot name the loss', () => { async function errorCensus(make: () => unknown) { await boot(async () => { throw make(); @@ -297,17 +310,45 @@ describe('sys_file hydrate read fault — distinguishable from "no file" (#6116) return logger.lines.error.map((l: any) => l.msg); } - it('reports the same `error` for a benign and a non-benign failure', async () => { + /** + * The `debug` channel carries the engine's ordinary read tracing too, so + * this census is narrowed to the one frame under test. ⛔ Narrowed by an + * EXACT message match, not a substring: a filter that also admitted + * `'Find operation starting'` would report a frame this block did not + * measure. + */ + async function debugCensus(make: () => unknown) { + await boot(async () => { + throw make(); + }); + await engine.find('doc'); + return logger.lines.debug.filter((l: any) => l.msg === 'Find operation failed'); + } + + it('[#13273] the benign cause no longer reaches `error` — it reaches `debug`', async () => { const benign = await errorCensus(() => new Error('no such table: sys_file')); const outage = await errorCensus(() => Object.assign(new Error('connect ECONNREFUSED 127.0.0.1:5432'), { code: 'ECONNREFUSED' })); - // Identical — so an operator reading only this line learns that a read - // failed, never whether the answer they received can be trusted. - expect(benign).toEqual(['Find operation failed']); + // "The table was never provisioned" is a routine state, not a failure to + // report — and every caller on that path treats it as a normal answer. + expect(benign).toEqual([]); + // ⭐ The positive control on that zero: the SAME read, one cause over, + // still reaches `error`. So the empty census above measures the + // classification and not a broken fixture. expect(outage).toEqual(['Find operation failed']); }); + it('[#13273] the benign frame is still recorded, one channel down', async () => { + // ⛔ Demoted, not muted: the frame is still emitted, still names the + // object, and now carries its own classification instead of a stack. + const benign = await debugCensus(() => new Error('no such table: sys_file')); + expect(benign.map((l: any) => l.msg)).toEqual(['Find operation failed']); + + const [meta] = benign[0].args; + expect(meta).toMatchObject({ object: 'sys_file', reason: 'table-not-provisioned' }); + }); + it('names only the sub-read, not the degradation it caused', async () => { await boot(async () => { throw Object.assign(new Error('connect ECONNREFUSED 127.0.0.1:5432'), { code: 'ECONNREFUSED' }); diff --git a/packages/objectql/src/engine-find-missing-table-log-level.test.ts b/packages/objectql/src/engine-find-missing-table-log-level.test.ts new file mode 100644 index 0000000000..314f6a3674 --- /dev/null +++ b/packages/objectql/src/engine-find-missing-table-log-level.test.ts @@ -0,0 +1,340 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * #13273 — a `find` that failed because the table was never created is not the + * same fact as a `find` that FAILED, and the two must not share a log level. + * + * ## What was measured, and where + * + * `os migrate plan --database-url file:`, run from an + * example app with `NODE_ENV=production` — the ordinary first run, and exactly + * the run the command exists to describe. It exits 0 and prints a correct plan. + * On the way there it emitted **five** `ERROR Find operation failed` records + * with full stack traces, one per boot-path probe of a table that does not + * exist yet: + * + * | caller | object | + * |:---|:---| + * | `readAuthoredTranslationLayer` (`core/src/fallbacks/authored-translation-sync.ts`) | `sys_metadata` | + * | `ObjectQLPlugin.readAuthoredHookRows` (`objectql/src/plugin.ts`) | `sys_metadata` | + * | `ObjectQLPlugin.readAuthoredActionRows` (`objectql/src/plugin.ts`) | `sys_metadata` | + * | `ObjectStoreActionActivationStore.probe` (`objectql/src/action-activation.ts`) | `sys_metadata_activation` | + * | `ObjectQL.readMigrationFlagVerified` (`objectql/src/engine.ts`) | `sys_migration` | + * + * Every one of those callers treats a missing table as a normal answer and says + * so in its own code — `readMigrationFlagVerified`'s "an unreadable table … + * → false", the two re-syncs' `authoredRows: 0`, and the activation probe's + * caller, which already follows the frame with a `warn` stating the consequence + * in operator terms. So the `error` channel was firing for a condition every + * consumer downstream of it handles as routine, which is the over-application + * that trains operators to skim `error`. + * + * ## ⛔ What this file pins is a DISCRIMINATION, not a silence + * + * The whole risk in a fix of this shape is collapsing "the table does not exist + * yet" into "the read failed" — which would buy a quiet log by making a real + * outage quiet too. So every zero here is paired with a positive control on the + * same seam: for each demoted class there is a sibling case that must still be + * loud, and the file fails if either half moves. + * + * Three things are deliberately NOT changed and are pinned as such: + * + * 1. **The throw.** Both branches rethrow, byte-identical, so no caller's + * control flow depends on the level chosen here. + * 2. **The write verbs.** `insert`/`update`/`delete` keep an unconditional + * `error` — a write to a table that does not exist is not a normal answer + * for any caller, and nothing landed. + * 3. **The `excludes` boundary** (#6347). Postgres' `column "x" of relation + * "y" does not exist` CONTAINS a legal missing-table phrase but is a + * column fault on a table that exists. It stays `error`. + * + * Drives a fake DRIVER (not a fake engine), so no engine write-verb dispatch + * contract is involved. + */ + +import { describe, it, expect, beforeEach } from 'vitest'; +import { ObjectQL } from './engine'; + +/** The object under read — registered, so the read reaches the driver. */ +const OBJECT = 'sys_probe'; + +/** + * The driver's own envelope, reproduced. `SqlDriver.backendStatementFault` + * composes this message and hangs the dialect error off a NON-ENUMERABLE + * `cause`, which is the only place the "no such table" text survives — so a + * classifier that reads the top-level message alone answers "not benign" here. + * Reproducing the envelope rather than throwing the raw dialect error is the + * point: it is what the engine actually catches in production. + */ +function envelope(cause: unknown): Error { + const err = new Error( + `The database refused to run this query for object '${OBJECT}'. The driver could not ` + + 'attribute the failure to any part of the request, so no verdict about the query is ' + + "claimed here. The backend's own diagnostic and the compiled statement were written " + + 'to the server log for an operator to read.', + ) as Error & { code?: string; status?: number }; + err.code = 'DATABASE_ERROR'; + Object.defineProperty(err, 'cause', { + value: cause, + enumerable: false, + writable: true, + configurable: true, + }); + return err; +} + +/** "The table has not been provisioned", in each dialect's own words. */ +const MISSING_TABLE: Array<[string, () => unknown]> = [ + ['SQLite / libsql message-only', () => new Error(`no such table: ${OBJECT}`)], + [ + 'PostgreSQL 42P01 undefined_table', + () => Object.assign(new Error(`relation "${OBJECT}" does not exist`), { code: '42P01' }), + ], + [ + 'MySQL ER_NO_SUCH_TABLE', + () => + Object.assign(new Error(`Table 'app.${OBJECT}' doesn't exist`), { + code: 'ER_NO_SUCH_TABLE', + errno: 1146, + }), + ], +]; + +/** + * "The rows may well exist — I just could not see them." Each is a real class + * the demotion must NOT reach; the last is #6347's exclusion, which carries a + * complete missing-table phrase inside a column fault on an existing table. + */ +const STILL_LOUD: Array<[string, () => unknown]> = [ + [ + 'connection refused', + () => Object.assign(new Error('connect ECONNREFUSED 127.0.0.1:5432'), { code: 'ECONNREFUSED' }), + ], + [ + 'statement timeout', + () => Object.assign(new Error('canceling statement due to statement timeout'), { code: '57014' }), + ], + [ + 'permission denied', + () => Object.assign(new Error(`permission denied for table ${OBJECT}`), { code: '42501' }), + ], + [ + 'connection terminated mid-query', + () => Object.assign(new Error('Connection terminated unexpectedly'), { code: '08006' }), + ], + [ + '#6347 — a COLUMN of a relation that exists', + () => + Object.assign(new Error(`column "label" of relation "${OBJECT}" does not exist`), { + code: '42703', + }), + ], +]; + +/** Records every line the engine writes, per level, with its raw arg list. */ +function makeCapturingLogger() { + const lines: Record> = { + debug: [], info: [], warn: [], error: [], trace: [], fatal: [], + }; + const push = (level: string) => (...args: any[]) => { + lines[level].push({ msg: String(args[0]), args: args.slice(1) }); + }; + const logger: any = { + lines, + debug: push('debug'), + info: push('info'), + warn: push('warn'), + error: push('error'), + trace: push('trace'), + fatal: push('fatal'), + child() { + return logger; + }, + }; + return logger; +} + +/** A driver whose every verb on {@link OBJECT} throws `fault()`. */ +function makeFailingDriver(fault: () => unknown) { + return { + name: 'memory', + version: '0.0.0', + supports: {}, + async connect() {}, + async disconnect() {}, + async checkHealth() { + return true; + }, + async execute() { + return null; + }, + async find() { + throw fault(); + }, + async findOne() { + throw fault(); + }, + async create() { + throw fault(); + }, + async update() { + throw fault(); + }, + async delete() { + throw fault(); + }, + async count() { + throw fault(); + }, + async bulkCreate() { + throw fault(); + }, + async bulkUpdate() { + throw fault(); + }, + async bulkDelete() { + throw fault(); + }, + async beginTransaction() { + return { __trx: true, commit: async () => {}, rollback: async () => {} }; + }, + async commit() {}, + async rollback() {}, + } as any; +} + +describe('engine `find` failure log level is chosen by CAUSE (#13273)', () => { + let engine: ObjectQL; + let logger: ReturnType; + + async function boot(fault: () => unknown) { + logger = makeCapturingLogger(); + engine = new ObjectQL({ logger } as any); + engine.registerDriver(makeFailingDriver(fault), true); + await engine.init(); + engine.registry.registerObject({ + name: OBJECT, + fields: { label: { type: 'text' } }, + } as any); + } + + /** Every `Find operation failed` line the run produced, keyed by level. */ + function frames() { + return { + error: logger.lines.error.filter((l: any) => l.msg === 'Find operation failed'), + debug: logger.lines.debug.filter((l: any) => l.msg === 'Find operation failed'), + }; + } + + beforeEach(() => { + logger = makeCapturingLogger(); + }); + + // ------------------------------------------------------- demoted class -- + + describe('"the table was never provisioned" — demoted to `debug`, stack dropped', () => { + for (const [label, make] of MISSING_TABLE) { + it(`no \`error\` frame, one \`debug\` frame — ${label}`, async () => { + await boot(() => envelope(make())); + + await expect(engine.find(OBJECT)).rejects.toThrow(); + + const seen = frames(); + expect(seen.error).toHaveLength(0); + expect(seen.debug).toHaveLength(1); + }); + } + + it('the demoted line still carries the object, the classification and the reason', async () => { + await boot(() => envelope(new Error(`no such table: ${OBJECT}`))); + await expect(engine.find(OBJECT)).rejects.toThrow(); + + // `debug(message, meta)` — meta is the FIRST trailing arg, and there is + // no Error argument at all, which is how the stack leaves the record. + const [meta] = frames().debug[0].args; + expect(meta).toMatchObject({ object: OBJECT, reason: 'table-not-provisioned' }); + expect(String((meta as any).error)).toContain( + `The database refused to run this query for object '${OBJECT}'`, + ); + // ⛔ The stack is what made this record expensive to read on a command + // that SUCCEEDS. Nothing in the demoted record carries one. + expect(JSON.stringify(meta)).not.toContain(' at '); + }); + + it('classifies through the driver envelope, not the raw dialect error', async () => { + // The envelope's own message says nothing about a missing table — the + // dialect text survives only on its non-enumerable `cause`. A classifier + // that read the top-level message would leave this at `error`, so this + // case is what proves the `cause` walk is the one being exercised. + await boot(() => envelope(new Error(`no such table: ${OBJECT}`))); + await expect(engine.find(OBJECT)).rejects.toThrow(); + + const [meta] = frames().debug[0].args; + // The classification landed even though the text the classifier keys on + // is nowhere in the message it was handed. + expect(String((meta as any).error)).not.toContain('no such table'); + expect(frames().debug).toHaveLength(1); + expect(frames().error).toHaveLength(0); + }); + }); + + // --------------------------------------------- positive control: loud -- + + describe('⭐ positive control — a read that genuinely FAILED is still loud', () => { + for (const [label, make] of STILL_LOUD) { + it(`one \`error\` frame carrying the Error, no \`debug\` frame — ${label}`, async () => { + await boot(() => envelope(make())); + + await expect(engine.find(OBJECT)).rejects.toThrow(); + + const seen = frames(); + expect(seen.debug).toHaveLength(0); + expect(seen.error).toHaveLength(1); + // `error(message, error, meta)` — the Error object is the FIRST + // trailing arg, which is what puts the stack in the record. + const [err, meta] = seen.error[0].args; + expect(err).toBeInstanceOf(Error); + expect(typeof (err as Error).stack).toBe('string'); + expect(meta).toMatchObject({ object: OBJECT }); + }); + } + + it('an unrecognised failure is loud — a benign verdict is earned, never defaulted to', async () => { + await boot(() => envelope(new Error('something nobody has classified yet'))); + await expect(engine.find(OBJECT)).rejects.toThrow(); + + expect(frames().error).toHaveLength(1); + expect(frames().debug).toHaveLength(0); + }); + }); + + // ------------------------------------------------ what did NOT change -- + + describe('⛔ unchanged: the throw, and the write verbs', () => { + it('rethrows the driver envelope on BOTH branches, unmodified', async () => { + await boot(() => envelope(new Error(`no such table: ${OBJECT}`))); + await expect(engine.find(OBJECT)).rejects.toThrow( + /The database refused to run this query/, + ); + + await boot(() => envelope(Object.assign(new Error('connect ECONNREFUSED 127.0.0.1:5432'), { code: 'ECONNREFUSED' }))); + await expect(engine.find(OBJECT)).rejects.toThrow( + /The database refused to run this query/, + ); + }); + + it('a WRITE to a table that does not exist is still `error`', async () => { + // Nothing landed, and the row the caller believes it stored is gone — + // never a normal answer, whatever the cause. + await boot(() => envelope(new Error(`no such table: ${OBJECT}`))); + + await expect(engine.insert(OBJECT, { label: 'x' } as any)).rejects.toThrow(); + + const insertFrames = logger.lines.error.filter( + (l: any) => l.msg === 'Insert operation failed', + ); + expect(insertFrames).toHaveLength(1); + expect(logger.lines.debug.filter((l: any) => l.msg === 'Insert operation failed')).toHaveLength(0); + }); + }); +}); diff --git a/packages/objectql/src/engine.ts b/packages/objectql/src/engine.ts index 2fd8872234..598d208ba2 100644 --- a/packages/objectql/src/engine.ts +++ b/packages/objectql/src/engine.ts @@ -8822,7 +8822,7 @@ export class ObjectQL implements IObjectQLEngine { return hookContext.result; } catch (e) { - this.logger.error('Find operation failed', e as Error, { object }); + this.reportFindFailure(object, e); throw e; } }); @@ -8830,6 +8830,75 @@ export class ObjectQL implements IObjectQLEngine { return opCtx.result as any[]; } + /** + * Report a failed {@link find} at the level its CAUSE earns — then leave the + * throw exactly where it was. + * + * ## The two facts this frame used to merge + * + * "The table has not been created yet" and "the read failed" are different + * facts, and until #13273 this line reported both at `error`, with a stack. + * The first one is the ordinary state of a database nobody has migrated yet, + * and every caller on that path already treats it as a normal answer and says + * so in its own code: {@link readMigrationFlagVerified} ("an unreadable table + * … → false"), `ObjectQLPlugin.readAuthoredHookRows` / + * `readAuthoredActionRows` (report `authoredRows: 0` and carry on), + * `readAuthoredTranslationLayer`, and `ObjectStoreActionActivationStore.probe` + * (whose caller already follows this frame with a `warn` stating the + * consequence in operator terms). + * + * Measured, on `os migrate plan --database-url file:`: five + * ERROR records with full stack traces, out of a command that EXITS 0 and + * prints a correct plan. Four stack traces are the first thing an operator + * sees when planning a database whose whole point is that it is not migrated + * yet — and an `error` channel that fires on a routine state is the + * over-application `sql-driver.ts` already names on a nearby line: it trains + * everyone to skim `error`. + * + * ## ⛔ What this is NOT is a broadened catch + * + * * The throw is UNCHANGED on both branches. No caller's control flow, no + * caller's `catch`, and no error envelope moves — this method decides a + * log level and nothing else. + * * Only the class that positively identifies as "relation does not exist" + * is demoted, asked through the shared {@link isMissingTableError} + * predicate (`@objectstack/metadata/errors`, #4825) — the same call + * {@link probeInstallOrganizations} and {@link resolveFileReferences} + * make, never a hand-rolled `code === '42P01'` copy. That predicate earns + * a benign verdict rather than defaulting to one: a connection drop, a + * timeout, a permission denial, a query fault — and, through its + * `excludes`, Postgres' `column "x" of relation "y" does not exist`, + * which contains a legal missing-table phrase but is a column fault on a + * table that EXISTS — all stay `error`, with the stack. + * * The fault stays visible without this frame: the driver's own refusal + * envelope (`SqlDriver.backendStatementFault` → `logger.warn`) carries + * the table, the dialect reason and the compiled statement, and is + * untouched here. That is deliberately the surviving loud half, and it is + * the half `runtime/src/expected-read-refusal-noise.ts` already documents + * as "where this class of fault can still be picked up". + * + * `debug` rather than `warn` for exactly that reason: the driver already puts + * one warn-level line per refusal in front of a reader, so a second would + * move this noise rather than remove it. What the demotion drops is the + * duplicate and its stack; the classification survives in the meta. + * + * ⛔ Deliberately READS only. `insert`/`update`/`delete` keep their + * unconditional `error`: a write to a table that does not exist is not a + * normal answer for any caller — nothing landed, and the row the caller + * believes it stored is gone. + */ + private reportFindFailure(object: string, error: unknown): void { + if (isMissingTableError(error)) { + this.logger.debug('Find operation failed', { + object, + reason: 'table-not-provisioned', + error: (error as { message?: unknown } | null | undefined)?.message, + }); + return; + } + this.logger.error('Find operation failed', error as Error, { object }); + } + /** * Read the ONE record the query selects, or `null`. * 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 2ae7ab20ea..bb076f8093 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 @@ -13,11 +13,29 @@ // `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`. +// `target.error(...)` / `target.debug(...)` — `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[frame] >= LEVEL_ORDER[config.level]`. +// +// ⚠️ [#13273] The frame this probe provokes is a MISSING TABLE, and `engine.ts` +// now classifies that class onto `debug` rather than `error` (its own +// `reportFindFailure`). Two mechanical consequences for this instrument, both +// measured rather than reasoned: +// +// * the threshold the engine channel is compared against is `debug` (rank 0), +// not `error` (rank 3) — so the positive control below probes at `debug`, +// which is the level that admits this frame, where `error` used to be; +// * `ObjectLogger.write` sends `error`/`fatal` to `process.stderr` and every +// other level to `process.stdout`, so the instrument patches BOTH streams +// and counts their union. Patching stderr alone would have read the +// demotion as "the frame stopped being emitted" — a false negative that +// looks exactly like the thing this file exists to detect. +// +// The asymmetry itself is unchanged in shape and is what stays pinned: the +// driver channel is loud at any level, the engine channel is only as loud as +// the fixture's own kernel logger. // // The correction #11569 ruled is a documentation one — no behaviour moves, no // consuming fixture goes loud. This file is what keeps that documentation @@ -32,11 +50,12 @@ // // ## 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`. +// The engine pass-through's destination under `environment: 'node'` is a +// process stream (`ObjectLogger.write` prefers them and only falls back to +// `console` where they are absent — the same finding the sibling module's +// #11571 block records): `process.stderr` for `error`/`fatal`, `process.stdout` +// for everything else. So the engine channel is counted by patching BOTH +// stream writers, 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 @@ -75,7 +94,12 @@ interface Readout { 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`. */ + /** + * Process-stream lines carrying the engine's `Find operation failed`, from + * `stderr` and `stdout` together — [#13273] the frame's level decides which + * of the two it lands on, and this file measures whether a reader saw it at + * all, not which pipe carried it. + */ readonly enginePassThrough: number; /** What the capture withheld and counted, per channel. */ readonly withheldRefusals: number; @@ -98,11 +122,12 @@ async function probeRead( declared: readonly string[], ): Promise { const warnings: string[] = []; - const stderr: string[] = []; + const streamed: string[] = []; const realWarn = console.warn; const realError = console.error; - const realWrite = process.stderr.write.bind(process.stderr); + const realErrWrite = process.stderr.write.bind(process.stderr); + const realOutWrite = process.stdout.write.bind(process.stdout); console.warn = (...args: unknown[]): void => { warnings.push(args.map((a) => String(a)).join(' ')); @@ -111,7 +136,11 @@ async function probeRead( warnings.push(args.map((a) => String(a)).join(' ')); }; (process.stderr as { write: unknown }).write = (chunk: unknown): boolean => { - stderr.push(String(chunk)); + streamed.push(String(chunk)); + return true; + }; + (process.stdout as { write: unknown }).write = (chunk: unknown): boolean => { + streamed.push(String(chunk)); return true; }; @@ -142,7 +171,8 @@ async function probeRead( } catch { /* the probe's verdict does not depend on a clean teardown */ } - (process.stderr as { write: unknown }).write = realWrite; + (process.stderr as { write: unknown }).write = realErrWrite; + (process.stdout as { write: unknown }).write = realOutWrite; console.warn = realWarn; console.error = realError; } @@ -150,7 +180,7 @@ async function probeRead( return { rejected, driverPassThrough: warnings.filter((l) => l.includes(`refused a read on '${table}'`)).length, - enginePassThrough: stderr.filter((l) => l.includes('Find operation failed')).length, + enginePassThrough: streamed.filter((l) => l.includes('Find operation failed')).length, withheldRefusals: capture?.totalRefusals() ?? -1, withheldEngineFrames: capture?.totalEngineFrames() ?? -1, silentChannels: capture?.silentChannels() ?? ['probe never built a capture'], @@ -159,7 +189,7 @@ async function probeRead( 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', + 'engine pass-through: a level above the frame\'s own (silent) drops it, while the driver stays loud', async () => { const seen = await probeRead('silent', UNDECLARED_TABLE, [DECLARED_TABLE]); @@ -179,16 +209,21 @@ describe('#11569 expected-read-refusal-noise: the two channels are not equally l ); it( - 'engine pass-through: the SAME unrecognised read is loud at `error` — the instrument produces a positive', + 'engine pass-through: the SAME unrecognised read is loud at `debug` — the instrument produces a positive', async () => { - const seen = await probeRead('error', UNDECLARED_TABLE, [DECLARED_TABLE]); + // [#13273] `debug` is the level that admits THIS frame: the probe reads a + // table that does not exist, and `engine.ts` classifies that class onto + // `debug`. Before #13273 the same control was run at `error`. The claim + // under test is unchanged — "the engine channel is only as loud as the + // kernel's own level" — only the rank it is compared against moved. + const seen = await probeRead('debug', 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`. + // when the kernel's level admits the frame. expect(seen.enginePassThrough).toBeGreaterThanOrEqual(1); }, BOOT_TIMEOUT, @@ -197,10 +232,11 @@ describe('#11569 expected-read-refusal-noise: the two channels are not equally l 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`. + // `ObjectLogger.isEnabled` compares rank: this frame ([#13273] `debug`, + // rank 0) is admitted only while the configured level is `debug`. + // `fatal` (4) and `silent` (5) both refuse it — as do `info` and `warn` + // — so a fixture that floats its kernel to `fatal` is just as blind as + // one at `silent`. The threshold, not the word `silent`, is the rule. const seen = await probeRead('fatal', UNDECLARED_TABLE, [DECLARED_TABLE]); expect(seen.rejected).toBe(true); diff --git a/packages/runtime/src/expected-read-refusal-noise.ts b/packages/runtime/src/expected-read-refusal-noise.ts index da3af9238f..064a196320 100644 --- a/packages/runtime/src/expected-read-refusal-noise.ts +++ b/packages/runtime/src/expected-read-refusal-noise.ts @@ -33,8 +33,16 @@ * 1. `[sql-driver] DATABASE_ERROR — the backend refused a read on '
' * … no such table:
`, from `SqlDriver.backendStatementFault` * through the driver's own `logger.warn`; - * 2. `ERROR Find operation failed {"object":"
",…}` one frame up - * (`objectql/src/engine.ts`), carrying the same fault as a stack. + * 2. `Find operation failed {"object":"
",…}` one frame up + * (`objectql/src/engine.ts`), carrying the same fault. ⚠️ [#13273] It used + * to be `ERROR`, with a stack, for EVERY cause; since #13273 the engine + * asks `isMissingTableError` and puts the "table not provisioned" class + * — i.e. exactly the class this module is declared over — on `debug` + * instead, with no stack and a `reason: 'table-not-provisioned'` meta. + * So this capture wraps BOTH channels (see `captureEngine`); which one a + * given frame arrives on is the ENGINE's classification, never this + * module's, and a frame that arrives on `error` is by construction one + * the engine did NOT recognise as a missing table. * * Turbo interleaves package logs without attribution, so in the shared shard * log those are indistinguishable from a real failure. Not a hypothetical: @@ -69,8 +77,8 @@ * * `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`). + * early unless the frame's OWN level is enabled, which it is not whenever + * the configured level ranks above it (for `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 @@ -80,6 +88,13 @@ * rule for all of them, and do not read a quiet engine channel in one fixture * as evidence about another. * + * ⚠️ [#13273] The threshold moved for the "table not provisioned" class, and + * moved DOWN: that frame is now `debug` (rank 0), so a fixture has to be at + * `debug` to see an unrecognised one, where `info` used to be enough. The + * asymmetry above is unchanged in shape — the engine channel is still only as + * loud as the fixture's own kernel logger — the rank it is compared against + * is now the frame's, not `error`'s. + * * ⇒ 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 @@ -170,15 +185,21 @@ export interface ExpectedReadRefusalCapture { */ captureDriver(driver: unknown): void; /** - * Wrap the engine's `error` channel through a Proxy, so every OTHER logger - * 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. + * Wrap the engine's `error` AND `debug` channels through a Proxy, so every + * OTHER logger 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. + * + * ⚠️ [#13273] Both channels, because the engine now picks between them by + * cause: a read whose table was never provisioned goes to `debug`, every + * other read failure stays on `error`. Wrapping only one would leave this + * capture blind on whichever half the engine chose. * * ⚠️ [#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. + * above that frame's own level. The implementation carries the full note. */ captureEngine(engine: unknown): void; } @@ -262,13 +283,14 @@ export function captureExpectedReadRefusals( * ⚠️ [#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 fall-through below is `target.error(msg, err, meta)` — or, on the + * [#13273] `debug` arm, `target.debug(msg, 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 + * the frame's own level is enabled, and `error` is not whenever the + * configured level ranks above it — `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 @@ -289,26 +311,53 @@ export function captureExpectedReadRefusals( */ captureEngine(engine: unknown): void { const base = (engine as { logger: Record }).logger; + /** + * The one recognition rule, shared by both channels the engine can put + * this frame on. Written once so the `debug` arm cannot drift looser + * than the `error` arm — the direction that turns a pin back into a mute. + */ + const recognised = (msg: string, object: string | undefined, detail: string): boolean => { + const outstanding = object !== undefined ? (pending.get(object) ?? 0) : 0; + if ( + msg === 'Find operation failed' && + object !== undefined && + outstanding > 0 && + detail.includes(`refused to run this query for object '${object}'`) + ) { + pending.set(object, outstanding - 1); + bump(engineFrames, object); + return true; + } + return false; + }; (engine as { logger: unknown }).logger = new Proxy(base, { - get: (target: Record, key: string) => - key === 'error' - ? (msg: string, err?: unknown, meta?: unknown) => { - const object = (meta as { object?: string } | undefined)?.object; - const outstanding = object !== undefined ? (pending.get(object) ?? 0) : 0; - const detail = String((err as { message?: string } | undefined)?.message ?? ''); - if ( - msg === 'Find operation failed' && - object !== undefined && - outstanding > 0 && - detail.includes(`refused to run this query for object '${object}'`) - ) { - pending.set(object, outstanding - 1); - bump(engineFrames, object); - return; - } - target.error(msg, err, meta); - } - : target[key], + get: (target: Record, key: string) => { + if (key === 'error') { + return (msg: string, err?: unknown, meta?: unknown) => { + const object = (meta as { object?: string } | undefined)?.object; + const detail = String((err as { message?: string } | undefined)?.message ?? ''); + if (recognised(msg, object, detail)) return; + target.error(msg, err, meta); + }; + } + // [#13273] The SAME frame, on the channel the engine now chooses for + // a read whose table was never provisioned — which is every read this + // capture is declared over. `debug(msg, meta)` has no `error` + // argument, so the driver's envelope arrives as `meta.error` instead; + // the recognition rule above is otherwise identical, and a withheld + // frame is counted into the same `engineFrames` tally the caller + // asserts. ⛔ Without this arm the tally would read 0 for every + // declared table and `silentChannels()` would report a channel that + // is in fact firing — a false red across ~20 consuming fixtures. + if (key === 'debug') { + return (msg: string, meta?: unknown) => { + const m = meta as { object?: string; error?: unknown } | undefined; + if (recognised(msg, m?.object, String(m?.error ?? ''))) return; + target.debug(msg, meta); + }; + } + return target[key]; + }, }); }, };