fix(driver-sql): os migrate plan on a new database prints no DATABASE_ERROR for the tables whose DDL it deferred (#20821)

.changeset/20821-plan-deferred-ddl-reads.md

@@ -0,0 +1,29 @@
+---
+'@objectstack/driver-sql': patch
+---
+
+fix(driver-sql): `os migrate plan` on a database that does not exist yet no longer prints `DATABASE_ERROR` for the tables whose DDL it deferred (#20821)
+
+`os migrate plan` (and the boot of `os migrate apply`) runs with the SQL driver's DDL deferred: the driver records every table as pending `create_table` and creates none of them. The same boot then reads `sys_metadata`, `sys_metadata_activation` and `sys_migration`. On a new database those tables do not exist yet, so each read was refused, and each refusal printed a line like this on the driver's warn channel (stderr by default):
+
+```text
+[sql-driver] DATABASE_ERROR — the backend refused a read on 'sys_metadata' (SQLITE_ERROR) ... no such table: sys_metadata
+```
+
+Nothing was wrong: every reader already answers from the refusal, and the plan lists the same tables as pending creates. A dry run on a new database printed six of these lines.
+
+The driver now sends such a refusal to the logger's `debug` channel instead of `warn`, when all three hold:
+
+- this driver has DDL deferred;
+- the refused statement targets a table whose DDL this driver deferred;
+- the shared `isMissingTableError` predicate from `@objectstack/types` recognises the refusal as that table being missing.
+
+The default logger has no `debug`, so the line is not printed. The refusal is still thrown to the caller with the same envelope (`DATABASE_ERROR`, status 500), and the plan's output is unchanged.
+
+What still warns:
+
+- every other refusal on a deferred driver, such as a malformed statement on a table that exists;
+- a missing table that the driver did not defer, such as a table nothing in the boot declares;
+- every refusal once the deferred DDL has been applied, or on a driver that never deferred any.
+
+There is nothing to migrate.

packages/cli/src/commands/migrate/plan.deferred-reads.integration.test.ts

@@ -0,0 +1,184 @@
+// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license.
+
+/**
+ * [#20821] `os migrate plan` against a database that does not exist yet prints
+ * no `DATABASE_ERROR` for the tables whose DDL it deferred.
+ *
+ * ## The measured defect
+ *
+ * The plan boots with the SQL driver's DDL deferred, so every table is listed
+ * as `create_table` and none is created. The same boot then reads the tables
+ * it just listed: `sys_metadata` four times (the overlay restore, the authored
+ * translation, hook and action re-syncs), `sys_metadata_activation` once (the
+ * packaged-action ledger probe) and `sys_migration` once (the ADR-0104 gate
+ * announcement). Every reader already answered from the refusal; the driver
+ * still printed a `[sql-driver] DATABASE_ERROR` line on stderr for each, six
+ * alarms on a dry run where nothing was wrong. This fixture reproduced exactly
+ * those six on the base.
+ *
+ * ## What is pinned, and what is deliberately not
+ *
+ *  - Zero `DATABASE_ERROR` lines naming those three tables, in human mode and
+ *    under `--json`, on an absent file.
+ *  - The reads really happened and were really refused, so the zero is not a
+ *    boot that skipped them: the open value-shape gate is still announced (the
+ *    `sys_migration` read answered "not verified"), and the activation ledger
+ *    still reports itself unreadable (that stdout warning is kept on purpose;
+ *    it is the reader's own functional line, not the driver's).
+ *  - The plan's own answer: the three tables are still pending `create_table`,
+ *    and nothing is written to disk.
+ *
+ * ⛔ Only those three tables are counted. A host hook that reads a table the
+ * plan's composition never declares is a different door with its own card;
+ * its lines are not this pin's to forbid, and not its to excuse either.
+ *
+ * The driver-side conditions (deferred, in the driver's own deferred set, the
+ * shared missing-table predicate) and their controls are pinned in
+ * `@objectstack/driver-sql` (`sql-driver-20821-deferred-ddl-missing-table.test.ts`).
+ */
+
+import { describe, it, expect, beforeAll, afterAll } from 'vitest';
+import { spawn } from 'node:child_process';
+import { existsSync, mkdtempSync, rmSync, writeFileSync } from 'node:fs';
+import { tmpdir } from 'node:os';
+import { dirname, join, resolve } from 'node:path';
+import { fileURLToPath } from 'node:url';
+
+const HERE = dirname(fileURLToPath(import.meta.url));
+/** The source entry (tsx), as `test/helpers/serve-process.ts` spawns it; `src/` cannot import that helper. */
+const CLI = resolve(HERE, '../../../bin/run-dev.js');
+
+/**
+ * This process's environment for the child, minus the two families
+ * `test/helpers/serve-process.ts` `childEnv()` strips (its header says why):
+ * the vitest runner's own variables, and `NODE_PATH`, which moves the child's
+ * module resolution base. An `undefined` override unsets a variable.
+ */
+function childEnv(overrides: Record<string, string | undefined>): Record<string, string | undefined> {
+  const env: Record<string, string | undefined> = {};
+  for (const [key, value] of Object.entries(process.env)) {
+    if (key === 'TEST' || key === 'VITEST' || key.startsWith('VITEST_') || key === 'NODE_PATH') continue;
+    env[key] = value;
+  }
+  return { ...env, ...overrides };
+}
+
+/** The tables whose DDL the plan defers and whose boot readers it still runs. */
+const DEFERRED_READ_TABLES = ['sys_metadata', 'sys_metadata_activation', 'sys_migration'] as const;
+
+const RUN_BUDGET_MS = 90_000;
+
+interface PlanRun {
+  code: number | null;
+  stdout: string;
+  stderr: string;
+}
+
+let dir: string;
+let dbFile: string;
+
+beforeAll(() => {
+  dir = mkdtempSync(join(tmpdir(), 'os-20821-'));
+  dbFile = join(dir, 'absent.sqlite');
+  // A lookup field makes the value-shape gate applicable, so the boot reads
+  // `sys_migration` exactly as a real app's boot does.
+  writeFileSync(
+    join(dir, 'objectstack.config.ts'),
+    [
+      'export default {',
+      "  manifest: { id: 'com.example.os20821', name: 'Deferred reads', version: '0.0.0', type: 'app' },",
+      '  objects: [',
+      "    { name: 'os20821_account', fields: { name: { type: 'text' } } },",
+      "    { name: 'os20821_contact', fields: { name: { type: 'text' }, account: { type: 'lookup', reference: 'os20821_account' } } },",
+      '  ],',
+      '};',
+      '',
+    ].join('\n'),
+  );
+});
+
+afterAll(() => {
+  rmSync(dir, { recursive: true, force: true });
+});
+
+function runPlan(extra: string[]): Promise<PlanRun> {
+  return new Promise((resolve, reject) => {
+    const child = spawn(
+      process.execPath,
+      [CLI, 'migrate', 'plan', ...extra, '--database-url', `file:${dbFile}`],
+      {
+        cwd: dir,
+        env: childEnv({
+          // No compiled artifact: the host config is the deployment.
+          OS_ARTIFACT_PATH: join(dir, 'dist', 'objectstack.json'),
+          OS_DATABASE_URL: undefined,
+          DATABASE_URL: undefined,
+          TURSO_DATABASE_URL: undefined,
+          OS_DATABASE_DRIVER: undefined,
+        }),
+        stdio: ['ignore', 'pipe', 'pipe'],
+      },
+    );
+    let stdout = '';
+    let stderr = '';
+    child.stdout.on('data', (c) => { stdout += String(c); });
+    child.stderr.on('data', (c) => { stderr += String(c); });
+    const timer = setTimeout(() => {
+      child.kill('SIGKILL');
+      reject(new Error(`os migrate plan did not finish within ${RUN_BUDGET_MS}ms\n${stderr}`));
+    }, RUN_BUDGET_MS);
+    child.on('close', (code) => {
+      clearTimeout(timer);
+      resolve({ code, stdout, stderr });
+    });
+  });
+}
+
+/** Every driver `DATABASE_ERROR` line, on either stream, that names one of the three tables. */
+function deferredTableDatabaseErrors(run: PlanRun): string[] {
+  return `${run.stdout}\n${run.stderr}`
+    .split('\n')
+    .filter((line) => line.includes('DATABASE_ERROR'))
+    .filter((line) => DEFERRED_READ_TABLES.some((t) => line.includes(`'${t}'`)));
+}
+
+describe('[#20821] os migrate plan on an absent database: no DATABASE_ERROR for the tables it deferred', () => {
+  it('human mode: zero lines for the three tables, the reads still answered, the plan unchanged', async () => {
+    expect(existsSync(dbFile)).toBe(false);
+
+    const run = await runPlan([]);
+
+    expect(run.code, run.stderr).toBe(0);
+    expect(deferredTableDatabaseErrors(run)).toEqual([]);
+
+    // The reads happened and were refused: the readers' own answers are here.
+    const lines = run.stdout.split('\n');
+    expect(lines.some((l) => l.includes('[value-shape]') && l.includes('NOT enforced'))).toBe(true);
+    expect(lines.some((l) => l.includes('WARN') && l.includes('sys_metadata_activation'))).toBe(true);
+
+    // The plan's own answer: each of the three is still pending creation.
+    for (const table of DEFERRED_READ_TABLES) {
+      expect(lines.some((l) => l.includes(`+ ${table} [create_table`))).toBe(true);
+    }
+    expect(existsSync(dbFile)).toBe(false);
+  }, 120_000);
+
+  it('--json: zero lines for the three tables, and the payload still lists them as pending creates', async () => {
+    const run = await runPlan(['--json']);
+
+    expect(run.code, run.stderr).toBe(0);
+    expect(deferredTableDatabaseErrors(run)).toEqual([]);
+
+    const payload = JSON.parse(run.stdout) as {
+      total: number;
+      changes: unknown[];
+      pending: Array<{ table: string; kind: string }>;
+    };
+    expect(payload.total).toBe(0);
+    expect(payload.changes).toEqual([]);
+    for (const table of DEFERRED_READ_TABLES) {
+      expect(payload.pending.filter((p) => p.table === table).map((p) => p.kind)).toEqual(['create_table']);
+    }
+    expect(existsSync(dbFile)).toBe(false);
+  }, 120_000);
+});

packages/drivers/driver-sql/src/sql-driver-20821-deferred-ddl-missing-table.test.ts

@@ -0,0 +1,176 @@
+// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license.
+
+/**
+ * [#20821] A missing table whose DDL THIS driver deferred leaves the warn
+ * channel. Nothing else does.
+ *
+ * ## The measured defect
+ *
+ * `os migrate plan --database-url file:ABSENT.sqlite` boots with the driver's
+ * DDL deferred (`setDeferredDdl(true)`), so the plan can list every table as
+ * `create_table` instead of creating it. The same boot then reads
+ * `sys_metadata` (four readers), `sys_metadata_activation` and `sys_migration`,
+ * every one of which the plan has just listed as not existing yet. Each read
+ * was refused, each reader already answered from the refusal, and each refusal
+ * also printed a `[sql-driver] DATABASE_ERROR` line on the warn channel: six
+ * alarms on a dry run where nothing was wrong.
+ *
+ * ## What this file pins, from the driver's side
+ *
+ * The command-level pin lives in `@objectstack/cli`
+ * (`src/commands/migrate/plan.deferred-reads.integration.test.ts`). Here the
+ * three conditions are exercised one at a time, each against a real SQLite
+ * file, and every case asserts the refusal itself is unchanged: the caller
+ * still gets the ADR-0112 envelope (`DATABASE_ERROR`, `500`).
+ *
+ *  ① DDL deferred, table in this driver's deferred set, table missing: the
+ *    refusal goes to `debug`, not `warn`. After the deferred work is flushed
+ *    the table exists and the same read answers with nothing logged.
+ *
+ * Controls, each a refusal that must still warn:
+ *
+ *  ② a malformed read on an EXISTING table whose DDL is deferred (the backend
+ *    refuses the statement, and the table is there);
+ *  ③ a missing table that is NOT in the deferred set, on the same deferred
+ *    driver (nobody in this boot declared it, so its absence is information).
+ */
+
+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';
+
+/** An object this boot declares, standing in for `sys_metadata` and its peers. */
+const DEFERRED = { name: 'os20821_deferred', fields: { name: { type: 'text' }, state: { type: 'text' } } };
+/** A table nothing in the boot declares. */
+const UNDECLARED = 'os20821_undeclared';
+
+type Line = { level: 'warn' | 'debug' | 'info' | 'error'; message: string };
+
+class LineProbe 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<Line['level'], (m: string) => 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) }),
+    };
+  }
+
+  linesFor(level: Line['level'], object: string): string[] {
+    return this.lines
+      .filter((l) => l.level === level && l.message.includes(`'${object}'`))
+      .map((l) => l.message);
+  }
+}
+
+const open: LineProbe[] = [];
+const dirs: string[] = [];
+
+function databaseFile(): string {
+  const dir = mkdtempSync(join(tmpdir(), 'os-20821-'));
+  dirs.push(dir);
+  return join(dir, 'app.sqlite');
+}
+
+function driver(filename: string): LineProbe {
+  const d = new LineProbe({
+    client: 'better-sqlite3',
+    connection: { filename },
+    useNullAsDefault: true,
+  } as SqlDriverConfig);
+  open.push(d);
+  return d;
+}
+
+/** A driver booted the way `os migrate plan` boots it: DDL deferred, objects declared. */
+async function deferredDriver(filename: string): Promise<LineProbe> {
+  const d = driver(filename);
+  d.setDeferredDdl(true);
+  await d.initObjects([DEFERRED] as any);
+  expect(d.deferredSchemaObjectCount).toBe(1);
+  return d;
+}
+
+async function refusalOf(read: () => Promise<unknown>): Promise<any> {
+  try {
+    await read();
+  } catch (e) {
+    return e;
+  }
+  throw new Error('expected the backend to refuse this read');
+}
+
+afterEach(async () => {
+  while (open.length) await open.pop()?.disconnect().catch(() => {});
+  while (dirs.length) rmSync(dirs.pop()!, { recursive: true, force: true });
+});
+
+describe('[#20821] a missing table whose DDL this driver deferred is not a DATABASE_ERROR', () => {
+  it('① deferred and missing: the read goes to debug, the caller still gets the envelope, and the flush ends it', async () => {
+    const d = await deferredDriver(databaseFile());
+
+    const refusal = await refusalOf(() => d.find(DEFERRED.name, { where: { state: 'active' } }));
+
+    expect(refusal?.code).toBe('DATABASE_ERROR');
+    expect(refusal?.status).toBe(500);
+    expect(d.linesFor('warn', DEFERRED.name)).toEqual([]);
+    // Demoted, not deleted: the dialect text is still on the debug channel.
+    const demoted = d.linesFor('debug', DEFERRED.name);
+    expect(demoted).toHaveLength(1);
+    expect(demoted[0]).toContain('no such table');
+
+    // `os migrate apply` flushes the deferred work: the table now exists and
+    // the same read answers, with nothing logged at any level.
+    await d.flushDeferredSchemaDdl();
+    const before = d.lines.length;
+    expect(await d.find(DEFERRED.name, { where: { state: 'active' } })).toEqual([]);
+    expect(d.lines.slice(before).filter((l) => l.message.includes(`'${DEFERRED.name}'`))).toEqual([]);
+  });
+});
+
+describe('[#20821] CONTROLS — every other refusal on a deferred driver still warns', () => {
+  it('② a malformed read on an EXISTING table whose DDL is deferred still warns', async () => {
+    const file = databaseFile();
+    const first = driver(file);
+    await first.initObjects([DEFERRED] as any);
+    await first.disconnect();
+
+    const d = await deferredDriver(file);
+    // More bound variables than SQLite accepts in one statement: the backend
+    // refuses the statement, and the table is there.
+    const tooMany: NonNullable<DriverQuery['where']> = {
+      id: { $in: Array.from({ length: 40_000 }, (_, i) => `k${i}`) },
+    };
+
+    const refusal = await refusalOf(() => d.find(DEFERRED.name, { where: tooMany }));
+
+    expect(refusal?.code).toBe('DATABASE_ERROR');
+    expect(refusal?.status).toBe(500);
+    const warned = d.linesFor('warn', DEFERRED.name);
+    expect(warned).toHaveLength(1);
+    expect(warned[0]).toContain('DATABASE_ERROR');
+    expect(d.linesFor('debug', DEFERRED.name)).toEqual([]);
+  });
+
+  it('③ a missing table OUTSIDE the deferred set, on the same deferred driver, still warns', async () => {
+    const d = await deferredDriver(databaseFile());
+
+    const refusal = await refusalOf(() => d.find(UNDECLARED, {}));
+
+    expect(refusal?.code).toBe('DATABASE_ERROR');
+    expect(refusal?.status).toBe(500);
+    const warned = d.linesFor('warn', UNDECLARED);
+    expect(warned).toHaveLength(1);
+    expect(warned[0]).toContain('no such table');
+    expect(d.linesFor('debug', UNDECLARED)).toEqual([]);
+  });
+});