mirror of
https://github.com/stablyai/orca.git
synced 2026-09-21 16:02:20 +00:00
fix(relay): treat database pool connect failures as transient, not director faults (#21243)
* fix(relay): treat pool connect failures as transient, not director faults pg-pool raises connection-acquire failures as a plain Error with no SQLSTATE, so the transient classifier matched only one of the three messages it can produce. The other two reached the routes unclassified and became HTTP 500s, which is what the rollout safety gate counts. The acquire boundary now marks the errors it produces, so "Connection terminated unexpectedly" counts as transient when the socket died during the handshake and stays a hard failure mid-statement, where a retry could repeat a commit whose outcome is unknown. /v1/regions and /v1/admin/evacuation-status gain the transient handling /v1/assign and /v1/resolve already had. * fix(relay): mirror the pool-connect verdict in failure diagnostics The query-failure event's connectionTimeout boolean matched one of the two messages connectionTimeoutMillis can produce, so the 210 dialling timeouts in the last day logged as false and were invisible to the field meant to find them. The pool-connect vocabulary now lives beside the acquire boundary that owns it, and both the router's classifier and the diagnostics read it from there, so the two cannot drift. The event also carries the routing verdict the caller already computed, making "how much of this burst reached users as a 500" one field. * fix(relay): null-safe transient classification and honest transient docs The classifier now runs inside the query catch, where a thrown null or undefined would have turned a database failure into a TypeError that buried it. The diagnostics doc claimed transient maps to a 503 or a 500. Sweeps, startup reconciliation, and admin routes that answer 409 all emit the same event, so counting the false ones over-states user-facing hard failures.
This commit is contained in:
@@ -223,7 +223,15 @@ export function createRelayApp(
|
||||
})
|
||||
app.get('/v1/regions', async (context) => {
|
||||
if (config.role === 'cell') return context.json({ error: 'director_only' }, 404)
|
||||
return context.json({ v: 1, regions: await regionCatalog() })
|
||||
try {
|
||||
return context.json({ v: 1, regions: await regionCatalog() })
|
||||
} catch (error) {
|
||||
if (!isRelayDatabaseTransientError(error)) throw error
|
||||
// Same contract as the assignment routes: a database that is briefly out
|
||||
// of reach is a retry, not a director fault.
|
||||
context.header('Retry-After', String(config.publicAssignmentRetryAfterSeconds))
|
||||
return context.json({ error: 'region_catalog_temporarily_unavailable' }, 503)
|
||||
}
|
||||
})
|
||||
app.post('/v1/assign', async (context) => {
|
||||
if (config.role === 'cell') return context.json({ error: 'director_only' }, 404)
|
||||
@@ -1307,12 +1315,17 @@ export function createRelayApp(
|
||||
if (body.data.completeReady && (await verifyReadOnlyAdminToken(bearer))) {
|
||||
return context.json({ error: 'insufficient_permission' }, 403)
|
||||
}
|
||||
const status = await operations.assignments.cellEvacuationStatus(
|
||||
body.data.sourceCellId,
|
||||
body.data.targetCellId,
|
||||
body.data.completeReady
|
||||
)
|
||||
return context.json({ v: 1, ...status })
|
||||
try {
|
||||
const status = await operations.assignments.cellEvacuationStatus(
|
||||
body.data.sourceCellId,
|
||||
body.data.targetCellId,
|
||||
body.data.completeReady
|
||||
)
|
||||
return context.json({ v: 1, ...status })
|
||||
} catch (error) {
|
||||
if (!isRelayDatabaseTransientError(error)) throw error
|
||||
return context.json({ error: 'database_temporarily_unavailable' }, 503)
|
||||
}
|
||||
})
|
||||
app.post('/v1/admin/cell-status', async (context) => {
|
||||
const bearer = readBearer(context.req.header('authorization'))
|
||||
|
||||
@@ -1,5 +1,20 @@
|
||||
import { describe, expect, it } from 'vitest'
|
||||
import { describe, expect, it, vi } from 'vitest'
|
||||
import { isRelayDatabaseTransientError } from './database.js'
|
||||
import { PostgresPoolPressure } from './postgres-pool-pressure.js'
|
||||
|
||||
// The only way to mark an error as an acquire failure is to fail a real
|
||||
// acquire, so the gated cases go through the pressure wrapper the pool uses.
|
||||
async function failedAcquire(message: string): Promise<unknown> {
|
||||
const pool = {
|
||||
totalCount: 0,
|
||||
idleCount: 0,
|
||||
waitingCount: 0,
|
||||
connect: vi.fn(async () => {
|
||||
throw new Error(message)
|
||||
})
|
||||
}
|
||||
return await new PostgresPoolPressure(pool as never).connect().catch((error: unknown) => error)
|
||||
}
|
||||
|
||||
describe('relay database transient errors', () => {
|
||||
it.each(['40P01', '40001', '55P03', '57014', '53300', '57P03', '08001', '08006'])(
|
||||
@@ -15,4 +30,39 @@ describe('relay database transient errors', () => {
|
||||
).toBe(true)
|
||||
expect(isRelayDatabaseTransientError(new TypeError('broken invariant'))).toBe(false)
|
||||
})
|
||||
|
||||
it('classifies a pool connect timeout that node-postgres reports with no code', () => {
|
||||
// pg-pool raises this only from its own connect path, so no statement ran.
|
||||
expect(
|
||||
isRelayDatabaseTransientError(
|
||||
new Error('Connection terminated due to connection timeout')
|
||||
)
|
||||
).toBe(true)
|
||||
})
|
||||
|
||||
it('classifies an early-ended socket only when it ended during the acquire', async () => {
|
||||
expect(
|
||||
isRelayDatabaseTransientError(await failedAcquire('Connection terminated unexpectedly'))
|
||||
).toBe(true)
|
||||
// The same message mid-statement leaves the commit outcome unknown, so it
|
||||
// must stay a hard failure rather than invite a retry.
|
||||
expect(
|
||||
isRelayDatabaseTransientError(new Error('Connection terminated unexpectedly'))
|
||||
).toBe(false)
|
||||
})
|
||||
|
||||
it.each([null, undefined, 'a thrown string'])(
|
||||
'survives %s reaching it instead of an error object',
|
||||
(thrown) => {
|
||||
expect(isRelayDatabaseTransientError(thrown)).toBe(false)
|
||||
}
|
||||
)
|
||||
|
||||
it('keeps a failed acquire that is not transient out of the retry path', async () => {
|
||||
expect(
|
||||
isRelayDatabaseTransientError(
|
||||
await failedAcquire('password authentication failed for user "relay"')
|
||||
)
|
||||
).toBe(false)
|
||||
})
|
||||
})
|
||||
|
||||
@@ -6,6 +6,7 @@ import pg from 'pg'
|
||||
import { RELAY_REGIONS } from '@orca-cloud/relay-contract'
|
||||
import {
|
||||
emptyPostgresPoolPressureCounts,
|
||||
isPostgresPoolConnectFailure,
|
||||
PostgresPoolPressure,
|
||||
type PostgresPoolPressureCounts
|
||||
} from './postgres-pool-pressure.js'
|
||||
@@ -924,13 +925,15 @@ function retryablePostgresTransactionError(error: unknown): boolean {
|
||||
}
|
||||
|
||||
export function isRelayDatabaseTransientError(error: unknown): boolean {
|
||||
const code = String((error as { code?: unknown }).code)
|
||||
// Runs inside the query catch, where a thrown null or undefined would turn a
|
||||
// database failure into a TypeError that buries it.
|
||||
const code = String((error as { code?: unknown } | null)?.code)
|
||||
if (['40P01', '40001', '55P03', '57014', '53300', '57P03', '08001', '08006'].includes(code)) {
|
||||
return true
|
||||
}
|
||||
return String((error as { message?: unknown }).message).includes(
|
||||
'timeout exceeded when trying to connect'
|
||||
)
|
||||
// A pool that cannot hand out a client reports no SQLSTATE at all, so the
|
||||
// acquire boundary owns that vocabulary.
|
||||
return isPostgresPoolConnectFailure(error)
|
||||
}
|
||||
|
||||
async function waitForPostgresRetry(random: () => number = Math.random): Promise<void> {
|
||||
@@ -965,6 +968,9 @@ class PostgresDatabase implements RelayDatabase {
|
||||
error,
|
||||
phase,
|
||||
sql,
|
||||
// Passed in rather than re-derived: the log has to say what the routes
|
||||
// actually did, and one classifier cannot drift from itself.
|
||||
transient: isRelayDatabaseTransientError(error),
|
||||
elapsedMs: performance.now() - startedAt,
|
||||
pool: this.pool
|
||||
})
|
||||
|
||||
@@ -9,6 +9,48 @@ export type PostgresPoolPressureCounts = {
|
||||
databasePoolWaitMsMax: number
|
||||
}
|
||||
|
||||
// A pool that cannot hand out a client throws a bare Error with no SQLSTATE, so
|
||||
// the message is all node-postgres gives us. Both of these come only from
|
||||
// pg-pool's connect path, so neither can be a statement that already ran.
|
||||
const POOL_CONNECT_TIMEOUT_MESSAGES = [
|
||||
// No pooled client came free within connectionTimeoutMillis.
|
||||
'timeout exceeded when trying to connect',
|
||||
// A new client's own handshake outran connectionTimeoutMillis.
|
||||
'Connection terminated due to connection timeout'
|
||||
]
|
||||
// pg raises this whenever a socket ends early, during the handshake and mid
|
||||
// statement alike, so only the acquire boundary can tell the two apart.
|
||||
const CONNECTION_TERMINATED_MESSAGE = 'Connection terminated unexpectedly'
|
||||
|
||||
// Membership is tracked beside the error rather than on it: an error object may
|
||||
// be frozen, and a mutated one would leak the marker into logs.
|
||||
const poolAcquireFailures = new WeakSet<object>()
|
||||
|
||||
function errorMessage(error: unknown): string {
|
||||
return String((error as { message?: unknown } | null)?.message)
|
||||
}
|
||||
|
||||
function isPostgresPoolAcquireFailure(error: unknown): boolean {
|
||||
return typeof error === 'object' && error !== null && poolAcquireFailures.has(error)
|
||||
}
|
||||
|
||||
// connectionTimeoutMillis firing, either waiting in the queue or dialling.
|
||||
export function isPostgresPoolConnectTimeout(error: unknown): boolean {
|
||||
const message = errorMessage(error)
|
||||
return POOL_CONNECT_TIMEOUT_MESSAGES.some((known) => message.includes(known))
|
||||
}
|
||||
|
||||
// Every way the pool can fail to hand out a usable client. An early-ended
|
||||
// socket counts only at the acquire boundary: retrying a statement whose commit
|
||||
// outcome is unknown is not safe.
|
||||
export function isPostgresPoolConnectFailure(error: unknown): boolean {
|
||||
if (isPostgresPoolConnectTimeout(error)) return true
|
||||
return (
|
||||
errorMessage(error).includes(CONNECTION_TERMINATED_MESSAGE) &&
|
||||
isPostgresPoolAcquireFailure(error)
|
||||
)
|
||||
}
|
||||
|
||||
const emptyCounts = (): PostgresPoolPressureCounts => ({
|
||||
databasePoolTotal: 0,
|
||||
databasePoolIdle: 0,
|
||||
@@ -32,14 +74,14 @@ export class PostgresPoolPressure {
|
||||
async connect(): Promise<pg.PoolClient> {
|
||||
const waitingBefore = this.pool.waitingCount
|
||||
const connection = this.pool.connect()
|
||||
if (this.pool.waitingCount <= waitingBefore) return await connection
|
||||
if (this.pool.waitingCount <= waitingBefore) return await markedAcquire(connection)
|
||||
|
||||
const waiter = Symbol()
|
||||
const startedAt = this.now()
|
||||
this.waiters.set(waiter, startedAt)
|
||||
this.waitersMax = Math.max(this.waitersMax, this.waiters.size)
|
||||
try {
|
||||
return await connection
|
||||
return await markedAcquire(connection)
|
||||
} finally {
|
||||
this.waitMsMax = Math.max(this.waitMsMax, this.now() - startedAt)
|
||||
this.waiters.delete(waiter)
|
||||
@@ -88,6 +130,15 @@ export class PostgresPoolPressure {
|
||||
}
|
||||
}
|
||||
|
||||
async function markedAcquire(connection: Promise<pg.PoolClient>): Promise<pg.PoolClient> {
|
||||
try {
|
||||
return await connection
|
||||
} catch (error) {
|
||||
if (typeof error === 'object' && error !== null) poolAcquireFailures.add(error)
|
||||
throw error
|
||||
}
|
||||
}
|
||||
|
||||
export function emptyPostgresPoolPressureCounts(): PostgresPoolPressureCounts {
|
||||
return emptyCounts()
|
||||
}
|
||||
|
||||
@@ -29,7 +29,8 @@ describePostgres('real PostgreSQL query failure phases', () => {
|
||||
event: 'orca_relay_postgres_query_failed',
|
||||
phase: 'execute',
|
||||
code: '57014',
|
||||
connectionTimeout: false
|
||||
connectionTimeout: false,
|
||||
transient: true
|
||||
})
|
||||
expect(await database.query('SELECT 1 AS ok')).toEqual([{ ok: 1 }])
|
||||
})
|
||||
@@ -58,6 +59,7 @@ describePostgres('real PostgreSQL query failure phases', () => {
|
||||
phase: 'acquire',
|
||||
code: 'unknown',
|
||||
connectionTimeout: true,
|
||||
transient: true,
|
||||
poolTotal: 1,
|
||||
poolIdle: 0
|
||||
})
|
||||
|
||||
@@ -55,6 +55,7 @@ describe('PostgreSQL query failure diagnostics', () => {
|
||||
operation: 'control-renewal',
|
||||
code: 'unknown',
|
||||
connectionTimeout: true,
|
||||
transient: true,
|
||||
elapsedMs: expect.any(Number),
|
||||
poolTotal: 10,
|
||||
poolIdle: 0,
|
||||
@@ -63,9 +64,15 @@ describe('PostgreSQL query failure diagnostics', () => {
|
||||
expect(JSON.stringify(vi.mocked(console.warn).mock.calls)).not.toContain('private')
|
||||
})
|
||||
|
||||
it.each(['57014', '55P03', 'ECONNRESET'])(
|
||||
// ECONNRESET carries no SQLSTATE the routes retry on, and it arrives after the
|
||||
// statement went out, so it stays a hard failure. The pair pins that boundary.
|
||||
it.each([
|
||||
['57014', true],
|
||||
['55P03', true],
|
||||
['ECONNRESET', false]
|
||||
] as const)(
|
||||
'identifies execute failure %s and releases its client',
|
||||
async (code) => {
|
||||
async (code, transient) => {
|
||||
const error = Object.assign(new Error('private-token'), { code, detail: sql })
|
||||
fakes.query.mockRejectedValueOnce(error)
|
||||
await expect(database.query(sql, ['private-token'])).rejects.toBe(error)
|
||||
@@ -75,19 +82,60 @@ describe('PostgreSQL query failure diagnostics', () => {
|
||||
phase: 'execute',
|
||||
operation: 'control-renewal',
|
||||
code,
|
||||
connectionTimeout: false
|
||||
connectionTimeout: false,
|
||||
transient
|
||||
})
|
||||
expect(JSON.stringify(vi.mocked(console.warn).mock.calls)).not.toContain('private-token')
|
||||
expect(JSON.stringify(vi.mocked(console.warn).mock.calls)).not.toContain(sql)
|
||||
}
|
||||
)
|
||||
|
||||
it('marks a dialling timeout that node-postgres reports with no code', async () => {
|
||||
// pg-pool raises this when a new client's own handshake outruns the limit.
|
||||
const error = new Error('Connection terminated due to connection timeout')
|
||||
fakes.connectError = error
|
||||
await expect(database.query(sql)).rejects.toBe(error)
|
||||
expect(JSON.parse(vi.mocked(console.warn).mock.calls[0]![0] as string)).toMatchObject({
|
||||
phase: 'acquire',
|
||||
code: 'unknown',
|
||||
connectionTimeout: true,
|
||||
transient: true
|
||||
})
|
||||
})
|
||||
|
||||
it('separates an early-ended socket from a timeout while still calling it transient', async () => {
|
||||
const error = new Error('Connection terminated unexpectedly')
|
||||
fakes.connectError = error
|
||||
await expect(database.query(sql)).rejects.toBe(error)
|
||||
expect(JSON.parse(vi.mocked(console.warn).mock.calls[0]![0] as string)).toMatchObject({
|
||||
phase: 'acquire',
|
||||
code: 'unknown',
|
||||
connectionTimeout: false,
|
||||
transient: true
|
||||
})
|
||||
})
|
||||
|
||||
it('reports an acquire failure that is not transient as a hard failure', async () => {
|
||||
const error = new Error('password authentication failed')
|
||||
fakes.connectError = error
|
||||
await expect(database.query(sql)).rejects.toBe(error)
|
||||
expect(JSON.parse(vi.mocked(console.warn).mock.calls[0]![0] as string)).toMatchObject({
|
||||
phase: 'acquire',
|
||||
connectionTimeout: false,
|
||||
transient: false
|
||||
})
|
||||
})
|
||||
|
||||
it('does not emit an arbitrary error code, message, query, or parameter', async () => {
|
||||
const error = { code: 'private-code', message: 'private-message' }
|
||||
fakes.query.mockRejectedValueOnce(error)
|
||||
await expect(database.query('SELECT private_column', ['private-param'])).rejects.toBe(error)
|
||||
const log = vi.mocked(console.warn).mock.calls[0]![0] as string
|
||||
expect(JSON.parse(log)).toMatchObject({ operation: 'other', code: 'unknown' })
|
||||
expect(JSON.parse(log)).toMatchObject({
|
||||
operation: 'other',
|
||||
code: 'unknown',
|
||||
transient: false
|
||||
})
|
||||
expect(log).not.toContain('private')
|
||||
})
|
||||
|
||||
|
||||
@@ -1,3 +1,5 @@
|
||||
import { isPostgresPoolConnectTimeout } from './postgres-pool-pressure.js'
|
||||
|
||||
type QueryFailurePhase = 'acquire' | 'execute'
|
||||
|
||||
const ERROR_CODES = new Set([
|
||||
@@ -23,6 +25,8 @@ export function reportPostgresQueryFailure(input: {
|
||||
error: unknown
|
||||
phase: QueryFailurePhase
|
||||
sql: string
|
||||
// The routing verdict, supplied by the caller that owns it.
|
||||
transient: boolean
|
||||
elapsedMs: number
|
||||
pool: { totalCount: number; idleCount: number; waitingCount: number }
|
||||
}): void {
|
||||
@@ -31,9 +35,7 @@ export function reportPostgresQueryFailure(input: {
|
||||
const error = input.error as { code?: unknown; message?: unknown } | null
|
||||
const code =
|
||||
typeof error?.code === 'string' && ERROR_CODES.has(error.code) ? error.code : 'unknown'
|
||||
const connectionTimeout =
|
||||
typeof error?.message === 'string' &&
|
||||
error.message.includes('timeout exceeded when trying to connect')
|
||||
const connectionTimeout = isPostgresPoolConnectTimeout(error)
|
||||
console.warn(
|
||||
JSON.stringify({
|
||||
event: 'orca_relay_postgres_query_failed',
|
||||
@@ -43,6 +45,7 @@ export function reportPostgresQueryFailure(input: {
|
||||
: 'other',
|
||||
code,
|
||||
connectionTimeout,
|
||||
transient: input.transient,
|
||||
elapsedMs: Math.max(0, Math.round(input.elapsedMs)),
|
||||
poolTotal: input.pool.totalCount,
|
||||
poolIdle: input.pool.idleCount,
|
||||
|
||||
@@ -265,6 +265,40 @@ describe('Relay region API', () => {
|
||||
expect(burst.every(({ status }) => status === 200)).toBe(true)
|
||||
expect(regionCatalog).toHaveBeenCalledOnce()
|
||||
})
|
||||
|
||||
it('answers a pool that cannot hand out a client with a retryable 503', async () => {
|
||||
const regionCatalog = vi.fn(async () => {
|
||||
throw new Error('Connection terminated due to connection timeout')
|
||||
})
|
||||
const app = createRelayApp(config({ publicAssignmentRetryAfterSeconds: 7 }), {
|
||||
store: {} as never,
|
||||
assignments: { regionCatalog } as never,
|
||||
drain: vi.fn(),
|
||||
ready: vi.fn(async () => true)
|
||||
})
|
||||
|
||||
const response = await app.request('/v1/regions')
|
||||
|
||||
expect(response.status).toBe(503)
|
||||
expect(response.headers.get('Retry-After')).toBe('7')
|
||||
expect(await response.json()).toEqual({ error: 'region_catalog_temporarily_unavailable' })
|
||||
})
|
||||
|
||||
it('still fails loudly when the region catalog breaks for a non-transient reason', async () => {
|
||||
const regionCatalog = vi.fn(async () => {
|
||||
throw new TypeError('broken invariant')
|
||||
})
|
||||
const app = createRelayApp(config(), {
|
||||
store: {} as never,
|
||||
assignments: { regionCatalog } as never,
|
||||
drain: vi.fn(),
|
||||
ready: vi.fn(async () => true)
|
||||
})
|
||||
|
||||
const response = await app.request('/v1/regions')
|
||||
|
||||
expect(response.status).toBe(500)
|
||||
})
|
||||
})
|
||||
|
||||
function assignmentRequest(relayHostId: string, extra: Record<string, unknown>): RequestInit {
|
||||
|
||||
@@ -8,12 +8,26 @@ covered. These events are diagnostic evidence, not a replacement for total SQL
|
||||
failure counters.
|
||||
|
||||
The event contains only an allowlisted error code, a connection-timeout boolean,
|
||||
the operation category (`control-renewal` or `other`), total elapsed milliseconds,
|
||||
and pool total/idle/waiting counts at failure. Total elapsed time includes acquisition.
|
||||
An acquisition timeout can mean either waiting in the queue or establishing a new
|
||||
connection; use the pool counts and independent server activity to distinguish them.
|
||||
Unknown error codes stay `unknown`. Query text, parameters, error messages, and
|
||||
identifiers are never emitted. Successful queries emit no additional event.
|
||||
a transient boolean, the operation category (`control-renewal` or `other`), total
|
||||
elapsed milliseconds, and pool total/idle/waiting counts at failure. Total elapsed
|
||||
time includes acquisition. An acquisition timeout can mean either waiting in the
|
||||
queue or establishing a new connection; `connectionTimeout` covers both, and the
|
||||
pool counts separate them: a queue wait has waiters, a dial does not.
|
||||
Unknown error codes stay `unknown`.
|
||||
|
||||
`transient` is the classification the request routes act on, not a second
|
||||
opinion: true means retryable, false means terminal. It is not a count of HTTP
|
||||
responses. Every caller of `PostgresDatabase.query` emits this event, including
|
||||
background sweeps, startup reconciliation, and admin routes that map a failure
|
||||
to 409, and none of those produces a 503 or a 500. Counting `transient=false`
|
||||
therefore over-counts user-facing hard failures; narrow by operation, or join
|
||||
against the route's own rejection logs, before reading it that way. A pool that
|
||||
cannot hand out a client carries no error code at all, so `code` stays `unknown`
|
||||
for that whole class and only these two booleans separate it from a genuine
|
||||
fault such as a rejected password.
|
||||
|
||||
Query text, parameters, error messages, and identifiers are never emitted.
|
||||
Successful queries emit no additional event.
|
||||
|
||||
Use structured GCE logs with `jsonPayload.event="orca_relay_postgres_query_failed"`.
|
||||
Compare counts by phase, operation, and code with the same cell's renewal outcomes
|
||||
|
||||
Reference in New Issue
Block a user