fix(plugin-audit): 让 provisioning 说出表建到了哪个 datasource (#4887)

.changeset/audit-provisioning-datasource-audible.md

@@ -0,0 +1,50 @@
+---
+"@objectstack/plugin-audit": patch
+---
+
+fix(plugin-audit): say where the audit system tables were provisioned, and stop skipping provisioning silently (#4887)
+
+`AuditPlugin.provisionSystemTables()` created `sys_audit_log` / `sys_activity` /
+`sys_comment` at `kernel:ready` and then said **nothing** — not on success, and
+not when it skipped the work entirely (`typeof engine.syncObjectSchema !==
+'function'` returned silently). `syncObjectSchema()` itself returns `void` and
+has three silent exits of its own — the object is not in the registry, no driver
+resolves for it, or the resolved driver has no `syncSchema` — none of which
+throw. So "provisioned three tables" and "provisioned nothing at all" produced
+byte-identical logs, and the only way to tell them apart was to go looking in a
+database.
+
+#4887 is what that costs. `sys_audit_log` and `sys_activity` were reported as
+never provisioned because they were absent from the primary SQLite file, with
+the silent `typeof` bail named as the likely cause. Neither was true:
+`sys_audit_log` (`lifecycle.class: 'audit'`) and `sys_activity`
+(`lifecycle.class: 'telemetry'`) are routed by **ADR-0057 §3.6** to the
+dedicated `telemetry` datasource whenever one is registered, and `os dev`
+registers one by default as a *sibling file* (`dev.db` → `dev.telemetry.db`).
+Both tables had been created — in the other store. `sys_comment` carries no
+lifecycle class, stays on the primary, and was the one that "existed". Nothing
+in the log connected those three facts.
+
+Provisioning now reports itself:
+
+- **Wholesale skip is a `warn`, naming the consequence** — the tables stay
+  lazy-created on first WRITE, so an env that READS one first (the home page
+  activity feed queries `sys_activity` before any mutation) logs "no such
+  table" until something writes.
+- **One `info` line per boot listing where each table landed** —
+  `sys_audit_log→telemetry, sys_activity→telemetry, sys_comment→sqlite`,
+  resolved through the engine's own `getDriverForObject`, so the log states the
+  routing rather than leaving it to be inferred.
+- **A second `info` line when the ADR-0057 split is in effect**, saying
+  explicitly that those tables live in a different store — on SQLite, a
+  different *file* — and that anything reading them without naming the object
+  (raw SQL against the default datasource) will report "no such table" even
+  though provisioning succeeded.
+- **An object that resolves to no driver is a `warn`** — `syncObjectSchema()`
+  returns without issuing any DDL in that case and throws nothing, so the
+  per-object `catch` never fires; from outside the engine this is the only place
+  it can be observed.
+
+Behaviour is otherwise unchanged: the same three objects are synced, per-object
+failures stay isolated, and an engine without on-demand DDL still degrades
+instead of failing `start()`.

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

@@ -39,8 +39,14 @@ function makeCtx(engine: unknown) {
     ['manifest', { register() {} }],
   ]);
   const readyHooks: Array<() => Promise<void> | void> = [];
+  // #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[] };
   const logger = {
-    info() {}, warn() {}, error() {}, debug() {},
+    info(msg: string) { logs.info.push(String(msg)); },
+    warn(msg: string) { logs.warn.push(String(msg)); },
+    error() {}, debug() {},
     child() { return logger; },
   };
   const ctx = {
@@ -51,7 +57,7 @@ function makeCtx(engine: unknown) {
       if (event === 'kernel:ready') readyHooks.push(fn);
     },
   } as any;
-  return { ctx, fireReady: async () => { for (const fn of readyHooks) await fn(); } };
+  return { ctx, logs, fireReady: async () => { for (const fn of readyHooks) await fn(); } };
 }
 
 describe('AuditPlugin — system table provisioning', () => {
@@ -89,6 +95,146 @@ describe('AuditPlugin — system table provisioning', () => {
   });
 });
 
+/**
+ * #4887 — provisioning must SAY what it did.
+ *
+ * `syncObjectSchema` returns `void` and has three silent exits of its own
+ * (object not registered / no driver / driver without `syncSchema`), so a
+ * caller that only catches throws cannot distinguish "created the table" from
+ * "did nothing". Combined with a silent `typeof sync !== 'function'` bail on
+ * this side, a boot where provisioning was skipped WHOLESALE logged exactly
+ * the same thing as a boot where it worked: nothing.
+ *
+ * #4887 is what that costs. `sys_audit_log` / `sys_activity` were reported as
+ * "never provisioned" because they were absent from the primary SQLite file —
+ * but ADR-0057 §3.6 routes both (lifecycle classes `audit` / `telemetry`) to
+ * the `telemetry` datasource when one is registered, and `os dev` registers one
+ * by default as a sibling file. The tables existed; the log just never said
+ * where. These tests pin the three statements an operator now gets.
+ */
+describe('AuditPlugin — provisioning is audible (#4887)', () => {
+  /** Engine whose datasource routing mirrors ADR-0057 §3.6 in `os dev`. */
+  function makeRoutingEngine(routes: Record<string, string | undefined>, defaultName = 'sqlite') {
+    return {
+      async syncObjectSchema(_name: string) { /* DDL issued on the resolved driver */ },
+      getDriverForObject(name: string) {
+        const ds = routes[name];
+        return ds === undefined ? undefined : { name: ds };
+      },
+      getDefaultDriverName() { return defaultName; },
+    };
+  }
+
+  it('warns — instead of returning silently — when the engine has no syncObjectSchema', async () => {
+    const { ctx, logs, fireReady } = makeCtx({ async find() { return []; } });
+    const plugin = new AuditPlugin();
+    await plugin.init(ctx);
+    await plugin.start(ctx);
+    await fireReady();
+
+    const warned = logs.warn.find((m) => m.includes('no syncObjectSchema'));
+    expect(warned).toBeDefined();
+    // The warning must name the CONSEQUENCE, not just the missing method:
+    // nothing is provisioned and a read-first env logs "no such table".
+    expect(warned).toMatch(/sys_activity/);
+    expect(warned).toMatch(/no such table/);
+  });
+
+  it('reports the datasource each system table was provisioned into', async () => {
+    // The exact `os dev` shape: audit + activity split off to `telemetry`,
+    // comment stays on the primary.
+    const engine = makeRoutingEngine({
+      sys_audit_log: 'telemetry',
+      sys_activity: 'telemetry',
+      sys_comment: 'sqlite',
+    });
+    const { ctx, logs, fireReady } = makeCtx(engine);
+    const plugin = new AuditPlugin();
+    await plugin.init(ctx);
+    await plugin.start(ctx);
+    await fireReady();
+
+    const placement = logs.info.find((m) => m.includes('system tables provisioned'));
+    expect(placement).toBeDefined();
+    expect(placement).toContain('sys_audit_log→telemetry');
+    expect(placement).toContain('sys_activity→telemetry');
+    expect(placement).toContain('sys_comment→sqlite');
+
+    // …and the split itself is called out, because "absent from the database I
+    // am looking at" is not "never created".
+    const split = logs.info.find((m) => m.includes('NON-default datasource'));
+    expect(split).toBeDefined();
+    expect(split).toContain('ADR-0057');
+    expect(split).toContain('sys_audit_log→telemetry');
+    expect(split).toContain('sys_activity→telemetry');
+    // sys_comment is ON the default datasource — it must not be listed as split.
+    expect(split).not.toContain('sys_comment');
+  });
+
+  it('says nothing about a split when every table is on the default datasource', async () => {
+    const engine = makeRoutingEngine({
+      sys_audit_log: 'sqlite',
+      sys_activity: 'sqlite',
+      sys_comment: 'sqlite',
+    });
+    const { ctx, logs, fireReady } = makeCtx(engine);
+    const plugin = new AuditPlugin();
+    await plugin.init(ctx);
+    await plugin.start(ctx);
+    await fireReady();
+
+    expect(logs.info.find((m) => m.includes('system tables provisioned'))).toBeDefined();
+    expect(logs.info.some((m) => m.includes('NON-default datasource'))).toBe(false);
+    expect(logs.warn.some((m) => m.includes('NO datasource driver'))).toBe(false);
+  });
+
+  it("warns when an object resolves to no driver — syncObjectSchema's own silent exit", async () => {
+    // `syncObjectSchema` returns without issuing DDL when no driver backs the
+    // object. It throws nothing, so the per-object catch never fires: the only
+    // way this is ever visible is from the outside, here.
+    const engine = makeRoutingEngine({
+      sys_audit_log: undefined,
+      sys_activity: 'sqlite',
+      sys_comment: 'sqlite',
+    });
+    const { ctx, logs, fireReady } = makeCtx(engine);
+    const plugin = new AuditPlugin();
+    await plugin.init(ctx);
+    await plugin.start(ctx);
+    await fireReady();
+
+    const warned = logs.warn.find((m) => m.includes('NO datasource driver'));
+    expect(warned).toBeDefined();
+    expect(warned).toContain('sys_audit_log');
+    // The other two still provisioned — one unroutable object does not stop them.
+    const placement = logs.info.find((m) => m.includes('system tables provisioned'));
+    expect(placement).toContain('sys_activity→sqlite');
+    expect(placement).toContain('sys_comment→sqlite');
+    expect(placement).not.toContain('sys_audit_log');
+  });
+
+  it('keeps reporting placements when one object fails to sync', async () => {
+    const engine = {
+      async syncObjectSchema(name: string) {
+        if (name === 'sys_activity') throw new Error('disk I/O error');
+      },
+      getDriverForObject() { return { name: 'sqlite' }; },
+      getDefaultDriverName() { return 'sqlite'; },
+    };
+    const { ctx, logs, fireReady } = makeCtx(engine);
+    const plugin = new AuditPlugin();
+    await plugin.init(ctx);
+    await plugin.start(ctx);
+    await fireReady();
+
+    expect(logs.warn.some((m) => m.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');
+    expect(placement).not.toContain('sys_activity');
+  });
+});
+
 /**
  * #4630 — the sys_comment record-level gates are only worth as much as their
  * MOUNTING: `comment-access-hooks.test.ts` proves what the hooks decide, this

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

@@ -181,19 +181,96 @@ export class AuditPlugin implements Plugin {
    * 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 this method reports where each table landed (#4887)
+   *
+   * `syncObjectSchema` returns `void` and exits SILENTLY on three conditions
+   * the plugin cannot see from the outside: the object is not in the registry,
+   * no driver resolves for it, or the resolved driver has no `syncSchema`. A
+   * caller that only catches throws therefore cannot tell "created" from "did
+   * nothing" — and neither could a reader of the log, because this method said
+   * nothing at all on success.
+   *
+   * That silence cost a whole misdiagnosis. #4887 reported these tables as
+   * "never provisioned" because they were absent from the primary SQLite file,
+   * and concluded the guard below had bailed out. It had not: `sys_audit_log`
+   * (`lifecycle.class: 'audit'`) and `sys_activity` (`lifecycle.class:
+   * 'telemetry'`) are routed by ADR-0057 §3.6 to the dedicated `telemetry`
+   * datasource whenever one is registered — which `os dev` provisions by
+   * default as a SIBLING FILE (`dev.db` → `dev.telemetry.db`). Their tables
+   * were created, in that other store. `sys_comment` carries no lifecycle
+   * class, stays on the primary, and was the one the reporter found. So the
+   * provisioning loop reports the resolved datasource per object, and calls out
+   * the split explicitly when it is in effect: a table that is "missing" from
+   * the database you are looking at, and a table that was never created, are
+   * different problems, and the log now distinguishes them.
    */
   private async provisionSystemTables(engine: IDataEngine, ctx: PluginContext): Promise<void> {
     // `syncObjectSchema` lives on the concrete ObjectQL engine, not the
     // IDataEngine contract; engines/drivers without on-demand DDL (e.g. an
     // in-memory test double) simply skip provisioning.
     const sync = (engine as unknown as { syncObjectSchema?: (name: string) => Promise<void> }).syncObjectSchema;
-    if (typeof sync !== 'function') return;
+    if (typeof sync !== 'function') {
+      // #4887 — this return used to be silent, so "provisioning was skipped
+      // wholesale" and "provisioning ran fine" produced identical logs. Name
+      // the consequence, not just the condition.
+      ctx.logger.warn(
+        'AuditPlugin: this engine exposes no syncObjectSchema() — sys_audit_log / sys_activity / sys_comment were NOT ' +
+          'provisioned up-front and stay lazy-created on first WRITE. An env that READS one first (the home page ' +
+          'activity feed queries sys_activity before any mutation) will log "no such table" until something writes to it.',
+      );
+      return;
+    }
+    // Same optional-probe posture as `syncObjectSchema` above: `getDriverForObject`
+    // is public on the concrete ObjectQL engine but not part of IDataEngine, so
+    // engines that lack it simply report no datasource — never an error.
+    const resolveDriver = (engine as unknown as {
+      getDriverForObject?: (name: string) => { name?: string } | undefined;
+    }).getDriverForObject;
+    // Declared on IDataEngine (optional — engines with no named-driver registry
+    // omit it), so no cast is needed here.
+    const defaultDatasource = engine.getDefaultDriverName?.();
+
+    const placements: string[] = [];
+    const offDefault: string[] = [];
     for (const obj of [SysAuditLog, SysActivity, SysComment]) {
       try {
         await sync.call(engine, obj.name);
       } catch (err) {
         ctx.logger.warn(`AuditPlugin: could not provision ${obj.name} storage — ${(err as Error)?.message ?? err}`);
+        continue;
       }
+      if (typeof resolveDriver !== 'function') continue;
+      let datasource: string | undefined;
+      try {
+        datasource = resolveDriver.call(engine, obj.name)?.name;
+      } catch {
+        datasource = undefined;
+      }
+      if (!datasource) {
+        // The second of the two silent exits #4887 asked to make audible: the
+        // call above resolved without throwing, but no driver backs this object,
+        // so `syncObjectSchema` returned having issued no DDL at all.
+        ctx.logger.warn(
+          `AuditPlugin: ${obj.name} resolves to NO datasource driver — syncObjectSchema() returned without creating its ` +
+            'storage. Reads and writes against it will fail with "no such table" until a driver backs its datasource.',
+        );
+        continue;
+      }
+      placements.push(`${obj.name}→${datasource}`);
+      if (defaultDatasource !== undefined && datasource !== defaultDatasource) offDefault.push(`${obj.name}→${datasource}`);
+    }
+
+    if (placements.length > 0) {
+      ctx.logger.info(`AuditPlugin: system tables provisioned — ${placements.join(', ')}`);
+    }
+    if (offDefault.length > 0) {
+      ctx.logger.info(
+        `AuditPlugin: ${offDefault.join(', ')} live on a NON-default datasource (ADR-0057 §3.6 lifecycle-class ` +
+          `separation), not on '${defaultDatasource}'. Their tables exist in that store — on SQLite, a different FILE. ` +
+          'Anything that reads them without naming the object (raw SQL on the default datasource) will report ' +
+          '"no such table" even though provisioning succeeded.',
+      );
     }
   }
 }