fix(plugin-audit): read-audit reports once per CAUSE, not once per process

.changeset/18247-read-audit-failure-reported-per-cause.md

@@ -0,0 +1,16 @@
+---
+'@objectstack/plugin-audit': patch
+---
+
+**The read-audit failure report now speaks once per CAUSE instead of once per PROCESS, and prints the telemetry-datasource remedy only for the cause it is the remedy for.**
+
+`installReadAuditWriter`'s `reportReadAuditWriteFailure` (`read-audit.ts`) carried its own process-level `failureReported` boolean and its own fixed message literal — the third independent copy of the pair #15166 fixed in `audit-writers.ts` and #17452 fixed in `auth-event-audit.ts`. Both defects were live on a seam the repo has already declared durability-critical (`persistReadAuditRows` is registered in `DURABILITY_CRITICAL_CALLEES`):
+
+- **The first failure of any cause silenced every later failure of every other cause for the life of the process.** A server could keep losing record-view batches for hours to a second, unrelated fault with one `error` line at the top of the log describing the first — and record-view rows are written from a buffer off the request path, so no in-flight request is left to notice. The dedupe key is now the failure's identity, `auditFailureCauseKey`, imported from `audit-writers.ts` rather than re-spelled. A repeat of an already-reported cause still degrades to `debug`; a NEW cause gets its own `error` line, once.
+- **The ADR-0057 §3.6 / `OS_TELEMETRY_DB` datasource guidance printed unconditionally**, so a fault with nothing to do with datasource routing (an `ERR_SYSTEM_WRITE_ORGANIZATION_REQUIRED` refusal, say) sent the operator to check something that was working. The guidance is not deleted and not weakened — it is asked for through the shared `isMissingTableError` predicate and printed for exactly the missing-table cause it was written for; every other cause now gets the driver's own verdict quoted at the head of the line plus the fix that matches it.
+
+**Behaviour that deliberately does not change:** the once-per-degradation anti-noise rule itself (a repeat of the same cause is still one line), the `error`-then-`warn` sink fallback (#9657), and the rule that an audit failure never reaches the read.
+
+No API, option or type moves; nothing an author writes changes.
+
+Clause-②: no

packages/plugins/plugin-audit/src/read-audit.test.ts

@@ -597,3 +597,195 @@ describe('#8992 shutdown drains the tail', () => {
     expect(writer.pending()).toBe(0);
   });
 });
+
+describe('read-audit failure reporting — once per CAUSE, not once per process (#18247)', () => {
+  interface LogLine {
+    level: string;
+    message: string;
+    meta?: Record<string, any>;
+  }
+
+  const driverError = (message: string, code?: string): Error => {
+    const e = new Error(message) as Error & { code?: string };
+    if (code !== undefined) e.code = code;
+    return e;
+  };
+
+  const NO_SUCH_TABLE = () => driverError('no such table: sys_audit_log', 'SQLITE_ERROR');
+  const ORG_REQUIRED = () =>
+    driverError('system write requires an organization', 'ERR_SYSTEM_WRITE_ORGANIZATION_REQUIRED');
+
+  /**
+   * A REAL engine whose ledger write fails with a caller-chosen error.
+   *
+   * The engine stays real for the reason this file's header gives — the hook
+   * dispatch and the field-presence probe are the engine's behaviour, not
+   * ours. Only `insert` is replaced, and only AFTER install, so the probe has
+   * already run against the real registry exactly as it does in production.
+   *
+   * `omitError: true` drops the OPTIONAL `error` sink (#9657) so the degrade
+   * path can be exercised on its own.
+   */
+  async function makeCauseHarness(
+    nextError: (n: number) => unknown,
+    omitError = false,
+  ): Promise<{ view: () => Promise<void>; at: (level: string) => LogLine[] }> {
+    const engine = await makeEngine();
+    await engine.insert(
+      'contact',
+      { id: 'c1', full_name: 'Wei Zhang', organization_id: 'org_a' },
+      { context: { isSystem: true } },
+    );
+    const logs: LogLine[] = [];
+    const logger: Record<string, unknown> = {
+      warn(message: string, meta?: Record<string, any>) {
+        logs.push({ level: 'warn', message, meta });
+      },
+      debug(message: string, meta?: Record<string, any>) {
+        logs.push({ level: 'debug', message, meta });
+      },
+    };
+    if (!omitError) {
+      logger.error = (message: string, _err?: Error, meta?: Record<string, any>) => {
+        logs.push({ level: 'error', message, meta });
+      };
+    }
+    const writer = installReadAuditWriter(engine, {
+      objects: ['contact'],
+      timers: makeManualTimers(),
+      logger: logger as any,
+    })!;
+    let n = 0;
+    (engine as any).insert = async () => {
+      throw nextError(n++);
+    };
+    /** One record view, drained immediately — one failed batch per call. */
+    const view = async (): Promise<void> => {
+      await engine.findOne('contact', { where: { id: 'c1' }, context: viewerCtx });
+      await writer.flush();
+    };
+    return { view, at: (level: string) => logs.filter((l) => l.level === level) };
+  }
+
+  it('reports a SECOND, DIFFERENT cause at error — a new cause is a new degradation', async () => {
+    // THE DEFECT. On the process-wide boolean this file carried, a second,
+    // unrelated fault produced one `debug` and no `error` at all: the first
+    // cause of the process had silenced every later cause for the life of the
+    // process, on a seam `DURABILITY_CRITICAL_CALLEES` already names.
+    let phase = 0;
+    const { view, at } = await makeCauseHarness(() => (phase === 0 ? NO_SUCH_TABLE() : ORG_REQUIRED()));
+
+    await view();
+    phase = 1;
+    await view();
+
+    const errors = at('error');
+    expect(errors).toHaveLength(2);
+    expect(errors[0].message).toMatch(/no such table: sys_audit_log/);
+    expect(errors[1].message).toMatch(/ERR_SYSTEM_WRITE_ORGANIZATION_REQUIRED/);
+    expect(at('debug')).toHaveLength(0);
+    expect(at('warn')).toEqual([]);
+  });
+
+  it('still degrades a REPEAT of an already-reported cause to debug', async () => {
+    // ⚠️ THE DISCRIMINATING CONTROL. Deleting the boolean outright would also
+    // make the test above pass, and would be the falsifier AGENTS.md names
+    // ("log every failure at `error`"). This is the half that must NOT change:
+    // the same cause on the same ledger still says it once.
+    const { view, at } = await makeCauseHarness(() => NO_SUCH_TABLE());
+
+    for (let i = 0; i < 5; i += 1) await view();
+
+    expect(at('error')).toHaveLength(1);
+    expect(at('debug')).toHaveLength(4);
+    // The repeats name the cause they were folded into, so a `debug` sweep can
+    // tell "the same fault, 4 more times" from "four different faults".
+    expect(at('debug')[0].meta?.cause).toBe(at('debug')[3].meta?.cause);
+  });
+
+  it('keys on the error CODE, never its message, so a per-row fault cannot flood `error`', async () => {
+    // ⚠️ THE ANTI-NOISE PIN (AGENTS.md; #4420). A driver names the offending
+    // ROW in its message, so a message-keyed dedupe would grow one `error`
+    // line per lost batch. 200 batches, 200 distinct messages, ONE code ⇒ one
+    // line.
+    const BATCHES = 200;
+    const { view, at } = await makeCauseHarness((i) =>
+      driverError(`UNIQUE constraint failed: sys_audit_log.id (row aud_${i})`, 'SQLITE_CONSTRAINT_UNIQUE'),
+    );
+
+    for (let i = 0; i < BATCHES; i += 1) await view();
+
+    expect(at('error')).toHaveLength(1);
+    expect(at('debug')).toHaveLength(BATCHES - 1);
+  });
+
+  it('folds a fault carrying NO code into ONE bucket rather than growing one', async () => {
+    // The other half of the bound: "the code, or its ABSENCE" is a single key
+    // value, so an uncoded driver — the shape with nothing bounded to key on —
+    // still says it once instead of once per flush.
+    const BATCHES = 200;
+    const { view, at } = await makeCauseHarness((i) => driverError(`insert failed for batch ${i}`));
+
+    for (let i = 0; i < BATCHES; i += 1) await view();
+
+    expect(at('error')).toHaveLength(1);
+    expect(at('debug')).toHaveLength(BATCHES - 1);
+  });
+
+  it('carries the underlying code and message in the first line it prints', async () => {
+    // The information was computed one line above the branch and dropped on
+    // the floor: the `error` path built a fixed string and never read `err`.
+    const { view, at } = await makeCauseHarness(() => ORG_REQUIRED());
+
+    await view();
+
+    const msg = at('error')[0].message;
+    expect(msg).toMatch(/ERR_SYSTEM_WRITE_ORGANIZATION_REQUIRED/);
+    expect(msg).toMatch(/system write requires an organization/);
+    // The consequence half is unchanged — it is still owed, and still first.
+    expect(msg).toMatch(/compliance trail is now INCOMPLETE/);
+    expect(msg).toMatch(/who viewed this record/);
+  });
+
+  it('prints the datasource remedy for the cause it is the remedy FOR, and not for others', async () => {
+    // ⛔ Not a deletion: the ADR-0057 §3.6 routing text is genuinely correct
+    // for the "no such table" cause it was written for, so it must still print
+    // there. What is fixed is that it used to print for EVERY cause.
+    const missing = await makeCauseHarness(() => NO_SUCH_TABLE());
+    await missing.view();
+    const forMissingTable = missing.at('error')[0].message;
+    expect(forMissingTable).toMatch(/telemetry/);
+    expect(forMissingTable).toMatch(/OS_TELEMETRY_DB=0/);
+
+    // The misdirection: the cause is an organization refusal and the text sent
+    // the operator to check a datasource that was working.
+    const refused = await makeCauseHarness(() => ORG_REQUIRED());
+    await refused.view();
+    const forRefusal = refused.at('error')[0].message;
+    expect(forRefusal).not.toMatch(/OS_TELEMETRY_DB/);
+    expect(forRefusal).not.toMatch(/telemetry/i);
+    // It still owes a fix — it just owes the RIGHT one.
+    expect(forRefusal).toMatch(/Fix:/);
+  });
+
+  it('[#9657] the `warn` fallback is per-cause too — a sink with no `error` hears the second fault', async () => {
+    // `ReadAuditLogger.error` is OPTIONAL, so the degrade path is the only
+    // channel a host without one ever gets. Fixing the dedupe on the `error`
+    // branch alone would leave that host exactly where it started.
+    let phase = 0;
+    const { view, at } = await makeCauseHarness(
+      () => (phase === 0 ? NO_SUCH_TABLE() : ORG_REQUIRED()),
+      true,
+    );
+
+    await view();
+    phase = 1;
+    await view();
+
+    const warns = at('warn');
+    expect(warns).toHaveLength(2);
+    expect(warns[0].message).toMatch(/no such table: sys_audit_log/);
+    expect(warns[1].message).toMatch(/ERR_SYSTEM_WRITE_ORGANIZATION_REQUIRED/);
+    expect(at('error')).toEqual([]);
+  });
+});

packages/plugins/plugin-audit/src/read-audit.ts

@@ -88,12 +88,26 @@
 
 import type { HookContext } from '@objectstack/spec/data';
 import type { IDataEngine } from '@objectstack/spec/contracts';
+import { isMissingTableError } from '@objectstack/types';
 // DERIVED, never re-typed — the same rule `audit-writers.ts` states for its own
 // two faces. An object excluded from write auditing (recursion, auth/session
 // noise, ADR-0057 telemetry plumbing) is excluded from read auditing for the
 // identical reasons, and a second hand-kept list would disagree on the day
 // either is fixed.
-import { AUDIT_EXCLUDED_OBJECTS, createFieldPresenceProbe } from './audit-writers.js';
+//
+// ⚠️ [#18247] `auditFailureCauseKey` / `auditFailureCauseSummary` join that
+// derivation for the same reason and on the same seam. #15166 replaced a
+// process-wide boolean with a cause key in `audit-writers.ts`; #17452 found a
+// SECOND copy of the boolean in `auth-event-audit.ts` and imported the key
+// rather than re-spelling it, and exported it for exactly that purpose. This
+// file was the THIRD copy. ⛔ A third spelling of the key is how the defect
+// travelled the first two times — import it.
+import {
+  AUDIT_EXCLUDED_OBJECTS,
+  auditFailureCauseKey,
+  auditFailureCauseSummary,
+  createFieldPresenceProbe,
+} from './audit-writers.js';
 
 /**
  * The ledger action this writer emits.
@@ -481,28 +495,94 @@ export function installReadAuditWriter(
     );
   };
 
-  let failureReported = false;
+  /**
+   * Report a lost batch of record-view rows — once per CAUSE, not once per
+   * failed flush.
+   *
+   * Same discipline, and the same reason, as `reportAuditWriteFailure` in
+   * `audit-writers.ts` and `reportAuthEventWriteFailure` in
+   * `auth-event-audit.ts`: a systemic cause (the ledger is unreachable from
+   * this connection) would otherwise emit one `error` per flush and train
+   * everyone to skim the channel. That much is unchanged, and ⛔ must stay —
+   * AGENTS.md records the once-per-degradation rule as a deliberate anti-noise
+   * choice and names 「log every failure at `error`」 as its falsifier.
+   *
+   * [#18247] What changed is the COUNTING UNIT, and it changed here for the
+   * THIRD time in this package: this file carried its OWN copy of the
+   * process-wide boolean and its OWN fixed message literal, so neither
+   * #15166's fix to `audit-writers.ts` nor #17452's to `auth-event-audit.ts`
+   * reached it. All three copies had the same two defects.
+   *
+   *  1. One process-wide boolean means the first failure of ANY cause silences
+   *     every later failure of every OTHER cause for the life of the process.
+   *     The rule's unit is a DEGRADATION and a second cause is a second
+   *     degradation, so the key is now the failure's identity —
+   *     {@link auditFailureCauseKey}, imported rather than re-spelled. A repeat
+   *     of an already-reported cause still degrades to `debug`, exactly as
+   *     before; a NEW cause gets its own `error` line, once.
+   *  2. The fixed literal printed the ADR-0057 §3.6 telemetry-datasource
+   *     remedy for every cause, so a fault that had nothing to do with
+   *     datasource routing sent its operator to check something that was
+   *     working. ⛔ The guidance is not deleted and not weakened — it is the
+   *     right remedy for the missing-table cause it was written for, and is now
+   *     printed for exactly that cause, asked through the shared
+   *     `isMissingTableError` predicate.
+   *
+   * ⭐ Why this seam is not merely the third repetition: `persistReadAuditRows`
+   * is registered in `DURABILITY_CRITICAL_CALLEES`
+   * (`scripts/check-durability-degradation-log-level.mjs`), so the repo has
+   * already declared this write durability-critical. A reporter that switches
+   * itself off after one cause is exactly the failure that declaration cannot
+   * afford — the board's green looks identical to a real one.
+   *
+   * ⛔ The key is built from the error's `code`, NEVER its message — see
+   * {@link auditFailureCauseKey} for why that is what keeps the cause set
+   * bounded by boot-declared vocabularies instead of by traffic.
+   */
+  const reportedReadAuditFailureCauses = new Set<string>();
   const reportReadAuditWriteFailure = (count: number, err: unknown): void => {
     const detail = String((err as any)?.message ?? err);
     try {
-      if (failureReported) {
-        logger?.debug?.('Read-audit write failed (already reported)', { count, err: detail });
+      // The object dimension of the shared key is the LEDGER here, not the
+      // object whose record was viewed. ⛔ Not an arbitrary choice between the
+      // two: one flush is ONE write carrying rows about MANY audited objects,
+      // so there is no single viewed object to name — picking whichever landed
+      // first in the batch would make the key depend on traffic, which is the
+      // one property {@link auditFailureCauseKey} exists to deny. The failure
+      // is a property of the write against `sys_audit_log`, so that is the
+      // object named, and the key reduces to the driver's code vocabulary:
+      // bounded by construction, and still the same key shape rather than a
+      // second one. (`audit-writers.ts` passes `ctx.object` and
+      // `auth-event-audit.ts` its constant `sys_session` because on those two
+      // seams the viewed/audited object IS single-valued per write.)
+      const cause = auditFailureCauseKey('sys_audit_log', err);
+      if (reportedReadAuditFailureCauses.has(cause)) {
+        logger?.debug?.('Read-audit write failed (already reported)', { count, err: detail, cause });
         return;
       }
-      failureReported = true;
+      reportedReadAuditFailureCauses.add(cause);
+      // `persistReadAuditRows` writes ONE table, so the missing-table question
+      // is asked about that one — unlike `persistAuditTrailRow`, which writes
+      // the ledger row and its `sys_activity` mirror and asks about both.
+      const missingTable = isMissingTableError(err, 'sys_audit_log');
       const message =
-        `Read-audit write FAILED — ${count} record-view row(s) were LOST and the compliance trail is now ` +
-          'INCOMPLETE. The reads themselves SUCCEEDED and returned 200, so the API, the screens and every ' +
-          'counter read clean; only the `sys_audit_log` rows recording WHO opened those records never landed, ' +
-          'and nothing retries them. Every subsequent batch is likely lost the same way (this is reported ONCE ' +
-          '— raise the log level to `debug` to see the rest). The whole point of this capability is answering ' +
-          '"who viewed this record" for an auditor, so the failure mode is a query that returns a confident, ' +
-          'wrong, SHORT answer. 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. Set `OS_TELEMETRY_DB=0` to keep every lifecycle-classed object on the primary ' +
-          'datasource.';
+        `Read-audit write FAILED (${auditFailureCauseSummary(err, detail)}) — ${count} record-view row(s) ` +
+          'were LOST and the compliance trail is now INCOMPLETE. The reads themselves SUCCEEDED and returned ' +
+          '200, so the API, the screens and every counter read clean; only the `sys_audit_log` rows recording ' +
+          'WHO opened those records never landed, and nothing retries them. Every subsequent batch failing ' +
+          'THIS WAY is lost the same way (this CAUSE is reported ONCE — raise the log level to `debug` to see ' +
+          'the rest; a DIFFERENT cause gets its own `error` line). The whole point of this capability is ' +
+          'answering "who viewed this record" for an auditor, so the failure mode is a query that returns a ' +
+          'confident, wrong, SHORT answer. ' +
+          (missingTable
+            ? '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. Set `OS_TELEMETRY_DB=0` to keep every lifecycle-classed object on the primary ' +
+              'datasource.'
+            : 'Fix: resolve the driver fault quoted at the head of this line on the connection this write ran ' +
+              'on — every batch that hits it loses its rows until it is resolved.');
       // `error` is OPTIONAL on this sink, so `logger?.error?.(…)` printed
       // NOTHING when the host injected one without it — the durability
       // degradation this text describes would then be reported by nobody at