diff --git a/.changeset/lost-audit-row-is-an-error.md b/.changeset/lost-audit-row-is-an-error.md new file mode 100644 index 0000000000..7d4106f6d1 --- /dev/null +++ b/.changeset/lost-audit-row-is-an-error.md @@ -0,0 +1,13 @@ +--- +'@objectstack/plugin-audit': patch +--- + +审计行写失败改为 `error` 级,并只报一次 + +按 AGENTS.md「Degradation log levels」的判据,审计写失败属 **durability / data-consistency** 类而非 functional 类:被审计的那次写入本身成功、数据已落库、接口返回 200,从外面看一切正常,只有记录「谁做的」的 `sys_audit_log` 行没有落地,而且没有任何重试。这正是 #4420 在合规账本上的同一形状,因此原先的 `WARN Audit write failed` 升级为 `error`。 + +这条 `error` 同时给出**后果**与**修复方向**:审计轨迹已不完整;`sys_audit_log` 受 ADR-0057 §3.6 生命周期分流,注册了 `telemetry` 数据源时会被路由过去(`os dev` 默认以兄弟 SQLite 文件形式提供一个),所以出现 "no such table" 通常意味着该次写入执行在了与建表处**不同**的数据源连接上;`OS_TELEMETRY_DB=0` 可让所有 lifecycle-classed 对象留在主数据源。 + +审计写发生在**每一次**数据变更上,因此该 `error` 全进程**只报一次**(后续失败降为 `debug`,细节仍可通过提高日志级别取回)—— 每次失败都报一遍会训练所有人略过 `error`,而这正是当初让 #4420 的 `warn` 无人阅读的反射。 + +写入点提取为具名的 `persistAuditTrailRow`,并登记进 `scripts/check-durability-degradation-log-level.mjs` 的 `DURABILITY_CRITICAL_CALLEES`,由 `pnpm check:durability-log-level` 守住该级别,防止日后被悄悄改回 `warn`。 diff --git a/packages/plugins/plugin-audit/src/audit-writers.test.ts b/packages/plugins/plugin-audit/src/audit-writers.test.ts index 963f3a694c..8cbeb55859 100644 --- a/packages/plugins/plugin-audit/src/audit-writers.test.ts +++ b/packages/plugins/plugin-audit/src/audit-writers.test.ts @@ -1033,3 +1033,130 @@ describe('audit writers — localized activity summaries (framework#3039)', () = expect(emits.find((e) => e.topic === 'collab.assignment')).toBeUndefined(); }); }); + +/** + * #5226 — a lost audit row is a DURABILITY degradation, so it is reported at + * `error`, not `warn`. + * + * The `warn` this replaces is the exact #4420 shape one table over: the audited + * write itself succeeds and returns 200, its row is on disk, and every counter + * reads clean — only the compliance ledger entry that records WHO did it never + * landed, and nothing retries it. By AGENTS.md's one question ("does the system + * still look normal from the outside, while something it claims is persisted + * has not actually landed?") that is `error`, and `pnpm check:durability-log-level` + * now holds the level there (`persistAuditTrailRow` is in its vocabulary). + * + * The failure these tests inject is the real one from the #5226 repro: on a + * `os dev --fresh` stack, ADR-0057 §3.6 routes `sys_audit_log` to the dedicated + * `telemetry` datasource, so an audited write running inside a transaction on + * the PRIMARY datasource reaches a connection where that table does not exist. + * 50 of 52 audit inserts in that boot succeeded; the 2 that ran inside a + * transaction raised exactly this SqliteError. + */ +describe('audit writers — a lost audit row is reported at error (#5226)', () => { + interface LogLine { level: string; message: string; meta?: any } + + /** Engine whose `sys_audit_log` insert always fails, capturing every log line. */ + function makeFailingEngine(failWith = 'no such table: sys_audit_log') { + const hooks = new Map any>>(); + const logs: LogLine[] = []; + const sudoApi = { + object(name: string) { + return { + async create(_row: Record) { + if (name === 'sys_audit_log') throw new Error(failWith); + return { id: 'generated-id' }; + }, + }; + }, + }; + const api = { sudo: () => sudoApi }; + const engine = { + getSchema(name: string) { + const fields = (SINGLE_TENANT as Record)[name]; + if (!fields) return undefined; + return { name, fields: Object.fromEntries(fields.map((f) => [f, { type: 'text' }])) }; + }, + registerHook(event: string, fn: (ctx: any) => any) { + const list = hooks.get(event) ?? []; + list.push(fn); + hooks.set(event, list); + }, + unregisterHooksByPackage() { /* no-op */ }, + logger: { + error(message: string, _err?: unknown, meta?: any) { logs.push({ level: 'error', message, meta }); }, + warn(message: string, meta?: any) { logs.push({ level: 'warn', message, meta }); }, + debug(message: string, meta?: any) { logs.push({ level: 'debug', message, meta }); }, + info() { /* unused */ }, + }, + }; + async function fire(event: string, ctx: any) { + for (const fn of hooks.get(event) ?? []) await fn({ ...ctx, event, api }); + } + return { engine, fire, logs }; + } + + const aWrite = (id: string) => ({ + object: 'crm_lead', + input: { id }, + result: { id, name: 'Acme' }, + session: { tenantId: 'org-1', userId: 'user-1' }, + }); + + it('logs at error — never warn — when the audit row cannot be written', async () => { + const { engine, fire, logs } = makeFailingEngine(); + installAuditWriters(engine as any); + + await fire('afterInsert', aWrite('l-1')); + + // The whole point of the change: this used to be the ONLY line, at `warn`. + expect(logs.filter((l) => l.level === 'warn')).toEqual([]); + const errors = logs.filter((l) => l.level === 'error'); + expect(errors).toHaveLength(1); + expect(errors[0].meta).toMatchObject({ object: 'crm_lead', action: 'create' }); + }); + + it('names both the CONSEQUENCE and the FIX in the first line it prints', async () => { + const { engine, fire, logs } = makeFailingEngine(); + installAuditWriters(engine as any); + + await fire('afterInsert', aWrite('l-1')); + + const msg = logs.find((l) => l.level === 'error')!.message; + // Consequence: the audited write SUCCEEDED, so nothing looks broken, while + // the ledger entry is missing and nothing retries it. + expect(msg).toMatch(/compliance trail is now INCOMPLETE/); + expect(msg).toMatch(/SUCCEEDED/); + expect(msg).toMatch(/nothing retries it/); + // Fix: where the table actually lives, and the opt-out that collapses the split. + expect(msg).toMatch(/telemetry/); + expect(msg).toMatch(/OS_TELEMETRY_DB=0/); + }); + + it('says it ONCE, not once per failed write (AGENTS.md)', async () => { + const { engine, fire, logs } = makeFailingEngine(); + installAuditWriters(engine as any); + + // An audit write runs on EVERY mutation, so a systemic cause would emit one + // `error` per write and train everyone to skim the channel — the reflex + // that made #4420's warn unreadable in the first place. + for (const id of ['l-1', 'l-2', 'l-3', 'l-4', 'l-5']) { + await fire('afterInsert', aWrite(id)); + } + + expect(logs.filter((l) => l.level === 'error')).toHaveLength(1); + // The rest stay recoverable at a higher log level rather than vanishing. + expect(logs.filter((l) => l.level === 'debug')).toHaveLength(4); + expect(logs.filter((l) => l.level === 'warn')).toEqual([]); + }); + + it('never lets a logging failure break the audited write', async () => { + const { engine, fire } = makeFailingEngine(); + // A logger that throws must not turn a swallowed audit failure into a + // user-facing 500 — the audited write already succeeded. + (engine as any).logger = { error() { throw new Error('logger exploded'); } }; + installAuditWriters(engine as any); + + await expect(fire('afterInsert', aWrite('l-1'))).resolves.toBeUndefined(); + }); +}); diff --git a/packages/plugins/plugin-audit/src/audit-writers.ts b/packages/plugins/plugin-audit/src/audit-writers.ts index c4697e4831..b07b482604 100644 --- a/packages/plugins/plugin-audit/src/audit-writers.ts +++ b/packages/plugins/plugin-audit/src/audit-writers.ts @@ -315,6 +315,68 @@ export function installAuditWriters( const getMessaging = opts.getMessaging ?? (() => undefined); const getI18n = opts.getI18n ?? (() => undefined); + /** + * Write the compliance ledger row (+ its activity mirror). + * + * Extracted as a NAMED callee so `pnpm check:durability-log-level` can anchor + * on it: the gate matches a declared vocabulary of durability-critical calls, + * and the bare `.create()` this used to be is far too generic a name to put + * in that vocabulary. Registered in `DURABILITY_CRITICAL_CALLEES` + * (`scripts/check-durability-degradation-log-level.mjs`) in the same PR, per + * the AGENTS.md rule — so a future edit cannot quietly walk the level back + * down to `warn`. + */ + const persistAuditTrailRow = async ( + api: any, + auditRow: Record, + activityRow: Record | undefined, + ): Promise => { + const sys = api.sudo(); + await sys.object('sys_audit_log').create(auditRow); + if (activityRow) await sys.object('sys_activity').create(activityRow); + }; + + /** + * Report a lost audit row — once per process, not once per failed write. + * + * AGENTS.md: "Say it once, at the first degradation, not once per failed + * write." An audit write runs on EVERY mutation, so a per-write `error` on a + * systemic cause (the table is unreachable from this connection) would emit + * one line per write and train everyone to skim `error` — the exact reflex + * that made #4420's `warn` unreadable. The first failure carries the full + * consequence + fix text; subsequent ones degrade to `debug` so the detail is + * still recoverable at a higher log level without drowning the channel. + */ + let auditFailureReported = false; + const reportAuditWriteFailure = (object: string, action: string, err: unknown): void => { + const detail = String((err as any)?.message ?? err); + const logger = (engine as any).logger; + try { + if (auditFailureReported) { + logger?.debug?.('Audit write failed (already reported)', { object, action, err: detail }); + return; + } + auditFailureReported = true; + // The two things an `error` here owes, both in the first line it prints: + // the CONSEQUENCE, concretely, and the FIX. + logger?.error?.( + 'Audit write FAILED — the compliance trail is now INCOMPLETE. The audited write itself SUCCEEDED and is on ' + + 'disk, so the API returned success and nothing downstream looks broken; only the `sys_audit_log` row that ' + + 'records who did it never landed, and nothing retries it. Every subsequent audited write is likely losing ' + + 'its row the same way (this is reported ONCE — raise the log level to `debug` to see the rest). ' + + 'Fix: confirm `sys_audit_log` is reachable from the connection this write ran on. Its ADR-0057 §3.6 ' + + "lifecycle class routes it to the dedicated `telemetry` datasource whenever one is registered (`os dev` " + + 'provisions one by default as a SIBLING SQLite file), so a "no such table" here usually means the write ' + + 'executed against a DIFFERENT datasource than the one the table was created in — see framework#5226. ' + + 'Set `OS_TELEMETRY_DB=0` to keep every lifecycle-classed object on the primary datasource.', + err instanceof Error ? err : new Error(detail), + { object, action }, + ); + } catch { + /* logging must never break the audited write */ + } + }; + // Workspace locale changes rarely, but writeAudit runs on every CRUD write — // memoize the settings lookup per principal scope with a short TTL so audit // logging doesn't add a settings query to every mutation's hot path. @@ -652,9 +714,6 @@ export function installAuditWriters( const activitiesEnabled = getObjectDef(ctx.object)?.enable?.activities !== false; try { - const sys = api.sudo(); - await sys.object('sys_audit_log').create(auditRow); - if (activitiesEnabled) await sys.object('sys_activity').create(activityRow); // Assignment notifications are NOT emitted here (framework#3403). Deciding // that an owner/assignee change warrants a bell is a business policy, not a // platform default — the kernel version guessed "who is the assignee" from @@ -666,9 +725,15 @@ export function installAuditWriters( // (Comment @mention notifications remain a platform behavior — they are // handled separately by the sys_comment hook below, since SKIP_OBJECTS // excludes it from this writer.) + await persistAuditTrailRow(api, auditRow, activitiesEnabled ? activityRow : undefined); } catch (err) { - // Log via engine logger if available, but never throw. - try { (engine as any).logger?.warn?.('Audit write failed', { object: ctx.object, action, err: String((err as any)?.message ?? err) }); } catch {} + // #5226 — DURABILITY degradation, not a functional one, so it is reported + // at `error` (AGENTS.md "Degradation log levels"): the audited write + // itself returned 200 and its row is on disk, so the system looks + // completely normal from the outside, while the compliance ledger entry + // that claims to record it never landed. Nothing retries it, and the gap + // surfaces — if ever — to an auditor who cannot connect it to this line. + reportAuditWriteFailure(ctx.object, action, err); } }; diff --git a/scripts/check-durability-degradation-log-level.mjs b/scripts/check-durability-degradation-log-level.mjs index bd32564d10..4c67c0416f 100644 --- a/scripts/check-durability-degradation-log-level.mjs +++ b/scripts/check-durability-degradation-log-level.mjs @@ -144,6 +144,10 @@ const DURABILITY_CRITICAL_CALLEES = new Map([ 'saveMetaItem', 'The metadata definition was never written to the authoritative store — the runtime looks completely normal because the in-memory registry already has it, and the definition simply vanishes on the next provision/restart (#4754, from #4669).', ], + [ + 'persistAuditTrailRow', + 'The compliance audit row was never written — the audited write itself succeeded and returned 200, so the API, the data and every counter read clean, while the `sys_audit_log` entry that records WHO did it is simply absent and nothing retries it. The gap surfaces, if ever, to an auditor who cannot connect it back to the write (#5226, the #4420 shape on the compliance ledger).', + ], [ 'deleteMetaItemFromLoader', 'The metadata definition was never deleted from the authoritative store — `unregister()` still resolves and still announces `deleted`, the in-memory registry entry is gone, and the surviving row is read straight back out of storage by the very next `list()`/`get()`, so the "deleted" item reappears and survives every restart. Nothing retries it (#5259).',