diff --git a/.changeset/auth-event-audit-cause-keyed-report.md b/.changeset/auth-event-audit-cause-keyed-report.md new file mode 100644 index 00000000000..e59dd303ca4 --- /dev/null +++ b/.changeset/auth-event-audit-cause-keyed-report.md @@ -0,0 +1,13 @@ +--- +"@objectstack/plugin-audit": patch +--- + +A lost auth-event row is reported once per failure CAUSE, not once per process, and the first line names the cause instead of a fixed remedy. + +`auth-event-audit.ts` — the writer behind the `login` / `logout` rows in `sys_audit_log` — carried its own, independent copy of both defects the record-level audit writer was fixed for. `reportAuthEventWriteFailure` deduped on a single process-wide boolean, so after the first failure of any cause, every later failure of every *other* cause degraded to `debug` for the life of the process: a long-running server could keep losing sign-in and sign-out rows for hours to a second, unrelated fault, with one `error` line at the top of the log describing the first. `persistAuthEventAuditRow` is registered in the durability-degradation vocabulary precisely because a lost audit row must be reported at `error`. + +The dedupe key is now the failure's identity — the error `code` (or its absence) together with the object the rows are about. A repeat of an already-reported cause still degrades to `debug`, exactly as before; a new cause reports at `error`, once. The key is built from the `code` and **never** the message: a driver names the offending row in its message, so a message-keyed dedupe would grow one `error` line per lost row. Keyed on the code, the reported-cause set is bounded by the driver's code vocabulary and does not grow with traffic — measured at one `error` line for 200 failed sign-ins carrying 200 distinct messages under one code, and the same one line for 200 carrying no code at all. + +The first `error` line now leads with the underlying code and message, which were already computed at the call site and passed only into the `debug` payload. The ADR-0057 §3.6 telemetry-datasource guidance is kept — it is the correct remedy for the "no such table" cause it was written for — but is now printed only for that cause, decided by the shared `isMissingTableError` predicate for the one table this writer writes. Previously it was printed unconditionally, so an organization refusal was answered with "check the datasource", sending the operator to inspect something that was working. + +The cause-key helpers are imported from the record-level writer in this same package rather than re-spelled here: a second copy of that key is how these defects reached this file, so a third spelling would repeat the mistake. No published export is added or changed. diff --git a/packages/plugins/plugin-audit/src/audit-writers.ts b/packages/plugins/plugin-audit/src/audit-writers.ts index 379e7067ca0..37e6bf2a895 100644 --- a/packages/plugins/plugin-audit/src/audit-writers.ts +++ b/packages/plugins/plugin-audit/src/audit-writers.ts @@ -726,8 +726,17 @@ function renderMilestoneSummary( * A code that is absent, or is not a scalar, collapses to ONE bucket rather * than growing one: an uncoded fault is "the uncoded fault on this object", and * a thousand of them is still one `error` line. + * + * ⚠️ [#17452] EXPORTED, for `auth-event-audit.ts`. That file carried a second, + * independent copy of the process-wide boolean this key replaced, and it now + * imports this one instead of re-spelling it — a second copy of the key is + * precisely how the defect reached that file, so a third spelling would be the + * same mistake again. Same seam as its `createFieldPresenceProbe` import. + * ⛔ Deliberately NOT re-exported from the package barrel: the sharing is + * internal to `@objectstack/plugin-audit` and the published surface is + * unchanged by it. */ -function auditFailureCauseKey(object: string, err: unknown): string { +export function auditFailureCauseKey(object: string, err: unknown): string { const code = (err as { code?: unknown } | null | undefined)?.code; const bounded = typeof code === 'string' || typeof code === 'number' ? String(code) : '(no code)'; // JSON rather than a separator character: an object name and a driver code @@ -743,8 +752,11 @@ function auditFailureCauseKey(object: string, err: unknown): string { * the line printed a fixed remedy and never looked at `err`. The code is what * makes two failures the same failure (see {@link auditFailureCauseKey}), so it * leads; the message is what makes this one legible. + * + * ⚠️ [#17452] Exported alongside {@link auditFailureCauseKey} and for the same + * reason — the two are one shape, and the auth-event sink needs both halves. */ -function auditFailureCauseSummary(err: unknown, detail: string): string { +export function auditFailureCauseSummary(err: unknown, detail: string): string { const code = (err as { code?: unknown } | null | undefined)?.code; return typeof code === 'string' || typeof code === 'number' ? `${String(code)}: ${detail}` : detail; } diff --git a/packages/plugins/plugin-audit/src/auth-event-audit.test.ts b/packages/plugins/plugin-audit/src/auth-event-audit.test.ts index aed06adc65d..4677f5caa1a 100644 --- a/packages/plugins/plugin-audit/src/auth-event-audit.test.ts +++ b/packages/plugins/plugin-audit/src/auth-event-audit.test.ts @@ -350,3 +350,203 @@ describe('[#8144] createAuthEventAuditSink writes a login row that names its act expect(meta).toMatchObject({ action: 'login' }); }); }); + +/** + * [#17452] The dedupe key is the failure's CAUSE, not the process. + * + * The block above pins that a lost auth-event row is reported at `error`, and + * that it is reported ONCE rather than once per failed sign-in. Both still + * hold. What this block pins is the COUNTING UNIT of that "once", and the two + * defects the process-wide version had — the SECOND, independent copy of the + * pair `audit-writers.ts` carried before #15166: + * + * 1. after the first failure of ANY cause, every later failure of every OTHER + * cause degraded to `debug` for the life of the process — a server could + * keep losing sign-in rows for hours to a second fault with one `error` + * line at the top of the log describing the first; + * 2. that one line named the ADR-0057 §3.6 telemetry-datasource remedy + * unconditionally, so a refusal that had nothing to do with datasource + * routing sent its operator to check something that was not broken. + * + * ⚠️ The anti-noise choice these must not undo is AGENTS.md's, and #4420 is + * what it was invented against: an unbounded per-event line nobody could read. + * `keys on the error CODE, never its message` below is the pin that keeps + * "once per cause" from decaying into it — ⛔ do not relax it to a message. + * + * The helpers are `audit-writers.ts`'s, imported rather than re-spelled: a + * second copy of this key is how the defect got here in the first place. + */ +describe('auth-event audit — reported once per CAUSE, not once per process (#17452)', () => { + interface LogLine { + level: string; + message: string; + meta?: Record; + } + + /** A sink whose ledger insert fails with a caller-chosen error each time. */ + function makeCauseSink(nextError: (n: number) => unknown) { + const logs: LogLine[] = []; + let n = 0; + const broken: any = { + getSchema: () => null, + insert: async () => { + throw nextError(n++); + }, + }; + const logger = { + error(message: string, _err?: Error, meta?: Record) { + logs.push({ level: 'error', message, meta }); + }, + warn(message: string, meta?: Record) { + logs.push({ level: 'warn', message, meta }); + }, + debug(message: string, meta?: Record) { + logs.push({ level: 'debug', message, meta }); + }, + }; + const sink = createAuthEventAuditSink({ getEngine: () => broken, logger }); + const signIn = (id: string) => sink.recordAuthEvent({ action: 'login', userId: id, sessionId: id }); + const at = (level: string) => logs.filter((l) => l.level === level); + return { sink, signIn, at, logs }; + } + + 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'); + + it('reports a SECOND, DIFFERENT cause at error — a new cause is a new degradation', async () => { + // THE DEFECT. On the process-wide boolean this was one `error` (the first + // cause) and one `debug`; the organization refusal — a completely + // different fault, with a different remedy — was never reported at all. + let phase = 0; + const { signIn, at } = makeCauseSink(() => (phase === 0 ? NO_SUCH_TABLE() : ORG_REQUIRED())); + + await signIn('usr_1'); + phase = 1; + await signIn('usr_2'); + + 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 object still says it once. + const { signIn, at } = makeCauseSink(() => NO_SUCH_TABLE()); + + for (const id of ['usr_1', 'usr_2', 'usr_3', 'usr_4', 'usr_5']) await signIn(id); + + 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 sign-in row — #4420 again, wearing the word "cause". 200 + // sign-ins, 200 distinct messages, ONE code ⇒ one line. + const EVENTS = 200; + const { signIn, at } = makeCauseSink((i) => + driverError(`UNIQUE constraint failed: sys_audit_log.id (row aud_${i})`, 'SQLITE_CONSTRAINT_UNIQUE'), + ); + + for (let i = 0; i < EVENTS; i += 1) await signIn(`usr_${i}`); + + expect(at('error')).toHaveLength(1); + expect(at('debug')).toHaveLength(EVENTS - 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 sign-in. + const EVENTS = 200; + const { signIn, at } = makeCauseSink((i) => driverError(`insert failed for record aud_${i}`)); + + for (let i = 0; i < EVENTS; i += 1) await signIn(`usr_${i}`); + + expect(at('error')).toHaveLength(1); + expect(at('debug')).toHaveLength(EVENTS - 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 { signIn, at } = makeCauseSink(() => ORG_REQUIRED()); + + await signIn('usr_1'); + + 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/); + }); + + 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 = makeCauseSink(() => NO_SUCH_TABLE()); + await missing.signIn('usr_1'); + 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 said + // "datasource". + const refused = makeCauseSink(() => ORG_REQUIRED()); + await refused.signIn('usr_1'); + 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 () => { + // `AuthEventAuditLogger.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. + const logs: Array<{ level: string; message: string }> = []; + let phase = 0; + const broken: any = { + getSchema: () => null, + insert: async () => { + throw phase === 0 ? NO_SUCH_TABLE() : ORG_REQUIRED(); + }, + }; + const logger = { + warn(message: string) { + logs.push({ level: 'warn', message }); + }, + debug(message: string) { + logs.push({ level: 'debug', message }); + }, + }; + const sink = createAuthEventAuditSink({ getEngine: () => broken, logger }); + + await sink.recordAuthEvent({ action: 'login', userId: 'usr_1' }); + phase = 1; + await sink.recordAuthEvent({ action: 'logout', userId: 'usr_1' }); + + const warns = logs.filter((l) => l.level === 'warn'); + expect(warns).toHaveLength(2); + expect(warns[1].message).toMatch(/ERR_SYSTEM_WRITE_ORGANIZATION_REQUIRED/); + }); +}); diff --git a/packages/plugins/plugin-audit/src/auth-event-audit.ts b/packages/plugins/plugin-audit/src/auth-event-audit.ts index 01f65820ed8..ba07853195c 100644 --- a/packages/plugins/plugin-audit/src/auth-event-audit.ts +++ b/packages/plugins/plugin-audit/src/auth-event-audit.ts @@ -62,7 +62,12 @@ */ import type { IDataEngine } from '@objectstack/spec/contracts'; -import { createFieldPresenceProbe } from './audit-writers.js'; +import { isMissingTableError } from '@objectstack/types'; +import { + auditFailureCauseKey, + auditFailureCauseSummary, + createFieldPresenceProbe, +} from './audit-writers.js'; /** The two auth session events the ledger records (`sys_audit_log.action`). */ export type AuthSessionAuditAction = 'login' | 'logout'; @@ -170,34 +175,79 @@ export function createAuthEventAuditSink(opts: AuthEventAuditSinkOptions): AuthE let probedEngine: IDataEngine | undefined; /** - * Report a lost auth-event row — once per process, not once per failure. + * Report a lost auth-event row — once per CAUSE, not once per failed write. * * Same discipline, and the same reason, as `reportAuditWriteFailure` in * `audit-writers.ts`: a systemic cause (the table is unreachable from this * connection) would otherwise emit one `error` per sign-in and train everyone - * to skim the channel. + * 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. + * + * [#17452] What changed is the COUNTING UNIT, and it changed here for the + * second time in this package: this file carried its OWN copy of the + * process-wide boolean and its OWN fixed message literal, so #15166's fix to + * `audit-writers.ts` did not reach it. Both 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. + * + * ⛔ 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. */ - let failureReported = false; + const reportedAuthEventFailureCauses = new Set(); const reportAuthEventWriteFailure = (action: string, err: unknown): void => { const detail = String((err as any)?.message ?? err); try { - if (failureReported) { - logger?.debug?.('Auth-event audit write failed (already reported)', { action, err: detail }); + // The object dimension of the shared key is `sys_session` here — the + // object these rows are ABOUT (`object_name`), which is what + // `audit-writers.ts` passes too (`ctx.object`). It is constant on this + // seam, so the key reduces to the driver's code vocabulary: bounded by + // construction, and still the same key shape rather than a second one. + const cause = auditFailureCauseKey(SESSION_OBJECT, err); + if (reportedAuthEventFailureCauses.has(cause)) { + logger?.debug?.('Auth-event audit write failed (already reported)', { + action, + err: detail, + cause, + }); return; } - failureReported = true; + reportedAuthEventFailureCauses.add(cause); + // `persistAuthEventAuditRow` 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 = - 'Auth-event audit write FAILED — the compliance trail is now INCOMPLETE. The sign-in/sign-out itself ' + - 'SUCCEEDED and the user holds a valid session, so the API returned 200 and nothing downstream looks ' + - `broken; only the \`sys_audit_log\` row recording the ${action} never landed, and nothing retries it. ` + - 'Every subsequent auth event is likely losing its row the same way (this is reported ONCE — raise the ' + - 'log level to `debug` to see the rest). The shipped `auth_events` list view and the system-overview ' + - 'widgets read exactly these rows, so they will keep showing an empty, healthy-looking screen. ' + - '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.'; + `Auth-event audit write FAILED (${auditFailureCauseSummary(err, detail)}) — the compliance trail is ` + + 'now INCOMPLETE. The sign-in/sign-out itself SUCCEEDED and the user holds a valid session, so the API ' + + 'returned 200 and nothing downstream looks broken; only the `sys_audit_log` row recording the ' + + `${action} never landed, and nothing retries it. Every subsequent auth event failing THIS WAY is ` + + 'losing its row 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 shipped `auth_events` list view and the ' + + 'system-overview widgets read exactly these rows, so they will keep showing an empty, healthy-looking ' + + 'screen. ' + + (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 auth event that hits it loses its row 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