fix(events): retry transient event_log persistence failures and stop racing function suspension (#966)

Production logs (2 months) show ~28 event_log inserts dying with
TypeError: fetch failed. Root cause: the MCP server emits telemetry
fire-and-forget and returns the JSON-RPC response immediately, so the
insert races Vercel function suspension; supabase-js surfaces the dead
fetch as a network error which was logged at error level.

Two-part fix:

- persistEvent (event-log-handler.ts) retries the insert once after
  250ms when the error message contains "fetch failed" (network class
  only; constraint violations and other Postgres errors are never
  retried). On final failure, telemetry event types (mcp.*, agent.*)
  log at warn; business events (journal_entry.*, invoice.*, etc.,
  which feed webhook delivery) stay at error.

- The mcp-server telemetry emit sites (tool_called, tools_list_called,
  resource_read, next_hint_followed, skill_loaded, workflow_started,
  agent.feedback) now schedule the emit via after() from next/server,
  which keeps the function alive past the response until the emit
  settles. Falls back to plain fire-and-forget when no request scope
  exists (direct handler invocation in tests).

Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Jakob Wennberg
2026-07-10 11:03:58 +02:00
committed by GitHub
co-authored by Claude Fable 5
parent 7c739529d6
commit f87277393d
3 changed files with 168 additions and 25 deletions
@@ -12,6 +12,22 @@ vi.mock('@/lib/auth/api-keys', () => ({
}),
}))
// Mock the logger so warn-vs-error level can be asserted (the real logger
// suppresses warn in the test environment). Hoisted: bus.ts calls
// createLogger at import time, before top-level consts initialize.
const { logWarn, logError } = vi.hoisted(() => ({
logWarn: vi.fn(),
logError: vi.fn(),
}))
vi.mock('@/lib/logger', () => ({
createLogger: () => ({
info: vi.fn(),
warn: logWarn,
error: logError,
child: vi.fn(),
}),
}))
// Import after mocks
import { registerEventLogHandler } from '../event-log-handler'
@@ -138,6 +154,86 @@ describe('event-log-handler', () => {
expect(mockInsert).toHaveBeenCalledTimes(1)
})
it('retries once when the insert fails with a network-class "fetch failed" error, then succeeds', async () => {
vi.useFakeTimers()
try {
mockInsert
.mockResolvedValueOnce({ error: { message: 'TypeError: fetch failed' } })
.mockResolvedValueOnce({ error: null })
const emitPromise = eventBus.emit({
type: 'customer.created',
payload: { customer: makeCustomer({ id: 'cust-retry' }), userId: 'user-1', companyId: 'company-1' },
})
await vi.advanceTimersByTimeAsync(250)
await emitPromise
expect(mockInsert).toHaveBeenCalledTimes(2)
expect(mockInsert.mock.calls[1][0]).toMatchObject({
event_type: 'customer.created',
entity_id: 'cust-retry',
})
expect(logWarn).not.toHaveBeenCalled()
expect(logError).not.toHaveBeenCalled()
} finally {
vi.useRealTimers()
}
})
it('does not retry non-network insert errors', async () => {
mockInsert.mockResolvedValue({
error: { message: 'duplicate key value violates unique constraint "event_log_pkey"' },
})
await eventBus.emit({
type: 'customer.created',
payload: { customer: makeCustomer(), userId: 'user-1', companyId: 'company-1' },
})
expect(mockInsert).toHaveBeenCalledTimes(1)
expect(logError).toHaveBeenCalledTimes(1)
})
it('logs telemetry (mcp.*) persistence failure at warn level after the retry also fails', async () => {
vi.useFakeTimers()
try {
mockInsert.mockResolvedValue({ error: { message: 'TypeError: fetch failed' } })
const emitPromise = eventBus.emit({
type: 'mcp.tool_called',
payload: { tool: 'gnubok_list_accounts', userId: 'user-1', companyId: 'company-1' } as never,
})
await vi.advanceTimersByTimeAsync(250)
await emitPromise
expect(mockInsert).toHaveBeenCalledTimes(2)
expect(logWarn).toHaveBeenCalledTimes(1)
expect(logError).not.toHaveBeenCalled()
} finally {
vi.useRealTimers()
}
})
it('keeps business event persistence failure at error level after the retry also fails', async () => {
vi.useFakeTimers()
try {
mockInsert.mockResolvedValue({ error: { message: 'TypeError: fetch failed' } })
const emitPromise = eventBus.emit({
type: 'invoice.created',
payload: { invoice: makeInvoice({ id: 'inv-err' }), userId: 'user-1', companyId: 'company-1' },
})
await vi.advanceTimersByTimeAsync(250)
await emitPromise
expect(mockInsert).toHaveBeenCalledTimes(2)
expect(logError).toHaveBeenCalledTimes(1)
expect(logWarn).not.toHaveBeenCalled()
} finally {
vi.useRealTimers()
}
})
it('persists period.locked with period entity_id', async () => {
const period = makeFiscalPeriod({ id: 'period-1' })
+42 -10
View File
@@ -129,8 +129,32 @@ function stripMetaFields(payload: Record<string, unknown>): Record<string, unkno
return data
}
/** Delay before the single retry of a network-class insert failure. */
const RETRY_DELAY_MS = 250
/**
* Network-class failure: supabase-js (undici) surfaces a dead connection as
* "TypeError: fetch failed", typically when the insert races Vercel function
* suspension. Only this class is retried; Postgres errors (constraint
* violations, RLS, bad columns) would fail identically on a retry.
*/
function isTransientNetworkError(message: string): boolean {
return message.includes('fetch failed')
}
/**
* Telemetry events (mcp.*, agent.*) are best-effort metrics: a lost row is
* not actionable, so their final persistence failure logs at warn. Business
* events (journal_entry.*, invoice.*, etc.) feed webhook delivery and stay
* at error level.
*/
function isTelemetryEvent(eventType: string): boolean {
return eventType.startsWith('mcp.') || eventType.startsWith('agent.')
}
/**
* Persist a single event to the event_log table.
* Retries once on network-class failures ("fetch failed") after a short delay.
*/
async function persistEvent(
eventType: string,
@@ -140,19 +164,27 @@ async function persistEvent(
data: Record<string, unknown>
): Promise<void> {
const supabase = createServiceClientNoCookies()
const row = {
user_id: userId,
company_id: companyId,
event_type: eventType,
entity_id: entityId,
data,
}
const { error } = await supabase
.from('event_log')
.insert({
user_id: userId,
company_id: companyId,
event_type: eventType,
entity_id: entityId,
data,
})
let { error } = await supabase.from('event_log').insert(row)
if (error && isTransientNetworkError(error.message)) {
await new Promise((resolve) => setTimeout(resolve, RETRY_DELAY_MS))
;({ error } = await supabase.from('event_log').insert(row))
}
if (error) {
log.error(`Failed to persist event ${eventType}:`, error.message)
if (isTelemetryEvent(eventType)) {
log.warn(`Failed to persist event ${eventType}:`, error.message)
} else {
log.error(`Failed to persist event ${eventType}:`, error.message)
}
}
}