Skip to content

Commit ab48938

Browse files
claude[bot]claude
andauthored
fix(plugin-audit): report a lost audit row once per CAUSE, and name the real cause in the first line (#17450)
* fix(plugin-audit): key the lost-audit-row report per CAUSE, and put the real cause in the first line `reportAuditWriteFailure` deduped on one 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, and the one `error` line it did print named the telemetry-datasource remedy unconditionally — the measured `ERR_SYSTEM_WRITE_ORGANIZATION_REQUIRED` refusal sent its operator to check a datasource that was working. The dedupe key is now the failure's identity — the error `code` (or its absence) plus the object. A repeat of an already-reported cause still degrades to `debug`; a new cause reports at `error`, once. The key is built from the `code` and never the message, which is what keeps the cause set bounded by the boot-declared object registry and the driver's code vocabulary rather than by traffic. The ADR-0057 §3.6 datasource guidance is kept and made conditional on the missing-table cause it is the remedy for, asked through the shared `isMissingTableError` predicate for both tables `persistAuditTrailRow` writes. Claude-Session: https://claude.ai/code/session_01ToDPcx9AESFubJkDiFMtKW Co-authored-by: Claude <noreply@anthropic.com> * chore(changeset): patch for the cause-keyed audit-write failure report Claude-Session: https://claude.ai/code/session_01ToDPcx9AESFubJkDiFMtKW Co-authored-by: Claude <noreply@anthropic.com> * build(plugin-audit): resolve @objectstack/types to source for tsc `pnpm check:type-source-resolution` reds on the new dependency: without a `paths` rule this package's typecheck would be a verdict about `types/dist` build state rather than about the checkout. Same entry, same spelling, same reasoning `plugin-security` records for the identical import. Claude-Session: https://claude.ai/code/session_01ToDPcx9AESFubJkDiFMtKW Co-authored-by: Claude <noreply@anthropic.com> --------- Co-authored-by: Claude <noreply@anthropic.com>
1 parent c4d1759 commit ab48938

6 files changed

Lines changed: 353 additions & 19 deletions

File tree

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,13 @@
1+
---
2+
"@objectstack/plugin-audit": patch
3+
---
4+
5+
A lost audit row is reported once per failure CAUSE, not once per process, and the first line names the cause instead of a fixed remedy.
6+
7+
`reportAuditWriteFailure` — the best-effort catch around `persistAuditTrailRow` — deduped on a single process-wide boolean. After the first failure of any cause, every later failure of every *other* cause degraded to `debug` for the life of the process, so a long-running server could keep losing compliance rows for hours to a second, unrelated fault with one `error` line at the top of the log describing the first. `persistAuditTrailRow` is registered in the durability-degradation vocabulary precisely because a lost audit row must be reported at `error`.
8+
9+
The dedupe key is now the failure's identity — the error `code` (or its absence) together with the object being audited. 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 failed write. Keyed on the code, the reported-cause set is bounded by the boot-declared object registry and the driver's code vocabulary and does not grow with traffic — measured at 65 lines for 6,500 failed writes and the same 65 for 26,000.
10+
11+
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 both tables 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.
12+
13+
`@objectstack/types` is added as a dependency for that predicate, rather than hand-rolling a second driver-error vocabulary.

packages/plugins/plugin-audit/package.json

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,8 @@
2323
"@objectstack/metadata-core": "workspace:*",
2424
"@objectstack/objectql": "workspace:*",
2525
"@objectstack/platform-objects": "workspace:*",
26-
"@objectstack/spec": "workspace:*"
26+
"@objectstack/spec": "workspace:*",
27+
"@objectstack/types": "workspace:*"
2728
},
2829
"devDependencies": {
2930
"@objectstack/driver-sqlite-wasm": "workspace:*",

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

Lines changed: 211 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1195,6 +1195,217 @@ describe('audit writers — a lost audit row is reported at error (#5226)', () =
11951195
});
11961196
});
11971197

1198+
/**
1199+
* [#15166] The dedupe key is the failure's CAUSE, not the process.
1200+
*
1201+
* The block above pins that a lost audit row is reported at `error`, and that
1202+
* it is reported ONCE rather than once per failed write. Both still hold. What
1203+
* this block pins is the COUNTING UNIT of that "once", and the two defects the
1204+
* process-wide version had:
1205+
*
1206+
* 1. after the first failure of ANY cause, every later failure of every OTHER
1207+
* cause degraded to `debug` for the life of the process — a server could
1208+
* keep losing rows for hours to a second fault with one `error` line at the
1209+
* top of the log describing the first;
1210+
* 2. that one line named the telemetry-datasource remedy unconditionally. The
1211+
* cause measured on #14927 was `ERR_SYSTEM_WRITE_ORGANIZATION_REQUIRED` and
1212+
* the text said "datasource" — the operator was sent to check something
1213+
* that was not broken.
1214+
*
1215+
* ⚠️ The anti-noise choice these must not undo is AGENTS.md's, and #4420 is
1216+
* what it was invented against: an unbounded per-write line nobody could read.
1217+
* `keys on the error CODE, never its message` below is the pin that keeps
1218+
* "once per cause" from decaying into it — ⛔ do not relax it to a message.
1219+
*/
1220+
describe('audit writers — reported once per CAUSE, not once per process (#15166)', () => {
1221+
interface LogLine { level: string; message: string; meta?: any }
1222+
1223+
/** Engine whose `sys_audit_log` insert fails with a caller-chosen error each time. */
1224+
function makeCauseEngine(nextError: (object: string, n: number) => unknown) {
1225+
const hooks = new Map<string, Array<(ctx: any) => any>>();
1226+
const logs: LogLine[] = [];
1227+
let n = 0;
1228+
const sudoApi = {
1229+
object(name: string) {
1230+
return {
1231+
async create(row: Record<string, any>) {
1232+
if (name === 'sys_audit_log') throw nextError(String(row.object_name), n++);
1233+
return { id: 'generated-id' };
1234+
},
1235+
};
1236+
},
1237+
};
1238+
const api = { sudo: () => sudoApi };
1239+
const engine = {
1240+
getSchema(name: string) {
1241+
const fields = (SINGLE_TENANT as Record<string, string[]>)[name];
1242+
if (fields) return { name, fields: Object.fromEntries(fields.map((f) => [f, { type: 'text' }])) };
1243+
return { name, fields: { id: { type: 'text' }, name: { type: 'text' } } };
1244+
},
1245+
registerHook(event: string, fn: (ctx: any) => any) {
1246+
const list = hooks.get(event) ?? [];
1247+
list.push(fn);
1248+
hooks.set(event, list);
1249+
},
1250+
unregisterHooksByPackage() { /* no-op */ },
1251+
logger: {
1252+
error(message: string, _err?: unknown, meta?: any) { logs.push({ level: 'error', message, meta }); },
1253+
warn(message: string, meta?: any) { logs.push({ level: 'warn', message, meta }); },
1254+
debug(message: string, meta?: any) { logs.push({ level: 'debug', message, meta }); },
1255+
info() { /* unused */ },
1256+
},
1257+
};
1258+
installAuditWriters(engine as any, 'test.audit');
1259+
const fire = async (object: string, id: string) => {
1260+
for (const fn of hooks.get('afterInsert') ?? []) {
1261+
await fn({
1262+
event: 'afterInsert',
1263+
api,
1264+
object,
1265+
input: { id },
1266+
result: { id, name: 'Acme' },
1267+
session: { organizationId: 'org-1', userId: 'user-1' },
1268+
});
1269+
}
1270+
};
1271+
const at = (level: string) => logs.filter((l) => l.level === level);
1272+
return { fire, at, logs };
1273+
}
1274+
1275+
const driverError = (message: string, code?: string): Error => {
1276+
const e = new Error(message) as Error & { code?: string };
1277+
if (code !== undefined) e.code = code;
1278+
return e;
1279+
};
1280+
1281+
const NO_SUCH_TABLE = () => driverError('no such table: sys_audit_log', 'SQLITE_ERROR');
1282+
const ORG_REQUIRED = () =>
1283+
driverError('system write requires an organization', 'ERR_SYSTEM_WRITE_ORGANIZATION_REQUIRED');
1284+
1285+
it('reports a SECOND, DIFFERENT cause at error — a new cause is a new degradation', async () => {
1286+
// THE DEFECT. On the process-wide key this was one `error` (the first
1287+
// cause) and one `debug`; the organization refusal — a completely
1288+
// different fault, with a different remedy — was never reported at all.
1289+
let phase = 0;
1290+
const { fire, at } = makeCauseEngine(() => (phase === 0 ? NO_SUCH_TABLE() : ORG_REQUIRED()));
1291+
1292+
await fire('crm_lead', 'l-1');
1293+
phase = 1;
1294+
await fire('crm_lead', 'l-2');
1295+
1296+
const errors = at('error');
1297+
expect(errors).toHaveLength(2);
1298+
expect(errors[0].message).toMatch(/no such table: sys_audit_log/);
1299+
expect(errors[1].message).toMatch(/ERR_SYSTEM_WRITE_ORGANIZATION_REQUIRED/);
1300+
expect(at('debug')).toHaveLength(0);
1301+
expect(at('warn')).toEqual([]);
1302+
});
1303+
1304+
it('still degrades a REPEAT of an already-reported cause to debug', async () => {
1305+
// Unchanged from the process-wide version, and the half that must not
1306+
// regress: the same cause on the same object says it once.
1307+
const { fire, at } = makeCauseEngine(() => NO_SUCH_TABLE());
1308+
1309+
for (const id of ['l-1', 'l-2', 'l-3', 'l-4', 'l-5']) await fire('crm_lead', id);
1310+
1311+
expect(at('error')).toHaveLength(1);
1312+
expect(at('debug')).toHaveLength(4);
1313+
// The repeats name the cause they were folded into, so a `debug` sweep can
1314+
// tell "the same fault, 4 more times" from "four different faults".
1315+
expect(at('debug')[0].meta?.cause).toBe(at('debug')[3].meta?.cause);
1316+
});
1317+
1318+
it('keys on the error CODE, never its message, so a per-row fault cannot flood `error`', async () => {
1319+
// ⚠️ THE ANTI-NOISE PIN (AGENTS.md; #4420). A driver names the offending
1320+
// ROW in its message, so a message-keyed dedupe would grow one `error`
1321+
// line per failed write — #4420 again, wearing the word "cause". 200
1322+
// writes, 200 distinct messages, ONE code ⇒ one line.
1323+
const WRITES = 200;
1324+
const { fire, at } = makeCauseEngine((_object, i) =>
1325+
driverError(`UNIQUE constraint failed: sys_audit_log.id (row aud_${i})`, 'SQLITE_CONSTRAINT_UNIQUE'));
1326+
1327+
for (let i = 0; i < WRITES; i += 1) await fire('crm_lead', `l-${i}`);
1328+
1329+
expect(at('error')).toHaveLength(1);
1330+
expect(at('debug')).toHaveLength(WRITES - 1);
1331+
});
1332+
1333+
it('folds a fault carrying NO code into ONE bucket rather than growing one', async () => {
1334+
// The other half of the bound: "the code, or its ABSENCE" is a single key
1335+
// value, so an uncoded driver — the shape with nothing bounded to key on —
1336+
// still says it once instead of once per write.
1337+
const WRITES = 200;
1338+
const { fire, at } = makeCauseEngine((_object, i) => driverError(`insert failed for record aud_${i}`));
1339+
1340+
for (let i = 0; i < WRITES; i += 1) await fire('crm_lead', `l-${i}`);
1341+
1342+
expect(at('error')).toHaveLength(1);
1343+
expect(at('debug')).toHaveLength(WRITES - 1);
1344+
});
1345+
1346+
it('carries the underlying code and message in the first line it prints', async () => {
1347+
// The information was computed one line above the branch and dropped on the
1348+
// floor: the `error` path built a fixed string and never read `err`.
1349+
const { fire, at } = makeCauseEngine(() => ORG_REQUIRED());
1350+
1351+
await fire('crm_lead', 'l-1');
1352+
1353+
const msg = at('error')[0].message;
1354+
expect(msg).toMatch(/ERR_SYSTEM_WRITE_ORGANIZATION_REQUIRED/);
1355+
expect(msg).toMatch(/system write requires an organization/);
1356+
// The consequence half is unchanged — it is still owed, and still first.
1357+
expect(msg).toMatch(/compliance trail is now INCOMPLETE/);
1358+
});
1359+
1360+
it('prints the datasource remedy for the cause it is the remedy FOR, and not for others', async () => {
1361+
// ⛔ Not a deletion: the ADR-0057 §3.6 routing text is genuinely correct for
1362+
// the "no such table" cause it was written for, so it must still print
1363+
// there. What is fixed is that it used to print for EVERY cause.
1364+
const missing = makeCauseEngine(() => NO_SUCH_TABLE());
1365+
await missing.fire('crm_lead', 'l-1');
1366+
const forMissingTable = missing.at('error')[0].message;
1367+
expect(forMissingTable).toMatch(/telemetry/);
1368+
expect(forMissingTable).toMatch(/OS_TELEMETRY_DB=0/);
1369+
1370+
// The measured #14927 misdirection: the cause was an organization refusal
1371+
// and the text said "datasource".
1372+
const refused = makeCauseEngine(() => ORG_REQUIRED());
1373+
await refused.fire('crm_lead', 'l-1');
1374+
const forRefusal = refused.at('error')[0].message;
1375+
expect(forRefusal).not.toMatch(/OS_TELEMETRY_DB/);
1376+
expect(forRefusal).not.toMatch(/telemetry/i);
1377+
// It still owes a fix — it just owes the RIGHT one.
1378+
expect(forRefusal).toMatch(/Fix:/);
1379+
});
1380+
1381+
it('asks the missing-table question about `sys_activity` too — the same writer writes both', async () => {
1382+
// `persistAuditTrailRow` writes the ledger row AND its activity mirror, and
1383+
// ADR-0057 §3.6 routes both, so the datasource remedy is the remedy for
1384+
// either table going missing.
1385+
const { fire, at } = makeCauseEngine(() =>
1386+
driverError('no such table: sys_activity', 'SQLITE_ERROR'));
1387+
1388+
await fire('crm_lead', 'l-1');
1389+
1390+
expect(at('error')[0].message).toMatch(/OS_TELEMETRY_DB=0/);
1391+
});
1392+
1393+
it('separates causes per OBJECT as well as per code, and stays bounded by both', async () => {
1394+
// The key is (object, code). Two objects failing the same way are two
1395+
// lines — that is the ruling's granularity — and the count is bounded by
1396+
// the DECLARED object set, never by traffic: 3 objects x 40 writes each,
1397+
// all with distinct per-row messages, is still 3 lines.
1398+
const objects = ['crm_lead', 'crm_account', 'crm_contact'];
1399+
const { fire, at } = makeCauseEngine((object, i) =>
1400+
driverError(`insert failed for ${object} record aud_${i}`, 'SQLITE_CONSTRAINT_UNIQUE'));
1401+
1402+
for (const object of objects) for (let i = 0; i < 40; i += 1) await fire(object, `r-${i}`);
1403+
1404+
expect(at('error')).toHaveLength(objects.length);
1405+
expect(at('debug')).toHaveLength(objects.length * 40 - objects.length);
1406+
});
1407+
});
1408+
11981409
/**
11991410
* [#8707] Which organization an audit row is stamped with — the RECORD'S own,
12001411
* honouring the maintainer's ruling on #8287.

0 commit comments

Comments
 (0)