diff --git a/.changeset/audit-provisioning-datasource-audible.md b/.changeset/audit-provisioning-datasource-audible.md new file mode 100644 index 0000000000..94ef58449a --- /dev/null +++ b/.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()`. diff --git a/packages/plugins/plugin-audit/src/audit-plugin.test.ts b/packages/plugins/plugin-audit/src/audit-plugin.test.ts index ad6612175c..63ef960686 100644 --- a/packages/plugins/plugin-audit/src/audit-plugin.test.ts +++ b/packages/plugins/plugin-audit/src/audit-plugin.test.ts @@ -39,8 +39,14 @@ function makeCtx(engine: unknown) { ['manifest', { register() {} }], ]); const readyHooks: Array<() => Promise | 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, 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 diff --git a/packages/plugins/plugin-audit/src/audit-plugin.ts b/packages/plugins/plugin-audit/src/audit-plugin.ts index cab179f646..c0cae440a0 100644 --- a/packages/plugins/plugin-audit/src/audit-plugin.ts +++ b/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 { // `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 }).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.', + ); } } }