From 6434aeeff6b1bb69af27e1bcdf7fcf322d2fa3bb Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 30 Sep 2026 07:42:03 +0000 Subject: [PATCH 1/3] fix(driver-sql): a missing table read by the driver's own pre-DDL question leaves the warn channel The first boot of a new database printed one `[sql-driver] DATABASE_ERROR ... no such table: sys_migration` line. The read is the engine's migration-gate read, reached through the ADR-0104 media-arm resolver the driver asks at the start of its first initObjects, before its schema pass has created any table. The resolver now runs inside an async scope, and the read-exit terminal routes one class off the warn channel inside that scope: a missing table, recognised by the shared isMissingTableError over the envelope's declared target. Every other refusal still warns, and so does a missing table read outside the scope. The resolver's answer is unchanged. Claude-Session: https://claude.ai/code/session_01DEvba2nBuD4tWzfq8r8NFY Co-authored-by: Claude --- packages/drivers/driver-sql/src/sql-driver.ts | 78 ++++++++++++++++--- 1 file changed, 69 insertions(+), 9 deletions(-) diff --git a/packages/drivers/driver-sql/src/sql-driver.ts b/packages/drivers/driver-sql/src/sql-driver.ts index 2462eccd9c0..a3647fd1115 100644 --- a/packages/drivers/driver-sql/src/sql-driver.ts +++ b/packages/drivers/driver-sql/src/sql-driver.ts @@ -88,6 +88,7 @@ import { uniqueViolationColumn, resolveTenancyPosture, declareTargetedTable, + isMissingTableError, } from '@objectstack/types'; import { postureEnforcesWall } from '@objectstack/spec/security'; import { @@ -147,10 +148,34 @@ import { import { recoverUnencodedJsonText } from './unencoded-json-text.js'; import knex, { Knex } from 'knex'; import { nanoid } from 'nanoid'; +import { AsyncLocalStorage } from 'node:async_hooks'; import { createHash } from 'node:crypto'; import { existsSync } from 'node:fs'; import { currentPerfTiming, perfNow, type PerfTiming } from '@objectstack/observability'; +/** + * [#20768] The async scope of a driver's own PRE-DDL question: the ADR-0104 + * media-arm resolver that {@link SqlDriver.resolveFileColumnsMoved} asks at the + * start of the first `initObjects`, before this driver has created any table. + * + * The resolver the engine supplies answers by reading `sys_migration`. On the + * first boot of a new database that table does not exist yet, because this + * very schema pass is what creates it. The backend refuses the read, and the + * resolver answers "not moved", which is the correct answer for a store with + * no columns. So the refusal is the ordinary state of a new database, and not + * a `DATABASE_ERROR` to put in front of an operator. + * + * Only one question reads through this scope, and only + * {@link SqlDriver.backendStatementFault} consults it. ⛔ It demotes one class, + * a missing table, recognised by the shared `isMissingTableError`. Any other + * refusal inside the scope still warns, and so does a missing table outside it. + * + * Module-level rather than per instance: the read the question issues goes to + * whichever driver serves the ledger. On a multi-datasource composition that + * can be another instance of this class, and it is in the same async chain. + */ +const PRE_DDL_QUESTION_SCOPE = new AsyncLocalStorage(); + /** * Default ID length for auto-generated IDs. */ @@ -6113,6 +6138,13 @@ export class SqlDriver implements IDataDriver { protected logger: { warn: (msg: string, meta?: any) => void; info?: (msg: string, meta?: any) => void; + /** + * [#20768] Below-warn channel for a refusal that is the ordinary state of + * the store, not a fault (see {@link SqlDriver.backendStatementFault}). + * The default sink has none, so such a line is dropped unless a host + * injects a logger that keeps `debug`. + */ + debug?: (msg: string, meta?: any) => void; /** * Durability-degradation channel (see AGENTS.md §Degradation log levels): * used when a constraint the metadata claims is enforced is NOT — e.g. a @@ -10010,20 +10042,45 @@ export class SqlDriver implements IDataDriver { const detail = (error as { message?: unknown } | null | undefined)?.message; const code = (error as { code?: unknown } | null | undefined)?.code; - this.logger.warn( - `[sql-driver] DATABASE_ERROR — the backend refused a read on '${object}'` + - (typeof code === 'string' && code.length > 0 ? ` (${code})` : '') + - '. The dialect message below is kept server-side: it carries the compiled statement, ' + - 'and on the dialects that inline them the bound literals too (#7929, #8931): ' + - `${typeof detail === 'string' ? detail : String(error)}`, - ); + const dialectText = typeof detail === 'string' ? detail : String(error); // [#13438] The table the statement was compiled against, resolved the way // {@link SqlDriver.getBuilder} resolves it — a federated object's // `external.remoteName`, otherwise the object's own name — because every // read exit that reaches here built its statement through `getBuilder`. // Declared on the envelope for `isMissingTableError`; never in the message. const targetedTable = this.physicalTableByObject[object] ?? object; - return backendStatementFaultError(object, error, targetedTable); + const envelope = backendStatementFaultError(object, error, targetedTable); + + // [#20768] One class leaves the warn channel, and only inside one scope: a + // table that does not exist yet, read while a driver asks its pre-DDL + // question (the ADR-0104 media-arm resolver, asked before the schema pass + // creates any table). On the first boot of a new database that read is + // `sys_migration`, and its refusal is the ordinary state of the store. The + // resolver hears the refusal and answers "not moved", as it always did. + // + // ⛔ Demoted, not deleted: the same dialect text goes to `debug`, which the + // default sink does not have. ⛔ Asked through the one shared predicate, + // over the envelope's DECLARED target, so a missing table named by some + // other relation (a view over a dropped table) is not this class. Every + // other refusal in the scope, and a missing table outside it, warns below. + if (PRE_DDL_QUESTION_SCOPE.getStore() === true && isMissingTableError(envelope, object)) { + this.logger.debug?.( + `[sql-driver] '${object}' does not exist yet: it was read while this driver asked its ` + + 'pre-DDL question (the ADR-0104 media-arm resolver), before its schema pass created ' + + 'any table. The refusal goes back to the resolver, which answers from it: ' + + dialectText, + ); + return envelope; + } + + this.logger.warn( + `[sql-driver] DATABASE_ERROR — the backend refused a read on '${object}'` + + (typeof code === 'string' && code.length > 0 ? ` (${code})` : '') + + '. The dialect message below is kept server-side: it carries the compiled statement, ' + + 'and on the dialects that inline them the bound literals too (#7929, #8931): ' + + dialectText, + ); + return envelope; } async count(object: string, query?: DriverQuery, options?: DriverOptions): Promise { @@ -19840,7 +19897,10 @@ export class SqlDriver implements IDataDriver { this.fileColumnsMovedAsked = true; this.fileColumnsMovedResolver = undefined; try { - this.fileColumnsMoved = (await resolver()) === true; + // [#20768] Asked inside the pre-DDL scope. On a new database the ledger + // the resolver reads does not exist yet, and that refusal is not a + // fault. The answer is unchanged — see {@link PRE_DDL_QUESTION_SCOPE}. + this.fileColumnsMoved = (await PRE_DDL_QUESTION_SCOPE.run(true, resolver)) === true; } catch { this.fileColumnsMoved = false; } From d9331bc0f4205958844a3b6ef16e4cb2ede51542 Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 30 Sep 2026 07:47:11 +0000 Subject: [PATCH 2/3] test(driver-sql,runtime): pin the first and second boot of a new SQLite database, and the refusals that still warn The driver pin runs a resolver shaped like the engine's through initObjects on a new file; the runtime pin boots a real ObjectQL engine over a real SqlDriver twice. Controls: a malformed read on an existing table, a missing table named by another relation, and a missing table read outside the question all still warn. Adds the patch changeset. Claude-Session: https://claude.ai/code/session_01DEvba2nBuD4tWzfq8r8NFY Co-authored-by: Claude --- .../20768-first-boot-migration-gate-read.md | 22 ++ ...768-pre-ddl-question-missing-table.test.ts | 287 ++++++++++++++++++ ...ot-migration-gate-read.integration.test.ts | 160 ++++++++++ 3 files changed, 469 insertions(+) create mode 100644 .changeset/20768-first-boot-migration-gate-read.md create mode 100644 packages/drivers/driver-sql/src/sql-driver-20768-pre-ddl-question-missing-table.test.ts create mode 100644 packages/runtime/src/first-boot-migration-gate-read.integration.test.ts diff --git a/.changeset/20768-first-boot-migration-gate-read.md b/.changeset/20768-first-boot-migration-gate-read.md new file mode 100644 index 00000000000..e8a3888cbb8 --- /dev/null +++ b/.changeset/20768-first-boot-migration-gate-read.md @@ -0,0 +1,22 @@ +--- +'@objectstack/driver-sql': patch +--- + +fix(driver-sql): the first boot of a new database no longer prints a `DATABASE_ERROR` for `sys_migration` (#20768) + +On the first boot of a new database, the SQL driver printed this line once, on its warn channel (stderr by default): + +```text +[sql-driver] DATABASE_ERROR — the backend refused a read on 'sys_migration' (SQLITE_ERROR) ... no such table: sys_migration +``` + +Nothing was wrong. At the start of its first schema sync, before it creates any table, the driver asks whether this deployment's file columns have moved (the ADR-0104 media-arm resolver). The resolver the engine supplies answers by reading `sys_migration`. On a new database that table does not exist yet, so the read is refused and the answer is "not moved", which is correct for an empty store. + +The driver now asks that question inside an async scope. Inside it, a read refused because its own target table does not exist goes to the logger's `debug` channel instead of `warn`. The default logger has no `debug`, so the line is not printed. The logger shape gains an optional `debug`. The refusal is still thrown to the resolver, and the resolver's answer is the same as before. + +What still warns: + +- every other refusal inside that scope, such as a malformed statement on a table that exists, or a missing table named by another relation (a view over a dropped table); +- a missing table read anywhere else, as before. + +The missing-table check is the shared `isMissingTableError` from `@objectstack/types`, which `@objectstack/metadata/errors` re-exports. There is nothing to migrate. diff --git a/packages/drivers/driver-sql/src/sql-driver-20768-pre-ddl-question-missing-table.test.ts b/packages/drivers/driver-sql/src/sql-driver-20768-pre-ddl-question-missing-table.test.ts new file mode 100644 index 00000000000..288d97c4210 --- /dev/null +++ b/packages/drivers/driver-sql/src/sql-driver-20768-pre-ddl-question-missing-table.test.ts @@ -0,0 +1,287 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * [#20768] A missing table read by a driver's own PRE-DDL question leaves the + * warn channel. Nothing else does. + * + * ## The measured defect + * + * `objectstack dev --database file:NEW.sqlite` on `examples/app-crm` printed + * one line on the first boot of a new database, on the driver's warn channel + * (stderr): + * + * ```text + * [sql-driver] DATABASE_ERROR — the backend refused a read on 'sys_migration' (SQLITE_ERROR) ... + * select * from `sys_migration` where `id` = 'adr-0104-file-references' limit 1 - no such table: sys_migration + * ``` + * + * The read is the engine's migration-gate read. The ADR-0104 media-arm + * resolver reaches it, and this driver asks that resolver at the start of its + * first `initObjects`, before its schema pass has created any table. On a new + * database the ledger is not there yet, the resolver answers "not moved", and + * that answer is right. Only the log line was wrong. + * + * ## What this file pins, from the driver's side + * + * The engine-driven boot is pinned in `@objectstack/runtime` + * (`first-boot-migration-gate-read.integration.test.ts`). Here the resolver is + * a stand-in that reads the ledger the way the engine does: one row by id, + * with a failed read answered as "not moved". + * + * ① first boot: the question's read of a table that does not exist yet goes + * to `debug`, not `warn`. The resolver still gets the refusal envelope, and + * the arm is the one it always was. + * ② the same holds when the ledger is served by ANOTHER driver instance: the + * scope follows the async chain, not the instance. + * ③ second boot: the table exists, the read succeeds, nothing is logged, and + * the answer comes from the ledger row. + * + * Controls, each a refusal that must still warn: + * + * ④ a malformed read on an EXISTING table, inside the question; + * ⑤ a missing table named by some OTHER relation (a view over a dropped + * table), inside the question; + * ⑥ a missing table read OUTSIDE the question. + */ + +import { describe, it, expect, afterEach } from 'vitest'; +import { mkdtempSync, rmSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import type { DriverQuery } from '@objectstack/spec/contracts'; +import { SqlDriver } from './sql-driver.js'; +import type { SqlDriverConfig } from './sql-driver.js'; + +const LEDGER = 'sys_migration'; +const MIGRATION_ID = 'adr-0104-file-references'; +/** The ledger's columns the engine's gate read looks at, as a stand-in object. */ +const LEDGER_OBJECT = { + name: LEDGER, + fields: { + last_run_at: { type: 'text' }, + verified_at: { type: 'text' }, + columns_moved_at: { type: 'text' }, + blocking: { type: 'number' }, + }, +}; +/** An app object with a media column: the column the arm decides the encoding of. */ +const MEDIA_OBJECT = { name: 'os20768_doc', fields: { cover: { type: 'image' }, title: { type: 'text' } } }; + +type Line = { level: 'warn' | 'debug' | 'info' | 'error'; message: string }; + +/** Reads the arm the way every writer and every DDL branch reads it. */ +class ArmProbe extends SqlDriver { + readonly lines: Line[] = []; + + constructor(config: SqlDriverConfig) { + super(config); + // Arrow closures on purpose: this sink records, it is not the receiver test + // (`logger-receiver-detach.test.ts` owns that). + (this as unknown as { logger: Record void> }).logger = { + warn: (m) => this.lines.push({ level: 'warn', message: String(m) }), + debug: (m) => this.lines.push({ level: 'debug', message: String(m) }), + info: (m) => this.lines.push({ level: 'info', message: String(m) }), + error: (m) => this.lines.push({ level: 'error', message: String(m) }), + }; + } + + get arm(): boolean { + return (this as unknown as { fileColumnsMoved: boolean }).fileColumnsMoved; + } + + databaseErrors(level: Line['level'], object: string): string[] { + return this.lines + .filter((l) => l.level === level && l.message.includes(`'${object}'`)) + .map((l) => l.message); + } +} + +const open: ArmProbe[] = []; +const dirs: string[] = []; + +function newDatabaseFile(): string { + const dir = mkdtempSync(join(tmpdir(), 'os-20768-')); + dirs.push(dir); + // Named but not created: the first driver to connect creates it, as a new + // deployment's first boot does. + return join(dir, 'new.sqlite'); +} + +function driver(filename: string): ArmProbe { + const d = new ArmProbe({ + client: 'better-sqlite3', + connection: { filename }, + useNullAsDefault: true, + } as SqlDriverConfig); + open.push(d); + return d; +} + +/** A resolver shaped like the engine's: read one ledger row, a failure is "not moved". */ +function ledgerResolver(ledger: SqlDriver, observed: { error?: any; row?: any; asked: number }) { + return async (): Promise => { + observed.asked += 1; + try { + observed.row = await ledger.findOne(LEDGER, { where: { id: MIGRATION_ID } }); + return observed.row?.verified_at != null && observed.row?.columns_moved_at != null; + } catch (e) { + observed.error = e; + return false; + } + }; +} + +afterEach(async () => { + while (open.length) await open.pop()?.disconnect().catch(() => {}); + while (dirs.length) rmSync(dirs.pop()!, { recursive: true, force: true }); +}); + +describe('[#20768] a missing table read by the pre-DDL question is not a DATABASE_ERROR', () => { + it('① first boot: the ledger read goes to debug; the resolver hears the refusal; the arm is unchanged', async () => { + const d = driver(newDatabaseFile()); + const observed: { error?: any; row?: any; asked: number } = { asked: 0 }; + expect(d.setFileColumnsMovedResolver(ledgerResolver(d, observed))).toBe(true); + + await d.initObjects([LEDGER_OBJECT, MEDIA_OBJECT] as any); + + // The question was asked, and its read really was refused, with the envelope. + expect(observed.asked).toBe(1); + expect(observed.error?.code).toBe('DATABASE_ERROR'); + expect(observed.error?.status).toBe(500); + // No warn line for the ledger ... + expect(d.databaseErrors('warn', LEDGER)).toEqual([]); + // ... and the demoted line exists: demoted, not deleted. + const demoted = d.databaseErrors('debug', LEDGER); + expect(demoted).toHaveLength(1); + expect(demoted[0]).toContain('no such table'); + // The arm the resolver's answer set: "not moved", as before. + expect(d.arm).toBe(false); + // The schema pass went on to create the ledger. + expect(await d.find(LEDGER, {})).toEqual([]); + }); + + it('② the scope follows the async chain: a ledger served by another driver instance is demoted too', async () => { + const asker = driver(newDatabaseFile()); + const ledger = driver(newDatabaseFile()); + const observed: { error?: any; row?: any; asked: number } = { asked: 0 }; + asker.setFileColumnsMovedResolver(ledgerResolver(ledger, observed)); + + await asker.initObjects([MEDIA_OBJECT] as any); + + expect(observed.error?.code).toBe('DATABASE_ERROR'); + expect(ledger.databaseErrors('warn', LEDGER)).toEqual([]); + expect(ledger.databaseErrors('debug', LEDGER)).toHaveLength(1); + expect(asker.arm).toBe(false); + }); + + it('③ second boot: the read succeeds, nothing is logged, and the answer comes from the ledger row', async () => { + const file = newDatabaseFile(); + const first = driver(file); + first.setFileColumnsMovedResolver(ledgerResolver(first, { asked: 0 })); + await first.initObjects([LEDGER_OBJECT, MEDIA_OBJECT] as any); + // Between boots, the column move is recorded, so the second boot's answer + // can only be "moved" if its read reached the row. + const now = new Date().toISOString(); + await first.create( + LEDGER, + { id: MIGRATION_ID, last_run_at: now, verified_at: now, columns_moved_at: now, blocking: 0 }, + { bypassTenantAudit: true }, + ); + await first.disconnect(); + + const second = driver(file); + const observed: { error?: any; row?: any; asked: number } = { asked: 0 }; + second.setFileColumnsMovedResolver(ledgerResolver(second, observed)); + await second.initObjects([LEDGER_OBJECT, MEDIA_OBJECT] as any); + + expect(observed.error).toBeUndefined(); + expect(observed.row?.id).toBe(MIGRATION_ID); + expect(second.arm).toBe(true); + expect(second.lines.filter((l) => l.message.includes('DATABASE_ERROR'))).toEqual([]); + expect(second.databaseErrors('debug', LEDGER)).toEqual([]); + }); +}); + +describe('[#20768] CONTROLS — every other refusal still warns', () => { + it('④ a malformed read on an EXISTING table, inside the question, still warns', async () => { + const file = newDatabaseFile(); + const first = driver(file); + await first.initObjects([LEDGER_OBJECT] as any); + await first.disconnect(); + + const d = driver(file); + const observed: { error?: any; row?: any; asked: number } = { asked: 0 }; + // More bound variables than SQLite accepts in one statement: the backend + // refuses the statement, and the table is there. + const tooMany: NonNullable = { + id: { $in: Array.from({ length: 40_000 }, (_, i) => `k${i}`) }, + }; + d.setFileColumnsMovedResolver(async () => { + observed.asked += 1; + try { + await d.find(LEDGER, { where: tooMany }); + } catch (e) { + observed.error = e; + } + return false; + }); + + await d.initObjects([MEDIA_OBJECT] as any); + + expect(observed.asked).toBe(1); + expect(observed.error?.code).toBe('DATABASE_ERROR'); + expect(observed.error?.status).toBe(500); + const warned = d.databaseErrors('warn', LEDGER); + expect(warned).toHaveLength(1); + expect(warned[0]).toContain('DATABASE_ERROR'); + expect(d.databaseErrors('debug', LEDGER)).toEqual([]); + }); + + it('⑤ a missing table named by ANOTHER relation (a view over a dropped table), inside the question, still warns', async () => { + const file = newDatabaseFile(); + const first = driver(file); + await first.initObjects([LEDGER_OBJECT] as any); + await first.execute('create table os20768_gone (id text primary key)'); + await first.execute('create view os20768_view as select * from os20768_gone'); + await first.execute('drop table os20768_gone'); + await first.disconnect(); + + const d = driver(file); + const observed: { error?: any; asked: number } = { asked: 0 }; + d.setFileColumnsMovedResolver(async () => { + observed.asked += 1; + try { + await d.find('os20768_view', {}); + } catch (e) { + observed.error = e; + } + return false; + }); + + await d.initObjects([MEDIA_OBJECT] as any); + + expect(observed.error?.code).toBe('DATABASE_ERROR'); + expect(observed.error?.status).toBe(500); + expect(d.databaseErrors('warn', 'os20768_view')).toHaveLength(1); + expect(d.databaseErrors('debug', 'os20768_view')).toEqual([]); + }); + + it('⑥ a missing table read OUTSIDE the question still warns', async () => { + const d = driver(newDatabaseFile()); + d.setFileColumnsMovedResolver(ledgerResolver(d, { asked: 0 })); + await d.initObjects([LEDGER_OBJECT] as any); + // The question has been asked and answered; the scope is closed. + let refusal: any; + try { + await d.find('os20768_never_created', {}); + } catch (e) { + refusal = e; + } + expect(refusal?.code).toBe('DATABASE_ERROR'); + expect(refusal?.status).toBe(500); + const warned = d.databaseErrors('warn', 'os20768_never_created'); + expect(warned).toHaveLength(1); + expect(warned[0]).toContain('no such table'); + expect(d.databaseErrors('debug', 'os20768_never_created')).toEqual([]); + }); +}); diff --git a/packages/runtime/src/first-boot-migration-gate-read.integration.test.ts b/packages/runtime/src/first-boot-migration-gate-read.integration.test.ts new file mode 100644 index 00000000000..5e3c6d1f22e --- /dev/null +++ b/packages/runtime/src/first-boot-migration-gate-read.integration.test.ts @@ -0,0 +1,160 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * #20768 — the first and second boot of a new SQLite database print no + * `sys_migration` `DATABASE_ERROR`, and a real refusal still warns. + * + * ## The measured defect + * + * `objectstack dev --database file:NEW.sqlite` on `examples/app-crm` printed + * one line on the FIRST boot of a new database, on the SQL driver's warn + * channel (stderr), and nothing on the second boot: + * + * ```text + * [sql-driver] DATABASE_ERROR — the backend refused a read on 'sys_migration' (SQLITE_ERROR) ... + * select * from `sys_migration` where `id` = 'adr-0104-file-references' limit 1 - no such table: sys_migration + * ``` + * + * A stack captured at the read named its caller: `ObjectQL.haveFileColumnsMoved`, + * called by the resolver the engine hands the driver at `registerDriver`, which + * `SqlDriver.initObjects` asks before its schema pass has created any table. + * Nothing was wrong. The table did not exist yet, the gate answered "not + * verified" and "not moved", and that is the right answer for a new store. + * + * ## The construction + * + * The boot's own chain, without a kernel: a real `ObjectQL` engine and a real + * `SqlDriver` over a SQLite file that does not exist yet, `sys_migration` + * registered, and the engine's schema pass (`syncSchemas`), which reaches the + * same `driver.syncSchema` → `initObjects` → resolver → gate read. The driver's + * log is captured on every channel, so a line that moved to `debug` is still + * counted: the fix demotes the line, it does not delete it. + * + * The gate answers are asserted on both boots, so the change is to a log level + * and to nothing a gate decides. + */ + +import { describe, it, expect, afterEach } from 'vitest'; +import { existsSync, mkdtempSync, rmSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { ObjectQL } from '@objectstack/objectql'; +import { SqlDriver } from '@objectstack/driver-sql'; +import { SysMigration } from '@objectstack/platform-objects/system'; +import { FILE_REFERENCES_MIGRATION_ID } from '@objectstack/spec/system'; + +type Level = 'warn' | 'debug' | 'info' | 'error'; +type Line = { level: Level; message: string }; + +const openDrivers: SqlDriver[] = []; +const tempDirs: string[] = []; + +afterEach(async () => { + while (openDrivers.length) { + try { + await openDrivers.pop()?.disconnect(); + } catch { + /* already disconnected */ + } + } + while (tempDirs.length) rmSync(tempDirs.pop()!, { recursive: true, force: true }); +}); + +/** One boot of the engine over `file`, up to and including the schema pass. */ +async function boot(file: string): Promise<{ driver: SqlDriver; engine: ObjectQL; lines: Line[] }> { + const driver = new SqlDriver({ client: 'better-sqlite3', connection: { filename: file }, useNullAsDefault: true }); + openDrivers.push(driver); + const lines: Line[] = []; + const sink = (level: Level) => (message: string) => { + lines.push({ level, message: String(message) }); + }; + (driver as unknown as { logger: Record void> }).logger = { + warn: sink('warn'), + debug: sink('debug'), + info: sink('info'), + error: sink('error'), + }; + const engine = new ObjectQL(); + engine.registerDriver(driver as never, true); + await engine.init(); + engine.registry.registerObject(SysMigration as never, '#20768'); + await engine.syncSchemas(); + return { driver, engine, lines }; +} + +/** Every captured line on `level` that names `object` as the read's target. */ +function linesAbout(lines: Line[], level: Level, object: string): string[] { + return lines.filter((l) => l.level === level && l.message.includes(`'${object}'`)).map((l) => l.message); +} + +function newDatabaseFile(): string { + const dir = mkdtempSync(join(tmpdir(), 'os-20768-')); + tempDirs.push(dir); + return join(dir, 'new.sqlite'); +} + +describe('#20768 — the first boot of a new SQLite database reads the migration gate without a DATABASE_ERROR', () => { + it('first and second boot: no sys_migration DATABASE_ERROR on the warn channel; the gate answers are unchanged', async () => { + const file = newDatabaseFile(); + expect(existsSync(file)).toBe(false); + + // ── boot 1: the database does not exist when the gate is read. + const first = await boot(file); + expect(linesAbout(first.lines, 'warn', 'sys_migration')).toEqual([]); + expect(first.lines.filter((l) => l.level === 'warn' && l.message.includes('DATABASE_ERROR'))).toEqual([]); + // Lit: the gate WAS read before the table existed, and the refusal is + // still on record one level down. + const demoted = linesAbout(first.lines, 'debug', 'sys_migration'); + expect(demoted).toHaveLength(1); + expect(demoted[0]).toContain('no such table'); + // The answers, unchanged: not moved (the JSON arm), not verified. + expect((first.driver as unknown as { mediaColumnIsJson(): boolean }).mediaColumnIsJson()).toBe(true); + expect(await first.engine.haveFileColumnsMoved()).toBe(false); + expect(await first.engine.isFileReferencesMigrationVerified()).toBe(false); + expect(existsSync(file)).toBe(true); + + // The ledger records a verified migration between the boots, so the second + // boot can only answer "verified" if its gate read reached the row. + const now = new Date().toISOString(); + await first.driver.create( + 'sys_migration', + { id: FILE_REFERENCES_MIGRATION_ID, last_run_at: now, verified_at: now, applied_at: now, blocking: 0, advisory: 0 }, + { bypassTenantAudit: true }, + ); + await first.driver.disconnect(); + + // ── boot 2: the same file. + const second = await boot(file); + expect(second.lines.filter((l) => l.message.includes('DATABASE_ERROR'))).toEqual([]); + expect(linesAbout(second.lines, 'debug', 'sys_migration')).toEqual([]); + expect(await second.engine.isFileReferencesMigrationVerified()).toBe(true); + expect(await second.engine.haveFileColumnsMoved()).toBe(false); + }); + + it('CONTROL a malformed read on an existing table still warns, and so does a missing table read after boot', async () => { + const { driver, lines } = await boot(newDatabaseFile()); + + // More bound variables than SQLite takes in one statement, on a table that + // exists: the backend refuses it, and that is a real refusal. + const tooMany = Array.from({ length: 40_000 }, (_, i) => `k${i}`); + const malformed = await driver.find('sys_migration', { where: { id: { $in: tooMany } } }).then( + () => expect.fail('expected the backend to refuse the statement'), + (e: { code?: string; status?: number }) => e, + ); + expect(malformed.code).toBe('DATABASE_ERROR'); + expect(malformed.status).toBe(500); + const warned = linesAbout(lines, 'warn', 'sys_migration'); + expect(warned).toHaveLength(1); + expect(warned[0]).toContain('DATABASE_ERROR'); + + // A table nobody created, read once the boot is done: still a warn. + const missing = await driver.find('os20768_never_provisioned', {}).then( + () => expect.fail('expected the read of a table that was never created to fail'), + (e: { code?: string; status?: number }) => e, + ); + expect(missing.code).toBe('DATABASE_ERROR'); + expect(missing.status).toBe(500); + expect(linesAbout(lines, 'warn', 'os20768_never_provisioned')).toHaveLength(1); + expect(linesAbout(lines, 'debug', 'os20768_never_provisioned')).toEqual([]); + }); +}); From 1bd9b0947bf570d9caa1442d4a55c5be799b4c83 Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 30 Sep 2026 07:49:29 +0000 Subject: [PATCH 3/3] test(runtime): the malformed-read control counts only the lines its own reads log Measured under the reverse verification: with the fix reverted, the boot's own sys_migration line landed in the same capture and turned the control red. A control must not move with the defect it sits beside. Claude-Session: https://claude.ai/code/session_01DEvba2nBuD4tWzfq8r8NFY Co-authored-by: Claude --- .../src/first-boot-migration-gate-read.integration.test.ts | 3 +++ 1 file changed, 3 insertions(+) diff --git a/packages/runtime/src/first-boot-migration-gate-read.integration.test.ts b/packages/runtime/src/first-boot-migration-gate-read.integration.test.ts index 5e3c6d1f22e..3c7537173ea 100644 --- a/packages/runtime/src/first-boot-migration-gate-read.integration.test.ts +++ b/packages/runtime/src/first-boot-migration-gate-read.integration.test.ts @@ -133,6 +133,9 @@ describe('#20768 — the first boot of a new SQLite database reads the migration it('CONTROL a malformed read on an existing table still warns, and so does a missing table read after boot', async () => { const { driver, lines } = await boot(newDatabaseFile()); + // Count only what the reads below log. The boot's own lines are the first + // test's subject, and this control must not move with them. + lines.length = 0; // More bound variables than SQLite takes in one statement, on a table that // exists: the backend refuses it, and that is a real refusal.