Skip to content

Commit 3fbef41

Browse files
fix(plugin-webhooks): report a webhook delivery the outbox could not record at error, once per webhook (#24862)
Part of #24835 Clause-②: no #24835 remains open after this PR: it carries the log-level half only. The delivery loss itself has a measured root cause in `packages/drivers/driver-sql` (with the event built in `packages/objectql`), which is `domain:engine`'s code, so it is reported on the card as a fork and not patched here. ## What this PR changes When the `sys_http_delivery` write for a webhook event failed, `AutoEnqueuer.reportWriteFailure` logged one bare `WARN [webhook-auto-enqueuer] enqueue failed` per event. Under AGENTS.md "Degradation log levels" that is a durability loss, not a functional one. The record write that produced the event already answered 200, the webhook still reads active, and no delivery row exists, so the event is never sent, retried or redeliverable, and nothing else looks wrong. - The first lost delivery for a webhook is now logged at `error`. The line names the webhook, says the event is lost and why nothing else shows it, and says where the cause is (the record's meta) and what to restore. - It is said once per webhook (`writeFailing`, the enqueue twin of `droppedForSecret`). Each further lost event for that webhook is kept at `debug` with its `eventId`. - The next delivery recorded for that webhook clears the mark, so a later outage is loud again. Both enqueue call sites now route the success outcome too (`.then(recordedWrite, reportWriteFailure)`). - A logger without `error` still gets the line at `warn` (the file's existing fallback). The parked-subscription branch is unchanged. - No edit falls inside the mirror and declared-name region (the region the merged step-7c change rewrote). All hunks start at line 680 or later. ## Measured root cause of the PostgreSQL loss (not changed here) I reproduced it with the real `ObjectQL` engine and the real `SqlDriver` on a throwaway local PostgreSQL 16.15 cluster, and in-memory SQLite. The real `AutoEnqueuer` was wired the production way to the real `MessagingService` and `SqlHttpOutbox`. I ran one insert and one by-id update, then read `sys_http_delivery`: | run | rows | non-plain value in the `data.record.updated` payload | log | |---|---|---|---| | PG, base `41646a5788` | 1 (created only) | `payload.changes.updated_at` is a knex `Raw` | `WARN … enqueue failed … Converting circular structure to JSON … 'Timeout'` | | SQLite, base | 2 | none | none | | PG, this branch at `9a8a7f5103`, 2 updates | 1 | same `Raw` | one `ERROR` naming the webhook, then one `DEBUG` for the second loss | | PG at `9a8a7f5103`, driver handed a copy of the patch, 2 updates | 3 | none | none | The chain, at `41646a5788`: 1. `ObjectQL.update` passes `hookContext.input.data` to `driver.update` (`packages/objectql/src/engine.ts:18094`). It then publishes the same object as `DataEvent.changes` (`:18530`). 2. `SqlDriver.update` builds `formatted` from `formatInput` (`packages/drivers/driver-sql/src/sql-driver.ts:8767`). For a patch that needs no coercion, `formatInput` returns the caller's object itself (`:20336`, `:20526`), and so does `applyWriteColumnMap` for a managed object. Then `formatted.updated_at = this.updatedAtStamp()` (`:8778`) writes into the caller's patch. 3. On PostgreSQL and MySQL, `updatedAtStamp()` is `knex.fn.now()` (`:8579`), a `Raw` that holds the knex client, its pool and a Node `Timeout`. On SQLite it is an ISO string (`:8578`). That string is just as foreign to the caller's patch, but it serialises. 4. `projectRecordBodies` copies `changes` shallowly, and `sql-http-outbox.ts:192` `JSON.stringify` throws on it. `rotatedUpdateById` has the same in-place stamp (`:10207`). `updateMany` already builds a fresh object instead (`:10152`). The fork, the candidate fix sites and the evidence are on the card. ## Not added: a serialisation guard in `sql-http-outbox.ts` Reading of the dispatch's decision frame: it does not belong beside the root-cause fix. - **Real business need.** The only measured producer of a non-plain value is the driver stamp. Once that is fixed upstream, a guard has no measured pull. - **Long-term soundness.** Fixing the producer is the contract-first route. A guard is a second place that knows about payload shape. - **Preventing AI mistakes.** The outbox already refuses: it throws, and no row is written. The `error` line in this PR makes that refusal loud, with its cause in the meta. - **Startup focus.** A new guard is a new surface with no pull. ## Tests Run on head `377a12915e` (after merging `origin/main`, which brought the step-7c rewrite of the same file): - `pnpm --filter @objectstack/plugin-webhooks exec vitest run --maxWorkers=2`: `Test Files 21 passed (21)`, `Tests 226 passed (226)`. - `pnpm --filter @objectstack/plugin-webhooks typecheck`: exit 0 (`tsc --noEmit`, `tsconfig.scripts.json`, `check:test-typecheck: OK`). - `pnpm exec turbo run build --filter=@objectstack/plugin-webhooks...`: `17 successful, 17 total`. - New pins, in `src/auto-enqueuer.test.ts` under "a delivery that could not be recorded is reported at error": - the first loss is one `error` naming the webhook and `sys_http_delivery`, with the `eventId` and the cause in meta, and later losses go to `debug`, never `warn`; - two failing webhooks each get their own `error`; - a recorded delivery in between makes the next loss loud again; - the bulk path reports through the same register. They assert level, count and the named subjects, not prose. ## Ablation (one leg, the changed behaviour) `node scripts/ablation-replace.mjs` replaced `this.writeFailing.add(sub.id);` with the old bare `warn` and `return`. The anchor went from 1 hit to 0, and the blob from `81ae0a56ccfa` to `17c85086162a`. Then `vitest run src/auto-enqueuer.test.ts` gave `Tests 4 failed | 40 passed (44)`: exactly the four new pins. The restore was `git checkout HEAD`. The restored blob is `81ae0a56ccfa`, equal to the HEAD blob, and `git diff HEAD` is empty. This ran on head `377a12915e`; the same leg on the pre-merge head `9a8a7f5103` read the same 4 failed and 40 passed. The subject is imported from source (`./auto-enqueuer.js`), so no `dist/` was involved. ## Gates The local subset derived by `node scripts/pm/dispatch-gates.mjs --commands --repo objectstack-ai/objectstack` at `377a12915e` has 70 families. Each exit was captured before any pipe. - **67 families exited 0.** Among them: `check:engine-double-contract`, `check:nul-bytes`, `check:doc-authoring`, `check:issue-citations`, `check:cross-package-test-inputs`, `check:test-source-alias`, `check:type-check-coverage`, `check:published-files`, `check:dts-closure`, `check:lean-entry-closure`, `check:adr-0087-registration --base origin/main`, `check:changeset-no-major` and `check:empty-changeset`. - **2 families are NOT MEASURED: exit 3, PREREQUISITE NOT MET.** `check:dual-build-cjs-loads` needs every package's `dist/`. `check:i18n` needs the CLI build closure. Neither reads anything this diff changes. CI's `Lint & Repo Gates` runs both. - **1 family is a declared narrowing, not run locally.** `check:type-check-debt` (`--re-measure`) rebuilds the whole monorepo under the shared lock. CI's `Lint & Repo Gates` runs it. `--ran` reconciliation: `70 derived, 67 run, 2 NOT-MEASURED, 1 UNRUN` (the UNRUN is the declared `check:type-check-debt`). The full-battery `Temporal Conformance (live PG + MySQL)` job does not run on a PR. CI check-runs were not concluded when this body was written; the report on #24835 cites them. ## Acceptance notes - The card's other half, the lost PostgreSQL deliveries, is unchanged by this PR and is routed as a fork on #24835. - The same in-place stamp reaches every other reader of the update event's `changes` and of `hookContext.input.data` after the driver call. On PostgreSQL and MySQL that is a knex `Raw`; on SQLite it is a driver-stamped `updated_at` the caller never wrote. I measured only the webhook reader here. - The parked-subscription branch still logs every lost record at `error`, with no say-once. I left it as it was. It is outside this card's defect. - `pnpm check:durability-log-level` cannot see this seam, because it judges `try`/`catch` blocks and this is a promise rejection handler. I did not extend it (new gates default to no). --- _Generated by [Claude Code](https://claude.ai/code/session_011TdZ8GjixNZFLz1xJD9zzK)_ Co-authored-by: Claude <noreply@anthropic.com>
1 parent 4cef6e2 commit 3fbef41

3 files changed

Lines changed: 187 additions & 8 deletions

File tree

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,11 @@
1+
---
2+
'@objectstack/plugin-webhooks': patch
3+
---
4+
5+
fix(plugin-webhooks): a webhook delivery the outbox could not record is now reported at `error`, once per webhook, with what was lost and how to fix it
6+
7+
Clause-②: no
8+
9+
- **What was wrong.** When the `sys_http_delivery` write for a webhook event failed, the auto-enqueuer logged one bare `WARN [webhook-auto-enqueuer] enqueue failed` line per event. The event was lost: it is never sent, retried or redeliverable, because no row exists. The record write that produced the event had already answered 200, and the webhook still read active in Setup, so nothing else looked wrong. On PostgreSQL every record-update delivery was lost this way.
10+
- **What changed.** The first lost delivery for a webhook is logged at `error`. The line names the webhook, says the event is lost and why nothing else shows it, and says where the cause is (the record's meta) and what to restore. Later lost events for the same webhook are logged at `debug`, each with its `eventId`. The `error` is said again only after a delivery for that webhook was recorded in between. A logger without `error` still receives the line at `warn`. Bulk (`data.records.*`) deliveries are reported the same way.
11+
- **Unchanged.** Successful deliveries, the delivery rows, the parked-subscription path and every export. This change does not fix the PostgreSQL loss itself: that cause is upstream of the webhook plugin and is fixed separately.

‎packages/plugins/plugin-webhooks/src/auto-enqueuer.test.ts‎

Lines changed: 114 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -592,6 +592,120 @@ describe('AutoEnqueuer', () => {
592592
});
593593
});
594594

595+
/**
596+
* #24835 — a delivery the outbox could not record is a DURABILITY loss: the
597+
* record write already answered 200 and the webhook still reads active, so it
598+
* is reported at `error` (AGENTS.md "Degradation log levels"), said once per
599+
* webhook, and re-armed by the next delivery recorded for that webhook. The
600+
* measured cause was a payload `JSON.stringify` refused on PostgreSQL; any
601+
* refused write takes the same path, so the fake throws that error.
602+
*/
603+
describe('AutoEnqueuer — a delivery that could not be recorded is reported at error (#24835)', () => {
604+
type Line = { level: 'debug' | 'warn' | 'error'; msg: string; meta?: any };
605+
function capturingLogger() {
606+
const lines: Line[] = [];
607+
const logger = {
608+
info() {},
609+
debug: (msg: string, meta?: unknown) => { lines.push({ level: 'debug', msg, meta }); },
610+
warn: (msg: string, meta?: unknown) => { lines.push({ level: 'warn', msg, meta }); },
611+
error: (msg: string, _err?: unknown, meta?: unknown) => { lines.push({ level: 'error', msg, meta }); },
612+
};
613+
// Only the lines about a lost event: they carry its `eventId`.
614+
const about = (level: Line['level']) => lines.filter((l) => l.level === level && l.meta?.eventId);
615+
return { logger, about };
616+
}
617+
const refused: HttpEnqueueFn = async () => {
618+
throw new TypeError("Converting circular structure to JSON --> starting at object with constructor 'Timeout'");
619+
};
620+
const at = (s: number) => `2026-10-20T00:00:0${s}.000Z`;
621+
622+
it('reports the first lost delivery once at error, naming the webhook; later losses stay at debug', async () => {
623+
const engine = new FakeEngine({ sys_webhook: [webhook({ name: 'contact_changed' })] });
624+
const realtime = new FakeRealtime();
625+
const { logger, about } = capturingLogger();
626+
const ae = new AutoEnqueuer(engine, realtime, refused, { refreshIntervalMs: 0, logger });
627+
await ae.start();
628+
629+
await realtime.publish(event('updated', 'contact', { id: 'c-1' }, at(1)));
630+
await realtime.publish(event('updated', 'contact', { id: 'c-1' }, at(2)));
631+
await flush();
632+
await ae.stop();
633+
634+
const errors = about('error');
635+
expect(errors).toHaveLength(1);
636+
expect(errors[0].msg).toContain("'contact_changed'");
637+
expect(errors[0].msg).toContain('sys_http_delivery');
638+
expect(errors[0].meta).toMatchObject({ webhook: 'contact_changed', eventId: `contact:c-1:updated:${at(1)}` });
639+
expect(String(errors[0].meta.err)).toContain('circular');
640+
// The second loss is still on record, with its own event id — not a
641+
// second error, and never the old bare warn.
642+
expect(about('debug').map((l) => l.meta.eventId)).toEqual([`contact:c-1:updated:${at(2)}`]);
643+
expect(about('warn')).toHaveLength(0);
644+
});
645+
646+
it('says it once per webhook — one failing webhook does not silence another', async () => {
647+
const engine = new FakeEngine({
648+
sys_webhook: [webhook({ id: 'wh-a', name: 'hook_a' }), webhook({ id: 'wh-b', name: 'hook_b' })],
649+
});
650+
const realtime = new FakeRealtime();
651+
const { logger, about } = capturingLogger();
652+
const ae = new AutoEnqueuer(engine, realtime, refused, { refreshIntervalMs: 0, logger });
653+
await ae.start();
654+
655+
await realtime.publish(event('created', 'contact', { id: 'c-1' }, at(1)));
656+
await flush();
657+
await ae.stop();
658+
659+
expect(about('error').map((l) => l.meta.webhook).sort()).toEqual(['hook_a', 'hook_b']);
660+
});
661+
662+
it('is loud again once a delivery for the webhook was recorded in between', async () => {
663+
const engine = new FakeEngine({ sys_webhook: [webhook({ name: 'contact_changed' })] });
664+
const realtime = new FakeRealtime();
665+
const { logger, about } = capturingLogger();
666+
let broken = true;
667+
const enqueue: HttpEnqueueFn = async (input) => {
668+
if (broken) return refused(input);
669+
return 'id';
670+
};
671+
const ae = new AutoEnqueuer(engine, realtime, enqueue, { refreshIntervalMs: 0, logger });
672+
await ae.start();
673+
674+
await realtime.publish(event('updated', 'contact', { id: 'c-1' }, at(1)));
675+
await flush();
676+
broken = false;
677+
await realtime.publish(event('updated', 'contact', { id: 'c-1' }, at(2)));
678+
await flush();
679+
broken = true;
680+
await realtime.publish(event('updated', 'contact', { id: 'c-1' }, at(3)));
681+
await flush();
682+
await ae.stop();
683+
684+
expect(about('error').map((l) => l.meta.eventId)).toEqual([
685+
`contact:c-1:updated:${at(1)}`,
686+
`contact:c-1:updated:${at(3)}`,
687+
]);
688+
expect(about('debug')).toHaveLength(0);
689+
});
690+
691+
it('reports a lost bulk delivery through the same register', async () => {
692+
const engine = new FakeEngine({ sys_webhook: [webhook({ name: 'contact_bulk', triggers: 'bulk_update' })] });
693+
const realtime = new FakeRealtime();
694+
const { logger, about } = capturingLogger();
695+
const ae = new AutoEnqueuer(engine, realtime, refused, { refreshIntervalMs: 0, logger });
696+
await ae.start();
697+
698+
await realtime.publish(bulkEvent('updated', 'contact', 3, at(1)));
699+
await flush();
700+
await ae.stop();
701+
702+
const errors = about('error');
703+
expect(errors).toHaveLength(1);
704+
expect(errors[0].meta.webhook).toBe('contact_bulk');
705+
expect(about('warn')).toHaveLength(0);
706+
});
707+
});
708+
595709
/**
596710
* #4639 — predicate writes dispatch under their OWN opt-in triggers.
597711
*

‎packages/plugins/plugin-webhooks/src/auto-enqueuer.ts‎

Lines changed: 62 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -677,12 +677,23 @@ export class AutoEnqueuer {
677677
*
678678
* AGENTS.md decides that with one question — *does the system still look
679679
* normal from the outside while something it claims is persisted has not
680-
* landed?* For a PARKED subscription the answer is unambiguously yes, and
681-
* worse than for an ordinary enqueue failure: the durable record is the
680+
* landed?* The answer is yes on BOTH branches, so both report at `error`.
681+
*
682+
* [#24835] The ordinary branch used to log a bare `warn` ("enqueue
683+
* failed"), on the reading that the subscription is otherwise healthy. That
684+
* reading is the problem: the record write that produced the event already
685+
* answered 200, the webhook still reads active, and the `sys_http_delivery`
686+
* row — the outbox's whole durability claim — was never written, so the
687+
* event is never sent, retried or redeliverable, and nothing else looks
688+
* wrong. Measured on PostgreSQL, where every update delivery was lost this
689+
* way behind one WARN per event. It is said ONCE per webhook
690+
* ({@link writeFailing}), with the consequence and the fix, and re-armed by
691+
* the next recorded delivery for that webhook; each further lost event is
692+
* kept at `debug` with its `eventId`.
693+
*
694+
* For a PARKED subscription it is worse still: the durable record is the
682695
* only trace this event ever existed, so losing the write puts us back
683-
* exactly where this issue started, silently. So `error` there, and the
684-
* pre-existing `warn` for an ordinary enqueue, where the delivery itself is
685-
* the thing that did not happen and the subscription is otherwise healthy.
696+
* exactly where #8069 started, silently.
686697
*
687698
* The realistic cause of the parked branch is a host that wired
688699
* {@link HttpEnqueueFn} straight to `IHttpOutbox.enqueue` instead of
@@ -699,7 +710,30 @@ export class AutoEnqueuer {
699710
): void {
700711
const meta = { webhook: sub.name, eventId, err: (err as Error)?.message ?? err };
701712
if (!sub.parkedReason) {
702-
this.logger?.warn?.(`[webhook-auto-enqueuer] ${verb} failed`, meta);
713+
if (this.writeFailing.has(sub.id)) {
714+
this.logger?.debug?.(
715+
`[webhook-auto-enqueuer] webhook '${sub.name}': ${verb} failed again — this event `
716+
+ 'is lost too (reported at error on the first failure)',
717+
meta,
718+
);
719+
return;
720+
}
721+
this.writeFailing.add(sub.id);
722+
const lost =
723+
`[webhook-auto-enqueuer] webhook '${sub.name}': a delivery could not be recorded in `
724+
+ 'sys_http_delivery, so this event is LOST — it will never be sent, retried or '
725+
+ 'redelivered, and there is no row for an operator to find. The record write that '
726+
+ 'produced it already succeeded and the webhook still reads active, so nothing else '
727+
+ 'looks wrong. Fix: the cause in this record\'s meta says why the outbox write was '
728+
+ 'refused — make that write succeed (the datasource holding sys_http_delivery '
729+
+ 'reachable and its schema synced; a payload the outbox cannot store comes from the '
730+
+ 'event\'s producer, upstream of this webhook). Said once until a delivery for this '
731+
+ 'webhook is recorded again; each further lost event is logged at debug with its eventId.';
732+
if (typeof this.logger?.error === 'function') {
733+
this.logger?.error(lost, err, meta);
734+
} else {
735+
this.logger?.warn?.(lost, meta);
736+
}
703737
return;
704738
}
705739
const message =
@@ -718,6 +752,20 @@ export class AutoEnqueuer {
718752
}
719753
}
720754

755+
/**
756+
* [#24835] Webhook ids whose outbox write has failed and not yet succeeded
757+
* again — the say-once ledger for {@link reportWriteFailure}'s ordinary
758+
* branch, the enqueue twin of {@link droppedForSecret}: the loud first
759+
* report is said once per outage, and said again if the same webhook breaks
760+
* after a delivery for it was recorded.
761+
*/
762+
private readonly writeFailing = new Set<string>();
763+
764+
/** [#24835] A delivery for `sub` was recorded — a later failure is a new outage. */
765+
private recordedWrite(sub: CachedSubscription): void {
766+
this.writeFailing.delete(sub.id);
767+
}
768+
721769
private park(sub: CachedSubscription, err: unknown, credential: DropReason): void {
722770
sub.secret = undefined;
723771
sub.headers = undefined;
@@ -1195,7 +1243,10 @@ export class AutoEnqueuer {
11951243
action,
11961244
timestamp: event.timestamp,
11971245
},
1198-
}).catch((err) => this.reportWriteFailure(sub, eventId, err, 'enqueue'));
1246+
}).then(
1247+
() => this.recordedWrite(sub),
1248+
(err) => this.reportWriteFailure(sub, eventId, err, 'enqueue'),
1249+
);
11991250
}
12001251
}
12011252

@@ -1333,7 +1384,10 @@ export class AutoEnqueuer {
13331384
action,
13341385
timestamp: event.timestamp,
13351386
},
1336-
}).catch((err) => this.reportWriteFailure(sub, eventId, err, 'bulk enqueue'));
1387+
}).then(
1388+
() => this.recordedWrite(sub),
1389+
(err) => this.reportWriteFailure(sub, eventId, err, 'bulk enqueue'),
1390+
);
13371391
}
13381392
}
13391393

0 commit comments

Comments
 (0)