fix(plugin-audit): a failed boot provisioning of an audit table is logged at error, naming what is lost and the fix

.changeset/22913-audit-provision-failure-error.md

@@ -0,0 +1,13 @@
+---
+'@objectstack/plugin-audit': patch
+---
+
+A failed boot provisioning of an audit table is logged at `error`, naming what is lost and the fix
+
+Clause-②: no
+
+At `kernel:ready`, `AuditPlugin` creates the storage for `sys_audit_log`, `sys_activity`, `sys_comment` and `sys_comment_reaction`. When the driver refuses one of those DDL statements, the boot still completes and the deployment looks healthy, but the table does not exist. For `sys_audit_log` and `sys_activity` the loss is silent: audited writes keep succeeding while their audit and activity rows have nowhere to land. That failure was logged at `warn`. It is now logged at `error`, once per object per boot and never per write. The boot is still not failed.
+
+- **What the line says.** It names the object, what is lost without it, and that the deployment keeps looking healthy. It gives the fix: resolve the driver's refusal, then restart (this provisioning runs on every boot) or run `os migrate apply`, which creates the missing storage. `os migrate plan` lists it as a `create_table` entry for that object. Both remedies were measured to create a missing `sys_activity` once the fault was gone, with and without the telemetry sibling database.
+- **Where the driver's error is.** In the record's meta as `{ object, error }`, not in the message, so a multi-line driver error stays one record.
+- **What is unchanged.** The other objects are still provisioned when one fails, and the placement lines (`system tables provisioned`, the non-default datasource note) are unchanged. A log search on `could not provision sys_activity storage` (or any of the four object names) still matches the line.

packages/cli/src/commands/migrate/plan.telemetry-sibling.integration.test.ts

@@ -105,15 +105,30 @@ function childEnv(f: Fixture, extra: NodeJS.ProcessEnv = {}): NodeJS.ProcessEnv
   };
 }
 
-/** `os serve`'s own provision-and-exit: the full composition schema-synced into the fixture's database(s). */
-function serveBoot(f: Fixture, extra: NodeJS.ProcessEnv = {}): void {
+/** How much of each of the serving boot's streams an assertion message carries: its TAIL, where the boot diagnostics replay. */
+const BOOT_STREAM_TAIL = 8_000;
+
+/**
+ * `os serve`'s own provision-and-exit: the full composition schema-synced into the fixture's database(s).
+ *
+ * [#22913] Returns the child's own output, so every later assertion that reads what the boot provisioned can
+ * carry it: a boot that exits 0 with one table missing names its cause on its stderr (a refused DDL is logged
+ * there at `error`), and an assertion that failed without it left the CI log unable to confirm or refute one.
+ */
+function serveBoot(f: Fixture, extra: NodeJS.ProcessEnv = {}): string {
   const boot = spawnSync(TSX, [RUN_DEV, 'serve', '--no-server', '--no-ui', '--no-console', '--port', '0'], {
     cwd: f.dir, env: childEnv(f, { ...extra, OS_MIGRATE_AND_EXIT: '1' }), encoding: 'utf8', timeout: 240_000,
   });
-  expect(boot.status, `the serving boot did not provision the database:\n${`${boot.stdout}\n${boot.stderr}`.slice(-800)}`)
-    .toBe(0);
+  const output =
+    `--- the serving boot's stderr (exit ${boot.status}) ---\n${(boot.stderr ?? '').slice(-BOOT_STREAM_TAIL)}\n` +
+    `--- the serving boot's stdout ---\n${(boot.stdout ?? '').slice(-BOOT_STREAM_TAIL)}`;
+  expect(boot.status, `the serving boot did not provision the database:\n${output}`).toBe(0);
+  return output;
 }
 
+/** The message an assertion on what the boot provisioned carries, so its failure names the boot's own account. */
+const afterBoot = (bootOutput: string, what: string): string => `${what}\n${bootOutput}`;
+
 function command(f: Fixture, argv: string[], extra: NodeJS.ProcessEnv = {}): { exit: number | null; payload: any } {
   const run = spawnSync(TSX, [RUN_DEV, 'migrate', ...argv], { cwd: f.dir, env: childEnv(f, extra), encoding: 'utf8', timeout: 240_000 });
   let payload: any;
@@ -154,14 +169,14 @@ const pendingTables = (payload: any): string[] => (payload.pending ?? []).map((p
 describe('os migrate plan / apply plan each object against the database it lives in (#22579)', () => {
   it('after a development boot: the sibling is named and planned, nothing lifecycle-classed is planned for the primary, apply creates nothing', () => {
     const f = fixture();
-    serveBoot(f);
+    const booted = serveBoot(f);
 
     // The serving boot's layout — the thing the plan must describe.
-    expect(existsSync(f.sibling), 'the development boot provisioned no telemetry sibling: nothing to plan against').toBe(true);
+    expect(existsSync(f.sibling), afterBoot(booted, 'the development boot provisioned no telemetry sibling: nothing to plan against')).toBe(true);
     const primaryTables = tables(f.primary);
     const siblingTables = tables(f.sibling);
-    expect(siblingTables).toEqual(expect.arrayContaining(['sys_audit_log', 'sys_metadata_audit']));
-    expect(primaryTables.filter((t) => siblingTables.includes(t)), 'one table in both databases').toEqual([]);
+    expect(siblingTables, afterBoot(booted, 'the sibling the boot provisioned')).toEqual(expect.arrayContaining(['sys_audit_log', 'sys_metadata_audit']));
+    expect(primaryTables.filter((t) => siblingTables.includes(t)), afterBoot(booted, 'one table in both databases')).toEqual([]);
     // [#22580] What a retired lifecycle-classed object leaves behind: its table,
     // in the sibling, declared by nothing.
     const retired = 'sys_os22580_retired_event';
@@ -172,8 +187,8 @@ describe('os migrate plan / apply plan each object against the database it lives
     const plan = command(f, ['plan', '--json']);
     expect(plan.exit, JSON.stringify(plan.payload).slice(0, 800)).toBe(0);
     // Nothing to create anywhere — above all no lifecycle-classed object for the primary.
-    expect(pendingTables(plan.payload)).toEqual([]);
-    expect(plan.payload.changes).toEqual([]);
+    expect(pendingTables(plan.payload), afterBoot(booted, 'a table the serving boot did not provision')).toEqual([]);
+    expect(plan.payload.changes, afterBoot(booted, 'a change the serving boot did not make')).toEqual([]);
     expect(plan.payload.telemetryDatabase).toBe(f.sibling);
     expect(plan.payload.composition?.coverage?.unexaminedObjects).toBe(0);
     // Both databases' objects examined: their tables, less the raw-DDL one.
@@ -197,17 +212,17 @@ describe('os migrate plan / apply plan each object against the database it lives
 
   it('the control — a deployment with no sibling plans as it did; with the sibling on, an absent one is planned and not created', () => {
     const f = fixture();
-    serveBoot(f, { OS_TELEMETRY_DB: '0' });
+    const booted = serveBoot(f, { OS_TELEMETRY_DB: '0' });
     expect(existsSync(f.sibling)).toBe(false);
     const primaryTables = tables(f.primary);
-    expect(primaryTables).toEqual(expect.arrayContaining(['sys_audit_log', 'sys_metadata_audit']));
+    expect(primaryTables, afterBoot(booted, 'the primary the boot provisioned')).toEqual(expect.arrayContaining(['sys_audit_log', 'sys_metadata_audit']));
 
     // No sibling: no sibling named, nothing pending, every object on the primary.
     const control = command(f, ['plan', '--json'], { OS_TELEMETRY_DB: '0' });
     expect(control.exit, JSON.stringify(control.payload).slice(0, 800)).toBe(0);
     expect('telemetryDatabase' in control.payload).toBe(false);
-    expect(pendingTables(control.payload)).toEqual([]);
-    expect(control.payload.changes).toEqual([]);
+    expect(pendingTables(control.payload), afterBoot(booted, 'a table the serving boot did not provision')).toEqual([]);
+    expect(control.payload.changes, afterBoot(booted, 'a change the serving boot did not make')).toEqual([]);
     expect(control.payload.managedTables).toBe(primaryTables.length - NOT_AN_OBJECT.length);
 
     // The sibling on, over this deployment: the serving boot would now keep

packages/plugins/plugin-audit/src/audit-plugin.test.ts

@@ -42,11 +42,20 @@ function makeCtx(engine: unknown) {
   // #4887 — the log IS the deliverable for the provisioning path: its silence
   // is what made a working-but-elsewhere table read as a never-created one.
   // Capture info/warn so the tests can assert on what an operator would see.
-  const logs = { info: [] as string[], warn: [] as string[] };
+  // [#22913] …and every `error` call whole, in the contract's
+  // `error(message, error?, meta?)` shape, so a pin can count them.
+  const logs = {
+    info: [] as string[],
+    warn: [] as string[],
+    error: [] as Array<{ message: string; error: unknown; meta: Record<string, unknown> | undefined }>,
+  };
   const logger = {
     info(msg: string) { logs.info.push(String(msg)); },
     warn(msg: string) { logs.warn.push(String(msg)); },
-    error() {}, debug() {},
+    error(msg: string, error?: unknown, meta?: Record<string, unknown>) {
+      logs.error.push({ message: String(msg), error, meta });
+    },
+    debug() {},
     child() { return logger; },
   };
   const ctx = {
@@ -95,6 +104,71 @@ describe('AuditPlugin — system table provisioning', () => {
   });
 });
 
+/**
+ * [#22913] A failed provision is a DURABILITY degradation, so it is reported at
+ * `error` — once per object, never per write — and the boot is not failed.
+ *
+ * When an object's DDL throws, the boot still completes and the deployment
+ * serves as healthy while the table does not exist; for `sys_audit_log` /
+ * `sys_activity`, audited writes keep succeeding while their audit rows have
+ * nowhere to land. AGENTS.md "Degradation log levels" sends that class to
+ * `error`, with the consequence and the fix in the first line. The wording is
+ * not pinned: the pins hold the level, the count, the named object, the named
+ * remedy command and the driver's refusal in meta.
+ */
+describe('AuditPlugin — a failed provision is an error, once per object (#22913)', () => {
+  const OBJECTS = ['sys_audit_log', 'sys_activity', 'sys_comment', 'sys_comment_reaction'];
+
+  /** Every DDL succeeds except the named object's, which the driver refuses. */
+  function makeEngine(refused?: string) {
+    return {
+      async syncObjectSchema(name: string) {
+        if (name === refused) throw new Error(`there is already an index named ${name}`);
+      },
+      getDriverForObject() { return { name: 'sqlite' }; },
+      getDefaultDriverName() { return 'sqlite'; },
+    };
+  }
+
+  async function boot(refused?: string) {
+    const { ctx, logs, fireReady } = makeCtx(makeEngine(refused));
+    const plugin = new AuditPlugin();
+    await plugin.init(ctx);
+    await plugin.start(ctx);
+    // The boot is NOT failed: kernel:ready resolves.
+    await expect(fireReady()).resolves.toBeUndefined();
+    return logs;
+  }
+
+  it.each(OBJECTS)('a refused DDL for %s logs exactly one error line naming it, the remedy and the refusal', async (name) => {
+    const logs = await boot(name);
+
+    expect(logs.error).toHaveLength(1);
+    const [line] = logs.error;
+    expect(line.message).toContain(name);
+    // ② the fix, by its named subject: the command measured to create it.
+    expect(line.message).toContain('os migrate apply');
+    // One line: the first line carries both halves.
+    expect(line.message).not.toContain('\n');
+    // The driver's refusal travels in meta, never interpolated into the line.
+    expect(line.meta).toEqual({ object: name, error: `there is already an index named ${name}` });
+    // …and it is not ALSO reported at a quieter level.
+    expect(logs.warn.filter((m) => m.includes('could not provision'))).toEqual([]);
+    // The other three objects still provisioned.
+    const placement = logs.info.find((m) => m.includes('system tables provisioned'));
+    for (const other of OBJECTS.filter((o) => o !== name)) expect(placement).toContain(`${other}→sqlite`);
+    expect(placement).not.toContain(`${name}→`);
+  });
+
+  it('CONTROL: a clean provision logs no error at all', async () => {
+    const logs = await boot();
+
+    expect(logs.error).toEqual([]);
+    const placement = logs.info.find((m) => m.includes('system tables provisioned'));
+    for (const name of OBJECTS) expect(placement).toContain(`${name}→sqlite`);
+  });
+});
+
 /**
  * #4887 — provisioning must SAY what it did.
  *
@@ -231,7 +305,7 @@ describe('AuditPlugin — provisioning is audible (#4887)', () => {
     await plugin.start(ctx);
     await fireReady();
 
-    expect(logs.warn.some((m) => m.includes('could not provision sys_activity'))).toBe(true);
+    expect(logs.error.some((e) => e.message.includes('could not provision sys_activity'))).toBe(true);
     const placement = logs.info.find((m) => m.includes('system tables provisioned'));
     expect(placement).toContain('sys_audit_log→sqlite');
     expect(placement).toContain('sys_comment→sqlite');

packages/plugins/plugin-audit/src/audit-plugin.ts

@@ -138,6 +138,48 @@ function createHostLocaleReader(
   };
 }
 
+/**
+ * [#22913] What is lost when one of this plugin's objects has no storage — the
+ * CONSEQUENCE half of {@link provisionFailureLine}, said concretely per object.
+ * `sys_audit_log` / `sys_activity` are written as a side effect of audited
+ * writes, so their loss is invisible to the writer; a comment or a reaction is
+ * written by its own request, which fails.
+ */
+function lostWithoutStorage(objectName: string): string {
+  switch (objectName) {
+    case 'sys_audit_log':
+      return 'Audited writes keep succeeding, but the `sys_audit_log` rows that record who did what, and the ' +
+        '`sys_activity` rows written after them, cannot land, and nothing retries them.';
+    case 'sys_activity':
+      return "Audited writes keep succeeding, but their `sys_activity` rows (a record's activity timeline and the " +
+        'recent-activity feed) cannot land, and nothing retries them.';
+    case 'sys_comment':
+      return 'Every comment write fails until it exists.';
+    case 'sys_comment_reaction':
+      return 'Every comment reaction write fails until it exists.';
+    default:
+      return 'Every write to it fails until it exists.';
+  }
+}
+
+/**
+ * [#22913] The ONE line `provisionSystemTables` prints when an object's DDL
+ * throws — at `error`, carrying both halves AGENTS.md "Degradation log levels"
+ * asks of a durability degradation: ① the consequence, and that the deployment
+ * keeps looking healthy; ② the fix. Both remedies named were measured to create
+ * the missing storage once the driver fault is gone.
+ */
+function provisionFailureLine(objectName: string): string {
+  return (
+    `AuditPlugin: could not provision ${objectName} storage — its storage was NOT created. ` +
+    `${lostWithoutStorage(objectName)} The boot still completes and the deployment keeps looking healthy. ` +
+    "Fix: resolve the driver's refusal (in this record's meta), then restart, since this provisioning runs on " +
+    `every boot, or run \`os migrate apply\`, which creates the missing storage (\`os migrate plan\` lists it as ` +
+    `\`create_table:${objectName}\`). If the boot log also carries \`Schema sync FAILED for object ` +
+    `'${objectName}'\`, that is the same refusal.`
+  );
+}
+
 /**
  * AuditPlugin
  *
@@ -472,20 +514,34 @@ export class AuditPlugin implements Plugin {
   /**
    * Provision the physical tables for this plugin's system objects up-front.
    *
-   * sys_audit_log / sys_activity / sys_comment are otherwise lazy-created on
-   * first WRITE (the SQL driver issues DDL when the first row is inserted). A
-   * freshly provisioned env that READS one first — the home page's recent-
-   * activity feed queries sys_activity before any mutation has happened — hits
-   * SQLite "no such table", which the engine logs as a `Find operation failed`
-   * ERROR on every load. The UI degrades to an empty feed, but the log is noisy
-   * and can mask real errors. Creating the tables at kernel:ready (once the
-   * engine + registry are ready) makes a new env consistent from the start.
+   * A freshly provisioned env that READS one of these tables before anything
+   * created it — the home page's recent-activity feed queries sys_activity
+   * before any mutation has happened — hits SQLite "no such table", which the
+   * engine logs as a `Find operation failed` ERROR on every load. Creating the
+   * tables at kernel:ready (once the engine + registry are ready) makes a new
+   * env consistent from the start. A WRITE does not create a missing table
+   * either: the SQL driver's insert fails with the same "no such table".
    *
    * `syncObjectSchema` is idempotent — the SQL driver only creates a table when
    * it is absent (and alters to add columns) — so this is safe on every boot,
    * and a no-op for objects whose table already exists. Per-object failures are
    * isolated so one bad object can't block the rest.
    *
+   * ## Why a failed provision is an `error` (#22913)
+   *
+   * When an object's DDL throws here, the boot still completes and the
+   * deployment serves as healthy, but the table does not exist. For
+   * `sys_audit_log` / `sys_activity` the loss is invisible: they are written as
+   * a SIDE EFFECT of audited writes, which keep succeeding while their audit
+   * rows have nowhere to land. That is the durability class AGENTS.md
+   * "Degradation log levels" sends to `error`, with the consequence and the
+   * fix in the first line. Both remedies the line names were measured to
+   * create a missing table once the driver fault is gone: a restart (this
+   * method runs on every boot) and `os migrate apply` (`os migrate plan` lists
+   * it as `create_table`). `OS_SKIP_SCHEMA_SYNC` is NOT named: this method
+   * issues its DDL whether or not that flag is set, so the flag cannot make
+   * this failure deliberate.
+   *
    * ## Why this method reports where each table landed (#4887)
    *
    * `syncObjectSchema` returns `void` and exits SILENTLY on three conditions
@@ -542,7 +598,16 @@ export class AuditPlugin implements Plugin {
       try {
         await sync.call(engine, obj.name);
       } catch (err) {
-        ctx.logger.warn(`AuditPlugin: could not provision ${obj.name} storage — ${(err as Error)?.message ?? err}`);
+        // A DURABILITY degradation, so `error` (AGENTS.md "Degradation log
+        // levels"; see "Why a failed provision is an `error`" above). Once per
+        // object per boot, never per write. The boot is deliberately NOT failed:
+        // refusing to boot is a separate policy call. The driver's refusal goes
+        // in meta, not in the message: a multi-line driver error would split the
+        // record, and only its first fragment would carry the level.
+        ctx.logger.error(provisionFailureLine(obj.name), undefined, {
+          object: obj.name,
+          error: (err as Error)?.message ?? String(err),
+        });
         continue;
       }
       if (typeof resolveDriver !== 'function') continue;