From 168cf1e33220c9276782e1fec73cb921db9388a9 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 12 Oct 2026 06:59:34 +0000 Subject: [PATCH 1/2] fix(plugin-audit): a failed boot provisioning of an audit table is logged at error, naming what is lost and the fix AuditPlugin's kernel:ready provisioning caught a refused DDL for sys_audit_log / sys_activity / sys_comment / sys_comment_reaction and logged it at warn. The boot completes and the deployment looks healthy while the table does not exist; for the two audit tables, audited writes keep succeeding while their rows have nowhere to land. That is the durability class AGENTS.md "Degradation log levels" sends to error. The catch now logs one error per object per boot. Its first line names the object, what is lost, that the deployment keeps looking healthy, and the measured fix: resolve the driver's refusal, then restart or run `os migrate apply`. The driver's message goes in meta. The boot is still not failed. Pins: a refused DDL on each of the four objects logs exactly one error naming it and `os migrate apply`, with the refusal in meta; the control, a clean provision, logs no error. The telemetry-sibling integration test now carries the serve child's own output in the assertions that read what the boot provisioned. Claude-Session: https://claude.ai/code/session_01CeRCvvvjxbxu2iYJAc5Cce Co-authored-by: Claude --- .../22913-audit-provision-failure-error.md | 13 +++ ...plan.telemetry-sibling.integration.test.ts | 43 ++++++---- .../plugin-audit/src/audit-plugin.test.ts | 80 +++++++++++++++++- .../plugins/plugin-audit/src/audit-plugin.ts | 83 +++++++++++++++++-- 4 files changed, 193 insertions(+), 26 deletions(-) create mode 100644 .changeset/22913-audit-provision-failure-error.md diff --git a/.changeset/22913-audit-provision-failure-error.md b/.changeset/22913-audit-provision-failure-error.md new file mode 100644 index 00000000000..3ac425d05b0 --- /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 `create_table:`. 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 storage` 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; From 9ac3a46f5574e094922acc6d2cd723d96d091ab8 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 12 Oct 2026 07:09:35 +0000 Subject: [PATCH 2/2] docs(changeset): spell the plan entry and the log search without angle-bracket placeholders Claude-Session: https://claude.ai/code/session_01CeRCvvvjxbxu2iYJAc5Cce Co-authored-by: Claude --- .changeset/22913-audit-provision-failure-error.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/.changeset/22913-audit-provision-failure-error.md b/.changeset/22913-audit-provision-failure-error.md index 3ac425d05b0..c2ba43fbd1d 100644 --- a/.changeset/22913-audit-provision-failure-error.md +++ b/.changeset/22913-audit-provision-failure-error.md @@ -8,6 +8,6 @@ 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 `create_table:`. Both remedies were measured to create a missing `sys_activity` once the fault was gone, with and without the telemetry sibling database. +- **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 storage` still matches the line. +- **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.