diff --git a/.changeset/22913-audit-provision-failure-error.md b/.changeset/22913-audit-provision-failure-error.md new file mode 100644 index 00000000000..c2ba43fbd1d --- /dev/null +++ b/.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. diff --git a/packages/cli/src/commands/migrate/plan.telemetry-sibling.integration.test.ts b/packages/cli/src/commands/migrate/plan.telemetry-sibling.integration.test.ts index 0d9f03c3f25..c9102fdd509 100644 --- a/packages/cli/src/commands/migrate/plan.telemetry-sibling.integration.test.ts +++ b/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 diff --git a/packages/plugins/plugin-audit/src/audit-plugin.test.ts b/packages/plugins/plugin-audit/src/audit-plugin.test.ts index 2e17983f17b..7d65c76fd60 100644 --- a/packages/plugins/plugin-audit/src/audit-plugin.test.ts +++ b/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 | 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) { + 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'); diff --git a/packages/plugins/plugin-audit/src/audit-plugin.ts b/packages/plugins/plugin-audit/src/audit-plugin.ts index 62c66faef04..435b0fb1dc1 100644 --- a/packages/plugins/plugin-audit/src/audit-plugin.ts +++ b/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;