From 6195b0000124648378e738018ae74704acde21ed Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 17 Sep 2026 06:50:41 +0000 Subject: [PATCH] fix(plugin-audit): read-audit reports once per CAUSE, not once per process MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `reportReadAuditWriteFailure` 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`, on a seam already registered in `DURABILITY_CRITICAL_CALLEES`. The dedupe key is now `auditFailureCauseKey`, imported rather than re-spelled (a second copy of the key is how this defect reached the second file), and the ADR-0057 §3.6 / `OS_TELEMETRY_DB` guidance is printed for the missing-table cause it is the remedy for, asked through the shared `isMissingTableError` predicate. Claude-Session: https://claude.ai/code/session_01WmBwEiWPff9JZPd5BSGNeH Co-authored-by: Claude --- ...7-read-audit-failure-reported-per-cause.md | 16 ++ .../plugin-audit/src/read-audit.test.ts | 192 ++++++++++++++++++ .../plugins/plugin-audit/src/read-audit.ts | 114 +++++++++-- 3 files changed, 305 insertions(+), 17 deletions(-) create mode 100644 .changeset/18247-read-audit-failure-reported-per-cause.md diff --git a/.changeset/18247-read-audit-failure-reported-per-cause.md b/.changeset/18247-read-audit-failure-reported-per-cause.md new file mode 100644 index 00000000000..e3f3cfd5b4a --- /dev/null +++ b/.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 diff --git a/packages/plugins/plugin-audit/src/read-audit.test.ts b/packages/plugins/plugin-audit/src/read-audit.test.ts index fa33e6a6e6e..c1ec449ab61 100644 --- a/packages/plugins/plugin-audit/src/read-audit.test.ts +++ b/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; + } + + 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; 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 = { + warn(message: string, meta?: Record) { + logs.push({ level: 'warn', message, meta }); + }, + debug(message: string, meta?: Record) { + logs.push({ level: 'debug', message, meta }); + }, + }; + if (!omitError) { + logger.error = (message: string, _err?: Error, meta?: Record) => { + 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 => { + 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([]); + }); +}); diff --git a/packages/plugins/plugin-audit/src/read-audit.ts b/packages/plugins/plugin-audit/src/read-audit.ts index f202954dad8..ae1e1b9a217 100644 --- a/packages/plugins/plugin-audit/src/read-audit.ts +++ b/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(); 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