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/packages/plugins/plugin-audit/src/audit-writers.test.ts b/packages/plugins/plugin-audit/src/audit-writers.test.ts index 7ee7aa8326..bc88c088e7 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-audit/src/audit-writers.ts b/packages/plugins/plugin-audit/src/audit-writers.ts index d8851acbee..eec865f54f 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.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 be215bd654..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; } @@ -172,7 +180,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 +191,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.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-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.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'] }) }; 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..cf760604c2 100644 --- a/scripts/check-durability-degradation-log-level.mjs +++ b/scripts/check-durability-degradation-log-level.mjs @@ -850,31 +850,240 @@ 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/` + * 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 | 3266 | 645 | + * | `(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 +1329,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 +1665,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 +1728,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 +1792,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 +1827,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 +1950,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 +1961,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 +1982,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 +1995,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 +2259,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 +2358,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 +2403,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 +2916,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 +3170,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}`);