From bafcec30edbc74252fa9b09eb81908b242608a95 Mon Sep 17 00:00:00 2001 From: os-steve Date: Tue, 18 Aug 2026 16:05:18 +0000 Subject: [PATCH 1/4] fix(devx): the durability log-level matcher reads the callee, and stops accepting a spelling that prints nothing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `loggerLevel()` required the callee to be a plain property access, so `(logger.error ?? logger.warn)(...)` — a call on a parenthesized expression — collected no levels and the catch was reported as `catch swallows the failure with no log at all`, the harshest verdict in the file, on code that is loud at runtime. The dangerous half was the repair that report invited. The one fallback spelling the matcher DID accept is `logger.error?.(...)`, which prints nothing at all against a sink that has no `error` — and `error` is declared optional on exactly the sinks that use the idiom. So the gate's cheapest satisfaction converted a loud degradation into a silent one. - resolve the callee structurally: parentheses, `??`/`||`, a ternary, `.call`/`.apply`/`.bind`, non-null assertions, `logger['error']`, and a same-file `const` holding a fallback are followed to whatever they end at. - an optional CALL (`?.(`) no longer counts as loud: it is the author's own statement that the call may not print, and the sink it holds still has `warn`. Optionality on the RECEIVER (`logger?.error(...)`) is deliberately not judged. - "I could not read this call" is its own verdict, `unreadable-report`, instead of being folded into `silent-swallow`. - six seams the tightened rule found — plugin-audit x3, plugin-email, plugin-security x2, all on sinks whose `error` is declared optional — now reach for `error` and fall back to `warn` instead of to silence. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01XqDQYVU5smx29ts9pAErja --- .../plugins/plugin-audit/src/audit-writers.ts | 16 +- .../plugin-audit/src/auth-event-audit.ts | 16 +- .../plugins/plugin-audit/src/read-audit.ts | 16 +- .../plugins/plugin-email/src/outbox-sweep.ts | 10 +- .../src/permission-set-projection.ts | 26 +- ...check-durability-degradation-log-level.mjs | 666 ++++++++++++++++-- 6 files changed, 675 insertions(+), 75 deletions(-) diff --git a/packages/plugins/plugin-audit/src/audit-writers.ts b/packages/plugins/plugin-audit/src/audit-writers.ts index 49caa20103..bc7d03792a 100644 --- a/packages/plugins/plugin-audit/src/audit-writers.ts +++ b/packages/plugins/plugin-audit/src/audit-writers.ts @@ -881,7 +881,7 @@ export function installAuditWriters( auditFailureReported = true; // The two things an `error` here owes, both in the first line it prints: // the CONSEQUENCE, concretely, and the FIX. - logger?.error?.( + const message = '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 ' + @@ -890,10 +890,16 @@ export function installAuditWriters( "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 }, - ); + 'Set `OS_TELEMETRY_DB=0` to keep every lifecycle-classed object on the primary datasource.'; + // `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 + // all (#9657). Reach for `error`, fall back to `warn`, never to silence. + if (logger?.error) { + logger.error(message, err instanceof Error ? err : new Error(detail), { object, action }); + } else { + logger?.warn?.(message, { object, action, err: detail }); + } } catch { /* logging must never break the audited write */ } diff --git a/packages/plugins/plugin-audit/src/auth-event-audit.ts b/packages/plugins/plugin-audit/src/auth-event-audit.ts index be215bd654..4006caf81d 100644 --- a/packages/plugins/plugin-audit/src/auth-event-audit.ts +++ b/packages/plugins/plugin-audit/src/auth-event-audit.ts @@ -172,7 +172,7 @@ export function createAuthEventAuditSink(opts: AuthEventAuditSinkOptions): AuthE return; } failureReported = true; - logger?.error?.( + 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. ` + @@ -183,10 +183,16 @@ export function createAuthEventAuditSink(opts: AuthEventAuditSinkOptions): AuthE '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.', - err instanceof Error ? err : new Error(detail), - { action }, - ); + 'to keep every lifecycle-classed object on the primary datasource.'; + // `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 + // all (#9657). Reach for `error`, fall back to `warn`, never to silence. + if (logger?.error) { + logger.error(message, err instanceof Error ? err : new Error(detail), { action }); + } else { + logger?.warn?.(message, { action, err: detail }); + } } catch { /* logging must never break the auth response */ } diff --git a/packages/plugins/plugin-audit/src/read-audit.ts b/packages/plugins/plugin-audit/src/read-audit.ts index 7ce03450e8..c3e12d333e 100644 --- a/packages/plugins/plugin-audit/src/read-audit.ts +++ b/packages/plugins/plugin-audit/src/read-audit.ts @@ -461,7 +461,7 @@ export function installReadAuditWriter( return; } failureReported = true; - logger?.error?.( + 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, ' + @@ -473,10 +473,16 @@ export function installReadAuditWriter( '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.', - err instanceof Error ? err : new Error(detail), - { count }, - ); + 'datasource.'; + // `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 + // all (#9657). Reach for `error`, fall back to `warn`, never to silence. + if (logger?.error) { + logger.error(message, err instanceof Error ? err : new Error(detail), { count }); + } else { + logger?.warn?.(message, { count, err: detail }); + } } catch { /* logging must never break the read */ } diff --git a/packages/plugins/plugin-email/src/outbox-sweep.ts b/packages/plugins/plugin-email/src/outbox-sweep.ts index 56998acb12..3c27031551 100644 --- a/packages/plugins/plugin-email/src/outbox-sweep.ts +++ b/packages/plugins/plugin-email/src/outbox-sweep.ts @@ -199,13 +199,17 @@ export async function sweepStrandedOutbox( result.failed++; if (!rowErrorReported) { rowErrorReported = true; - logger?.error?.( + const message = `EmailServicePlugin: outbox sweep could not advance sys_email row '${rowId}' — that message stays ` + 'at `queued`, undelivered, and nothing will look at it again until the next restart, while the ' + 'server keeps reporting healthy. Fix: the cause below comes from the datasource or the queue, ' + 'not from the message itself (a message that cannot be sent is recorded as `failed` on its own ' - + `row); restore that dependency and restart to re-sweep. Cause: ${err?.message ?? err}`, - ); + + `row); restore that dependency and restart to re-sweep. Cause: ${err?.message ?? err}`; + // `SweepLogger.error` is OPTIONAL, so `logger?.error?.(…)` printed + // NOTHING against a sink that has only `warn` — the stranded row would + // then be reported by nobody (#9657). Fall back to `warn`, not silence. + if (logger?.error) logger.error(message); + else logger?.warn?.(message); } } } diff --git a/packages/plugins/plugin-security/src/permission-set-projection.ts b/packages/plugins/plugin-security/src/permission-set-projection.ts index 3ce8c32639..31568f83d2 100644 --- a/packages/plugins/plugin-security/src/permission-set-projection.ts +++ b/packages/plugins/plugin-security/src/permission-set-projection.ts @@ -800,14 +800,17 @@ export function createPermissionSetWriteThrough( // definition never returned to the metadata store — the stores // disagree silently until someone notices the set behaves like a // legacy data-door row. - logger?.error?.( + const message = '[security] restored permission set was NOT re-authored into metadata (ADR-0094 D3) — the record is ' + 'back and looks healthy, but the metadata store has no definition for it, so a metadata-driven ' + 're-provision will not recreate it. Fix: make the record body spec-valid (the error names the ' + - 'offending key) and re-save the set through Setup, or re-run boot reconciliation.', - e as Error, - { name: row.name }, - ); + 'offending key) and re-save the set through Setup, or re-run boot reconciliation.'; + // `ProjectionLogger.error` is OPTIONAL, so `logger?.error?.(…)` printed + // NOTHING against a sink that has only `warn` — the durability + // degradation described above would then be reported by nobody at all + // (#9657). Reach for `error`, fall back to `warn`, never to silence. + if (logger?.error) logger.error(message, e as Error, { name: row.name }); + else logger?.warn?.(message, { name: row.name, error: String((e as Error)?.message ?? e) }); } } return; @@ -1023,7 +1026,7 @@ export async function reconcilePermissionSetProjection( // the summary line below. #4669: this was a `warn` with no counter, // which is why a 100%-failing backfill sat green for a release. if (out.backfillFailed === 1) { - logger?.error?.( + const message = '[security] permission-set backfill into metadata FAILED (ADR-0094 D4) — this environment has ' + '`sys_permission_set` records with NO metadata definition backing them, and the one-time backfill ' + 'did not write one. Nothing will look broken: the records still list in Setup and the evaluator ' + @@ -1032,10 +1035,13 @@ export async function reconcilePermissionSetProjection( 'of them, and every boot retries and fails identically. Fix: make the record body spec-valid — the ' + 'error below names the offending key; `permissionSetBodyFromRow()` already drops storage columns ' + '(`active`, timestamps, provenance), so a rejection here means the stored facet JSON itself is ' + - 'off-contract — then reboot to re-run reconciliation, or delete the orphan record.', - e as Error, - { name: row.name }, - ); + 'off-contract — then reboot to re-run reconciliation, or delete the orphan record.'; + // `ProjectionLogger.error` is OPTIONAL, so `logger?.error?.(…)` printed + // NOTHING against a sink that has only `warn` — the durability + // degradation described above would then be reported by nobody at all + // (#9657). Reach for `error`, fall back to `warn`, never to silence. + if (logger?.error) logger.error(message, e as Error, { name: row.name }); + else logger?.warn?.(message, { name: row.name, error: String((e as Error)?.message ?? e) }); } } } else if (recordDiffersFromBody(row, effective)) { diff --git a/scripts/check-durability-degradation-log-level.mjs b/scripts/check-durability-degradation-log-level.mjs index 281cbe933e..df0711e264 100644 --- a/scripts/check-durability-degradation-log-level.mjs +++ b/scripts/check-durability-degradation-log-level.mjs @@ -850,31 +850,238 @@ function calleeName(node) { return undefined; } +/** The receiver names that make a `.(…)` call a LOG. */ +const LOGGER_RECEIVERS = /^(logger|log|console)$/i; + +/** Every level name the two vocabularies above know. */ +const ALL_LEVELS = new Set([...LOUD_LEVELS, ...QUIET_LEVELS]); + /** - * `x.logger.warn(...)` / `logger.warn(...)` / `this.log.error(...)` / - * `console.error(...)` → 'warn' | 'error' | … - * - * Matched on the SHAPE `.(…)`, so a renamed local - * (`const log = ctx.logger`) is still seen. `console` counts because - * `console.error` is every bit as loud as `logger.error` — measuring the gate - * against the repo turned up a real site (`metadata/src/loaders/ - * database-loader.ts` history-schema sync) that reports honestly via `console`, - * and flagging it would have been a false positive. + * How far a callee is resolved through parentheses / fallbacks / `const` + * aliases before the resolver gives up and says so. The deepest real chain in + * the repo is 3 (`(a.error?.bind(a) ?? a.warn.bind(a))` behind a `const`), so + * this is that plus headroom; a chain longer than this is reported as + * UNREADABLE rather than as silence, which is the safe direction (see below). */ -function loggerLevel(node) { - if (!ts.isCallExpression(node)) return undefined; - const expr = node.expression; - if (!ts.isPropertyAccessExpression(expr) || !ts.isIdentifier(expr.name)) return undefined; - const level = expr.name.text; - if (!LOUD_LEVELS.has(level) && !QUIET_LEVELS.has(level)) return undefined; - const receiver = expr.expression; - let receiverName; - if (ts.isIdentifier(receiver)) receiverName = receiver.text; - else if (ts.isPropertyAccessExpression(receiver) && ts.isIdentifier(receiver.name)) { - receiverName = receiver.name.text; +const MAX_CALLEE_RESOLUTION_DEPTH = 6; + +/** The receiver name of `.`, for the vocabulary test. */ +function logReceiverName(expr) { + if (ts.isIdentifier(expr)) return expr.text; + if (ts.isPropertyAccessExpression(expr) && ts.isIdentifier(expr.name)) return expr.name.text; + return undefined; +} + +/** + * Resolve a CALLEE expression to the log levels the call may reach. + * + * @returns `{ levels: string[], unreadable: boolean }` — `unreadable` means + * "this looks like a report and I could not read it", which is a + * DIFFERENT fact from "there is no log here" (see `loggerLevels`). + */ +function resolveLogCallee(expr, ctx, depth = 0) { + const res = { levels: [], unreadable: false }; + if (!expr) return res; + if (depth > MAX_CALLEE_RESOLUTION_DEPTH) { + res.unreadable = true; + return res; + } + const merge = (r) => { + res.levels.push(...r.levels); + if (r.unreadable) res.unreadable = true; + }; + + // Transparent wrappers: `(…)`, `…!`, `… as T`. + if ( + ts.isParenthesizedExpression(expr) || + ts.isNonNullExpression(expr) || + ts.isAsExpression(expr) + ) { + return resolveLogCallee(expr.expression, ctx, depth + 1); + } + + // `a ?? b` / `a || b` — the fallback idiom. EVERY branch contributes: the + // call reaches whichever one is defined, and the existing + // `levels.filter(LOUD)` semantic then decides, exactly as it already does + // for a catch that contains both a `warn` and an `error`. + if (ts.isBinaryExpression(expr)) { + const op = expr.operatorToken.kind; + if (op !== ts.SyntaxKind.QuestionQuestionToken && op !== ts.SyntaxKind.BarBarToken) { + return res; + } + merge(resolveLogCallee(expr.left, ctx, depth + 1)); + merge(resolveLogCallee(expr.right, ctx, depth + 1)); + return res; } - if (!receiverName) return undefined; - return /^(logger|log|console)$/i.test(receiverName) ? level : undefined; + + // `(cond ? a : b)(…)` — same reasoning as the fallback. + if (ts.isConditionalExpression(expr)) { + merge(resolveLogCallee(expr.whenTrue, ctx, depth + 1)); + merge(resolveLogCallee(expr.whenFalse, ctx, depth + 1)); + return res; + } + + if (ts.isPropertyAccessExpression(expr) && ts.isIdentifier(expr.name)) { + const name = expr.name.text; + // `.call(recv, …)` / `.apply(recv, args)` / `.bind(recv)` are ADAPTERS, + // not levels: what is being called is whatever they are called ON. + // `driver-turso` uses `.call` because `(a ?? b)(…)` loses the receiver + // binding — it is the MORE correct spelling of the same idiom, so + // reading it as a log is not a loosening. + if (name === 'call' || name === 'apply' || name === 'bind') { + return resolveLogCallee(expr.expression, ctx, depth + 1); + } + if (!ALL_LEVELS.has(name)) return res; + const receiverName = logReceiverName(expr.expression); + // Receiver vocabulary UNCHANGED (#8897 owns that half). A level name on + // an unrecognised receiver is not reported as unreadable either: that + // narrowness is already filed, measured and deliberate, and turning it + // into a new verdict here would re-open it by the back door. + if (receiverName && LOGGER_RECEIVERS.test(receiverName)) res.levels.push(name); + return res; + } + + // `logger['error'](…)` is the same call; `logger[key](…)` is a report this + // checker cannot read, and says so rather than counting it as silence. + if (ts.isElementAccessExpression(expr)) { + const receiverName = logReceiverName(expr.expression); + if (!receiverName || !LOGGER_RECEIVERS.test(receiverName)) return res; + const arg = expr.argumentExpression; + if (arg && ts.isStringLiteralLike(arg) && ALL_LEVELS.has(arg.text)) { + res.levels.push(arg.text); + return res; + } + res.unreadable = true; + return res; + } + + if (ts.isIdentifier(expr)) { + // A same-file `const report = ` — the SAME "follow the + // indirection" discipline this file already applies to same-file helper + // FUNCTIONS, extended to a helper stored in a const. Without it, + // `const log = l.error?.bind(l) ?? l.warn.bind(l); log(…)` (6 calls in + // `catch` blocks across three trigger/service packages) reads as silence. + const alias = ctx.logAliases?.get(expr.text); + if (alias) { + res.levels.push(...alias.levels); + if (alias.unreadable) res.unreadable = true; + return res; + } + // A bare `warn(…)` naming a same-file function is handled one level up, + // by `collectLoggedLevels`' helper walk. One this file cannot see (an + // IMPORTED `warn`) is a report we cannot read — not a silent catch. + if (ALL_LEVELS.has(expr.text) && !ctx.functionBodies?.has(expr.text)) { + res.unreadable = true; + } + return res; + } + + return res; +} + +/** + * `x.logger.warn(...)` / `logger.warn(...)` / `this.log.error(...)` / + * `console.error(...)` / `(logger.error ?? logger.warn)(…)` → + * `[{ level, conditional }]`. + * + * `console` counts because `console.error` is every bit as loud as + * `logger.error` — measuring the gate against the repo turned up a real site + * (`metadata/src/loaders/database-loader.ts` history-schema sync) that reports + * honestly via `console`, and flagging it would have been a false positive. + * + * ## Why the callee is RESOLVED rather than matched (#9657) + * + * The old matcher required the callee to be a plain property access, so it read + * exactly one spelling. A census of every log-emitting call under `packages/` + * (3,294 calls, 655 of them inside a `catch`) found SIX shape families: + * + * | callee shape | calls | in a catch | + * |---------------------------------------------------------|------:|-----------:| + * | `logger.error(…)` and its `?.` variants | 3252 | 642 | + * | `(logger.error ?? logger.warn)(…)` | 6 | 2 | + * | `(logger.error ?? logger.warn).call(logger, …)` | 1 | 0 | + * | `((c.warn ?? c.error))?.(…)` | 1 | 0 | + * | `l.error?.bind(l) ?? l.warn.bind(l)` stored in a `const` | 8 | 6 | + * | bare `warn(…)` / `info(…)` / `log(…)` (helper, same-file or imported) | 26 | 5 | + * + * Only the first was visible. The other five exist because `error` is OPTIONAL + * on the driver sinks (`SqlDriver.logger` declares `error?`, and hosts do inject + * `{ warn }`-only sinks), so every author invents their own way to spell "error + * if you have one, warn if you do not". Adding spellings one at a time is an + * instalment plan against a set that is still growing — the callee is therefore + * RESOLVED through the constructs that build these shapes. + * + * ## ⛔ `?.(` is CONDITIONAL, and a conditional log is NOT loud + * + * This is the half that matters more than the widening, and it is why the + * widening alone would have been actively harmful. + * + * `logger.error?.(msg)` — the ONE fallback spelling the old matcher accepted — + * prints NOTHING against a sink that has no `error`. So the cheapest way to + * clear a "this catch swallows the failure with no log at all" report was to + * adopt it: the gate goes green and the operator goes blind, which is the exact + * #4420 shape this whole rule exists to prevent (and the same argument + * `FAILURE_PROPAGATION_CALLEES`' header makes about bolting on a `logger.error`). + * A gate whose cheapest satisfaction is harmful has the wrong shape. + * + * So the OPTIONAL-CALL token is read as what it is: the author's own statement + * that this call may not print. An emission spelled `?.(` does not count toward + * `loud` — the fix is to give it the fallback it is missing, which is now a + * shape the checker can read: + * + * ⛔ l.error?.(msg) // may print nothing + * ✅ (l.error ?? l.warn)(msg) // always prints; reaches `error` + * ✅ (l.error ?? l.warn).call(l, msg) // same, keeping the receiver + * ✅ this.logDurabilityFailure(msg) // a named same-file helper + * + * The cheapest satisfaction is now the correct code. + * + * ⛔ Optionality on the RECEIVER (`logger?.error(…)`) is deliberately NOT + * judged. It says "there may be no sink at all", and when there is no sink + * there is no better level to fall back to — there is nothing the author could + * do about it. It is `?.(`, on a sink that DOES exist and DOES have `warn`, + * that chooses silence over the alternative it is holding. Measured: judging + * receiver optionality too would have flagged 22 further in-`catch` calls with + * no remedy to offer any of them. + */ +function loggerLevels(node, ctx) { + if (!ts.isCallExpression(node)) return { levels: [], unreadable: false }; + const resolved = resolveLogCallee(node.expression, ctx); + const conditional = !!node.questionDotToken; + return { + levels: resolved.levels.map((level) => ({ level, conditional })), + // "Unreadable" is only reported when NOTHING resolved: a callee that + // reached a level is classified, not deferred. + unreadable: resolved.unreadable && resolved.levels.length === 0, + }; +} + +/** + * Same-file `const = ` bindings. + * + * Two shapes in the repo, both in `catch` blocks that reason explicitly about + * the durability class: + * + * const log = this.logger.error?.bind(this.logger) ?? this.logger.warn.bind(this.logger); + * const report = this.logger?.error?.bind(this.logger) ?? this.logger?.warn?.bind(this.logger); + * + * Indexed in one pass and resolved with the same resolver, so a fallback stored + * in a const is read exactly like a fallback called inline. Only `const`/`let` + * declarations with an initializer are indexed, keyed by bare name — the same + * key model, with the same trade-off, as `indexFunctionBodies` above. + */ +function indexLogAliases(sf, functionBodies) { + const byName = new Map(); + const ctx = { functionBodies, logAliases: byName }; + walkAll(sf, (node) => { + if (!ts.isVariableDeclaration(node) || !ts.isIdentifier(node.name)) return; + const init = node.initializer; + if (!init || ts.isArrowFunction(init) || ts.isFunctionExpression(init)) return; + const resolved = resolveLogCallee(init, ctx); + if (resolved.levels.length === 0) return; + byName.set(node.name.text, resolved); + }); + return byName; } /** @@ -1120,31 +1327,52 @@ function indexFunctionBodies(sf) { * like the hand-copied driver-error predicates `@objectstack/metadata/errors` * exists to prevent. * + * @param ctx `{ functionBodies, logAliases, unreadable? }` — the same-file + * indexes the resolver follows. When `unreadable` is an array, calls + * that LOOK like a report and could not be read are appended to it; the + * read-seam rule passes none and is therefore unaffected by that half. * @param lineOf Resolves a node to its 1-based line, for the report. - * @returns `{ level, line, viaHelper? }[]` — `viaHelper` names the same-file - * function the log was found inside, when it was not inline. + * @returns `{ level, conditional, line, viaHelper? }[]` — `viaHelper` names the + * same-file function the log was found inside, when it was not inline; + * `conditional` marks an emission that may not print at all (see + * `loggerLevels`). */ -function collectLoggedLevels(block, functionBodies, lineOf, seen = new Set(), depth = 0) { +function collectLoggedLevels(block, ctx, lineOf, seen = new Set(), depth = 0) { const levels = []; walkSameTickInclusive(block, (child) => { - const level = loggerLevel(child); - if (level) { - levels.push({ level, line: lineOf(child) }); + const found = loggerLevels(child, ctx); + if (found.levels.length > 0) { + for (const l of found.levels) levels.push({ ...l, line: lineOf(child) }); return; } + if (found.unreadable && ctx.unreadable) { + ctx.unreadable.push({ line: lineOf(child), text: sourceSnippet(child) }); + } if (depth >= 3) return; const name = calleeName(child); if (!name || seen.has(name)) return; - const body = functionBodies.get(name); + const body = ctx.functionBodies.get(name); if (!body) return; seen.add(name); - for (const l of collectLoggedLevels(body, functionBodies, lineOf, seen, depth + 1)) { + for (const l of collectLoggedLevels(body, ctx, lineOf, seen, depth + 1)) { levels.push({ ...l, viaHelper: name }); } }); return levels; } +/** The first line of a node's source text, for a diagnostic that names it. */ +function sourceSnippet(node) { + let text; + try { + text = node.getText(); + } catch { + return ''; + } + const firstLine = text.split('\n')[0].trim(); + return firstLine.length > 72 ? `${firstLine.slice(0, 72)}…` : firstLine; +} + // ───────────────────────────────────────────────────────────────────────────── // READ-SEAM INVENTION RULE (#5186) — analysis // ───────────────────────────────────────────────────────────────────────────── @@ -1435,6 +1663,7 @@ function analyzeReadSeams(sf, relPath, findings, seams, options = {}) { const discriminators = options.discriminators ?? READ_FAILURE_DISCRIMINATORS; const lineOf = (node) => sf.getLineAndCharacterOfPosition(node.getStart(sf)).line + 1; const functionBodies = indexFunctionBodies(sf); + const logAliases = indexLogAliases(sf, functionBodies); const ctx = { functionBodies, discriminators, usedDiscriminators: new Set() }; /** Does this catch RECOVER (rather than propagate on every path)? */ @@ -1497,7 +1726,14 @@ function analyzeReadSeams(sf, relPath, findings, seams, options = {}) { if (reads.length === 0) return; const catchBlock = node.catchClause.block; - const logs = collectLoggedLevels(catchBlock, functionBodies, lineOf); + // No `unreadable` sink: this rule asks "did the catch say anything at + // all?", and an unreadable call is not a verdict it has any use for. + // Its census and its findings are byte-identical before and after #9657. + const logs = collectLoggedLevels( + catchBlock, + { functionBodies, logAliases }, + lineOf, + ); // 2. On which paths does it invent an answer? TWO criteria over the // same exits — an EMPTY/ZERO value, or the function's own input @@ -1554,6 +1790,7 @@ function analyzeSourceFile(sf, relPath, findings, seams, options = {}) { const usedPropagationSites = options.usedPropagationSites; const lineOf = (node) => sf.getLineAndCharacterOfPosition(node.getStart(sf)).line + 1; const functionBodies = indexFunctionBodies(sf); + const logAliases = indexLogAliases(sf, functionBodies); const globalPropagation = [...FAILURE_PROPAGATION_CALLEES].map(([name, d]) => ({ name, @@ -1588,7 +1825,17 @@ function analyzeSourceFile(sf, relPath, findings, seams, options = {}) { walkSameTickInclusive(block, (child) => { if (ts.isThrowStatement(child)) rethrows = true; }); - return { levels: collectLoggedLevels(block, functionBodies, lineOf), rethrows }; + // `unreadable` collects the calls that LOOK like a report and could not + // be read. Kept separate from `levels` so that "I could not recognise + // this" can be REPORTED AS ITSELF instead of being folded into "this + // catch said nothing" — see the `unreadable-report` verdict below. + const unreadable = []; + const levels = collectLoggedLevels( + block, + { functionBodies, logAliases, unreadable }, + lineOf, + ); + return { levels, rethrows, unreadable }; }; /** @@ -1701,7 +1948,7 @@ function analyzeSourceFile(sf, relPath, findings, seams, options = {}) { if (guarded.length === 0) return; // 2. How does the catch respond? - const { levels, rethrows } = collectResponse(node.catchClause.block); + const { levels, rethrows, unreadable } = collectResponse(node.catchClause.block); // Only an UNCONDITIONAL rethrow excuses the seam — see catchRecovers(). const propagatesAlways = rethrows && !catchRecovers(node.catchClause.block); @@ -1712,7 +1959,15 @@ function analyzeSourceFile(sf, relPath, findings, seams, options = {}) { ); if (delivery?.site && usedPropagationSites) usedPropagationSites.add(delivery.site); - const loud = levels.filter((l) => LOUD_LEVELS.has(l.level)); + // A CONDITIONAL emission (`logger.error?.(…)`) is not loud: on the + // branch where the method is absent it prints nothing at all, and the + // sink it is holding still has a `warn`. See `loggerLevels`' header for + // why that spelling had to stop satisfying this rule — it was the gate's + // own cheapest satisfaction, and it converts a loud degradation into a + // silent one. The correct repair is the fallback, which this checker now + // reads in every spelling the repo uses. + const loud = levels.filter((l) => LOUD_LEVELS.has(l.level) && !l.conditional); + const conditionalLoud = levels.filter((l) => LOUD_LEVELS.has(l.level) && l.conditional); const quiet = levels.filter((l) => QUIET_LEVELS.has(l.level)); const seam = { @@ -1725,7 +1980,11 @@ function analyzeSourceFile(sf, relPath, findings, seams, options = {}) { propagates: delivery ? `${delivery.name}()${delivery.site ? ' (site-declared)' : ''}` : undefined, propagatesWhy: delivery?.why, loud: loud.map((l) => `${l.level}@${l.line}${l.viaHelper ? ` via ${l.viaHelper}()` : ''}`), + conditional: conditionalLoud.map( + (l) => `${l.level}?.@${l.line}${l.viaHelper ? ` via ${l.viaHelper}()` : ''}`, + ), quiet: quiet.map((l) => `${l.level}@${l.line}${l.viaHelper ? ` via ${l.viaHelper}()` : ''}`), + unreadable: unreadable.map((u) => `${u.text}@${u.line}`), }; seams.push(seam); @@ -1734,7 +1993,19 @@ function analyzeSourceFile(sf, relPath, findings, seams, options = {}) { findings.push({ ...seam, why: DURABILITY_CRITICAL_CALLEES.get(guarded[0].callee), - kind: quiet.length > 0 ? 'quiet-log' : 'silent-swallow', + // Verdict ORDER is the message the author reads, so the most + // actionable fact wins. A catch that reached for `error` and spelled + // it conditionally is one token from correct; one this checker could + // not read is not an accusation at all; only after both is "there is + // no log here" the truth. + kind: + conditionalLoud.length > 0 + ? 'conditional-log' + : unreadable.length > 0 + ? 'unreadable-report' + : quiet.length > 0 + ? 'quiet-log' + : 'silent-swallow', }); }); } @@ -1986,6 +2257,78 @@ function runReadSeamRule({ list = false } = {}) { return failed ? 1 : 0; } +/** + * The `found :` line — what the checker actually observed, in its own words. + * + * ⛔ `unreadable-report` is NOT an accusation of silence. It says the checker + * could not read the call, and names it, so the author can tell "you are quiet" + * from "I could not read you". Reporting the second as the first is the defect + * #9657 was filed for: a loud `(logger.error ?? logger.warn)(…)` was reported as + * `catch swallows the failure with no log at all`, and the cheapest way to + * silence THAT accusation is to make the code genuinely silent. + */ +function describeFinding(v) { + switch (v.kind) { + case 'conditional-log': + return ( + `catch reaches \`error\` only CONDITIONALLY (${v.conditional.join(', ')}) — the \`?.(\` ` + + 'says the sink may not have that method, and on that branch this catch prints nothing at all' + + (v.quiet.length > 0 ? `; the only unconditional log is ${v.quiet.join(', ')}` : '') + ); + case 'unreadable-report': + return ( + `catch calls something this checker could not read as a log (${v.unreadable.join(', ')}) — ` + + 'this is NOT a finding that the catch is silent, it is the checker saying it cannot tell' + ); + case 'quiet-log': + return `catch logs ${v.quiet.join(', ')} and does not rethrow`; + default: + return 'catch swallows the failure with no log at all'; + } +} + +/** The `fix :` block — the repair that is correct for THIS verdict. */ +function remedyFor(v) { + const propagationOption = + ' OR : if this catch already HANDS THE FAILURE TO THE CALLER on every path (an error envelope, a per-item outcome report), do NOT bolt on a log — declare how it delivers, in FAILURE_PROPAGATION_CALLEES or FAILURE_PROPAGATION_SITES in this script (#5241). Adding a redundant `logger.error` to a path whose common case is a rejected request is the mirror-image failure AGENTS.md warns about.\n'; + + if (v.kind === 'conditional-log') { + return ( + ' fix : give the optional call the FALLBACK it is missing, so something always prints:\n' + + ' (this.logger.error ?? this.logger.warn)(msg, meta)\n' + + ' (this.logger.error ?? this.logger.warn).call(this.logger, msg)\n' + + ' or a named same-file helper: `if (l.error) l.error(msg, meta); else l.warn(msg, meta);`\n' + + ' (`SqlDriver.logDurabilityFailure` is the worked example, #9665.) This checker\n' + + ' reads all three, and follows a same-file helper transitively.\n' + + ' ⛔ NOT : deleting the `?.` — that throws on a sink without the method. And do NOT\n' + + ' settle for `logger.warn(…)`: the reach for `error` was right, only its\n' + + ' fallback was missing.\n' + + propagationOption + ); + } + if (v.kind === 'unreadable-report') { + return ( + ' fix : NOTHING may be wrong with this code — read it first. If it does report loudly,\n' + + ' spell the report in a shape this checker reads: `logger.error(…)`, a fallback\n' + + ' `(logger.error ?? logger.warn)(…)`, or a NAMED same-file helper (followed\n' + + ' transitively). If the reporter is imported from another module, a same-file\n' + + ' wrapper around it is the smallest change that makes the seam auditable.\n' + + ' ⛔ NOT : `logger.error?.(…)` — it satisfies nothing here, and prints nothing at all\n' + + ' against a sink that has no `error`.\n' + + ' If the code is genuinely silent, the fix below is the real one.\n' + + ' then : log at `error` naming the CONSEQUENCE and the FIX (see packages/services/service-automation/src/plugin.ts start(), #4460), or rethrow.\n' + + propagationOption + ); + } + return ( + ' fix : log at `error` naming the CONSEQUENCE and the FIX (see packages/services/service-automation/src/plugin.ts start(), #4460), or rethrow.\n' + + ' ⛔ NOT : `logger.error?.(…)` — an optional call prints nothing against a sink that has no\n' + + ' `error`, so it buys green by making the degradation genuinely silent. Spell the\n' + + ' fallback instead: `(logger.error ?? logger.warn)(msg, meta)`.\n' + + propagationOption + ); +} + function run({ list = false } = {}) { const packagesDir = join(ROOT, 'packages'); const files = collectSourceFiles(packagesDir); @@ -2013,9 +2356,13 @@ function run({ list = false } = {}) { ? `recovers on one branch, loud (${s.loud.join(', ')})` : s.loud.length > 0 ? `loud (${s.loud.join(', ')})` - : s.quiet.length > 0 - ? `QUIET (${s.quiet.join(', ')})` - : 'SILENT'; + : s.conditional.length > 0 + ? `CONDITIONAL (${s.conditional.join(', ')})` + : s.quiet.length > 0 + ? `QUIET (${s.quiet.join(', ')})` + : s.unreadable.length > 0 + ? `UNREADABLE (${s.unreadable.join(', ')})` + : 'SILENT'; console.log(` ${s.file}:${s.catchLine} guards ${s.callee}()@${s.calleeLine} → ${verdict}`); // A propagating seam is EXCUSED, so the census must show the reason // it was excused — otherwise reviewing the vocabulary means reading @@ -2054,13 +2401,15 @@ function run({ list = false } = {}) { console.error(` ${v.file}:${v.catchLine}`); console.error(` guards : ${v.callee}() at line ${v.calleeLine}`); console.error(` consequence: ${v.why}`); - console.error( - ` found : ${v.kind === 'quiet-log' ? `catch logs ${v.quiet.join(', ')} and does not rethrow` : 'catch swallows the failure with no log at all'}`, - ); - console.error( - ` fix : log at \`error\` naming the CONSEQUENCE and the FIX (see packages/services/service-automation/src/plugin.ts start(), #4460), or rethrow.\n` + - ` OR : if this catch already HANDS THE FAILURE TO THE CALLER on every path (an error envelope, a per-item outcome report), do NOT bolt on a log — declare how it delivers, in FAILURE_PROPAGATION_CALLEES or FAILURE_PROPAGATION_SITES in this script (#5241). Adding a redundant \`logger.error\` to a path whose common case is a rejected request is the mirror-image failure AGENTS.md warns about.\n`, - ); + console.error(` found : ${describeFinding(v)}`); + // The FIX line is per-verdict on purpose. One generic remedy is what + // made this gate harmful: told "no log at all", the cheapest repair + // an author reaches for is `logger.error?.(…)`, which the old + // matcher accepted and which prints NOTHING against a sink with no + // `error` (#9657). A gate must never be cheapest to satisfy by + // going quieter, so each verdict names the repair that is correct + // FOR IT. + console.error(remedyFor(v)); } } @@ -2565,6 +2914,218 @@ function selfTest() { sites: [['t.ts::migrateStoredMetadata', { callees: [['record', 'effect']] }]], expectViolation: true, }, + // ── #9657: CALLEE SHAPES ───────────────────────────────────────── + // + // Every fixture below is a shape the repo actually writes (see the + // census in `loggerLevels`' header), and every one of them read as + // `catch swallows the failure with no log at all` before this. They pin + // the VERDICT, not just "did it flag": a wrong verdict that still fails + // is precisely the defect — it is what pushed an author toward + // `logger.error?.(…)`, which is silence. + { + name: 'passes: (logger.error ?? logger.warn)(…) — the parenthesized fallback', + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { (this.logger.error ?? this.logger.warn)('CONSEQUENCE + FIX', { e }); } + } }`, + expectViolation: false, + expectSeams: 1, + }, + { + name: 'passes: (logger.error ?? logger.warn).call(logger, …) — driver-turso spelling', + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { (this.logger.error ?? this.logger.warn).call(this.logger, 'CONSEQUENCE + FIX'); } + } }`, + expectViolation: false, + expectSeams: 1, + }, + { + name: 'passes: (logger.error || logger.warn)(…) — the || spelling of the same idiom', + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { (this.logger.error || this.logger.warn)('CONSEQUENCE + FIX'); } + } }`, + expectViolation: false, + expectSeams: 1, + }, + { + name: 'passes: (cond ? logger.error : logger.warn)(…) — ternary callee', + code: ` + class P { async f(driver: any, obj: any, hard: boolean) { + try { await driver.syncSchema('t', obj); } + catch (e) { (hard ? this.logger.error : this.logger.warn)('CONSEQUENCE + FIX'); } + } }`, + expectViolation: false, + expectSeams: 1, + }, + { + name: "passes: logger['error'](…) — a level named by a string literal", + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { this.logger['error']('CONSEQUENCE + FIX', { e }); } + } }`, + expectViolation: false, + expectSeams: 1, + }, + { + name: 'passes: a fallback stored in a same-file const and called through it', + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { + const report = this.logger.error?.bind(this.logger) ?? this.logger.warn.bind(this.logger); + report('CONSEQUENCE + FIX'); + } + } }`, + expectViolation: false, + expectSeams: 1, + }, + { + name: 'passes: the #9665 named-helper shape (guarded error, warn fallback)', + code: ` + class P { + logDurabilityFailure(msg: string, meta?: any) { + if (this.logger.error) this.logger.error(msg, meta); + else this.logger.warn(msg, meta); + } + async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { this.logDurabilityFailure('CONSEQUENCE + FIX', { e }); } + } + }`, + expectViolation: false, + expectSeams: 1, + }, + { + name: 'passes: logger?.error(…) — optionality on the RECEIVER is not judged', + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { this.logger?.error('CONSEQUENCE + FIX', { e }); } + } }`, + expectViolation: false, + expectSeams: 1, + }, + { + // ⛔ THE one that must be red. It is the spelling the old matcher + // accepted, and against a sink with no `error` it prints nothing — + // so accepting it made the gate's cheapest satisfaction harmful. + name: 'flags: logger.error?.(…) alone — an optional call may print nothing', + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { this.logger.error?.('CONSEQUENCE + FIX', { e }); } + } }`, + expectViolation: true, + expectSeams: 1, + expectCount: 1, + expectKinds: ['conditional-log'], + }, + { + name: 'flags: (logger.error ?? logger.warn)?.(…) — the fallback itself called optionally', + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { (this.logger.error ?? this.logger.warn)?.('CONSEQUENCE + FIX'); } + } }`, + expectViolation: true, + expectSeams: 1, + expectCount: 1, + expectKinds: ['conditional-log'], + }, + { + name: 'flags: a conditional error next to an unconditional debug is still conditional', + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { + this.logger.debug('detail', { e }); + this.logger.error?.('CONSEQUENCE + FIX', { e }); + } + } }`, + expectViolation: true, + expectSeams: 1, + expectCount: 1, + expectKinds: ['conditional-log'], + }, + { + // The fallback machinery must not become a way to be quiet: every + // branch of `(warn ?? info)` is quiet, so the verdict is quiet-log. + name: 'flags: (logger.warn ?? logger.info)(…) — a fallback between two QUIET levels', + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { (this.logger.warn ?? this.logger.info)('degraded'); } + } }`, + expectViolation: true, + expectSeams: 1, + expectCount: 1, + expectKinds: ['quiet-log'], + }, + { + // ⭐ The verdict this file did not have. `reportFailure` is imported + // from another module, so the checker cannot read it — and saying + // "this catch swallows the failure with no log at all" about a + // catch that reports loudly is what taught authors to reach for the + // silent spelling. It is still a violation (the checker cannot + // prove the seam is loud), but it accuses the right thing. + name: 'flags: an unreadable report is `unreadable-report`, NOT `silent-swallow`', + code: ` + import { warn } from './log'; + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { warn('something happened', { e }); } + } }`, + expectViolation: true, + expectSeams: 1, + expectCount: 1, + expectKinds: ['unreadable-report'], + }, + { + name: 'flags: logger[level](…) with a computed level is unreadable, not silent', + code: ` + class P { async f(driver: any, obj: any, level: string) { + try { await driver.syncSchema('t', obj); } + catch (e) { this.logger[level]('something happened', { e }); } + } }`, + expectViolation: true, + expectSeams: 1, + expectCount: 1, + expectKinds: ['unreadable-report'], + }, + { + // A bare `warn(…)` that IS a same-file function is followed by the + // helper walk, so it must NOT be reported as unreadable — the two + // mechanisms have to agree or every same-file reporter becomes a + // false `unreadable-report`. + name: 'passes: a bare warn(…) naming a same-file helper that logs error', + code: ` + function warn(msg: string) { console.error(msg); } + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } + catch (e) { warn('CONSEQUENCE + FIX'); } + } }`, + expectViolation: false, + expectSeams: 1, + }, + { + // A genuinely empty catch must still read as SILENT: the new + // verdicts must not swallow the original one. + name: 'flags: a truly empty catch is still `silent-swallow`', + code: ` + class P { async f(driver: any, obj: any) { + try { await driver.syncSchema('t', obj); } catch { /* ignore */ } + } }`, + expectViolation: true, + expectSeams: 1, + expectCount: 1, + expectKinds: ['silent-swallow'], + }, { // A propagating catch is still a SEAM — it is reported by `--list` // and it must not vanish from the census. #4754's whole precision @@ -2607,15 +3168,26 @@ function selfTest() { const sitesMismatch = c.expectSitesUsed !== undefined && JSON.stringify(usedList) !== JSON.stringify([...c.expectSitesUsed].sort()); - if (got !== c.expectViolation || countMismatch || seamMismatch || sitesMismatch) { + // `expectKinds` pins WHICH verdict, not just that there was one. #9657 + // is the reason: the old rule reported a loud fallback as + // `silent-swallow`, and a boolean `expectViolation` cannot tell a right + // verdict from a wrong one — the wrong one is what made the gate's + // cheapest satisfaction harmful. + const kinds = findings.map((f) => f.kind).sort(); + const kindsMismatch = + c.expectKinds !== undefined && + JSON.stringify(kinds) !== JSON.stringify([...c.expectKinds].sort()); + if (got !== c.expectViolation || countMismatch || seamMismatch || sitesMismatch || kindsMismatch) { failures++; console.error( ` ✗ ${c.name}: expected violation=${c.expectViolation}` + (c.expectCount !== undefined ? ` count=${c.expectCount}` : '') + (c.expectSeams !== undefined ? ` seams=${c.expectSeams}` : '') + (c.expectSitesUsed !== undefined ? ` sitesUsed=${JSON.stringify(c.expectSitesUsed)}` : '') + + (c.expectKinds !== undefined ? ` kinds=${JSON.stringify(c.expectKinds)}` : '') + `, got violation=${got} count=${findings.length} seams=${seams.length}` + - (c.expectSitesUsed !== undefined ? ` sitesUsed=${JSON.stringify(usedList)}` : ''), + (c.expectSitesUsed !== undefined ? ` sitesUsed=${JSON.stringify(usedList)}` : '') + + (c.expectKinds !== undefined ? ` kinds=${JSON.stringify(kinds)}` : ''), ); } else { console.log(` ✓ ${c.name}`); From dc74acaff1ca9e512642d2635cedd2b342d12154 Mon Sep 17 00:00:00 2001 From: os-steve Date: Tue, 18 Aug 2026 16:15:43 +0000 Subject: [PATCH 2/4] test(plugins): pin that a sink without `error` still hears the durability report MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit One per repaired package. Each asserts the MESSAGE lands at `warn` — not merely that nothing threw, which the silent `logger?.error?.(…)` version satisfied too. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01XqDQYVU5smx29ts9pAErja --- .../plugin-audit/src/audit-writers.test.ts | 27 +++++++++++++++-- .../plugin-email/src/outbox-sweep.test.ts | 20 +++++++++++++ .../src/permission-set-projection.test.ts | 30 +++++++++++++++++++ 3 files changed, 75 insertions(+), 2 deletions(-) diff --git a/packages/plugins/plugin-audit/src/audit-writers.test.ts b/packages/plugins/plugin-audit/src/audit-writers.test.ts index d6a609ad39..e713fb8748 100644 --- a/packages/plugins/plugin-audit/src/audit-writers.test.ts +++ b/packages/plugins/plugin-audit/src/audit-writers.test.ts @@ -1068,7 +1068,7 @@ 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') { + function makeFailingEngine(failWith = 'no such table: sys_audit_log', omitError = false) { const hooks = new Map any>>(); const logs: LogLine[] = []; const sudoApi = { @@ -1095,7 +1095,12 @@ describe('audit writers — a lost audit row is reported at error (#5226)', () = }, unregisterHooksByPackage() { /* no-op */ }, logger: { - error(message: string, _err?: unknown, meta?: any) { logs.push({ level: 'error', message, meta }); }, + // `omitError` reproduces the sink a host may legitimately inject: the + // kernel `Logger` requires `error`, but this reporter reaches its sink + // through `(engine as any).logger`, so nothing checks. #9657. + ...(omitError + ? {} + : { 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 */ }, @@ -1127,6 +1132,24 @@ describe('audit writers — a lost audit row is reported at error (#5226)', () = expect(errors[0].meta).toMatchObject({ object: 'crm_lead', action: 'create' }); }); + it('still reports the lost row when the sink has NO `error` — at warn, never in silence (#9657)', async () => { + // The regression this pins: the report used to be spelled + // `logger?.error?.(…)`, an optional call that emits NOTHING against a sink + // without `error`. The compliance trail was then incomplete AND unreported. + // ⛔ Asserting only "did not throw" would pass on the silent version too, + // so this asserts the MESSAGE lands, and that it is the same one. + const { engine, fire, logs } = makeFailingEngine('no such table: sys_audit_log', true); + installAuditWriters(engine as any); + + await fire('afterInsert', aWrite('l-1')); + + const warns = logs.filter((l) => l.level === 'warn'); + expect(warns).toHaveLength(1); + expect(warns[0].message).toMatch(/compliance trail is now INCOMPLETE/); + expect(warns[0].message).toMatch(/OS_TELEMETRY_DB=0/); + expect(warns[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); diff --git a/packages/plugins/plugin-email/src/outbox-sweep.test.ts b/packages/plugins/plugin-email/src/outbox-sweep.test.ts index 76d179af19..6835f1db95 100644 --- a/packages/plugins/plugin-email/src/outbox-sweep.test.ts +++ b/packages/plugins/plugin-email/src/outbox-sweep.test.ts @@ -270,6 +270,26 @@ describe('failures are loud, counted, and never stop the batch', () => { expect(perRow[0]).toMatch(/engine exploded/); }); + it('[#9657] reports a stranded row to a sink with NO `error` — at warn, not in silence', async () => { + // `SweepLogger.error` is declared OPTIONAL, and the per-row report used to + // be `logger?.error?.(…)`: against a `{ info, warn }` sink it emitted + // NOTHING, so the message that stays `queued` forever was reported by + // nobody while the server kept looking healthy. + const engine = fakeEngine([{ id: 'row-bad', created_at: ago(min(30)) }]); + const service = fakeService({ + deliver: () => { throw new Error('engine exploded'); }, + }); + const logger = { info: vi.fn(), warn: vi.fn() }; + + const res = await sweepStrandedOutbox({ engine, service, logger, now: () => NOW }); + + expect(res).toMatchObject({ scanned: 1, failed: 1 }); + const warned = lines(logger.warn).filter((l) => l.includes('could not advance sys_email row')); + expect(warned).toHaveLength(1); + expect(warned[0]).toMatch(/row-bad/); + expect(warned[0]).toMatch(/engine exploded/); // the cause survives the fallback + }); + it('propagates a failure of the query itself — the sweep did not happen', async () => { const engine = { find: vi.fn(async () => { throw new Error('no such table: sys_email'); }) }; await expect(sweepStrandedOutbox({ engine, service: fakeService(), now: () => NOW })) diff --git a/packages/plugins/plugin-security/src/permission-set-projection.test.ts b/packages/plugins/plugin-security/src/permission-set-projection.test.ts index 7c8d9deefa..ab90558443 100644 --- a/packages/plugins/plugin-security/src/permission-set-projection.test.ts +++ b/packages/plugins/plugin-security/src/permission-set-projection.test.ts @@ -1016,6 +1016,36 @@ describe('reconcilePermissionSetProjection', () => { expect(logs.some((l) => l.level === 'info' && /reconciled/.test(l.msg))).toBe(false); }); + it('[#9657] a sink with NO `error` still hears the backfill failure — at warn, not in silence', async () => { + // `ProjectionLogger.error` is declared OPTIONAL, and the report used to be + // spelled `logger?.error?.(…)` — an optional call that emits NOTHING when + // the method is absent. A host injecting `{ info, warn }` therefore lost + // the whole durability report, on the one path that must never be quiet. + const ql = makeQl(); + const protocol = makeProtocol(ql); + ql.permRows.push({ + id: 'ps_bad', name: 'broken_set', managed_by: 'admin', active: true, + label: 'Broken Set', object_permissions: JSON.stringify({ ticket: { allowRead: 'yes-please' } }), + }); + const logs: Array<{ level: string; msg: string; meta?: any }> = []; + const logger = { + info: (m: string, meta?: any) => logs.push({ level: 'info', msg: m, meta }), + warn: (m: string, meta?: any) => logs.push({ level: 'warn', msg: m, meta }), + }; + + const out = await reconcilePermissionSetProjection(protocol, { ql, logger }); + + expect(out.backfillFailed).toBe(1); + const firstFailure = logs.find((l) => /backfill into metadata FAILED/.test(l.msg)); + expect(firstFailure).toBeDefined(); + expect(firstFailure!.level).toBe('warn'); + // The consequence and the fix survive the fallback — a downgraded level is + // a degradation of the CHANNEL, never of the message. + expect(firstFailure!.msg).toMatch(/Nothing will look broken/); + expect(firstFailure!.msg).toMatch(/Fix:/); + expect(firstFailure!.meta?.name).toBe('broken_set'); + }); + it('heals a record that drifted from an EXISTING metadata definition (metadata wins)', async () => { const ql = makeQl(); const declared = { member_default: envBody({ name: 'member_default', systemPermissions: ['declared.baseline'] }) }; From 8f479316ade75ecb3c590e04403eafe1c4974d92 Mon Sep 17 00:00:00 2001 From: os-steve Date: Tue, 18 Aug 2026 21:48:49 +0000 Subject: [PATCH 3/4] fix(plugin-audit): AuthEventAuditLogger declares the `warn` fallback its report needs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `error` is optional on this sink, so a durability report that reaches for it needs somewhere to fall back to — and this interface declared no `warn` at all, while its sibling `ReadAuditLogger` in the same package always has. The type, not the call site, was the thing missing the channel. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01XqDQYVU5smx29ts9pAErja --- .../plugin-audit/src/auth-event-audit.test.ts | 23 +++++++++++++++++++ .../plugin-audit/src/auth-event-audit.ts | 8 +++++++ 2 files changed, 31 insertions(+) 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 5e8cf476cc..e0ed6e612a 100644 --- a/packages/plugins/plugin-audit/src/auth-event-audit.test.ts +++ b/packages/plugins/plugin-audit/src/auth-event-audit.test.ts @@ -319,4 +319,27 @@ describe('[#8144] createAuthEventAuditSink writes a login row that names its act // on a systemic cause trains everyone to skim the channel. expect(logger.debug).toHaveBeenCalledTimes(1); }); + + it('[#9657] a sink with NO `error` still hears it — at warn, not in silence', async () => { + // `AuthEventAuditLogger.error` is OPTIONAL and the report used to be + // `logger?.error?.(…)`, an optional call that emits NOTHING when the method + // is absent. The sign-in still succeeds either way, which is exactly why + // the missing ledger row has to be somebody's problem out loud. + const broken: any = { + getSchema: () => null, + insert: async () => { + throw new Error('no such table: sys_audit_log'); + }, + }; + const logger = { warn: vi.fn(), debug: vi.fn() }; + const sink = createAuthEventAuditSink({ getEngine: () => broken, logger }); + + await expect(sink.recordAuthEvent({ action: 'login', userId: 'usr_1' })).resolves.toBeUndefined(); + + expect(logger.warn).toHaveBeenCalledTimes(1); + const [msg, meta] = logger.warn.mock.calls[0]; + expect(String(msg)).toContain('INCOMPLETE'); + expect(String(msg)).toContain('Fix:'); + expect(meta).toMatchObject({ action: 'login' }); + }); }); diff --git a/packages/plugins/plugin-audit/src/auth-event-audit.ts b/packages/plugins/plugin-audit/src/auth-event-audit.ts index 4006caf81d..e88ef35cdb 100644 --- a/packages/plugins/plugin-audit/src/auth-event-audit.ts +++ b/packages/plugins/plugin-audit/src/auth-event-audit.ts @@ -105,6 +105,14 @@ export interface AuthSessionAuditEvent { */ export interface AuthEventAuditLogger { error?(msg: string, err?: Error, meta?: Record): void; + /** + * The fallback channel for the durability report below. `error` is optional + * here, so a sink that has none must still have somewhere to put a lost audit + * row — reaching for `error` and finding nothing must degrade to `warn`, + * never to silence (#9657). Signature and optionality mirror + * `ReadAuditLogger` in `read-audit.ts`, which already declared it. + */ + warn?(msg: string, meta?: Record): void; debug?(msg: string, meta?: Record): void; } From 3a6a4b20a86214e7f5d9a2201db117b184d0a83c Mon Sep 17 00:00:00 2001 From: os-steve Date: Tue, 18 Aug 2026 21:50:27 +0000 Subject: [PATCH 4/4] chore: changeset for the durability-report fallback, and re-measure the shape census Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01XqDQYVU5smx29ts9pAErja --- .../durability-log-level-callee-shapes.md | 23 +++++++++++++++++++ ...check-durability-degradation-log-level.mjs | 6 +++-- 2 files changed, 27 insertions(+), 2 deletions(-) create mode 100644 .changeset/durability-log-level-callee-shapes.md diff --git a/.changeset/durability-log-level-callee-shapes.md b/.changeset/durability-log-level-callee-shapes.md new file mode 100644 index 0000000000..a8b49c394a --- /dev/null +++ b/.changeset/durability-log-level-callee-shapes.md @@ -0,0 +1,23 @@ +--- +"@objectstack/plugin-audit": patch +"@objectstack/plugin-email": patch +"@objectstack/plugin-security": patch +--- + +A durability failure reported to a logger without `error` is no longer lost + +Six degradation reports — a lost `sys_audit_log` row (CRUD, auth-event and +read-audit writers), a stranded `sys_email` row, and the two permission-set +metadata backfill failures — were spelled `logger?.error?.(…)`. `error` is +declared OPTIONAL on those sinks, and an optional call emits nothing at all when +the method is absent: a host injecting a `{ info, warn }` logger received no +report whatsoever, on exactly the paths whose whole point is that nothing else +looks broken afterwards. + +Each now reaches for `error` and falls back to `warn`, never to silence. The +message, its consequence and its fix are identical on both channels; only the +level degrades, and only when the sink cannot do better. + +`AuthEventAuditLogger` additionally declares the `warn?` method it needs for +that fallback, matching `ReadAuditLogger`, which always had it. The addition is +optional, so no existing sink stops satisfying the interface. diff --git a/scripts/check-durability-degradation-log-level.mjs b/scripts/check-durability-degradation-log-level.mjs index df0711e264..cf760604c2 100644 --- a/scripts/check-durability-degradation-log-level.mjs +++ b/scripts/check-durability-degradation-log-level.mjs @@ -993,11 +993,13 @@ function resolveLogCallee(expr, ctx, depth = 0) { * * The old matcher required the callee to be a plain property access, so it read * exactly one spelling. A census of every log-emitting call under `packages/` - * (3,294 calls, 655 of them inside a `catch`) found SIX shape families: + * found SIX shape families — 3,308 calls, 658 of them inside a `catch` + * (measured on the tree this landed in; re-run it before trusting the counts, + * the SHAPES are the durable part): * * | callee shape | calls | in a catch | * |---------------------------------------------------------|------:|-----------:| - * | `logger.error(…)` and its `?.` variants | 3252 | 642 | + * | `logger.error(…)` and its `?.` variants | 3266 | 645 | * | `(logger.error ?? logger.warn)(…)` | 6 | 2 | * | `(logger.error ?? logger.warn).call(logger, …)` | 1 | 0 | * | `((c.warn ?? c.error))?.(…)` | 1 | 0 |