fix(plugin-audit): 审计行写失败升为 error 并只报一次 (#5226 之二);#5226 主缺陷前提被证伪

.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`。

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<string, Array<(ctx: any) => any>>();
+    const logs: LogLine[] = [];
+    const sudoApi = {
+      object(name: string) {
+        return {
+          async create(_row: Record<string, any>) {
+            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<string, string[]>)[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();
+  });
+});

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<string, any>,
+    activityRow: Record<string, any> | undefined,
+  ): Promise<void> => {
+    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);
     }
   };
 

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).',