Files
orca/cloud/apps/relay/src/boot-database-open.test.ts
T
Jinwoo Hong ce5d8c02d4 fix(relay): wait out a cold proxy at boot instead of exiting the cell (#21516)
* fix(relay): wait out a cold proxy at boot instead of exiting the cell

A cell container starts its relay process beside a cloud-sql-proxy that is
itself still dialling. The first pool acquire therefore competes with a proxy
cold start, and the 2s connect timeout that protects the request path fires
before the proxy is listening. `openRelayDatabase` rejects out of the region
backfill, the top-level await rejects, and the process exits; COS restarts the
container and the next boot succeeds 1-3s later. The 2026-09-18 fleet roll saw
0-7 of these per cell, including on cells with zero hosts, so it is a property
of the boot sequence rather than of database load.

The boot open now retries on transient errors only, inside a 45s wall-clock
window with exponential backoff from 250ms to 4s. The classifier is the one the
request path already uses, so a rejected credential or a bad URL still exits on
the first attempt. Each wait logs `orca_relay_boot_database_retry` and a
give-up logs `orca_relay_boot_database_failed`, both with the bounded error
category, so a rollout can tell a slow boot from a stuck one without reading
container exit codes.

The bounded startup retry is lifted out of `reconcileCellAdmissionAtStartup`,
which had the same loop; its attempt budget, flat delay, and both log events are
unchanged (a flat delay is a cap equal to the base).

* fix(relay): retry the boot open only when Postgres is unreachable

The boot open re-runs the schema apply, and applyPostgresSchema refuses to
repeat a DDL lock timeout on purpose: relation locks are granted in queue order,
so a repeat parks every writer behind the same statement again. Gating the boot
retry on the full request-path classifier would have re-queued it up to 16 times
in 45s on sustained 55P03 - the mechanism behind the 2026-09-16 outage.

The boot call site now has its own predicate: pool connect failures (both
connect-timeout messages and an acquire-marked early-ended socket) plus 08001
and 08006. Lock and overload SQLSTATEs - 55P03, 57014, 53300 - exit on the first
attempt. The retry predicate moves onto the policy because what a step re-runs,
not the request path, decides what it may repeat; the startup reconcile keeps
the full classifier, which is what lets it wait out 55P03.
2026-09-18 17:55:19 -04:00

127 lines
4.9 KiB
TypeScript

import { afterEach, describe, expect, it, vi, type MockInstance } from 'vitest'
import { openRelayDatabaseAtBoot } from './boot-database-open.js'
import type { RelayDatabase } from './database.js'
const input = { dataDir: '/tmp/orca-relay-boot', databaseUrl: 'postgres://relay@localhost/relay' }
// The message the fleet actually saw: pg-pool reports the connect timeout with
// no SQLSTATE, so the classifier has only this text to go on.
const connectTimeout = (): Error => new Error('Connection terminated due to connection timeout')
const database = {} as RelayDatabase
function loggedEvents(warn: MockInstance<typeof console.warn>): string[] {
return warn.mock.calls.map((call) => String(JSON.parse(String(call[0])).event))
}
afterEach(() => {
vi.useRealTimers()
vi.restoreAllMocks()
})
describe('relay boot database open', () => {
it('waits out a cold proxy instead of failing the boot', async () => {
vi.useFakeTimers()
const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined)
const open = vi
.fn<() => Promise<RelayDatabase>>()
.mockRejectedValueOnce(connectTimeout())
.mockRejectedValueOnce(connectTimeout())
.mockResolvedValue(database)
const opening = openRelayDatabaseAtBoot(input, open)
await vi.runAllTimersAsync()
expect(await opening).toBe(database)
expect(open).toHaveBeenCalledTimes(3)
expect(open).toHaveBeenCalledWith(input)
expect(loggedEvents(warn)).toEqual([
'orca_relay_boot_database_retry',
'orca_relay_boot_database_retry',
'orca_relay_boot_database_recovered'
])
expect(JSON.parse(String(warn.mock.calls[0]?.[0]))).toMatchObject({
attempt: 1,
delayMs: expect.any(Number),
code: 'unknown',
connectionTimeout: true
})
})
it('fails the boot immediately when the database rejects the relay', async () => {
const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined)
const denied = Object.assign(new Error('password authentication failed'), { code: '28P01' })
const open = vi.fn<() => Promise<RelayDatabase>>().mockRejectedValue(denied)
await expect(openRelayDatabaseAtBoot(input, open)).rejects.toBe(denied)
expect(open).toHaveBeenCalledTimes(1)
expect(loggedEvents(warn)).toEqual(['orca_relay_boot_database_failed'])
expect(JSON.parse(String(warn.mock.calls[0]?.[0]))).toMatchObject({
attempts: 1,
retryable: false,
code: 'unknown'
})
})
// A retry re-runs the schema apply, which must never re-queue a boot DDL
// behind the writers that beat it; the request path treats these as transient.
it.each(['55P03', '57014', '53300'])(
'refuses to re-queue the schema apply after SQLSTATE %s',
async (code) => {
const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined)
const contention = Object.assign(new Error('lock unavailable'), { code })
const open = vi.fn<() => Promise<RelayDatabase>>().mockRejectedValue(contention)
await expect(openRelayDatabaseAtBoot(input, open)).rejects.toBe(contention)
expect(open).toHaveBeenCalledTimes(1)
expect(loggedEvents(warn)).toEqual(['orca_relay_boot_database_failed'])
expect(JSON.parse(String(warn.mock.calls[0]?.[0]))).toMatchObject({
attempts: 1,
retryable: false,
code
})
}
)
it('waits out a connection failure the driver does report a SQLSTATE for', async () => {
vi.useFakeTimers()
vi.spyOn(console, 'warn').mockImplementation(() => undefined)
const unreachable = Object.assign(new Error('connection refused'), { code: '08006' })
const open = vi
.fn<() => Promise<RelayDatabase>>()
.mockRejectedValueOnce(unreachable)
.mockResolvedValue(database)
const opening = openRelayDatabaseAtBoot(input, open)
await vi.runAllTimersAsync()
expect(await opening).toBe(database)
expect(open).toHaveBeenCalledTimes(2)
})
it('gives up once the retry budget is spent', async () => {
vi.useFakeTimers()
vi.setSystemTime(0)
vi.spyOn(Math, 'random').mockReturnValue(0)
const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined)
const failure = connectTimeout()
const open = vi.fn<() => Promise<RelayDatabase>>().mockRejectedValue(failure)
const opening = openRelayDatabaseAtBoot(input, open)
const rejection = expect(opening).rejects.toBe(failure)
await vi.runAllTimersAsync()
await rejection
expect(Date.now()).toBeLessThanOrEqual(45_000)
expect(open.mock.calls.length).toBeGreaterThan(1)
const events = loggedEvents(warn)
expect(events.at(-1)).toBe('orca_relay_boot_database_failed')
expect(events.filter((event) => event === 'orca_relay_boot_database_retry')).toHaveLength(
open.mock.calls.length - 1
)
expect(JSON.parse(String(warn.mock.calls.at(-1)?.[0]))).toMatchObject({
attempts: open.mock.calls.length,
retryable: true,
connectionTimeout: true
})
})
})