diff --git a/packages/runtime/src/metadata-list-ambient-vs-bare-transaction.integration.test.ts b/packages/runtime/src/metadata-list-ambient-vs-bare-transaction.integration.test.ts index f5fe57c19f..3e3eba76bc 100644 --- a/packages/runtime/src/metadata-list-ambient-vs-bare-transaction.integration.test.ts +++ b/packages/runtime/src/metadata-list-ambient-vs-bare-transaction.integration.test.ts @@ -71,12 +71,134 @@ const STALL_CEILING_MS = 20_000; /** The seeded row `list('object')` must come back with. */ const SEEDED_NAME = 'thing'; +/** The one table the BARE case's stalled read is issued against. */ +const STALLED_OBJECT = 'sys_metadata'; + +// ═══════════════════════════════════════════════════════════════════════════ +// [#10380] The BARE case's expected error output: WITHHELD from the shared +// log, and ASSERTED instead +// ═══════════════════════════════════════════════════════════════════════════ +// +// This test PASSES, and its subject is a failure — so it printed three +// ERROR-shaped features into the shared `Test Core` log on every run: +// +// 1. knex's own `Acquire connection error: …` (+ a `tarn/PendingOperation` +// stack), from the client's logger; +// 2. the driver's `[sql-driver] DATABASE_ERROR — the backend refused a read +// on 'sys_metadata'…`, from `SqlDriver.backendStatementFault`; +// 3. the engine's `ERROR Find operation failed {"object":"sys_metadata",…}` +// one frame up (`engine.ts`), carrying the same fault as a stack. +// +// Turbo interleaves package logs without attribution, so in that shard log +// these are indistinguishable from a real failure. Not a hypothetical: they +// were lifted VERBATIM into a p1 flake signature (#10293) and sent a whole +// dispatch cycle at the wrong mechanism. Expected-failure noise from a green +// test is a diagnosis tax on every future red shard. +// +// ⛔ What this is NOT is a mute. Silencing alone would make this file BLIND: +// if the stall ever stopped happening, the log would go quiet and NOTHING +// would notice — a live pin quietly demoted to a decoration. So each sink +// below does two things instead of one: +// +// * it withholds ONLY the expected fault — named table AND named reason. +// Any other table, any other reason, any other level and any other logger +// method is forwarded to the real console untouched; +// * it COUNTS what it withheld, and the tests assert the counts. BARE +// asserts all three channels fired; AMBIENT asserts that none did, which +// is a new false-negative guard in its own right — an ambient read that +// silently started stalling would otherwise have its evidence swallowed. +// +// ⛔ The pin's own assertions are untouched by all of this. Nothing below +// reads or relaxes them; this is the console side-effect only. + +/** Per-channel tally of what the fixture withheld from the shared log. */ +interface WithheldNoise { + /** knex's acquire-timeout notice. */ + knexAcquire: number; + /** The driver's read-exit envelope for {@link STALLED_OBJECT}. */ + driverRefusal: number; + /** The engine frame above it. */ + engineFind: number; +} + +/** + * The three predicates, each pinned to BOTH the table and the reason. + * + * `engineFind` is deliberately the narrowest of the three: it fires only for a + * frame sitting directly above a driver refusal this fixture already + * recognised (`pendingRefusals`), so an identically-shaped engine error that + * did NOT come from the expected stall still reaches the log with its frame + * intact. + */ +function newNoiseCapture() { + const withheld: WithheldNoise = { knexAcquire: 0, driverRefusal: 0, engineFind: 0 }; + /** Recognised driver refusals not yet consumed by their engine frame. */ + let pendingRefusals = 0; + + return { + withheld, + + /** + * knex's `log.warn`. `SqlDriverConfig` is `Knex.Config &` extras and the + * constructor forwards everything it does not itself consume, so this + * arrives at knex's `Logger` untouched. ⛔ Only `warn` is overridden — + * knex's `debug` / `error` / `deprecate` keep their defaults. + */ + knexWarn: (message: unknown): void => { + const line = typeof message === 'string' ? message : String(message); + // knex's default `warn` sink is `console.log`; forwarding at `warn` is + // if anything louder, never quieter. + if (/^Acquire connection error:/.test(line) && /timed out/i.test(line)) { + withheld.knexAcquire += 1; + return; + } + console.warn(line); + }, + + /** + * The driver's sink, mirroring the default's `{ warn, error }` shape so + * `logDurabilityFailure` still finds an `error` channel to fall back to. + */ + driverLogger: { + warn: (msg: string, meta?: unknown): void => { + const line = String(msg); + if ( + line.includes(`the backend refused a read on '${STALLED_OBJECT}'`) && + /Timeout acquiring a connection/i.test(line) + ) { + withheld.driverRefusal += 1; + pendingRefusals += 1; + return; + } + console.warn(msg, meta ?? ''); + }, + error: (msg: string, meta?: unknown): void => console.error(msg, meta ?? ''), + }, + + /** + * The engine's `error` channel, reached through a Proxy so every OTHER + * logger method stays the engine's own. + */ + engineError: (msg: string, err?: unknown, meta?: unknown): boolean => { + if (pendingRefusals === 0 || msg !== 'Find operation failed') return false; + if ((meta as { object?: string } | undefined)?.object !== STALLED_OBJECT) return false; + const detail = String((err as { message?: string } | undefined)?.message ?? ''); + if (!detail.includes(`refused to run this query for object '${STALLED_OBJECT}'`)) return false; + pendingRefusals -= 1; + withheld.engineFind += 1; + return true; + }, + }; +} + interface Fixture { engine: ObjectQL; driver: SqlDriver; loader: DatabaseLoader; /** Every `driver.find` the fixture has observed, and whether it carried a transaction. */ reads: () => Array<{ object: string; hasTx: boolean }>; + /** [#10380] What this fixture withheld from the shared log, per channel. */ + withheld: WithheldNoise; } let fixture: Fixture | null = null; @@ -92,13 +214,24 @@ afterEach(async () => { }); async function boot(): Promise { + // [#10380] Installed BEFORE the driver exists, because knex's logger is + // baked into the client at construction. + const noise = newNoiseCapture(); + const driver = new SqlDriver({ client: 'better-sqlite3', connection: { filename: ':memory:' }, useNullAsDefault: true, // See the header: shortens the wait, not the shape. acquireConnectionTimeout: ACQUIRE_MS, + // [#10380] Channel 1 of 3 — knex's own `Acquire connection error`. + log: { warn: noise.knexWarn }, }); + // [#10380] Channel 2 of 3 — the driver's read-exit envelope. Assignment + // rather than a constructor option because `logger` is a protected field + // with a `console` default; this is the idiom the field's own doc comment + // names ("Tests inject a spy") and that ~20 sibling driver suites use. + (driver as unknown as { logger: unknown }).logger = noise.driverLogger; await driver.initObjects([SysMetadataObject as any]); // Seeded through the driver rather than the engine: `sys_metadata` is @@ -113,6 +246,19 @@ async function boot(): Promise { }); const engine = new ObjectQL(); + // [#10380] Channel 3 of 3 — the engine frame above the driver's exit. A + // Proxy on `error` ALONE, the idiom `engine-readonly-when-parent.test.ts` + // established: every other logger method resolves to the engine's own. + const engineLogger = (engine as any).logger; + (engine as any).logger = new Proxy(engineLogger, { + get: (target: any, key: string) => + key === 'error' + ? (msg: string, err?: unknown, meta?: unknown) => { + if (noise.engineError(msg, err, meta)) return; + target.error(msg, err, meta); + } + : target[key], + }); engine.registerDriver(driver, true); await engine.init(); // The engine's own proxy, not `engine.registry.registerObject` — the registry @@ -146,6 +292,7 @@ async function boot(): Promise { object: call[0] as string, hasTx: (call[2] as { transaction?: unknown } | undefined)?.transaction !== undefined, })), + withheld: noise.withheld, }; return fixture; } @@ -167,7 +314,7 @@ function assertEffectiveTimeout(driver: SqlDriver): void { describe('#7842 metadata list under an open transaction: ambient vs bare (real ObjectQL + real SqlDriver)', () => { it('AMBIENT — a transaction opened via engine.transaction() is threaded onto the loader read, which completes', async () => { - const { engine, driver, loader, reads } = await boot(); + const { engine, driver, loader, reads, withheld } = await boot(); assertEffectiveTimeout(driver); const before = reads().length; @@ -207,10 +354,18 @@ describe('#7842 metadata list under an open transaction: ambient vs bare (real O // And it did not stall on the way: the whole ambient case finishes inside // the acquire bound the bare case exhausts. expect(elapsed).toBeLessThan(STALL_CEILING_MS); + + // ── [#10380] The capture's own anti-vacuity guard, on the side that is + // expected to be SILENT. The ambient path must produce none of the three + // features — so if it ever started stalling, the sinks installed for the + // bare case would swallow the evidence and this case would still pass on + // the assertions above. Asserting the absence closes that. + expect(withheld, 'the AMBIENT path must emit no expected-failure noise at all') + .toEqual({ knexAcquire: 0, driverRefusal: 0, engineFind: 0 }); }); it('BARE — a transaction opened directly on the driver is invisible to the ambient store, and the loader read stalls out connection acquisition', async () => { - const { engine, driver, loader, reads } = await boot(); + const { engine, driver, loader, reads, withheld } = await boot(); assertEffectiveTimeout(driver); const before = reads().length; @@ -259,6 +414,20 @@ describe('#7842 metadata list under an open transaction: ambient vs bare (real O const bare = reads().slice(before).filter((r) => r.object === 'sys_metadata'); expect(bare.length).toBeGreaterThan(0); expect(bare.every((r) => !r.hasTx)).toBe(true); + + // ── [#10380] The capture is a PIN, not a mute. These three lines used + // to reach the shared `Test Core` log out of a PASSING test and were + // read there as a real failure; they are withheld now, and asserted + // here instead. If the stall stops happening, the log goes quiet AND + // these go red — which is exactly the failure mode a bare `console` + // mute would have hidden. One assertion per channel so a silent one + // names itself. + expect(withheld.knexAcquire, "knex's acquire-timeout notice was never emitted") + .toBeGreaterThan(0); + expect(withheld.driverRefusal, `the driver's read refusal for '${STALLED_OBJECT}' was never emitted`) + .toBeGreaterThan(0); + expect(withheld.engineFind, "the engine's 'Find operation failed' frame was never emitted") + .toBeGreaterThan(0); } finally { await driver.rollback(trx); } diff --git a/packages/runtime/src/notification-schema-conformance.integration.test.ts b/packages/runtime/src/notification-schema-conformance.integration.test.ts index 4c0f48b95f..55824b3fef 100644 --- a/packages/runtime/src/notification-schema-conformance.integration.test.ts +++ b/packages/runtime/src/notification-schema-conformance.integration.test.ts @@ -62,6 +62,125 @@ const declaredNotificationKeys = () => new Set(Object.keys((NotificationSchema a const declaredMarkReadKeys = () => new Set(Object.keys((MarkNotificationsReadResponseSchema as any).shape)); const declaredMarkAllReadKeys = () => new Set(Object.keys((MarkAllNotificationsReadResponseSchema as any).shape)); +// ═══════════════════════════════════════════════════════════════════════════ +// [#10380] The authz resolver's expected read failures: WITHHELD from the +// shared log, and ASSERTED instead +// ═══════════════════════════════════════════════════════════════════════════ +// +// This fixture provisions the messaging objects and nothing else, so every +// request's `resolveUserAuthzGrants` (`core/src/security/resolve-authz-context.ts`) +// reads six `sys_*` tables that were never created. `tryFind` swallows each +// one by design — the resolver is fail-closed and must always resolve — but on +// the way out the driver and the engine each log it. Measured on `origin/main`: +// 63 `[sql-driver] DATABASE_ERROR — the backend refused a read on '…'` lines +// and 63 matching `ERROR Find operation failed` frames, out of a suite whose +// eight tests all PASS. +// +// Turbo interleaves package logs without attribution, so in the `Test Core` +// shard log those are indistinguishable from a real failure — they were lifted +// verbatim into a p1 flake signature (#10293) and cost a full dispatch cycle +// aimed at the wrong mechanism. +// +// ⛔ Not a mute. A capture that only silences would make this file blind: if +// those reads ever started SUCCEEDING (someone provisions the tables) or +// stopped happening (the resolver drops a read), the log would go quiet and +// nothing would notice. So the sinks below withhold ONLY the expected fault — +// each line must name one of the six tables AND carry that same table's +// `no such table` reason — and record what they withheld, which `afterAll` +// asserts. Everything else reaches the console untouched. + +/** + * The six tables the resolver reads and this fixture does not provision. + * Derived by measurement, not from the resolver's source, so a read this + * fixture stops provoking shows up as a changed set rather than silently. + */ +const ABSENT_AUTHZ_TABLES = [ + 'sys_user', + 'sys_member', + 'sys_user_position', + 'sys_user_permission_set', + 'sys_position', + 'sys_setting', +] as const; + +/** + * The five of them read on EVERY grant resolution, i.e. on every request this + * file makes. `sys_setting` is deliberately NOT here: it is read on only some + * routes (3 of the 12 resolutions), so requiring it would turn a single-test + * `-t` run red without meaning anything. + */ +const ALWAYS_READ_AUTHZ_TABLES = ABSENT_AUTHZ_TABLES.filter((t) => t !== 'sys_setting'); + +/** Installs the two sinks and hands back the tables they withheld. */ +function captureExpectedAbsentTableNoise() { + const withheld = new Set(); + /** Recognised driver refusals not yet consumed by their engine frame. */ + const pending = new Map(); + + /** The refusal envelope AND the dialect reason must name the SAME table. */ + const expectedRefusal = (line: string): string | undefined => + ABSENT_AUTHZ_TABLES.find( + (t) => line.includes(`refused a read on '${t}'`) && line.includes(`no such table: ${t}`), + ); + + return { + withheld, + + /** + * The driver's sink. Mirrors the default's `{ warn, error }` shape so + * `logDurabilityFailure` still finds an `error` channel. + */ + install(driver: unknown): void { + (driver as { logger: unknown }).logger = { + warn: (msg: string, meta?: unknown): void => { + const table = expectedRefusal(String(msg)); + if (table) { + withheld.add(table); + pending.set(table, (pending.get(table) ?? 0) + 1); + return; + } + console.warn(msg, meta ?? ''); + }, + error: (msg: string, meta?: unknown): void => console.error(msg, meta ?? ''), + }; + }, + + /** + * The engine's `error` channel, through a Proxy so every other logger + * method stays the engine's own. + * + * ⛔ Gated on `pending`: an engine frame is withheld only when it sits + * directly above a driver refusal this capture already recognised. A + * `DATABASE_ERROR` on one of these six 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. + */ + wrapEngine(engine: unknown): void { + const base = (engine as { logger: any }).logger; + (engine as { logger: any }).logger = new Proxy(base, { + get: (target: any, key: string) => + key === 'error' + ? (msg: string, err?: unknown, meta?: unknown) => { + const object = (meta as { object?: string } | undefined)?.object; + const outstanding = object ? (pending.get(object) ?? 0) : 0; + const detail = String((err as { message?: string } | undefined)?.message ?? ''); + if ( + msg === 'Find operation failed' && + object && + outstanding > 0 && + detail.includes(`refused to run this query for object '${object}'`) + ) { + pending.set(object, outstanding - 1); + return; + } + target.error(msg, err, meta); + } + : target[key], + }); + }, + }; +} + /** Minimal `auth` service — `x-test-user` names the principal, absent = anonymous. */ function fakeAuthPlugin(): Plugin { return { @@ -86,10 +205,16 @@ describe('[#5792] the notification wire bodies conform to the schemas the catalo let kernel: ObjectKernel; let baseUrl: string; let messaging: MessagingService; + /** [#10380] The expected-noise capture, asserted in `afterAll`. */ + const noise = captureExpectedAbsentTableNoise(); beforeAll(async () => { kernel = new ObjectKernel({ logLevel: 'silent' }); - await kernel.use(new DriverPlugin(new SqliteWasmDriver({ filename: ':memory:' }))); + // [#10380] The driver is named rather than inlined so its logger can be + // scoped before it ever runs a statement. + const driver = new SqliteWasmDriver({ filename: ':memory:' }); + noise.install(driver); + await kernel.use(new DriverPlugin(driver)); await kernel.use(new ObjectQLPlugin()); // Inline delivery so `emit()` materializes the inbox row synchronously. await kernel.use(new MessagingServicePlugin({ reliableDelivery: false })); @@ -98,6 +223,10 @@ describe('[#5792] the notification wire bodies conform to the schemas the catalo await kernel.use(createDispatcherPlugin({ prefix: '/api/v1', securityHeaders: false, requireAuth: false })); await kernel.bootstrap(); + // [#10380] The engine only exists once the kernel has bootstrapped; the + // reads this scopes all happen later, per request. + noise.wrapEngine(kernel.getService('objectql')); + const httpServer = kernel.getService('http.server'); baseUrl = `http://127.0.0.1:${httpServer.getPort!()}`; messaging = kernel.getService('notification'); @@ -118,6 +247,21 @@ describe('[#5792] the notification wire bodies conform to the schemas the catalo new Promise((resolve) => setTimeout(resolve, 10_000)), ]); } + + // [#10380] The capture is a PIN, not a mute — asserted after shutdown so + // a failure here can never leave the kernel running. Every one of these + // reads happens on EVERY grant resolution, so this holds for a single + // filtered test as well as for the whole file. If one goes silent, the + // right repair is to re-derive the list above, NOT to relax this: a + // resolver read that stopped happening is a finding, and a table that + // started resolving means this fixture now provisions it. + for (const table of ALWAYS_READ_AUTHZ_TABLES) { + expect( + noise.withheld.has(table), + `the expected '${table}' read failure was never emitted — resolveUserAuthzGrants ` + + 'no longer reads it, or it no longer fails, and this capture has stopped measuring it', + ).toBe(true); + } }, 30_000); /** Drive one route as `user`, asserting the shared envelope, and hand back `data`. */