Skip to content

Commit 31f2ebc

Browse files
committed
fix(plugin-email,plugin-security): the two durability SUMMARY reports must print against an error-less sink
`SweepLogger.error` and `ProjectionLogger.error` are declared OPTIONAL, and both batch summaries were spelled `logger?.error?.(…)` — an optional call that emits NOTHING when the method is absent. #9657 repaired the six per-row reports of this shape; it could not reach these two, because the gate only judges a call inside a `catch` and a summary sits after the loop. That made the split WORSE, not better: against a `{ info, warn }` sink the per-row detail now landed at `warn` while the count of failures stayed silent, so the detail and the total reported through different channels. Both summaries now reach for `error` and fall back to `warn`, never to silence. Also extends `check:durability-log-level` with a SUMMARY limb so the class cannot regress: a report keyed on the counter a durability-critical catch accumulated into is judged on SPELLING alone — the limb never second-guesses a chosen level. Measured before it was proposed: 2 judged (both sites here), 1 discovered and deliberately not judged (`objectql/plugin.ts`, author-chosen `info`), 3 dropped as boolean latches rather than counters. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01DdCnBGcHeufjrq7drTD3wt
1 parent 8012960 commit 31f2ebc

6 files changed

Lines changed: 643 additions & 14 deletions

File tree

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,15 @@
1+
---
2+
"@objectstack/plugin-email": patch
3+
"@objectstack/plugin-security": patch
4+
---
5+
6+
**Durability fix:** the two boot-time **summary** reports now reach a logger sink that has no `error` method, instead of printing nothing at all (#9748).
7+
8+
`SweepLogger.error` and `ProjectionLogger.error` are both declared **optional**, and both summaries were spelled `logger?.error?.(…)` — an optional call that emits **nothing** when the method is absent. #9657 repaired the six per-row reports of this shape; it could not see these two, because `check:durability-log-level` only judges a call inside a `catch`, and a summary sits after the loop. Against a `{ info, warn }` sink the result was that the repair made the split **worse**: the per-row detail arrived at `warn` while the count of failures vanished, so the detail and the total reported through different channels.
9+
10+
- `sweepStrandedOutbox()`*"N stranded `sys_email` row(s) could NOT be delivered"*. Mail the platform **accepted** and never delivered, previously summarised to nobody.
11+
- `reconcilePermissionSetProjection()`*"N FAILED backfill(s)"*. Worse than a plain omission here: the `else` branch carrying the `info` "reconciled" line is skipped too, so such a sink heard **neither** — the reassuring half-truth this rule exists to remove, arrived at from the other side.
12+
13+
Both now reach for `error` and fall back to `warn`, never to silence — the same repair shape #9657 applied to the per-row lines. A sink that **does** have `error` is unaffected and still gets the summary at `error`; a downgraded level is a degradation of the channel, never of the message, so the consequence and the fix survive the fallback intact.
14+
15+
Also enforced from now on: `check:durability-log-level` grew a **summary limb** that judges a report keyed on the counter a durability-critical `catch` accumulated into, so this class cannot regress silently. The limb never second-guesses a chosen log **level** — it only checks that a call that reaches for `error` can actually print.

packages/plugins/plugin-email/src/outbox-sweep.test.ts

Lines changed: 41 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -290,6 +290,47 @@ describe('failures are loud, counted, and never stop the batch', () => {
290290
expect(warned[0]).toMatch(/engine exploded/); // the cause survives the fallback
291291
});
292292

293+
it('[#9748] the batch SUMMARY also reaches a sink with NO `error` — at warn, not in silence', async () => {
294+
// #9657 repaired the PER-ROW line above; this summary sits outside any
295+
// `catch`, so the durability gate could not see it and it kept the
296+
// `logger?.error?.(…)` spelling. Against a `{ info, warn }` sink the repair
297+
// therefore made the split WORSE, not better: the detail survived at `warn`
298+
// while the TOTAL — how many accepted messages never reached anyone —
299+
// vanished. The counts and the detail reported through different channels.
300+
const engine = fakeEngine([
301+
{ id: 'row-bad-1', created_at: ago(min(30)) },
302+
{ id: 'row-bad-2', created_at: ago(min(29)) },
303+
]);
304+
const service = fakeService({
305+
deliver: () => { throw new Error('engine exploded'); },
306+
});
307+
const logger = { info: vi.fn(), warn: vi.fn() };
308+
309+
const res = await sweepStrandedOutbox({ engine, service, logger, now: () => NOW });
310+
311+
expect(res).toMatchObject({ scanned: 2, failed: 2 });
312+
const summary = lines(logger.warn).filter((l) => l.includes('could NOT be delivered'));
313+
expect(summary).toHaveLength(1);
314+
expect(summary[0]).toMatch(/2 stranded sys_email row\(s\)/); // the COUNT is the whole point
315+
expect(summary[0]).toMatch(/never reached a recipient/); // consequence survives the fallback
316+
expect(summary[0]).toMatch(/Durable queue delivery/); // and so does the fix
317+
});
318+
319+
it('[#9748] a sink that HAS `error` still gets the summary at error, not downgraded', async () => {
320+
// The fallback must not cost a capable sink its level — the reach for
321+
// `error` was right; only its absence of a fallback was wrong.
322+
const engine = fakeEngine([{ id: 'row-bad-1', created_at: ago(min(30)) }]);
323+
const service = fakeService({
324+
deliver: () => { throw new Error('engine exploded'); },
325+
});
326+
const logger = fakeLogger();
327+
328+
await sweepStrandedOutbox({ engine, service, logger, now: () => NOW });
329+
330+
expect(lines(logger.error).filter((l) => l.includes('could NOT be delivered'))).toHaveLength(1);
331+
expect(lines(logger.warn).filter((l) => l.includes('could NOT be delivered'))).toHaveLength(0);
332+
});
333+
293334
it('propagates a failure of the query itself — the sweep did not happen', async () => {
294335
const engine = { find: vi.fn(async () => { throw new Error('no such table: sys_email'); }) };
295336
await expect(sweepStrandedOutbox({ engine, service: fakeService(), now: () => NOW }))

packages/plugins/plugin-email/src/outbox-sweep.ts

Lines changed: 11 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -224,14 +224,22 @@ export async function sweepStrandedOutbox(
224224
);
225225

226226
if (result.failed > 0) {
227-
logger?.error?.(
227+
const summary =
228228
`EmailServicePlugin: ${result.failed} stranded sys_email row(s) could NOT be delivered by the boot `
229229
+ 'sweep. Those messages were accepted by the platform and have still never reached a recipient; '
230230
+ 'nothing retries them in this process. Fix: read the failures with '
231231
+ "`SELECT id, error FROM sys_email WHERE status = 'failed'`, fix the transport (Settings → Mail), and "
232232
+ 'turn on Settings → Mail → "Durable queue delivery" so future failures are retried and dead-lettered '
233-
+ 'instead of depending on the next restart.',
234-
);
233+
+ 'instead of depending on the next restart.';
234+
// Same defect as the per-row report above, one scope out (#9748). No
235+
// `catch` guards this line, so `check:durability-log-level` could not see
236+
// it and #9657 left it spelled `logger?.error?.(…)` — which printed
237+
// NOTHING against a sink that has only `warn`. Because the per-row line WAS
238+
// repaired, such a sink then heard every individual failure and never the
239+
// COUNT of accepted mail that reached nobody: the detail and the total
240+
// reported through different channels. Fall back to `warn`, not silence.
241+
if (logger?.error) logger.error(summary);
242+
else logger?.warn?.(summary);
235243
}
236244

237245
return result;

packages/plugins/plugin-security/src/permission-set-projection.test.ts

Lines changed: 60 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1046,6 +1046,66 @@ describe('reconcilePermissionSetProjection', () => {
10461046
expect(firstFailure!.meta?.name).toBe('broken_set');
10471047
});
10481048

1049+
it('[#9748] the reconcile SUMMARY also reaches a sink with NO `error` — at warn, not in silence', async () => {
1050+
// #9657 repaired the FIRST-FAILURE line above; this summary sits outside
1051+
// any `catch`, so the durability gate could not see it and it kept the
1052+
// `logger?.error?.(…)` spelling. Against a `{ info, warn }` sink the repair
1053+
// therefore made the split WORSE, not better: the first failure survived at
1054+
// `warn` while the TOTAL — how many definitions will not survive a
1055+
// re-provision — vanished, and the `info` "reconciled" line is skipped too,
1056+
// so the sink heard neither. That silence is the reassuring half-truth this
1057+
// rule exists to remove, arrived at from the other side.
1058+
const ql = makeQl();
1059+
const protocol = makeProtocol(ql);
1060+
ql.permRows.push({
1061+
id: 'ps_bad', name: 'broken_set', managed_by: 'admin', active: true,
1062+
label: 'Broken Set', object_permissions: JSON.stringify({ ticket: { allowRead: 'yes-please' } }),
1063+
});
1064+
ql.permRows.push({
1065+
id: 'ps_bad2', name: 'broken_set_2', managed_by: 'admin', active: true,
1066+
label: 'Broken Set 2', object_permissions: JSON.stringify({ ticket: { nonsense: true } }),
1067+
});
1068+
const logs: Array<{ level: string; msg: string; meta?: any }> = [];
1069+
const logger = {
1070+
info: (m: string, meta?: any) => logs.push({ level: 'info', msg: m, meta }),
1071+
warn: (m: string, meta?: any) => logs.push({ level: 'warn', msg: m, meta }),
1072+
};
1073+
1074+
const out = await reconcilePermissionSetProjection(protocol, { ql, logger });
1075+
1076+
expect(out.backfillFailed).toBe(2);
1077+
const summary = logs.filter((l) => /FAILED backfill/.test(l.msg));
1078+
expect(summary).toHaveLength(1);
1079+
expect(summary[0]!.level).toBe('warn');
1080+
expect(summary[0]!.msg).toMatch(/2 FAILED backfill/); // the COUNT is the whole point
1081+
expect(summary[0]!.msg).toMatch(/will not survive a re-provision/);
1082+
expect(summary[0]!.meta?.failedNames).toEqual(['broken_set', 'broken_set_2']);
1083+
// and never the reassuring half-truth instead
1084+
expect(logs.some((l) => /reconciled \(ADR-0094 D4\)/.test(l.msg))).toBe(false);
1085+
});
1086+
1087+
it('[#9748] a sink that HAS `error` still gets the summary at error, not downgraded', async () => {
1088+
const ql = makeQl();
1089+
const protocol = makeProtocol(ql);
1090+
ql.permRows.push({
1091+
id: 'ps_bad', name: 'broken_set', managed_by: 'admin', active: true,
1092+
label: 'Broken Set', object_permissions: JSON.stringify({ ticket: { allowRead: 'yes-please' } }),
1093+
});
1094+
const logs: Array<{ level: string; msg: string; meta?: any; cause?: Error }> = [];
1095+
const logger = {
1096+
info: (m: string, meta?: any) => logs.push({ level: 'info', msg: m, meta }),
1097+
warn: (m: string, meta?: any) => logs.push({ level: 'warn', msg: m, meta }),
1098+
error: (m: string, cause?: Error, meta?: any) => logs.push({ level: 'error', msg: m, cause, meta }),
1099+
};
1100+
1101+
await reconcilePermissionSetProjection(protocol, { ql, logger });
1102+
1103+
const summary = logs.filter((l) => /FAILED backfill/.test(l.msg));
1104+
expect(summary).toHaveLength(1);
1105+
expect(summary[0]!.level).toBe('error');
1106+
expect(summary[0]!.meta?.failedNames).toEqual(['broken_set']);
1107+
});
1108+
10491109
it('heals a record that drifted from an EXISTING metadata definition (metadata wins)', async () => {
10501110
const ql = makeQl();
10511111
const declared = { member_default: envBody({ name: 'member_default', systemPermissions: ['declared.baseline'] }) };

packages/plugins/plugin-security/src/permission-set-projection.ts

Lines changed: 12 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -1064,13 +1064,20 @@ export async function reconcilePermissionSetProjection(
10641064
// The summary carries the same level as the degradation it summarizes —
10651065
// an `info` "reconciled" line over a failed backfill is the reassuring
10661066
// half-truth this rule exists to remove.
1067-
logger?.error?.(
1067+
const summary =
10681068
`[security] sys_permission_set projection reconciled with ${out.backfillFailed} FAILED backfill(s) ` +
10691069
'(ADR-0094 D4) — those records have no metadata definition and will not survive a re-provision. ' +
1070-
'See the first-failure error above for the offending key and the fix.',
1071-
undefined,
1072-
{ ...out, failedNames: failedNames.slice(0, 10) },
1073-
);
1070+
'See the first-failure error above for the offending key and the fix.';
1071+
const summaryMeta = { ...out, failedNames: failedNames.slice(0, 10) };
1072+
// Same defect as the first-failure report above, one scope out (#9748). No
1073+
// `catch` guards this line, so `check:durability-log-level` could not see
1074+
// it and #9657 left it spelled `logger?.error?.(…)` — which printed NOTHING
1075+
// against a sink that has only `warn`. Worse here than a plain omission:
1076+
// the `else` below is skipped too, so such a sink heard neither the count
1077+
// nor the reassuring "reconciled" line, while the first-failure report
1078+
// (repaired by #9657) still arrived. Fall back to `warn`, not silence.
1079+
if (logger?.error) logger.error(summary, undefined, summaryMeta);
1080+
else logger?.warn?.(summary, summaryMeta);
10741081
} else {
10751082
logger?.info?.('[security] sys_permission_set projection reconciled (ADR-0094 D4)', { ...out });
10761083
}

0 commit comments

Comments
 (0)