Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 15 additions & 0 deletions .changeset/durability-summary-reports-error-less-sink.md
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,15 @@
---
"@objectstack/plugin-email": patch
"@objectstack/plugin-security": patch
---

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

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

- `sweepStrandedOutbox()` — *"N stranded `sys_email` row(s) could NOT be delivered"*. Mail the platform **accepted** and never delivered, previously summarised to nobody.
- `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.

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.

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.
41 changes: 41 additions & 0 deletions packages/plugins/plugin-email/src/outbox-sweep.test.ts
Original file line numberDiff line numberDiff line change
Expand Up@@ -290,6 +290,47 @@ describe('failures are loud, counted, and never stop the batch', () => {
expect(warned[0]).toMatch(/engine exploded/); // the cause survives the fallback
});

it('[#9748] the batch SUMMARY also reaches a sink with NO `error` — at warn, not in silence', async () => {
// #9657 repaired the PER-ROW line above; this summary sits outside any
// `catch`, so the durability gate could not see it and it kept the
// `logger?.error?.(…)` spelling. Against a `{ info, warn }` sink the repair
// therefore made the split WORSE, not better: the detail survived at `warn`
// while the TOTAL — how many accepted messages never reached anyone —
// vanished. The counts and the detail reported through different channels.
const engine = fakeEngine([
{ id: 'row-bad-1', created_at: ago(min(30)) },
{ id: 'row-bad-2', created_at: ago(min(29)) },
]);
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: 2, failed: 2 });
const summary = lines(logger.warn).filter((l) => l.includes('could NOT be delivered'));
expect(summary).toHaveLength(1);
expect(summary[0]).toMatch(/2 stranded sys_email row\(s\)/); // the COUNT is the whole point
expect(summary[0]).toMatch(/never reached a recipient/); // consequence survives the fallback
expect(summary[0]).toMatch(/Durable queue delivery/); // and so does the fix
});

it('[#9748] a sink that HAS `error` still gets the summary at error, not downgraded', async () => {
// The fallback must not cost a capable sink its level — the reach for
// `error` was right; only its absence of a fallback was wrong.
const engine = fakeEngine([{ id: 'row-bad-1', created_at: ago(min(30)) }]);
const service = fakeService({
deliver: () => { throw new Error('engine exploded'); },
});
const logger = fakeLogger();

await sweepStrandedOutbox({ engine, service, logger, now: () => NOW });

expect(lines(logger.error).filter((l) => l.includes('could NOT be delivered'))).toHaveLength(1);
expect(lines(logger.warn).filter((l) => l.includes('could NOT be delivered'))).toHaveLength(0);
});

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 }))
Expand Down
14 changes: 11 additions & 3 deletions packages/plugins/plugin-email/src/outbox-sweep.ts
Original file line numberDiff line numberDiff line change
Expand Up@@ -224,14 +224,22 @@ export async function sweepStrandedOutbox(
);

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

return result;
Expand Down
Original file line numberDiff line numberDiff line change
Expand Up@@ -1046,6 +1046,66 @@ describe('reconcilePermissionSetProjection', () => {
expect(firstFailure!.meta?.name).toBe('broken_set');
});

it('[#9748] the reconcile SUMMARY also reaches a sink with NO `error` — at warn, not in silence', async () => {
// #9657 repaired the FIRST-FAILURE line above; this summary sits outside
// any `catch`, so the durability gate could not see it and it kept the
// `logger?.error?.(…)` spelling. Against a `{ info, warn }` sink the repair
// therefore made the split WORSE, not better: the first failure survived at
// `warn` while the TOTAL — how many definitions will not survive a
// re-provision — vanished, and the `info` "reconciled" line is skipped too,
// so the sink heard neither. That silence is the reassuring half-truth this
// rule exists to remove, arrived at from the other side.
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' } }),
});
ql.permRows.push({
id: 'ps_bad2', name: 'broken_set_2', managed_by: 'admin', active: true,
label: 'Broken Set 2', object_permissions: JSON.stringify({ ticket: { nonsense: true } }),
});
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(2);
const summary = logs.filter((l) => /FAILED backfill/.test(l.msg));
expect(summary).toHaveLength(1);
expect(summary[0]!.level).toBe('warn');
expect(summary[0]!.msg).toMatch(/2 FAILED backfill/); // the COUNT is the whole point
expect(summary[0]!.msg).toMatch(/will not survive a re-provision/);
expect(summary[0]!.meta?.failedNames).toEqual(['broken_set', 'broken_set_2']);
// and never the reassuring half-truth instead
expect(logs.some((l) => /reconciled \(ADR-0094 D4\)/.test(l.msg))).toBe(false);
});

it('[#9748] a sink that HAS `error` still gets the summary at error, not downgraded', async () => {
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; cause?: Error }> = [];
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 }),
error: (m: string, cause?: Error, meta?: any) => logs.push({ level: 'error', msg: m, cause, meta }),
};

await reconcilePermissionSetProjection(protocol, { ql, logger });

const summary = logs.filter((l) => /FAILED backfill/.test(l.msg));
expect(summary).toHaveLength(1);
expect(summary[0]!.level).toBe('error');
expect(summary[0]!.meta?.failedNames).toEqual(['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'] }) };
Expand Down
Original file line numberDiff line numberDiff line change
Expand Up@@ -1064,13 +1064,20 @@ export async function reconcilePermissionSetProjection(
// The summary carries the same level as the degradation it summarizes —
// an `info` "reconciled" line over a failed backfill is the reassuring
// half-truth this rule exists to remove.
logger?.error?.(
const summary =
`[security] sys_permission_set projection reconciled with ${out.backfillFailed} FAILED backfill(s) ` +
'(ADR-0094 D4) — those records have no metadata definition and will not survive a re-provision. ' +
'See the first-failure error above for the offending key and the fix.',
undefined,
{ ...out, failedNames: failedNames.slice(0, 10) },
);
'See the first-failure error above for the offending key and the fix.';
const summaryMeta = { ...out, failedNames: failedNames.slice(0, 10) };
// Same defect as the first-failure report above, one scope out (#9748). No
// `catch` guards this line, so `check:durability-log-level` could not see
// it and #9657 left it spelled `logger?.error?.(…)` — which printed NOTHING
// against a sink that has only `warn`. Worse here than a plain omission:
// the `else` below is skipped too, so such a sink heard neither the count
// nor the reassuring "reconciled" line, while the first-failure report
// (repaired by #9657) still arrived. Fall back to `warn`, not silence.
if (logger?.error) logger.error(summary, undefined, summaryMeta);
else logger?.warn?.(summary, summaryMeta);
} else {
logger?.info?.('[security] sys_permission_set projection reconciled (ADR-0094 D4)', { ...out });
}
Expand Down
Loading
Loading