From 3305fc2818929567b521d7fe87c17b2493e859c6 Mon Sep 17 00:00:00 2001 From: Waleed Latif Date: Tue, 22 Sep 2026 22:24:29 -0700 Subject: [PATCH 1/2] fix(db): retry migration lock timeouts within a time budget instead of eight attempts --- .../db/scripts/lock-timeout-retry.test.ts | 117 ++++++++++++++++++ packages/db/scripts/lock-timeout-retry.ts | 66 ++++++++++ packages/db/scripts/migrate.ts | 59 +++++---- 3 files changed, 217 insertions(+), 25 deletions(-) create mode 100644 packages/db/scripts/lock-timeout-retry.test.ts create mode 100644 packages/db/scripts/lock-timeout-retry.ts diff --git a/packages/db/scripts/lock-timeout-retry.test.ts b/packages/db/scripts/lock-timeout-retry.test.ts new file mode 100644 index 00000000000..c9a54dbd734 --- /dev/null +++ b/packages/db/scripts/lock-timeout-retry.test.ts @@ -0,0 +1,117 @@ +/** + * @vitest-environment node + */ + +import { retryOnLockTimeout } from '@sim/db/scripts/lock-timeout-retry' +import { describe, expect, it, vi } from 'vitest' + +const BACKOFF = { baseMs: 2_000, maxMs: 30_000 } as const + +function pgError(code: string): Error { + return Object.assign(new Error(`postgres error ${code}`), { code }) +} + +/** A fake clock that only advances when the retry loop sleeps. */ +function fakeClock() { + let nowMs = 0 + return { + now: () => nowMs, + sleep: vi.fn(async (ms: number) => { + nowMs += ms + }), + advance: (ms: number) => { + nowMs += ms + }, + } +} + +describe('retryOnLockTimeout', () => { + it('keeps retrying lock timeouts well past eight attempts while the budget lasts', async () => { + const clock = fakeClock() + let calls = 0 + const result = await retryOnLockTimeout( + async () => { + calls++ + clock.advance(5_000) + if (calls < 20) throw pgError('55P03') + return 'applied' + }, + { budgetMs: 20 * 60_000, backoff: BACKOFF, now: clock.now, sleep: clock.sleep } + ) + + expect(result).toBe('applied') + expect(calls).toBe(20) + expect(clock.sleep).toHaveBeenCalledTimes(19) + }) + + it('throws the last lock timeout once the next retry would end past the budget', async () => { + const clock = fakeClock() + const onRetry = vi.fn() + const attempt = vi.fn(async () => { + clock.advance(5_000) + throw pgError('55P03') + }) + + await expect( + retryOnLockTimeout(attempt, { + budgetMs: 2 * 60_000, + backoff: BACKOFF, + now: clock.now, + sleep: clock.sleep, + onRetry, + }) + ).rejects.toMatchObject({ code: '55P03' }) + + expect(clock.now()).toBeLessThan(2 * 60_000) + for (const [{ elapsedMs, delayMs }] of onRetry.mock.calls) { + expect(elapsedMs + delayMs).toBeLessThan(2 * 60_000) + } + expect(attempt).toHaveBeenCalledTimes(onRetry.mock.calls.length + 1) + }) + + it('finds a lock timeout wrapped in a cause chain', async () => { + const clock = fakeClock() + let calls = 0 + await retryOnLockTimeout( + async () => { + calls++ + if (calls === 1) throw new Error('Failed query', { cause: pgError('55P03') }) + }, + { budgetMs: 60_000, backoff: BACKOFF, now: clock.now, sleep: clock.sleep } + ) + + expect(calls).toBe(2) + }) + + it('does not retry any other error', async () => { + const clock = fakeClock() + const attempt = vi.fn(async () => { + throw pgError('42P07') + }) + + await expect( + retryOnLockTimeout(attempt, { + budgetMs: 60_000, + backoff: BACKOFF, + now: clock.now, + sleep: clock.sleep, + }) + ).rejects.toMatchObject({ code: '42P07' }) + expect(attempt).toHaveBeenCalledTimes(1) + expect(clock.sleep).not.toHaveBeenCalled() + }) + + it('passes the attempt number to each attempt', async () => { + const clock = fakeClock() + const seen: number[] = [] + await retryOnLockTimeout( + async (attemptNumber) => { + seen.push(attemptNumber) + if (attemptNumber < 3) throw pgError('55P03') + }, + { budgetMs: 60_000, backoff: BACKOFF, now: clock.now, sleep: clock.sleep } + ) + + expect(seen).toEqual([1, 2, 3]) + }) +}) diff --git a/packages/db/scripts/lock-timeout-retry.ts b/packages/db/scripts/lock-timeout-retry.ts new file mode 100644 index 00000000000..6bc395a5255 --- /dev/null +++ b/packages/db/scripts/lock-timeout-retry.ts @@ -0,0 +1,66 @@ +import { getPostgresErrorCode } from '@sim/utils/errors' +import { sleep as defaultSleep } from '@sim/utils/helpers' +import { backoffWithJitter } from '@sim/utils/retry' + +/** SQLSTATE `lock_not_available`, raised when `lock_timeout` expires. */ +const LOCK_NOT_AVAILABLE = '55P03' + +export interface LockTimeoutRetryAttempt { + /** The attempt that just failed, starting at 1. */ + attempt: number + delayMs: number + elapsedMs: number + budgetMs: number +} + +export interface LockTimeoutRetryOptions { + /** + * Total wall-clock time, measured from the first attempt, during which a lock + * timeout is retried. A retry whose delay would end past the budget is not + * started; the last lock timeout is thrown instead. + */ + budgetMs: number + backoff: { baseMs: number; maxMs: number } + onRetry?: (attempt: LockTimeoutRetryAttempt) => void + now?: () => number + sleep?: (ms: number) => Promise +} + +/** + * Run `attempt` until it succeeds, retrying only lock timeouts (55P03, found + * anywhere in the wrapped `cause` chain) for up to `budgetMs`. + * + * DDL on a hot table needs an ACCESS EXCLUSIVE lock, which it can only take in + * a moment when no transaction holds any lock on the table. Each attempt must + * keep a short `lock_timeout`, because a queued ACCESS EXCLUSIVE request blocks + * every later query on the table for as long as it waits. Many short attempts + * spread over a long budget find such a moment without ever stalling traffic + * for more than one `lock_timeout`; a fixed attempt count gives up after a few + * minutes whenever the table is continuously held by transactions that each + * outlive the timeout. Any other error is thrown immediately. + */ +export async function retryOnLockTimeout( + attempt: (attemptNumber: number) => Promise, + options: LockTimeoutRetryOptions +): Promise { + const now = options.now ?? Date.now + const sleep = options.sleep ?? defaultSleep + const startedAt = now() + for (let attemptNumber = 1; ; attemptNumber++) { + try { + return await attempt(attemptNumber) + } catch (error) { + if (getPostgresErrorCode(error) !== LOCK_NOT_AVAILABLE) throw error + const delayMs = backoffWithJitter(attemptNumber, null, options.backoff) + const elapsedMs = now() - startedAt + if (elapsedMs + delayMs >= options.budgetMs) throw error + options.onRetry?.({ + attempt: attemptNumber, + delayMs, + elapsedMs, + budgetMs: options.budgetMs, + }) + await sleep(delayMs) + } + } +} diff --git a/packages/db/scripts/migrate.ts b/packages/db/scripts/migrate.ts index b66f0484760..c760107eb5c 100644 --- a/packages/db/scripts/migrate.ts +++ b/packages/db/scripts/migrate.ts @@ -5,6 +5,7 @@ import { drizzle } from 'drizzle-orm/postgres-js' import { migrate } from 'drizzle-orm/postgres-js/migrator' import postgres from 'postgres' import { runScriptMigrations } from '../script-migrations/index' +import { retryOnLockTimeout } from './lock-timeout-retry' /** * Concurrent-index convention: plain `CREATE INDEX` write-blocks large/hot @@ -77,7 +78,14 @@ const LOCK_RETRY_INTERVAL_MS = 5_000 * query on the table behind it — a table-wide stall for the whole wait. */ const DDL_LOCK_TIMEOUT = '5s' -const MAX_MIGRATE_ATTEMPTS = 8 +/** + * Total time to keep retrying lock timeouts. A table held continuously by + * transactions that each outlive `DDL_LOCK_TIMEOUT` frees up only in short + * windows, so the budget is time-based rather than a small attempt count. It + * stays under `LOCK_ACQUIRE_DEADLINE_MS` so a runner waiting on the advisory + * lock sees this one finish, one way or the other, before its own deadline. + */ +const MIGRATE_LOCK_RETRY_BUDGET_MS = 20 * 60_000 const MIGRATE_RETRY_BACKOFF = { baseMs: 2_000, maxMs: 30_000 } as const const CONNECT_MAX_ATTEMPTS = 10 @@ -182,14 +190,6 @@ async function acquireMigrationLock(): Promise { } } -/** - * Run pending migrations, retrying on lock timeout (55P03, found anywhere in - * the wrapped `cause` chain). Each attempt re-verifies the lock session (pid) - * and re-asserts the session timeouts — a migration file may have changed them, - * and `SET` cannot be parameterized, hence `client.unsafe` with constants. - * Replays are safe: drizzle rolls the batch back on failure, and post-COMMIT - * CONCURRENTLY statements are idempotent by convention. - */ /** * Verify the session still holds the migration advisory lock: a changed * backend pid means the connection was recycled and the lock silently dropped. @@ -206,25 +206,34 @@ async function assertLockSessionHeld(): Promise { } } +/** + * Run pending migrations, retrying lock timeouts within + * `MIGRATE_LOCK_RETRY_BUDGET_MS` (see `retryOnLockTimeout`). Each attempt re-verifies the lock session (pid) + * and re-asserts the session timeouts — a migration file may have changed them, + * and `SET` cannot be parameterized, hence `client.unsafe` with constants. + * Replays are safe: drizzle rolls the batch back on failure, and post-COMMIT + * CONCURRENTLY statements are idempotent by convention. + */ async function runMigrationsWithRetry(): Promise { - for (let attempt = 1; ; attempt++) { - await assertLockSessionHeld() - await client.unsafe('SET statement_timeout = 0') - await client.unsafe(`SET lock_timeout = '${DDL_LOCK_TIMEOUT}'`) - try { + await retryOnLockTimeout( + async () => { + await assertLockSessionHeld() + await client.unsafe('SET statement_timeout = 0') + await client.unsafe(`SET lock_timeout = '${DDL_LOCK_TIMEOUT}'`) await migrate(drizzle(client), { migrationsFolder: './migrations' }) - return - } catch (error) { - const isLockTimeout = getPostgresErrorCode(error) === '55P03' - if (!isLockTimeout || attempt >= MAX_MIGRATE_ATTEMPTS) throw error - const delayMs = backoffWithJitter(attempt, null, MIGRATE_RETRY_BACKOFF) - console.warn( - `WARN: migration DDL hit lock_timeout (attempt ${attempt}/${MAX_MIGRATE_ATTEMPTS}); ` + - `retrying in ${Math.round(delayMs)}ms.` - ) - await sleep(delayMs) + }, + { + budgetMs: MIGRATE_LOCK_RETRY_BUDGET_MS, + backoff: MIGRATE_RETRY_BACKOFF, + onRetry: ({ attempt, delayMs, elapsedMs, budgetMs }) => { + console.warn( + `WARN: migration DDL hit lock_timeout (attempt ${attempt}, ` + + `${Math.round(elapsedMs / 1000)}s of ${Math.round(budgetMs / 1000)}s budget); ` + + `retrying in ${Math.round(delayMs)}ms.` + ) + }, } - } + ) } /** From dd1edbfbad916a2ccabb9973d1bdb73384851693 Mon Sep 17 00:00:00 2001 From: Waleed Latif Date: Tue, 22 Sep 2026 22:37:18 -0700 Subject: [PATCH 2/2] fix(db): measure the migration lock budget on a monotonic clock and never start an attempt past it --- .../db/scripts/lock-timeout-retry.test.ts | 32 ++++++++++++++++--- packages/db/scripts/lock-timeout-retry.ts | 12 ++++--- 2 files changed, 35 insertions(+), 9 deletions(-) diff --git a/packages/db/scripts/lock-timeout-retry.test.ts b/packages/db/scripts/lock-timeout-retry.test.ts index c9a54dbd734..0da4d4977f2 100644 --- a/packages/db/scripts/lock-timeout-retry.test.ts +++ b/packages/db/scripts/lock-timeout-retry.test.ts @@ -44,10 +44,12 @@ describe('retryOnLockTimeout', () => { expect(clock.sleep).toHaveBeenCalledTimes(19) }) - it('throws the last lock timeout once the next retry would end past the budget', async () => { + it('starts no attempt after the budget and throws the last lock timeout', async () => { const clock = fakeClock() const onRetry = vi.fn() + const startedAt: number[] = [] const attempt = vi.fn(async () => { + startedAt.push(clock.now()) clock.advance(5_000) throw pgError('55P03') }) @@ -62,13 +64,33 @@ describe('retryOnLockTimeout', () => { }) ).rejects.toMatchObject({ code: '55P03' }) - expect(clock.now()).toBeLessThan(2 * 60_000) - for (const [{ elapsedMs, delayMs }] of onRetry.mock.calls) { - expect(elapsedMs + delayMs).toBeLessThan(2 * 60_000) - } + for (const start of startedAt) expect(start).toBeLessThan(2 * 60_000) + /** The last attempt may run one lock timeout past the budget, never more. */ + expect(clock.now()).toBeLessThan(2 * 60_000 + 5_000) expect(attempt).toHaveBeenCalledTimes(onRetry.mock.calls.length + 1) }) + it('does not start an attempt when a timer resolves after the budget', async () => { + let nowMs = 0 + const attempt = vi.fn(async () => { + nowMs += 1_000 + throw pgError('55P03') + }) + + await expect( + retryOnLockTimeout(attempt, { + budgetMs: 60_000, + backoff: BACKOFF, + now: () => nowMs, + /** The process stalls: the timer fires long after its delay. */ + sleep: async () => { + nowMs += 120_000 + }, + }) + ).rejects.toMatchObject({ code: '55P03' }) + expect(attempt).toHaveBeenCalledOnce() + }) + it('finds a lock timeout wrapped in a cause chain', async () => { const clock = fakeClock() let calls = 0 diff --git a/packages/db/scripts/lock-timeout-retry.ts b/packages/db/scripts/lock-timeout-retry.ts index 6bc395a5255..dd283e05c55 100644 --- a/packages/db/scripts/lock-timeout-retry.ts +++ b/packages/db/scripts/lock-timeout-retry.ts @@ -15,13 +15,16 @@ export interface LockTimeoutRetryAttempt { export interface LockTimeoutRetryOptions { /** - * Total wall-clock time, measured from the first attempt, during which a lock - * timeout is retried. A retry whose delay would end past the budget is not - * started; the last lock timeout is thrown instead. + * Time, measured on a monotonic clock from the first attempt, within which + * attempts may start. No attempt starts once the budget has elapsed, whether + * the backoff delay would end past it or a timer resolved late; the last lock + * timeout is thrown instead. An attempt that starts in time can still run for + * up to one `lock_timeout` past the budget. */ budgetMs: number backoff: { baseMs: number; maxMs: number } onRetry?: (attempt: LockTimeoutRetryAttempt) => void + /** Monotonic milliseconds; defaults to `performance.now`, immune to wall-clock corrections. */ now?: () => number sleep?: (ms: number) => Promise } @@ -43,7 +46,7 @@ export async function retryOnLockTimeout( attempt: (attemptNumber: number) => Promise, options: LockTimeoutRetryOptions ): Promise { - const now = options.now ?? Date.now + const now = options.now ?? (() => performance.now()) const sleep = options.sleep ?? defaultSleep const startedAt = now() for (let attemptNumber = 1; ; attemptNumber++) { @@ -61,6 +64,7 @@ export async function retryOnLockTimeout( budgetMs: options.budgetMs, }) await sleep(delayMs) + if (now() - startedAt >= options.budgetMs) throw error } } }