Skip to content

Commit dd8172e

Browse files
Elon Muskclaude
andauthored
test(runtime): withhold and assert the expected error noise in two passing pins (#10630)
Both suites PASS while printing ERROR-shaped lines into the shared Test Core log, where turbo interleaves package output without attribution. Those lines were adopted verbatim as a p1 flake signature (#10293) and sent a full dispatch cycle at the wrong mechanism. Each expected line is now withheld by a sink scoped to the named table AND the named reason, and COUNTED — the tests assert the counts, so a capture that went quiet because the emission disappeared fails instead of passing silently. Anything unexpected still reaches the console untouched. Fixes #10380 Claude-Session: https://claude.ai/code/session_019bmVFqoQPq63zhKrxdYG1r Co-authored-by: Claude <noreply@anthropic.com>
1 parent 844bf29 commit dd8172e

2 files changed

Lines changed: 316 additions & 3 deletions

File tree

‎packages/runtime/src/metadata-list-ambient-vs-bare-transaction.integration.test.ts‎

Lines changed: 171 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -71,12 +71,134 @@ const STALL_CEILING_MS = 20_000;
7171
/** The seeded row `list('object')` must come back with. */
7272
const SEEDED_NAME = 'thing';
7373

74+
/** The one table the BARE case's stalled read is issued against. */
75+
const STALLED_OBJECT = 'sys_metadata';
76+
77+
// ═══════════════════════════════════════════════════════════════════════════
78+
// [#10380] The BARE case's expected error output: WITHHELD from the shared
79+
// log, and ASSERTED instead
80+
// ═══════════════════════════════════════════════════════════════════════════
81+
//
82+
// This test PASSES, and its subject is a failure — so it printed three
83+
// ERROR-shaped features into the shared `Test Core` log on every run:
84+
//
85+
// 1. knex's own `Acquire connection error: …` (+ a `tarn/PendingOperation`
86+
// stack), from the client's logger;
87+
// 2. the driver's `[sql-driver] DATABASE_ERROR — the backend refused a read
88+
// on 'sys_metadata'…`, from `SqlDriver.backendStatementFault`;
89+
// 3. the engine's `ERROR Find operation failed {"object":"sys_metadata",…}`
90+
// one frame up (`engine.ts`), carrying the same fault as a stack.
91+
//
92+
// Turbo interleaves package logs without attribution, so in that shard log
93+
// these are indistinguishable from a real failure. Not a hypothetical: they
94+
// were lifted VERBATIM into a p1 flake signature (#10293) and sent a whole
95+
// dispatch cycle at the wrong mechanism. Expected-failure noise from a green
96+
// test is a diagnosis tax on every future red shard.
97+
//
98+
// ⛔ What this is NOT is a mute. Silencing alone would make this file BLIND:
99+
// if the stall ever stopped happening, the log would go quiet and NOTHING
100+
// would notice — a live pin quietly demoted to a decoration. So each sink
101+
// below does two things instead of one:
102+
//
103+
// * it withholds ONLY the expected fault — named table AND named reason.
104+
// Any other table, any other reason, any other level and any other logger
105+
// method is forwarded to the real console untouched;
106+
// * it COUNTS what it withheld, and the tests assert the counts. BARE
107+
// asserts all three channels fired; AMBIENT asserts that none did, which
108+
// is a new false-negative guard in its own right — an ambient read that
109+
// silently started stalling would otherwise have its evidence swallowed.
110+
//
111+
// ⛔ The pin's own assertions are untouched by all of this. Nothing below
112+
// reads or relaxes them; this is the console side-effect only.
113+
114+
/** Per-channel tally of what the fixture withheld from the shared log. */
115+
interface WithheldNoise {
116+
/** knex's acquire-timeout notice. */
117+
knexAcquire: number;
118+
/** The driver's read-exit envelope for {@link STALLED_OBJECT}. */
119+
driverRefusal: number;
120+
/** The engine frame above it. */
121+
engineFind: number;
122+
}
123+
124+
/**
125+
* The three predicates, each pinned to BOTH the table and the reason.
126+
*
127+
* `engineFind` is deliberately the narrowest of the three: it fires only for a
128+
* frame sitting directly above a driver refusal this fixture already
129+
* recognised (`pendingRefusals`), so an identically-shaped engine error that
130+
* did NOT come from the expected stall still reaches the log with its frame
131+
* intact.
132+
*/
133+
function newNoiseCapture() {
134+
const withheld: WithheldNoise = { knexAcquire: 0, driverRefusal: 0, engineFind: 0 };
135+
/** Recognised driver refusals not yet consumed by their engine frame. */
136+
let pendingRefusals = 0;
137+
138+
return {
139+
withheld,
140+
141+
/**
142+
* knex's `log.warn`. `SqlDriverConfig` is `Knex.Config &` extras and the
143+
* constructor forwards everything it does not itself consume, so this
144+
* arrives at knex's `Logger` untouched. ⛔ Only `warn` is overridden —
145+
* knex's `debug` / `error` / `deprecate` keep their defaults.
146+
*/
147+
knexWarn: (message: unknown): void => {
148+
const line = typeof message === 'string' ? message : String(message);
149+
// knex's default `warn` sink is `console.log`; forwarding at `warn` is
150+
// if anything louder, never quieter.
151+
if (/^Acquire connection error:/.test(line) && /timed out/i.test(line)) {
152+
withheld.knexAcquire += 1;
153+
return;
154+
}
155+
console.warn(line);
156+
},
157+
158+
/**
159+
* The driver's sink, mirroring the default's `{ warn, error }` shape so
160+
* `logDurabilityFailure` still finds an `error` channel to fall back to.
161+
*/
162+
driverLogger: {
163+
warn: (msg: string, meta?: unknown): void => {
164+
const line = String(msg);
165+
if (
166+
line.includes(`the backend refused a read on '${STALLED_OBJECT}'`) &&
167+
/Timeout acquiring a connection/i.test(line)
168+
) {
169+
withheld.driverRefusal += 1;
170+
pendingRefusals += 1;
171+
return;
172+
}
173+
console.warn(msg, meta ?? '');
174+
},
175+
error: (msg: string, meta?: unknown): void => console.error(msg, meta ?? ''),
176+
},
177+
178+
/**
179+
* The engine's `error` channel, reached through a Proxy so every OTHER
180+
* logger method stays the engine's own.
181+
*/
182+
engineError: (msg: string, err?: unknown, meta?: unknown): boolean => {
183+
if (pendingRefusals === 0 || msg !== 'Find operation failed') return false;
184+
if ((meta as { object?: string } | undefined)?.object !== STALLED_OBJECT) return false;
185+
const detail = String((err as { message?: string } | undefined)?.message ?? '');
186+
if (!detail.includes(`refused to run this query for object '${STALLED_OBJECT}'`)) return false;
187+
pendingRefusals -= 1;
188+
withheld.engineFind += 1;
189+
return true;
190+
},
191+
};
192+
}
193+
74194
interface Fixture {
75195
engine: ObjectQL;
76196
driver: SqlDriver;
77197
loader: DatabaseLoader;
78198
/** Every `driver.find` the fixture has observed, and whether it carried a transaction. */
79199
reads: () => Array<{ object: string; hasTx: boolean }>;
200+
/** [#10380] What this fixture withheld from the shared log, per channel. */
201+
withheld: WithheldNoise;
80202
}
81203

82204
let fixture: Fixture | null = null;
@@ -92,13 +214,24 @@ afterEach(async () => {
92214
});
93215

94216
async function boot(): Promise<Fixture> {
217+
// [#10380] Installed BEFORE the driver exists, because knex's logger is
218+
// baked into the client at construction.
219+
const noise = newNoiseCapture();
220+
95221
const driver = new SqlDriver({
96222
client: 'better-sqlite3',
97223
connection: { filename: ':memory:' },
98224
useNullAsDefault: true,
99225
// See the header: shortens the wait, not the shape.
100226
acquireConnectionTimeout: ACQUIRE_MS,
227+
// [#10380] Channel 1 of 3 — knex's own `Acquire connection error`.
228+
log: { warn: noise.knexWarn },
101229
});
230+
// [#10380] Channel 2 of 3 — the driver's read-exit envelope. Assignment
231+
// rather than a constructor option because `logger` is a protected field
232+
// with a `console` default; this is the idiom the field's own doc comment
233+
// names ("Tests inject a spy") and that ~20 sibling driver suites use.
234+
(driver as unknown as { logger: unknown }).logger = noise.driverLogger;
102235
await driver.initObjects([SysMetadataObject as any]);
103236

104237
// Seeded through the driver rather than the engine: `sys_metadata` is
@@ -113,6 +246,19 @@ async function boot(): Promise<Fixture> {
113246
});
114247

115248
const engine = new ObjectQL();
249+
// [#10380] Channel 3 of 3 — the engine frame above the driver's exit. A
250+
// Proxy on `error` ALONE, the idiom `engine-readonly-when-parent.test.ts`
251+
// established: every other logger method resolves to the engine's own.
252+
const engineLogger = (engine as any).logger;
253+
(engine as any).logger = new Proxy(engineLogger, {
254+
get: (target: any, key: string) =>
255+
key === 'error'
256+
? (msg: string, err?: unknown, meta?: unknown) => {
257+
if (noise.engineError(msg, err, meta)) return;
258+
target.error(msg, err, meta);
259+
}
260+
: target[key],
261+
});
116262
engine.registerDriver(driver, true);
117263
await engine.init();
118264
// The engine's own proxy, not `engine.registry.registerObject` — the registry
@@ -146,6 +292,7 @@ async function boot(): Promise<Fixture> {
146292
object: call[0] as string,
147293
hasTx: (call[2] as { transaction?: unknown } | undefined)?.transaction !== undefined,
148294
})),
295+
withheld: noise.withheld,
149296
};
150297
return fixture;
151298
}
@@ -167,7 +314,7 @@ function assertEffectiveTimeout(driver: SqlDriver): void {
167314

168315
describe('#7842 metadata list under an open transaction: ambient vs bare (real ObjectQL + real SqlDriver)', () => {
169316
it('AMBIENT — a transaction opened via engine.transaction() is threaded onto the loader read, which completes', async () => {
170-
const { engine, driver, loader, reads } = await boot();
317+
const { engine, driver, loader, reads, withheld } = await boot();
171318
assertEffectiveTimeout(driver);
172319

173320
const before = reads().length;
@@ -207,10 +354,18 @@ describe('#7842 metadata list under an open transaction: ambient vs bare (real O
207354
// And it did not stall on the way: the whole ambient case finishes inside
208355
// the acquire bound the bare case exhausts.
209356
expect(elapsed).toBeLessThan(STALL_CEILING_MS);
357+
358+
// ── [#10380] The capture's own anti-vacuity guard, on the side that is
359+
// expected to be SILENT. The ambient path must produce none of the three
360+
// features — so if it ever started stalling, the sinks installed for the
361+
// bare case would swallow the evidence and this case would still pass on
362+
// the assertions above. Asserting the absence closes that.
363+
expect(withheld, 'the AMBIENT path must emit no expected-failure noise at all')
364+
.toEqual({ knexAcquire: 0, driverRefusal: 0, engineFind: 0 });
210365
});
211366

212367
it('BARE — a transaction opened directly on the driver is invisible to the ambient store, and the loader read stalls out connection acquisition', async () => {
213-
const { engine, driver, loader, reads } = await boot();
368+
const { engine, driver, loader, reads, withheld } = await boot();
214369
assertEffectiveTimeout(driver);
215370

216371
const before = reads().length;
@@ -259,6 +414,20 @@ describe('#7842 metadata list under an open transaction: ambient vs bare (real O
259414
const bare = reads().slice(before).filter((r) => r.object === 'sys_metadata');
260415
expect(bare.length).toBeGreaterThan(0);
261416
expect(bare.every((r) => !r.hasTx)).toBe(true);
417+
418+
// ── [#10380] The capture is a PIN, not a mute. These three lines used
419+
// to reach the shared `Test Core` log out of a PASSING test and were
420+
// read there as a real failure; they are withheld now, and asserted
421+
// here instead. If the stall stops happening, the log goes quiet AND
422+
// these go red — which is exactly the failure mode a bare `console`
423+
// mute would have hidden. One assertion per channel so a silent one
424+
// names itself.
425+
expect(withheld.knexAcquire, "knex's acquire-timeout notice was never emitted")
426+
.toBeGreaterThan(0);
427+
expect(withheld.driverRefusal, `the driver's read refusal for '${STALLED_OBJECT}' was never emitted`)
428+
.toBeGreaterThan(0);
429+
expect(withheld.engineFind, "the engine's 'Find operation failed' frame was never emitted")
430+
.toBeGreaterThan(0);
262431
} finally {
263432
await driver.rollback(trx);
264433
}

0 commit comments

Comments
 (0)