fix(devx): durability log-level matcher reads the callee, and stops accepting a spelling that prints nothing

.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.

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<string, Array<(ctx: any) => 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);

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 */
  }

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' });
+ });
 });

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<string, any>): 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<string, any>): void;
  debug?(msg: string, meta?: Record<string, any>): 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 */
  }

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 */
  }

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 }))

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);
  }
  }
  }

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'] }) };

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)) {