diff --git a/app/api/webhooks/dispatch/cron/__tests__/route.test.ts b/app/api/webhooks/dispatch/cron/__tests__/route.test.ts new file mode 100644 index 00000000..f683fabe --- /dev/null +++ b/app/api/webhooks/dispatch/cron/__tests__/route.test.ts @@ -0,0 +1,94 @@ +/** + * Tests for the per-minute webhook dispatch cron (#1257). + * + * The route is a thin wrapper, so there is exactly one thing here that is not + * covered by lib/webhooks/__tests__: the function budget. The dispatcher's + * CYCLE_BUDGET_MS is what hands unattempted claims back before a cycle ends, + * and the 160 s stuck-recovery window is derived from it. Both are only real + * if the platform grants the invocation more wall time than the budget spends, + * which is what `export const maxDuration` buys. Without it the route runs on + * the platform default, the release path can be killed before it fires, and + * rows stay stranded in in_flight carrying their claim-time updated_at. + */ +import { describe, it, expect, vi, beforeEach } from 'vitest' +import { NextResponse } from 'next/server' +import { verifyCronSecret } from '@/lib/auth/cron' +import { __TESTING__ } from '@/lib/webhooks/dispatcher' + +vi.mock('@/lib/auth/cron', () => ({ + verifyCronSecret: vi.fn(() => null), +})) + +vi.mock('@/lib/auth/api-keys', () => ({ + createServiceClientNoCookies: vi.fn(() => ({ __client: true })), +})) + +const dispatchDueDeliveries = vi.fn() +vi.mock('@/lib/webhooks/dispatcher', async (importOriginal) => { + const actual = await importOriginal() + return { + ...actual, + dispatchDueDeliveries: (...args: unknown[]) => dispatchDueDeliveries(...args), + } +}) + +import { GET, maxDuration } from '../route' + +function cronRequest(): Request { + return new Request('http://localhost:3000/api/webhooks/dispatch/cron') +} + +const SUMMARY = { + picked: 3, + delivered: 1, + failed: 1, + dead: 1, + skipped: 0, + released: 0, + recovered: 2, + recoveredDead: 1, +} + +beforeEach(() => { + vi.clearAllMocks() + vi.mocked(verifyCronSecret).mockReturnValue(null) + dispatchDueDeliveries.mockResolvedValue(SUMMARY) +}) + +describe('GET /api/webhooks/dispatch/cron', () => { + it('declares a function budget above the dispatcher cycle budget', () => { + expect(maxDuration).toBe(300) + // The load-bearing relation, not just the literal: the in-code budget can + // only hand claims back if the invocation is still alive when it expires. + expect(maxDuration * 1000).toBeGreaterThan(__TESTING__.CYCLE_BUDGET_MS) + // And the sweep window has to fit inside the invocation too, otherwise the + // window is derived from a bound nothing enforces. + expect(maxDuration * 1000).toBeGreaterThan( + __TESTING__.CYCLE_BUDGET_MS + + __TESTING__.REQUEST_TIMEOUT_MS + + __TESTING__.STUCK_RECOVERY_SLACK_MS, + ) + }) + + it('returns 401 and dispatches nothing when the cron secret is invalid', async () => { + vi.mocked(verifyCronSecret).mockReturnValueOnce( + NextResponse.json({ error: 'Unauthorized' }, { status: 401 }), + ) + + const response = await GET(cronRequest()) + + expect(response.status).toBe(401) + expect(dispatchDueDeliveries).not.toHaveBeenCalled() + }) + + it('returns the full dispatch summary, including the sweep outcome', async () => { + const response = await GET(cronRequest()) + expect(response.status).toBe(200) + + const body = (await response.json()) as { data: typeof SUMMARY } + // recovered / recoveredDead are the counts an operator needs to see that a + // tick took deliveries to the terminal, immutable 'dead' state. + expect(body.data).toEqual(SUMMARY) + expect(dispatchDueDeliveries).toHaveBeenCalledTimes(1) + }) +}) diff --git a/app/api/webhooks/dispatch/cron/route.ts b/app/api/webhooks/dispatch/cron/route.ts index 3169085a..23b9c872 100644 --- a/app/api/webhooks/dispatch/cron/route.ts +++ b/app/api/webhooks/dispatch/cron/route.ts @@ -17,6 +17,20 @@ import { withCronContext } from '@/lib/api/with-cron-context' import { dispatchDueDeliveries } from '@/lib/webhooks/dispatcher' import { createServiceClientNoCookies } from '@/lib/auth/api-keys' +/** + * Vercel function budget. Must stay comfortably above the dispatcher's own + * CYCLE_BUDGET_MS (120 s, lib/webhooks/dispatcher.ts): the in-code budget is + * what hands unattempted claims back before the loop ends, and it can only do + * that if the platform has not already killed the invocation. Without this + * export the route would run on the platform default, the budget check at + * 110 s could never fire, and the 160 s stuck-recovery window would be derived + * from a bound nothing enforces (#1257). + * + * Overlap with the per-minute schedule is expected and safe: claims are + * FOR UPDATE SKIP LOCKED and every attempt re-checks ownership before POSTing. + */ +export const maxDuration = 300 + export const GET = withCronContext('cron.webhook_dispatch', async (_request, ctx) => { const supabase = createServiceClientNoCookies() const summary = await dispatchDueDeliveries({ supabase }) @@ -26,6 +40,12 @@ export const GET = withCronContext('cron.webhook_dispatch', async (_request, ctx delivered: summary.delivered, failed: summary.failed, dead: summary.dead, + skipped: summary.skipped, + released: summary.released, + // The sweep's own outcome. recoveredDead > 0 means this tick took + // deliveries to the terminal, immutable 'dead' state: alertable. + recovered: summary.recovered, + recoveredDead: summary.recoveredDead, }) return NextResponse.json({ data: summary }) diff --git a/lib/webhooks/__tests__/dispatch-kick.test.ts b/lib/webhooks/__tests__/dispatch-kick.test.ts index f1b20c8c..d89bc718 100644 --- a/lib/webhooks/__tests__/dispatch-kick.test.ts +++ b/lib/webhooks/__tests__/dispatch-kick.test.ts @@ -14,6 +14,22 @@ vi.mock('next/server', () => ({ import { kickWebhookDispatch, resetKickStateForTests, KICK_BATCH_SIZE } from '../dispatch-kick' +/** + * A zero DispatchSummary. Spread rather than repeated so adding a counter to + * the summary does not mean re-editing every case in this file; these tests + * are about scheduling and coalescing, never about the counts. + */ +const EMPTY_SUMMARY = { + picked: 0, + delivered: 0, + failed: 0, + dead: 0, + skipped: 0, + released: 0, + recovered: 0, + recoveredDead: 0, +} + /** Resolves after the microtask queue drains, so floating work has run. */ const flush = () => new Promise((resolve) => setTimeout(resolve, 0)) @@ -24,7 +40,7 @@ beforeEach(() => { describe('kickWebhookDispatch', () => { it('runs one dispatch cycle with the small kick batch size', async () => { - const dispatch = vi.fn().mockResolvedValue({ picked: 1, delivered: 1, failed: 0, dead: 0 }) + const dispatch = vi.fn().mockResolvedValue({ ...EMPTY_SUMMARY, picked: 1, delivered: 1 }) kickWebhookDispatch(dispatch) await flush() @@ -46,7 +62,7 @@ describe('kickWebhookDispatch', () => { new Promise((resolve) => { setTimeout(() => { settled = true - resolve({ picked: 0, delivered: 0, failed: 0, dead: 0 }) + resolve({ ...EMPTY_SUMMARY }) }, 20) }), ) @@ -66,7 +82,7 @@ describe('kickWebhookDispatch', () => { it('coalesces a burst of kicks into a single cycle', async () => { // A bulk booking emits once per row. Without coalescing, 100 rows would // mean 100 claim round trips against the same handful of due deliveries. - const dispatch = vi.fn().mockResolvedValue({ picked: 0, delivered: 0, failed: 0, dead: 0 }) + const dispatch = vi.fn().mockResolvedValue({ ...EMPTY_SUMMARY }) for (let i = 0; i < 100; i++) kickWebhookDispatch(dispatch) await flush() @@ -75,7 +91,7 @@ describe('kickWebhookDispatch', () => { }) it('accepts a new kick once the previous cycle has started', async () => { - const dispatch = vi.fn().mockResolvedValue({ picked: 0, delivered: 0, failed: 0, dead: 0 }) + const dispatch = vi.fn().mockResolvedValue({ ...EMPTY_SUMMARY }) kickWebhookDispatch(dispatch) await flush() @@ -101,7 +117,7 @@ describe('kickWebhookDispatch', () => { kickWebhookDispatch(failing) await flush() - const ok = vi.fn().mockResolvedValue({ picked: 0, delivered: 0, failed: 0, dead: 0 }) + const ok = vi.fn().mockResolvedValue({ ...EMPTY_SUMMARY }) kickWebhookDispatch(ok) await flush() diff --git a/lib/webhooks/__tests__/dispatcher-auto-disable.test.ts b/lib/webhooks/__tests__/dispatcher-auto-disable.test.ts index f0968f8f..165f748a 100644 --- a/lib/webhooks/__tests__/dispatcher-auto-disable.test.ts +++ b/lib/webhooks/__tests__/dispatcher-auto-disable.test.ts @@ -76,12 +76,17 @@ function makeSupabase(opts: { } if (table === 'webhook_deliveries') { - // update(...).eq(...) -> markDead / markDelivered - // update(...).eq(...).lt(...).select('id') -> recoverStuckInFlight + // update(...).eq(...) -> markDead / markDelivered + // update(...).eq('id').eq('status').select('id') -> touchInFlight + // + // The touch must resolve to a NON-empty row set: an empty result means + // "this delivery is no longer ours" and the dispatcher skips the + // attempt, which would take the 410 auto-disable path out of reach. + // The stuck sweep no longer runs through this chain at all; it goes + // through rpc('recover_stuck_webhook_deliveries'). const thenable = { eq: () => thenable, - lt: () => thenable, - select: async () => ({ data: [], error: null }), + select: async () => ({ data: [{ id: DELIVERY_ID }], error: null }), then: (resolve: (v: { error: null }) => unknown) => resolve({ error: null }), } return { update: () => thenable } diff --git a/lib/webhooks/__tests__/dispatcher-stuck-recovery.test.ts b/lib/webhooks/__tests__/dispatcher-stuck-recovery.test.ts new file mode 100644 index 00000000..8ba7d151 --- /dev/null +++ b/lib/webhooks/__tests__/dispatcher-stuck-recovery.test.ts @@ -0,0 +1,470 @@ +/** + * Stuck-in_flight recovery and per-row re-stamping (#1257). + * + * Two defects are pinned here: + * + * 1. the sweep window used to be a fixed 2x REQUEST_TIMEOUT_MS (20 s), which + * is shorter than a single serial cycle, so cycle N recovered rows cycle + * N-1 was still working through; + * 2. recovery reset rows to 'failed' without charging an attempt, so + * MAX_ATTEMPTS stopped being a real cap. + * + * The window is now derived from the bounded cycle and the cap is enforced + * server-side by recover_stuck_webhook_deliveries, so the assertions here are + * about what the dispatcher hands the RPC and about the per-row re-stamp that + * makes a row's in_flight age measure its own attempt. + */ + +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest' +import type { SupabaseClient } from '@supabase/supabase-js' +import type { PinnedFetchResult } from '../pinned-fetch' + +vi.mock('@/lib/logger', () => ({ + createLogger: () => ({ + info: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + child: vi.fn(), + }), +})) + +// Import after mocks +import { dispatchDueDeliveries, __TESTING__ } from '../dispatcher' + +const COMPANY_ID = '11111111-1111-4111-8111-111111111111' +const WEBHOOK_ID = '22222222-2222-4222-8222-222222222222' +const DELIVERY_IDS = [ + 'aaaaaaaa-0001-4000-8000-000000000001', + 'aaaaaaaa-0002-4000-8000-000000000002', + 'aaaaaaaa-0003-4000-8000-000000000003', +] + +/** Fixed clock so the derived window is exactly assertable. */ +const NOW = new Date('2026-07-30T10:00:00.000Z') + +interface RecordedUpdate { + payload: Record + filters: Record +} + +interface Recorded { + rpcCalls: { fn: string; args: Record }[] + deliveryUpdates: RecordedUpdate[] +} + +/** + * Ordered-log Supabase stub in the same house style as + * dispatcher-auto-disable.test.ts. Every write against webhook_deliveries is + * appended to `deliveryUpdates` in the order it resolves, so the interleaving + * of touch writes and terminal writes is directly assertable. + * + * `lostOwnership` makes a specific delivery's touch resolve to zero rows, + * which is how the real table reports "another cycle owns this row now". + */ +function makeSupabase(opts: { + deliveryCount?: number + attempts?: number + lostOwnership?: Set + /** Rows the sweep RPC reports as recovered this tick. */ + recovered?: Array<{ id: string; status: string; attempts: number }> +} = {}): { client: SupabaseClient; recorded: Recorded } { + const recorded: Recorded = { rpcCalls: [], deliveryUpdates: [] } + const count = opts.deliveryCount ?? 1 + + const client = { + rpc: vi.fn(async (fn: string, args: Record) => { + recorded.rpcCalls.push({ fn, args }) + if (fn === 'claim_due_webhook_deliveries') { + return { + data: DELIVERY_IDS.slice(0, count).map((id) => ({ + id, + webhook_id: WEBHOOK_ID, + company_id: COMPANY_ID, + event_type: 'invoice.paid', + payload: { id: 'inv-1' }, + previous_attributes: null, + api_version: '2026-05-12', + attempts: opts.attempts ?? 0, + })), + error: null, + } + } + // recover_stuck_webhook_deliveries: nothing stuck unless a case says so. + return { data: opts.recovered ?? [], error: null } + }), + from: vi.fn((table: string) => { + if (table === 'webhook_deliveries') { + return { + update: (payload: Record) => { + const filters: Record = {} + const rec: RecordedUpdate = { payload, filters } + const chain: Record = { + eq: (col: string, val: unknown) => { + filters[col] = val + return chain + }, + in: (col: string, val: unknown) => { + filters[col] = val + return chain + }, + // touchInFlight terminates with .select('id') + select: async () => { + recorded.deliveryUpdates.push(rec) + const id = filters.id as string + const lost = opts.lostOwnership?.has(id) ?? false + return { data: lost ? [] : [{ id }], error: null } + }, + // markDelivered / markDead / markFailedForRetry await the chain + then: (resolve: (v: { error: null }) => unknown) => { + recorded.deliveryUpdates.push(rec) + return resolve({ error: null }) + }, + } + return chain + }, + } + } + + if (table === 'webhooks') { + return { + select: () => ({ + in: async () => ({ + data: [ + { + id: WEBHOOK_ID, + company_id: COMPANY_ID, + webhook_url: 'https://receiver.example.com/hook', + secret: 'whsec_test', + }, + ], + error: null, + }), + }), + } + } + + throw new Error(`unexpected table: ${table}`) + }), + } as unknown as SupabaseClient + + return { client, recorded } +} + +/** Receiver answers 200 and records which delivery ids were actually POSTed. */ +function makeOkFetch(postedIds: string[]) { + return async ( + _url: string, + init: { headers: Record }, + ): Promise => { + postedIds.push(init.headers['X-Gnubok-Delivery']) + return { + kind: 'ok', + status: 200, + headers: { 'content-type': 'application/json' }, + body: '{"ok":true}', + bodyTruncated: false, + pinnedAddress: '93.184.216.34', + } + } +} + +function recoverArgs(recorded: Recorded): Record { + const call = recorded.rpcCalls.find((c) => c.fn === 'recover_stuck_webhook_deliveries') + if (!call) throw new Error('recover_stuck_webhook_deliveries was never called') + return call.args +} + +describe('dispatcher stuck-in_flight recovery window', () => { + beforeEach(() => { + vi.clearAllMocks() + }) + + it('derives a window wider than one bounded cycle, so a mid-cycle row cannot be swept', async () => { + const { client, recorded } = makeSupabase() + + await dispatchDueDeliveries({ + supabase: client, + now: NOW, + pinnedFetchImpl: makeOkFetch([]) as never, + }) + + const args = recoverArgs(recorded) + const windowMs = NOW.getTime() - Date.parse(args.p_stuck_before as string) + + // The cycle budget (what actually bounds a cycle, whatever its batch size) + // plus one in-flight request plus slack. Spelled out as a literal as well + // as a derivation so a change to any constant has to be deliberate. + expect(windowMs).toBe(160_000) + expect(windowMs).toBe( + __TESTING__.CYCLE_BUDGET_MS + + __TESTING__.REQUEST_TIMEOUT_MS + + __TESTING__.STUCK_RECOVERY_SLACK_MS, + ) + + // The old threshold. A concurrent tick must no longer be able to re-arm a + // row that a live cycle claimed only a couple of attempts ago. + expect(windowMs).toBeGreaterThan(__TESTING__.REQUEST_TIMEOUT_MS * 2) + // And it must cover the whole bounded cycle, not just part of it. + expect(windowMs).toBeGreaterThan(__TESTING__.CYCLE_BUDGET_MS) + + expect(args.p_now).toBe(NOW.toISOString()) + }) + + it('uses the same window for the 5-row kick as for the 50-row cron', async () => { + const windows: number[] = [] + for (const batchSize of [5, __TESTING__.DEFAULT_BATCH_SIZE, 500]) { + const { client, recorded } = makeSupabase() + await dispatchDueDeliveries({ + supabase: client, + batchSize, + now: NOW, + pinnedFetchImpl: makeOkFetch([]) as never, + }) + windows.push(NOW.getTime() - Date.parse(recoverArgs(recorded).p_stuck_before as string)) + } + + // The sweep is tenant-global, so a small batch must not shrink the window + // and a large one must not stretch it: the cycle budget bounds every + // caller alike. A batch-derived window (the pre-#1257 shape, and the shape + // a "floor at DEFAULT_BATCH_SIZE" would silently allow again above 50) + // would produce 50_000 here for the kick and 160_000 for the cron. + expect(windows).toEqual([160_000, 160_000, 160_000]) + }) + + it('hands the attempts cap and the retry schedule to the RPC', async () => { + const { client, recorded } = makeSupabase() + + await dispatchDueDeliveries({ + supabase: client, + now: NOW, + pinnedFetchImpl: makeOkFetch([]) as never, + }) + + const args = recoverArgs(recorded) + // The cap stays single-sourced in TS; the increment happens in SQL, which + // is the only place `attempts = attempts + 1` can be expressed atomically. + expect(args.p_max_attempts).toBe(__TESTING__.MAX_ATTEMPTS) + expect(__TESTING__.MAX_ATTEMPTS).toBe(8) + + // And so does the backoff: a swept row must wait exactly as long as a row + // whose receiver answered 500. Re-arming at p_now let a repeatedly + // stranded delivery spend all 8 attempts inside half an hour and land in + // the terminal, immutable 'dead' state without ever being contacted. + expect(args.p_backoff).toEqual([...__TESTING__.RETRY_BACKOFF_SECONDS]) + expect(args.p_backoff).toEqual([60, 300, 1800, 7200, 43200, 86400, 172800]) + }) + + it('surfaces the sweep outcome in the summary, dead rows separately', async () => { + const { client } = makeSupabase({ + recovered: [ + { id: DELIVERY_IDS[0], status: 'failed', attempts: 2 }, + { id: DELIVERY_IDS[1], status: 'dead', attempts: 8 }, + { id: DELIVERY_IDS[2], status: 'dead', attempts: 8 }, + ], + }) + + const summary = await dispatchDueDeliveries({ + supabase: client, + now: NOW, + pinnedFetchImpl: makeOkFetch([]) as never, + }) + + // A tick that takes deliveries terminal has to be visible in the cron's + // own summary line, not only in a helper-level log.warn. + expect(summary.recovered).toBe(3) + expect(summary.recoveredDead).toBe(2) + }) +}) + +describe('dispatcher per-row in_flight re-stamp', () => { + beforeEach(() => { + vi.clearAllMocks() + }) + + it('re-stamps each row immediately before its own attempt, not once at claim time', async () => { + const { client, recorded } = makeSupabase({ deliveryCount: 3 }) + const posted: string[] = [] + + const summary = await dispatchDueDeliveries({ + supabase: client, + now: NOW, + pinnedFetchImpl: makeOkFetch(posted) as never, + }) + + expect(summary.delivered).toBe(3) + expect(posted).toEqual(DELIVERY_IDS) + + // touch, terminal, touch, terminal, touch, terminal. A single re-stamp at + // claim time (the pre-fix behaviour) would leave only the three terminal + // writes here, and rows 2 and 3 would carry the claim's updated_at into + // the next cycle's sweep window. + expect(recorded.deliveryUpdates).toHaveLength(6) + for (let i = 0; i < 3; i++) { + const touch = recorded.deliveryUpdates[i * 2] + expect(touch.payload).toEqual({ status: 'in_flight' }) + expect(touch.filters).toEqual({ id: DELIVERY_IDS[i], status: 'in_flight' }) + + const terminal = recorded.deliveryUpdates[i * 2 + 1] + expect(terminal.payload).toMatchObject({ status: 'delivered' }) + expect(terminal.filters).toEqual({ id: DELIVERY_IDS[i] }) + } + }) + + it('drops the POST when the touch shows the row is no longer ours', async () => { + const { client, recorded } = makeSupabase({ + deliveryCount: 3, + lostOwnership: new Set([DELIVERY_IDS[1]]), + }) + const posted: string[] = [] + + const summary = await dispatchDueDeliveries({ + supabase: client, + now: NOW, + pinnedFetchImpl: makeOkFetch(posted) as never, + }) + + // The duplicate POST is what the issue calls avoidable load: the loser of + // the race would have had its terminal write swallowed by the immutability + // trigger anyway. + expect(posted).toEqual([DELIVERY_IDS[0], DELIVERY_IDS[2]]) + expect(posted).not.toContain(DELIVERY_IDS[1]) + expect(summary.skipped).toBe(1) + expect(summary.delivered).toBe(2) + + // No terminal write for the row we no longer own. + const terminalForRow2 = recorded.deliveryUpdates.filter( + (u) => u.filters.id === DELIVERY_IDS[1] && u.payload.status !== 'in_flight', + ) + expect(terminalForRow2).toHaveLength(0) + }) + + it('reconciles the summary: picked === delivered + failed + dead + skipped + released', async () => { + const { client } = makeSupabase({ + deliveryCount: 3, + lostOwnership: new Set([DELIVERY_IDS[2]]), + }) + + const summary = await dispatchDueDeliveries({ + supabase: client, + now: NOW, + pinnedFetchImpl: makeOkFetch([]) as never, + }) + + expect(summary.picked).toBe(3) + expect( + summary.delivered + summary.failed + summary.dead + summary.skipped + summary.released, + ).toBe(summary.picked) + }) +}) + +describe('dispatcher cycle budget', () => { + beforeEach(() => { + vi.clearAllMocks() + }) + + afterEach(() => { + vi.restoreAllMocks() + }) + + it('hands back unattempted claims instead of stranding them in in_flight', async () => { + const { client, recorded } = makeSupabase({ deliveryCount: 3 }) + const posted: string[] = [] + + // `Date.now` is the dispatcher's only real-clock read (the injected `now` + // covers everything else), so driving it directly is enough to simulate a + // receiver that ate the whole budget on the first row. + let clock = 1_000_000 + vi.spyOn(Date, 'now').mockImplementation(() => clock) + + const slowFetch = async ( + _url: string, + init: { headers: Record }, + ): Promise => { + posted.push(init.headers['X-Gnubok-Delivery']) + clock += __TESTING__.CYCLE_BUDGET_MS + return { + kind: 'ok', + status: 200, + headers: { 'content-type': 'application/json' }, + body: '{"ok":true}', + bodyTruncated: false, + pinnedAddress: '93.184.216.34', + } + } + + const summary = await dispatchDueDeliveries({ + supabase: client, + now: NOW, + pinnedFetchImpl: slowFetch as never, + }) + + // Row 1 fits, rows 2 and 3 do not: they are released, not POSTed. + expect(posted).toEqual([DELIVERY_IDS[0]]) + expect(summary.delivered).toBe(1) + expect(summary.released).toBe(2) + expect(summary.picked).toBe(3) + + // Released rows go back to a re-claimable state immediately. Without this + // they would sit in in_flight for the full 160 s window before any sweep + // could re-arm them, and the sweep would then charge them an attempt they + // never made. + // + // 'pending', not 'failed': these rows carry attempts = 0, so they had + // never been attempted and their pre-claim status was necessarily + // 'pending'. webhook_deliveries is customer-visible behandlingshistorik; + // a delivery that was claimed and handed back without a single POST must + // not read as a failure there. + const release = recorded.deliveryUpdates.at(-1) + expect(release?.payload).toEqual({ + status: 'pending', + next_attempt_at: NOW.toISOString(), + }) + expect(release?.filters).toEqual({ + id: [DELIVERY_IDS[1], DELIVERY_IDS[2]], + status: 'in_flight', + }) + // Not an attempt: `attempts` must not be bumped and the previous attempt's + // diagnostic must survive. + expect(release?.payload).not.toHaveProperty('attempts') + expect(release?.payload).not.toHaveProperty('error') + }) + + it('releases a previously attempted row back to failed, not pending', async () => { + const { client, recorded } = makeSupabase({ deliveryCount: 3, attempts: 2 }) + const posted: string[] = [] + + let clock = 1_000_000 + vi.spyOn(Date, 'now').mockImplementation(() => clock) + + const slowFetch = async ( + _url: string, + init: { headers: Record }, + ): Promise => { + posted.push(init.headers['X-Gnubok-Delivery']) + clock += __TESTING__.CYCLE_BUDGET_MS + return { + kind: 'ok', + status: 200, + headers: { 'content-type': 'application/json' }, + body: '{"ok":true}', + bodyTruncated: false, + pinnedAddress: '93.184.216.34', + } + } + + const summary = await dispatchDueDeliveries({ + supabase: client, + now: NOW, + pinnedFetchImpl: slowFetch as never, + }) + + expect(summary.released).toBe(2) + // attempts > 0 means the row was already in the retry loop before this + // cycle claimed it, so 'failed' is its real pre-claim status. + const release = recorded.deliveryUpdates.at(-1) + expect(release?.payload).toEqual({ + status: 'failed', + next_attempt_at: NOW.toISOString(), + }) + }) +}) diff --git a/lib/webhooks/__tests__/recover-stuck-webhook-deliveries.pg.test.ts b/lib/webhooks/__tests__/recover-stuck-webhook-deliveries.pg.test.ts new file mode 100644 index 00000000..786938c5 --- /dev/null +++ b/lib/webhooks/__tests__/recover-stuck-webhook-deliveries.pg.test.ts @@ -0,0 +1,547 @@ +import { randomUUID } from 'node:crypto' +import { afterAll, describe, expect, it } from 'vitest' +import { getClient, getPool, runAsServiceRole } from '@/tests/pg/setup' +import { seedCompany } from '@/tests/pg/fixtures' + +/** + * recover_stuck_webhook_deliveries (migration 20260730123000, issue #1257). + * + * The sweep that pulls webhook deliveries out of in_flight moved from a + * PostgREST chain into SQL so it can charge an attempt atomically and land a + * row past MAX_ATTEMPTS on the same terminal state the normal retry path + * produces. The properties that need real Postgres: + * + * - `attempts = attempts + 1` actually happens (PostgREST cannot express it) + * - the re-armed row waits out the SAME backoff a normal failed attempt + * waits, so a repeatedly stranded row cannot burn its 8 attempts in + * minutes and land in the immutable 'dead' state uncontacted + * - a row at the cap becomes 'dead' with attempts = p_max_attempts, and the + * claim function then never picks it up again + * - terminal rows are skipped by the outer WHERE, so + * enforce_webhook_delivery_immutability never fires + * - the service-role gate rejects everyone else + */ + +// ────────────────────────────────────────────────────────────────────── +// Fixtures: parent webhook + child delivery (copied from +// claim-due-webhook-deliveries.pg.test.ts, plus explicit updated_at) +// ────────────────────────────────────────────────────────────────────── + +const MAX_ATTEMPTS = 8 + +/** + * RETRY_BACKOFF_SECONDS from lib/webhooks/dispatcher.ts, spelled out rather + * than imported: this file asserts what the SQL does with the array it is + * handed, and importing the constant would make a schedule change silently + * rewrite the expectations too. + */ +const BACKOFF = [60, 5 * 60, 30 * 60, 2 * 60 * 60, 12 * 60 * 60, 24 * 60 * 60, 48 * 60 * 60] + +/** + * Every delivery this file seeds, so the non-terminal ones can be removed + * again. The suite is tenant-global by nature (the sweep has no company + * filter) and a leftover row that becomes due later shows up as a phantom + * extra claim in the sibling claim-due suite, which reads the whole table. + * Terminal rows are left alone: block_webhook_delivery_terminal_delete + * forbids deleting them, and the claim function never picks them up anyway. + */ +const seededDeliveryIds: string[] = [] + +afterAll(async () => { + if (seededDeliveryIds.length === 0) return + await getPool().query( + `DELETE FROM public.webhook_deliveries + WHERE id = ANY($1::uuid[]) AND status NOT IN ('delivered', 'dead')`, + [seededDeliveryIds], + ) +}) + +async function insertWebhook(params: { companyId: string }): Promise { + const id = randomUUID() + await getPool().query( + `INSERT INTO public.webhooks + (id, company_id, name, event_type, webhook_url, secret, active) + VALUES ($1, $2, 'pg-test', 'invoice.paid', 'https://example.com/hook', $3, true)`, + [id, params.companyId, `whsec_${randomUUID().replace(/-/g, '')}`], + ) + return id +} + +/** + * updated_at is only auto-stamped by the BEFORE UPDATE trigger, so a value + * supplied at INSERT time sticks: that is what lets a row be seeded as + * "abandoned N seconds ago". + */ +async function insertDelivery(params: { + webhookId: string | null + companyId: string + status?: 'pending' | 'in_flight' | 'delivered' | 'failed' | 'dead' + attempts?: number + updatedAt?: string + nextAttemptAt?: string + responseStatus?: number | null +}): Promise { + const id = randomUUID() + await getPool().query( + `INSERT INTO public.webhook_deliveries + (id, webhook_id, company_id, event_type, payload, api_version, + status, next_attempt_at, attempts, updated_at, response_status) + VALUES ($1, $2, $3, 'invoice.paid', '{"hello":"world"}'::jsonb, '2026-05-12', + $4, $5, $6, $7, $8)`, + [ + id, + params.webhookId, + params.companyId, + params.status ?? 'in_flight', + params.nextAttemptAt ?? new Date().toISOString(), + params.attempts ?? 0, + params.updatedAt ?? new Date().toISOString(), + params.responseStatus ?? null, + ], + ) + seededDeliveryIds.push(id) + return id +} + +interface DeliveryRow { + status: string + attempts: number + error: string | null + next_attempt_at: Date + response_status: number | null +} + +async function readDelivery(id: string): Promise { + const r = await getPool().query( + `SELECT status, attempts, error, next_attempt_at, response_status + FROM public.webhook_deliveries WHERE id = $1`, + [id], + ) + const row = r.rows[0] + if (!row) throw new Error(`delivery ${id} not found`) + return row +} + +/** A timestamp far enough in the past to be inside any sane sweep window. */ +function longAgo(seconds: number): string { + return new Date(Date.now() - seconds * 1000).toISOString() +} + +/** Sweep boundary: rows older than this are abandoned. */ +function stuckBefore(seconds = 160): string { + return new Date(Date.now() - seconds * 1000).toISOString() +} + +describe('recover_stuck_webhook_deliveries.pg', () => { + it('charges an attempt and re-arms an abandoned in_flight row', async () => { + const { companyId } = await seedCompany() + const webhookId = await insertWebhook({ companyId }) + const deliveryId = await insertDelivery({ + webhookId, + companyId, + status: 'in_flight', + attempts: 0, + updatedAt: longAgo(600), + }) + + const pNow = new Date() + const returned = await runAsServiceRole(async (client) => { + const r = await client.query<{ id: string; status: string; attempts: number }>( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], $4)`, + [stuckBefore(), MAX_ATTEMPTS, BACKOFF, pNow.toISOString()], + ) + return r.rows + }) + + expect(returned.find((r) => r.id === deliveryId)).toMatchObject({ + status: 'failed', + attempts: 1, + }) + + const row = await readDelivery(deliveryId) + // The undercount is the second half of #1257: without the increment a row + // caught in the recover/re-claim loop is re-POSTed past MAX_ATTEMPTS. + expect(row.attempts).toBe(1) + expect(row.status).toBe('failed') + expect(row.error).toBe('recovered_from_in_flight_timeout') + // First backoff step, exactly like markFailedForRetry on a 0-attempt row. + // p_now would make the row re-claimable on the next per-minute tick, which + // is how a repeatedly stranded delivery burned all 8 attempts in minutes. + expect(row.next_attempt_at.getTime()).toBe(pNow.getTime() + BACKOFF[0] * 1000) + }) + + it('re-arms a swept row far enough out that the next tick cannot claim it', async () => { + const { companyId } = await seedCompany() + const webhookId = await insertWebhook({ companyId }) + const deliveryId = await insertDelivery({ + webhookId, + companyId, + status: 'in_flight', + attempts: 0, + updatedAt: longAgo(600), + }) + + const pNow = new Date() + await runAsServiceRole(async (client) => { + await client.query( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], $4)`, + [stuckBefore(), MAX_ATTEMPTS, BACKOFF, pNow.toISOString()], + ) + }) + + // The claim function is the real predicate: a swept row must NOT be due + // at the moment it was swept, nor a tick later. Rolled back so the claim's + // in_flight flips do not leak into the sibling claim-due suite. + const client = await getClient() + try { + await client.query('BEGIN') + const { rows } = await client.query<{ id: string }>( + `SELECT id FROM public.claim_due_webhook_deliveries($1, $2)`, + [100, new Date(pNow.getTime() + 59_000).toISOString()], + ) + expect(rows.map((r) => r.id)).not.toContain(deliveryId) + } finally { + await client.query('ROLLBACK').catch(() => {}) + client.release() + } + }) + + it('picks the backoff step for the attempt it just charged', async () => { + const { companyId } = await seedCompany() + const webhookId = await insertWebhook({ companyId }) + // attempts = 3 before the sweep, so the charged attempt is the 4th and the + // wait is BACKOFF[3] (2 h): index = attempts BEFORE this one, exactly the + // lookup markFailedForRetry does in TS, shifted by one for 1-indexed + // Postgres arrays. + const deliveryId = await insertDelivery({ + webhookId, + companyId, + status: 'in_flight', + attempts: 3, + updatedAt: longAgo(600), + }) + + const pNow = new Date() + await runAsServiceRole(async (client) => { + await client.query( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], $4)`, + [stuckBefore(), MAX_ATTEMPTS, BACKOFF, pNow.toISOString()], + ) + }) + + const row = await readDelivery(deliveryId) + expect(row.attempts).toBe(4) + expect(row.next_attempt_at.getTime()).toBe(pNow.getTime() + BACKOFF[3] * 1000) + }) + + it('clamps to the last backoff step instead of subscripting past the array', async () => { + const { companyId } = await seedCompany() + const webhookId = await insertWebhook({ companyId }) + const deliveryId = await insertDelivery({ + webhookId, + companyId, + status: 'in_flight', + attempts: 4, + updatedAt: longAgo(600), + }) + + // A two-step schedule with a cap of 8: index 5 is past the end. Without + // the least() clamp the subscript yields NULL and next_attempt_at would go + // NULL, which the claim function reads as "not due, ever". + const shortBackoff = [60, 300] + const pNow = new Date() + await runAsServiceRole(async (client) => { + await client.query( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], $4)`, + [stuckBefore(), MAX_ATTEMPTS, shortBackoff, pNow.toISOString()], + ) + }) + + const row = await readDelivery(deliveryId) + expect(row.attempts).toBe(5) + expect(row.next_attempt_at).not.toBeNull() + expect(row.next_attempt_at.getTime()).toBe(pNow.getTime() + 300 * 1000) + }) + + it('lands a row at the cap on the same dead state the normal path produces', async () => { + const { companyId } = await seedCompany() + const webhookId = await insertWebhook({ companyId }) + const deliveryId = await insertDelivery({ + webhookId, + companyId, + status: 'in_flight', + attempts: MAX_ATTEMPTS - 1, + updatedAt: longAgo(600), + responseStatus: 503, + }) + + await runAsServiceRole(async (client) => { + await client.query( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], now())`, + [stuckBefore(), MAX_ATTEMPTS, BACKOFF], + ) + }) + + const row = await readDelivery(deliveryId) + expect(row.status).toBe('dead') + expect(row.attempts).toBe(MAX_ATTEMPTS) + expect(row.error).toBe('attempts_exhausted:in_flight_timeout') + // The last recorded response is the only diagnostic left on an abandoned + // attempt: recovery must not null it out the way markDead-without-outcome + // does. + expect(row.response_status).toBe(503) + }) + + it('does not retry a recovered-at-cap row forever: the claim function skips it', async () => { + const { companyId } = await seedCompany() + const webhookId = await insertWebhook({ companyId }) + const deliveryId = await insertDelivery({ + webhookId, + companyId, + status: 'in_flight', + attempts: MAX_ATTEMPTS - 1, + updatedAt: longAgo(600), + }) + + await runAsServiceRole(async (client) => { + await client.query( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], now())`, + [stuckBefore(), MAX_ATTEMPTS, BACKOFF], + ) + }) + expect((await readDelivery(deliveryId)).status).toBe('dead') + + // Inside a rolled-back transaction: the claim function flips every due row + // in the table to in_flight, and this suite must not leave that behind for + // the sibling claim-due file. + const client = await getClient() + try { + await client.query('BEGIN') + const { rows } = await client.query<{ id: string }>( + `SELECT id FROM public.claim_due_webhook_deliveries($1, now())`, + [100], + ) + expect(rows.map((r) => r.id)).not.toContain(deliveryId) + } finally { + await client.query('ROLLBACK').catch(() => {}) + client.release() + } + }) + + it('a second sweep over the same rows does not trip the immutability trigger', async () => { + const { companyId } = await seedCompany() + const webhookId = await insertWebhook({ companyId }) + const deliveryId = await insertDelivery({ + webhookId, + companyId, + status: 'in_flight', + attempts: MAX_ATTEMPTS - 1, + updatedAt: longAgo(600), + }) + + const sweep = () => + runAsServiceRole(async (client) => { + await client.query( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], now())`, + [stuckBefore(), MAX_ATTEMPTS, BACKOFF], + ) + }) + + await sweep() + // The row is now 'dead', so the WHERE excludes it and + // enforce_webhook_delivery_immutability is never reached. A sweep that + // matched terminal rows would abort the whole statement with a + // check_violation. + await expect(sweep()).resolves.toBeUndefined() + + const row = await readDelivery(deliveryId) + expect(row.status).toBe('dead') + expect(row.attempts).toBe(MAX_ATTEMPTS) + }) + + it('leaves a row a live cycle is still working through alone', async () => { + const { companyId } = await seedCompany() + const webhookId = await insertWebhook({ companyId }) + // Freshly re-stamped by touchInFlight right before its own attempt. + const deliveryId = await insertDelivery({ + webhookId, + companyId, + status: 'in_flight', + attempts: 2, + updatedAt: new Date().toISOString(), + }) + + const returned = await runAsServiceRole(async (client) => { + const r = await client.query<{ id: string }>( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], now())`, + [stuckBefore(), MAX_ATTEMPTS, BACKOFF], + ) + return r.rows + }) + + expect(returned.map((r) => r.id)).not.toContain(deliveryId) + const row = await readDelivery(deliveryId) + expect(row.status).toBe('in_flight') + expect(row.attempts).toBe(2) + }) + + it('never touches terminal rows, however old their updated_at is', async () => { + const { companyId } = await seedCompany() + const webhookId = await insertWebhook({ companyId }) + const deliveredId = await insertDelivery({ + webhookId, + companyId, + status: 'delivered', + attempts: 1, + updatedAt: longAgo(6000), + }) + const deadId = await insertDelivery({ + webhookId, + companyId, + status: 'dead', + attempts: MAX_ATTEMPTS, + updatedAt: longAgo(6000), + }) + + // No check_violation: the statement must complete, not abort. + await expect( + runAsServiceRole(async (client) => { + await client.query( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], now())`, + [stuckBefore(), MAX_ATTEMPTS, BACKOFF], + ) + }), + ).resolves.toBeUndefined() + + expect(await readDelivery(deliveredId)).toMatchObject({ status: 'delivered', attempts: 1 }) + expect(await readDelivery(deadId)).toMatchObject({ status: 'dead', attempts: MAX_ATTEMPTS }) + }) + + it('requires the service role', async () => { + // Plain pool: superuser connection, auth.role() NULL. Nothing reachable by + // anon or authenticated may re-arm another tenant's deliveries. + await expect( + getPool().query( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], now())`, + [stuckBefore(), MAX_ATTEMPTS, BACKOFF], + ), + ).rejects.toThrow(/server-controlled service role/i) + }) + + it('rejects a missing stuck boundary and a non-positive cap', async () => { + await expect( + runAsServiceRole(async (client) => { + await client.query( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], now())`, + [null, MAX_ATTEMPTS, BACKOFF], + ) + }), + ).rejects.toThrow(/p_stuck_before is required/i) + + await expect( + runAsServiceRole(async (client) => { + await client.query( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], now())`, + [stuckBefore(), 0, BACKOFF], + ) + }), + ).rejects.toThrow(/p_max_attempts must be > 0/i) + + await expect( + runAsServiceRole(async (client) => { + await client.query( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], now())`, + [stuckBefore(), null, BACKOFF], + ) + }), + ).rejects.toThrow(/p_max_attempts must be > 0/i) + }) + + it('rejects a missing or non-positive backoff schedule', async () => { + // A NULL, empty or zero/negative schedule would re-arm swept rows for + // immediate re-claim, which is the strand loop the backoff exists to stop. + // Failing loudly beats silently reverting to next_attempt_at = p_now. + for (const backoff of [null, [], [60, 0], [60, -5]]) { + await expect( + runAsServiceRole(async (client) => { + await client.query( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], now())`, + [stuckBefore(), MAX_ATTEMPTS, backoff], + ) + }), + ).rejects.toThrow(/p_backoff/i) + } + }) +}) + +/** + * The other half of #1257 lives in TypeScript (touchInFlight), but it rests + * entirely on two DB behaviours that no mock can prove. Pinned here because + * if either stops holding, the fix silently reverts to the defect: a row + * carrying its claim-time updated_at into the next cycle's sweep. + */ +describe('in_flight re-stamp: the DB behaviour touchInFlight relies on', () => { + /** Byte-for-byte what PostgREST issues for the touchInFlight chain. */ + const TOUCH_SQL = `UPDATE public.webhook_deliveries + SET status = 'in_flight' + WHERE id = $1 AND status = 'in_flight' + RETURNING id` + + it('re-stamps updated_at on a no-op status write, pulling the row out of the sweep window', async () => { + const { companyId } = await seedCompany() + const webhookId = await insertWebhook({ companyId }) + // Claimed 10 minutes ago: deep inside any sweep window. + const deliveryId = await insertDelivery({ + webhookId, + companyId, + status: 'in_flight', + attempts: 1, + updatedAt: longAgo(600), + }) + + const touched = await getPool().query<{ id: string }>(TOUCH_SQL, [deliveryId]) + expect(touched.rowCount).toBe(1) + + // Postgres runs the UPDATE even though no column value changed, so the + // BEFORE UPDATE update_updated_at_column trigger (migration + // 20260515200000) fires and re-stamps updated_at. Without that, writing + // the status back verbatim would be an expensive no-op and the row's + // in_flight age would still measure the claim, not the attempt. + const { rows } = await getPool().query<{ updated_at: Date }>( + `SELECT updated_at FROM public.webhook_deliveries WHERE id = $1`, + [deliveryId], + ) + expect(Date.now() - rows[0].updated_at.getTime()).toBeLessThan(60_000) + + // And that is the property the sweep reads: the row was swept-eligible a + // moment ago and is not any more. + const swept = await runAsServiceRole(async (client) => { + const r = await client.query<{ id: string }>( + `SELECT * FROM public.recover_stuck_webhook_deliveries($1, $2, $3::int[], now())`, + [stuckBefore(), MAX_ATTEMPTS, BACKOFF], + ) + return r.rows + }) + expect(swept.map((r) => r.id)).not.toContain(deliveryId) + expect(await readDelivery(deliveryId)).toMatchObject({ status: 'in_flight', attempts: 1 }) + }) + + it('matches no row on a terminal delivery, so the immutability trigger never fires', async () => { + const { companyId } = await seedCompany() + const webhookId = await insertWebhook({ companyId }) + const deliveryId = await insertDelivery({ + webhookId, + companyId, + status: 'delivered', + attempts: 1, + updatedAt: longAgo(600), + }) + + // The status filter is what keeps the touch off terminal rows. If it were + // dropped, this would abort with a check_violation instead of returning + // zero rows, and the dispatcher would read that as "row still ours". + const touched = await getPool().query<{ id: string }>(TOUCH_SQL, [deliveryId]) + expect(touched.rowCount).toBe(0) + expect(await readDelivery(deliveryId)).toMatchObject({ status: 'delivered', attempts: 1 }) + }) +}) diff --git a/lib/webhooks/dispatch-kick.ts b/lib/webhooks/dispatch-kick.ts index 48f031e8..0a428065 100644 --- a/lib/webhooks/dispatch-kick.ts +++ b/lib/webhooks/dispatch-kick.ts @@ -34,13 +34,27 @@ * the same row at the same moment. That is a claim-time guarantee only, and it * is worth being precise about what it does NOT buy: the RPC autocommits, so * its locks are gone before any POST is issued, and from then on ownership is - * just status='in_flight'. A later cycle's recoverStuckInFlight sweep can - * re-arm a row that is still queued behind an earlier cycle's serial loop. - * Delivery therefore stays at-least-once, exactly as the public docs promise - * ("the same delivery id may arrive more than once ... idempotency is on - * you"). The kick does not change that contract: the cron already claims 50 - * rows serially against the same 20 s stuck threshold, which is a wider window - * than this batch of 5 can open. + * just status='in_flight'. Delivery therefore stays at-least-once, exactly as + * the public docs promise ("the same delivery id may arrive more than once ... + * idempotency is on you"). + * + * The kick does not widen that. Since #1257 the stuck sweep's window is a + * constant derived from the dispatcher's cycle budget rather than from the + * caller's batch size, so it is identical for both callers and always wider + * than any live cycle: neither the cron nor this 5-row kick can re-arm a row + * the other still owns. What remains is the genuine crash case, where a + * hard-killed invocation's rows are recovered while its POSTs may still be in + * flight; the ownership check in touchInFlight drops the loser's POST before + * it is issued. + * + * One asymmetry is worth stating plainly: the cron route backs the dispatcher's + * CYCLE_BUDGET_MS with `export const maxDuration = 300`, but this path cannot. + * after() runs inside whatever arbitrary API route emitted the event, and that + * route's maxDuration is not ours to set. It does not need to be: a kick claims + * at most KICK_BATCH_SIZE (5) rows and each attempt is capped at + * REQUEST_TIMEOUT_MS (10 s), so a kick cycle cannot exceed ~50 s of attempt + * time and the dispatcher's 110 s budget check never fires here. The bound on + * the kick is its batch size, not a clock. */ import { after } from 'next/server' diff --git a/lib/webhooks/dispatcher.ts b/lib/webhooks/dispatcher.ts index 5e9db252..d4355c78 100644 --- a/lib/webhooks/dispatcher.ts +++ b/lib/webhooks/dispatcher.ts @@ -45,6 +45,48 @@ const MAX_ATTEMPTS = RETRY_BACKOFF_SECONDS.length + 1 // initial + 7 retries = 8 const REQUEST_TIMEOUT_MS = 10_000 const MAX_RESPONSE_BODY_BYTES = 4096 +/** Rows claimed per cycle when the caller passes nothing: the cron. */ +const DEFAULT_BATCH_SIZE = 50 + +/** + * Wall-clock ceiling on one cycle's serial attempt loop. 50 rows at a 10 s + * receiver timeout is 500 s of worst case, which no serverless invocation + * survives, so bound the cycle explicitly instead of letting the platform + * kill it mid-loop and leaving the remainder to the sweep. + * + * The cron route backs this with `export const maxDuration = 300` + * (app/api/webhooks/dispatch/cron/route.ts): the budget is only a real bound + * if the platform actually grants the invocation more wall time than the + * budget spends, and the release path below only runs if the loop is still + * alive when the budget expires. + */ +const CYCLE_BUDGET_MS = 120_000 + +/** Slack over the cycle bound: claim round trip, re-stamp, terminal write, clock skew. */ +const STUCK_RECOVERY_SLACK_MS = 30_000 + +/** + * How long an in_flight row may legitimately sit before the sweep may treat + * it as abandoned: 160 s. Derived, not guessed (#1257), and deliberately + * independent of batch size. + * + * A cycle attempts its rows serially at up to REQUEST_TIMEOUT_MS each, but + * the loop is cut off by CYCLE_BUDGET_MS regardless of how many rows were + * claimed, so the BUDGET, not the row count, is what bounds a cycle's life: + * budget + one in-flight request + slack. A 5-row kick and a 50-row cron + * therefore use the same window, which is what the tenant-global sweep needs + * (neither caller may re-arm a row the other still owns). Anything + * batch-derived would let the kick pick a window narrower than the cron's + * live cycle occupies, which is the shape #1257 was reported against. + * + * A plain constant rather than a function of batchSize on purpose: the + * previous shape took a batchSize it could not act on (the clamp swallowed + * every value) and documented a floor that never fired. If CYCLE_BUDGET_MS + * changes this moves with it, and the cron's maxDuration must stay + * comfortably above it. + */ +const STUCK_IN_FLIGHT_AFTER_MS = CYCLE_BUDGET_MS + REQUEST_TIMEOUT_MS + STUCK_RECOVERY_SLACK_MS + interface DueDelivery { id: string webhook_id: string @@ -68,6 +110,14 @@ export interface DispatchSummary { delivered: number failed: number dead: number + /** Claimed but no longer ours by the time the attempt was due to start. */ + skipped: number + /** Claimed but handed back unattempted because the cycle budget ran out. */ + released: number + /** Rows this tick's sweep pulled out of an abandoned in_flight state. */ + recovered: number + /** Subset of `recovered` the sweep took terminal (attempts exhausted). */ + recoveredDead: number } /** @@ -85,21 +135,41 @@ export async function dispatchDueDeliveries(args: { /** Override for tests; injected pinned-fetch implementation. */ pinnedFetchImpl?: typeof pinnedHttpsFetch }): Promise { - const batchSize = args.batchSize ?? 50 + const batchSize = args.batchSize ?? DEFAULT_BATCH_SIZE const now = args.now ?? new Date() const pinnedFetchImpl = args.pinnedFetchImpl ?? pinnedHttpsFetch - const summary: DispatchSummary = { picked: 0, delivered: 0, failed: 0, dead: 0 } + const summary: DispatchSummary = { + picked: 0, + delivered: 0, + failed: 0, + dead: 0, + skipped: 0, + released: 0, + recovered: 0, + recoveredDead: 0, + } // Recover stuck in_flight rows: a previous tick that was killed mid-flight // (Vercel function timeout, hard crash, manual termination) leaves rows // marked in_flight forever otherwise. Sweep them back to 'failed' so the - // retry loop picks them up at next_attempt_at. + // retry loop picks them up at next_attempt_at, on the same backoff schedule + // a normal failed attempt gets. // - // Threshold = 2× REQUEST_TIMEOUT_MS. A live attempt takes at most - // REQUEST_TIMEOUT_MS plus the body read; doubling that gives an - // unambiguous "this is stuck, not in-flight" boundary. - await recoverStuckInFlight(args.supabase, now) + // The window is STUCK_IN_FLIGHT_AFTER_MS: the bounded cycle + // (CYCLE_BUDGET_MS, backed by the route's maxDuration) plus one receiver + // timeout plus slack. It is deliberately WIDER than any live cycle can be, + // so a row still queued behind an earlier cycle's serial loop is never + // re-armed under it (#1257). The old fixed 2x REQUEST_TIMEOUT_MS was + // narrower than a single cycle, which made every cycle recover the rows + // the previous cycle was still working through. + const recovery = await recoverStuckInFlight(args.supabase, now) + summary.recovered = recovery.recovered + summary.recoveredDead = recovery.dead + + // Real clock, not the injectable `now`: the budget bounds this invocation's + // wall time, so a fixed test `now` must not be able to trip it. + const cycleStartedAt = Date.now() const due = await claimDueDeliveries(args.supabase, batchSize, now) summary.picked = due.length @@ -109,7 +179,24 @@ export async function dispatchDueDeliveries(args: { const webhookIds = Array.from(new Set(due.map((d) => d.webhook_id))) const webhookMap = await loadWebhooksByIds(args.supabase, webhookIds) - for (const delivery of due) { + for (const [index, delivery] of due.entries()) { + // Out of budget: hand back everything we will not reach rather than + // letting the platform kill the invocation mid-loop and leaving the + // remainder stranded in in_flight until a sweep re-arms it. + if (Date.now() - cycleStartedAt >= CYCLE_BUDGET_MS - REQUEST_TIMEOUT_MS) { + const remaining = due.slice(index) + await releaseUnattempted( + args.supabase, + remaining.map((d) => ({ id: d.id, attempts: d.attempts })), + now, + ) + summary.released = remaining.length + log.warn('cycle budget exhausted: unattempted claims released', { + count: remaining.length, + }) + break + } + const webhook = webhookMap.get(delivery.webhook_id) if (!webhook) { // The webhook was deleted between enqueue and dispatch. Mark dead; @@ -137,6 +224,19 @@ export async function dispatchDueDeliveries(args: { continue } + // Re-stamp updated_at immediately before this row's own attempt, so the + // row's in_flight age measures the attempt rather than the claim, and use + // the same write as an ownership check (#1257). + if (!(await touchInFlight(args.supabase, delivery.id))) { + log.info('delivery skipped: no longer in_flight', { + deliveryId: delivery.id, + webhookId: webhook.id, + companyId: delivery.company_id, + }) + summary.skipped++ + continue + } + const outcome = await attemptDelivery({ delivery, webhook, @@ -193,37 +293,64 @@ export async function dispatchDueDeliveries(args: { // ────────────────────────────────────────────────────────────────────── /** - * Mark in_flight rows whose updated_at is older than the stuck-threshold - * back to 'failed' with next_attempt_at = now so they re-enter the - * dispatch queue. Best-effort: a write failure here is logged but + * Sweep in_flight rows whose updated_at is older than the stuck-threshold + * back into the retry queue, charging an attempt for the stall so + * MAX_ATTEMPTS stays a real cap. Best-effort: a failure here is logged but * doesn't block the rest of the cycle. + * + * The predicate now lives in SQL (recover_stuck_webhook_deliveries, + * migration 20260730123000) rather than in a PostgREST chain, because + * PostgREST can express neither `attempts = attempts + 1` nor the + * conditional flip to 'dead' at the cap, and a read-then-write loop would + * reopen a TOCTOU against enforce_webhook_delivery_immutability. MAX_ATTEMPTS + * and RETRY_BACKOFF_SECONDS are passed in so the cap AND the schedule stay + * single-sourced here in TS. + * + * A swept row is re-armed on the SAME backoff the normal failure path uses + * (markFailedForRetry), not immediately: a row that keeps getting stranded + * (deploy, instance recycle, a cycle that outlives its invocation) would + * otherwise be re-claimed on the very next per-minute tick, and could burn + * all MAX_ATTEMPTS in under half an hour and land in the terminal, immutable + * 'dead' state without its receiver ever having been contacted. The ~87 h + * retry schedule is the delivery guarantee; the sweep must not shorten it. + * + * Under READ COMMITTED (Postgres default), UPDATE re-evaluates the WHERE + * clause against each row's current value when it acquires the row lock. + * The function keeps `status = 'in_flight'` in the outer UPDATE's WHERE for + * exactly that reason: a row that raced from 'in_flight' to + * 'delivered'/'dead' between scan and lock fails re-evaluation and is + * skipped entirely, so the immutability trigger never fires and a mid-flight + * terminal flip cannot abort the sweep. */ -async function recoverStuckInFlight(supabase: SupabaseClient, now: Date): Promise { - const stuckBefore = new Date(now.getTime() - 2 * REQUEST_TIMEOUT_MS) - // Under READ COMMITTED (Postgres default), UPDATE re-evaluates the WHERE - // clause against each row's current value when it acquires the row lock. - // A row that raced from 'in_flight' to 'delivered'/'dead' between scan - // and lock will fail status='in_flight' on re-evaluation and be skipped - // entirely: the immutability trigger never fires, so a mid-flight - // terminal flip cannot abort the bulk update. - const { data, error } = await supabase - .from('webhook_deliveries') - .update({ - status: 'failed', - next_attempt_at: now.toISOString(), - error: 'recovered_from_in_flight_timeout', - }) - .eq('status', 'in_flight') - .lt('updated_at', stuckBefore.toISOString()) - .select('id') +async function recoverStuckInFlight( + supabase: SupabaseClient, + now: Date, +): Promise<{ recovered: number; dead: number }> { + const stuckBefore = new Date(now.getTime() - STUCK_IN_FLIGHT_AFTER_MS) + const { data, error } = await supabase.rpc('recover_stuck_webhook_deliveries', { + p_stuck_before: stuckBefore.toISOString(), + p_max_attempts: MAX_ATTEMPTS, + p_backoff: [...RETRY_BACKOFF_SECONDS], + p_now: now.toISOString(), + }) if (error) { log.warn('stuck in_flight recovery failed', { code: error.code }) - return + return { recovered: 0, dead: 0 } } - if (data && data.length > 0) { - log.warn('recovered stuck in_flight rows', { count: data.length }) + const rows = (data ?? []) as Array<{ id: string; status: string; attempts: number }> + const dead = rows.filter((r) => r.status === 'dead').length + if (rows.length > 0) { + log.warn('recovered stuck in_flight rows', { + count: rows.length, + dead, + retrying: rows.length - dead, + }) } + // Counts are returned as well as logged: a tick that takes deliveries + // terminal is the event worth alerting on, and it must be visible in the + // cron's own summary line rather than only in a helper-level warn. + return { recovered: rows.length, dead } } async function claimDueDeliveries( @@ -321,6 +448,91 @@ async function markFailedForRetry( if (error) log.warn('mark failed-for-retry update failed', { id, code: error.code }) } +/** + * Re-stamp a claimed row's updated_at right before its own attempt starts, + * and report whether the row is still ours. + * + * `status` is written back verbatim: Postgres runs the UPDATE regardless of + * whether any value changed, so the table's BEFORE UPDATE + * update_updated_at_column trigger (migration 20260515200000) re-stamps + * updated_at. That is what makes a row's in_flight age measure its attempt + * instead of the moment the whole batch was claimed, which is the property + * the stuck sweep reads. + * + * The `.eq('status', 'in_flight')` filter keeps the write off terminal rows, + * so enforce_webhook_delivery_immutability never fires. A zero-row result + * means the delivery is no longer ours (another cycle recovered and re-claimed + * it, or it already reached a terminal state): skip it rather than POSTing a + * duplicate whose terminal write would lose the race anyway. + */ +async function touchInFlight(supabase: SupabaseClient, id: string): Promise { + const { data, error } = await supabase + .from('webhook_deliveries') + .update({ status: 'in_flight' }) + .eq('id', id) + .eq('status', 'in_flight') + .select('id') + + if (error) { + // Infrastructure hiccup, not lost ownership: proceed. Worst case the row + // looks older than it is and a later sweep re-arms it, which is exactly + // the pre-existing behaviour. + log.warn('in_flight touch failed', { id, code: error.code }) + return true + } + return (data?.length ?? 0) > 0 +} + +/** + * Hand back rows this cycle claimed but will not attempt, so they are + * re-claimable immediately instead of waiting out the stuck window. + * + * Deliberately does NOT bump attempts (these rows were never attempted) and + * deliberately does NOT write `error` (a release is not a failure; overwriting + * would destroy the previous attempt's diagnostic). + * + * The status written back is the row's PRE-CLAIM status, reconstructed from + * `attempts` rather than guessed: claim_due_webhook_deliveries accepts + * status IN ('pending','failed'), and every path that writes 'failed' also + * writes attempts >= 1 (markFailedForRetry, the recovery sweep), while rows + * enter the table as 'pending' with attempts = 0. So attempts = 0 means the + * row was 'pending' and must go back to 'pending'. This matters because + * webhook_deliveries is behandlingshistorik (BFNAR 2013:2 kap 8 §) exposed on + * GET /webhooks/{id}/deliveries: a brand-new delivery that was claimed and + * handed back without a single POST must not read as 'failed' to the + * customer. Restoring the status verbatim would need the claim RPC to return + * it, which it does not; the attempts inference gets the same answer without + * changing a shipped function. + */ +async function releaseUnattempted( + supabase: SupabaseClient, + rows: Array<{ id: string; attempts: number }>, + now: Date, +): Promise { + if (rows.length === 0) return + + const byPriorStatus: Array<{ status: 'pending' | 'failed'; ids: string[] }> = [ + { status: 'pending', ids: rows.filter((r) => r.attempts === 0).map((r) => r.id) }, + { status: 'failed', ids: rows.filter((r) => r.attempts > 0).map((r) => r.id) }, + ] + + for (const group of byPriorStatus) { + if (group.ids.length === 0) continue + const { error } = await supabase + .from('webhook_deliveries') + .update({ status: group.status, next_attempt_at: now.toISOString() }) + .in('id', group.ids) + .eq('status', 'in_flight') + if (error) { + log.warn('release of unattempted claims failed', { + count: group.ids.length, + status: group.status, + code: error.code, + }) + } + } +} + async function markDead( supabase: SupabaseClient, id: string, @@ -651,4 +863,8 @@ export const __TESTING__ = { MAX_ATTEMPTS, REQUEST_TIMEOUT_MS, MAX_RESPONSE_BODY_BYTES, + DEFAULT_BATCH_SIZE, + CYCLE_BUDGET_MS, + STUCK_RECOVERY_SLACK_MS, + STUCK_IN_FLIGHT_AFTER_MS, } diff --git a/supabase/migrations/20260730123000_recover_stuck_webhook_deliveries.sql b/supabase/migrations/20260730123000_recover_stuck_webhook_deliveries.sql new file mode 100644 index 00000000..f243b468 --- /dev/null +++ b/supabase/migrations/20260730123000_recover_stuck_webhook_deliveries.sql @@ -0,0 +1,169 @@ +-- Migration: recover_stuck_webhook_deliveries +-- +-- Issue #1257. The dispatcher's in_flight sweep used to be a PostgREST chain +-- in lib/webhooks/dispatcher.ts: +-- +-- UPDATE webhook_deliveries +-- SET status = 'failed', next_attempt_at = now(), +-- error = 'recovered_from_in_flight_timeout' +-- WHERE status = 'in_flight' AND updated_at < now() - 20s +-- +-- Two defects, both fixed here plus in the TS caller: +-- +-- 1. WHY THE WINDOW CHANGED. The old 20 s threshold (2x the 10 s receiver +-- timeout) was far shorter than one dispatch cycle: the cron claims 50 rows +-- and attempts them SERIALLY, and updated_at was stamped once at claim +-- time. From row 3 onward every row in a cycle was already past the +-- threshold before its own attempt began, so cycle N recovered and +-- re-claimed rows cycle N-1 was still working through: duplicate POSTs of +-- the same X-Gnubok-Delivery, and a terminal status decided by a race whose +-- loser was swallowed as a log.warn. The caller now uses a window derived +-- from the bounded cycle (CYCLE_BUDGET_MS 120 s + one request timeout + +-- 30 s slack = 160 s, independent of batch size) and re-stamps updated_at +-- immediately before each row's own attempt, so no row a live cycle owns +-- can fall inside the window. The cycle bound is enforced, not assumed: +-- /api/webhooks/dispatch/cron declares maxDuration = 300, well above the +-- 120 s the loop is allowed to spend. +-- +-- 2. WHY attempts IS CHARGED. The old sweep reset rows to 'failed' without +-- touching attempts, so a delivery caught in the recover/re-claim loop +-- could be re-POSTed well past MAX_ATTEMPTS and the ~87 h retry budget +-- stopped being an upper bound. A stall is an attempt that produced no +-- receiver acknowledgement, so it is charged like any other. PostgREST +-- cannot express `attempts = attempts + 1`, nor the conditional flip at the +-- cap, and a read-then-write loop in JS would reopen a TOCTOU against +-- enforce_webhook_delivery_immutability. Hence this function. +-- +-- 2b. WHY THE STALL STILL WAITS OUT THE NORMAL BACKOFF. Charging an attempt is +-- only half of "make the cap real". Re-arming at p_now would make a +-- repeatedly stranded row (deploy, instance recycle, a cycle that outlives +-- its invocation) re-claimable on the very next per-minute tick, so it +-- could burn all 8 attempts in roughly 20 minutes and land in the terminal, +-- immutable 'dead' state without its receiver having been contacted once. +-- The sweep therefore reuses the dispatcher's own schedule: p_backoff is +-- RETRY_BACKOFF_SECONDS (60 s .. 48 h, ~87 h total) passed in from TS so it +-- stays single-sourced with markFailedForRetry, and the index math +-- (least(attempts + 1, array_length)) mirrors the 0-indexed lookup there. +-- A stall now costs an attempt AND the same wait a 500 response costs. +-- +-- 3. WHY A ROW PAST THE CAP GOES TO 'dead'. Once attempts + 1 reaches +-- p_max_attempts the row has exhausted its budget and must reach a terminal +-- state instead of looping (BFNAR 2013:2 kap 8 § behandlingshistorik: every +-- delivery row reaches a terminal state). The end state is byte-identical in +-- shape to what the normal path writes at dispatcher.ts's +-- 'attempts_exhausted' branch: status = 'dead', attempts = p_max_attempts, +-- error prefixed 'attempts_exhausted'. The suffix ':in_flight_timeout' +-- records that the last attempt stalled rather than returned. Unlike +-- markDead without an outcome, this branch does NOT null response_status / +-- response_body / response_headers and does NOT reset next_attempt_at: the +-- last recorded response is the only diagnostic left on an abandoned +-- attempt, and next_attempt_at is meaningless once terminal. +-- +-- The BEFORE UPDATE immutability trigger is NOT weakened or bypassed: the +-- outer UPDATE keeps `status = 'in_flight'` in its own WHERE (not only in the +-- CTE) so that under READ COMMITTED a row that raced to delivered/dead between +-- scan and lock fails re-evaluation and is skipped entirely. The trigger +-- therefore never fires, and a mid-flight terminal flip cannot abort the sweep. +-- +-- SECURITY DEFINER with an explicit service_role gate: the dispatcher runs +-- under createServiceClientNoCookies(), and nothing reachable by anon or +-- authenticated may re-arm another tenant's deliveries. Same shape as +-- 20260727100000_list_invoice_delivery_summaries_for_service.sql. + +-- The 3-argument shape never reached any deployed environment (this migration +-- has not been applied to production): the drop only cleans up developer and +-- CI databases where an earlier revision of THIS migration ran, so that adding +-- p_backoff cannot leave an ambiguous overload behind. +DROP FUNCTION IF EXISTS public.recover_stuck_webhook_deliveries(timestamptz, int, timestamptz); + +CREATE OR REPLACE FUNCTION public.recover_stuck_webhook_deliveries( + p_stuck_before timestamptz, + p_max_attempts int, + p_backoff int[], + p_now timestamptz DEFAULT now() +) +RETURNS TABLE (id uuid, status text, attempts int) +LANGUAGE plpgsql +SECURITY DEFINER +SET search_path = pg_catalog, public +AS $$ +BEGIN + IF auth.role() IS DISTINCT FROM 'service_role' THEN + RAISE EXCEPTION 'webhook delivery recovery requires a server-controlled service role' + USING ERRCODE = '42501'; + END IF; + + IF p_stuck_before IS NULL THEN + RAISE EXCEPTION 'p_stuck_before is required' USING ERRCODE = 'invalid_parameter_value'; + END IF; + + IF p_max_attempts IS NULL OR p_max_attempts <= 0 THEN + RAISE EXCEPTION 'p_max_attempts must be > 0; got %', p_max_attempts + USING ERRCODE = 'invalid_parameter_value'; + END IF; + + -- A missing, empty or non-positive backoff would silently re-arm swept rows + -- for immediate re-claim, which is exactly the strand loop this function + -- exists to bound. Fail loudly instead. + IF p_backoff IS NULL OR COALESCE(array_length(p_backoff, 1), 0) = 0 THEN + RAISE EXCEPTION 'p_backoff must be a non-empty int[] of retry delays in seconds' + USING ERRCODE = 'invalid_parameter_value'; + END IF; + + IF EXISTS (SELECT 1 FROM unnest(p_backoff) AS s(v) WHERE s.v IS NULL OR s.v <= 0) THEN + RAISE EXCEPTION 'p_backoff entries must all be > 0 seconds' + USING ERRCODE = 'invalid_parameter_value'; + END IF; + + RETURN QUERY + WITH stuck AS ( + SELECT wd.id + FROM public.webhook_deliveries wd + WHERE wd.status = 'in_flight' + AND wd.updated_at < p_stuck_before + FOR UPDATE SKIP LOCKED + ) + UPDATE public.webhook_deliveries wd + SET attempts = wd.attempts + 1, + status = CASE WHEN wd.attempts + 1 >= p_max_attempts THEN 'dead' ELSE 'failed' END, + -- Same lookup markFailedForRetry does in TS: index = attempts BEFORE + -- this one, clamped to the last step, and Postgres arrays are + -- 1-indexed so the JS index i becomes i + 1 here. + next_attempt_at = CASE WHEN wd.attempts + 1 >= p_max_attempts + THEN wd.next_attempt_at + ELSE p_now + ( + p_backoff[least(wd.attempts + 1, array_length(p_backoff, 1))] + * interval '1 second' + ) END, + error = CASE WHEN wd.attempts + 1 >= p_max_attempts + THEN 'attempts_exhausted:in_flight_timeout' + ELSE 'recovered_from_in_flight_timeout' END + FROM stuck + WHERE wd.id = stuck.id + AND wd.status = 'in_flight' + RETURNING wd.id, wd.status, wd.attempts; +END; +$$; + +REVOKE ALL ON FUNCTION public.recover_stuck_webhook_deliveries(timestamptz, int, int[], timestamptz) + FROM PUBLIC, anon, authenticated; +GRANT EXECUTE ON FUNCTION public.recover_stuck_webhook_deliveries(timestamptz, int, int[], timestamptz) + TO service_role; + +COMMENT ON FUNCTION public.recover_stuck_webhook_deliveries(timestamptz, int, int[], timestamptz) IS + 'Service-role sweep of webhook_deliveries rows abandoned in in_flight by a killed dispatch cycle. Charges one attempt per stall, re-arms on the caller-supplied retry backoff (p_backoff, seconds), and lands a row past p_max_attempts on the same dead/attempts-exhausted terminal state the normal retry path produces. Skips rows that raced to a terminal status, so the immutability trigger never fires.'; + +-- Deliberately unbounded (no LIMIT on the CTE): the sweep must clear every +-- abandoned row, and webhook_deliveries is tens of rows in production. If the +-- table ever grows, this needs a LIMIT plus a retention policy; both are +-- tracked as follow-ups on issue #1257 rather than guessed at here. + +-- Hygiene from #1257: no existing index serves this sweep. +-- idx_webhook_deliveries_due is partial on status IN ('pending','failed'), +-- which structurally excludes in_flight. No CONCURRENTLY: migrations run +-- inside a transaction, and the table is tiny (tens of rows in production). +CREATE INDEX IF NOT EXISTS idx_webhook_deliveries_in_flight_updated + ON public.webhook_deliveries (updated_at) + WHERE status = 'in_flight'; + +NOTIFY pgrst, 'reload schema';