diff --git a/cloud/apps/relay/src/app.ts b/cloud/apps/relay/src/app.ts index 38d35865b00..113d2731b9c 100644 --- a/cloud/apps/relay/src/app.ts +++ b/cloud/apps/relay/src/app.ts @@ -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')) diff --git a/cloud/apps/relay/src/database-transient-error.test.ts b/cloud/apps/relay/src/database-transient-error.test.ts index b29ff519328..72bbab4d35b 100644 --- a/cloud/apps/relay/src/database-transient-error.test.ts +++ b/cloud/apps/relay/src/database-transient-error.test.ts @@ -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 { + 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) + }) }) diff --git a/cloud/apps/relay/src/database.ts b/cloud/apps/relay/src/database.ts index 4a8fd3ee975..53f1836296e 100644 --- a/cloud/apps/relay/src/database.ts +++ b/cloud/apps/relay/src/database.ts @@ -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 { @@ -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 }) diff --git a/cloud/apps/relay/src/postgres-pool-pressure.ts b/cloud/apps/relay/src/postgres-pool-pressure.ts index e18bf2bdd42..ab0f188067f 100644 --- a/cloud/apps/relay/src/postgres-pool-pressure.ts +++ b/cloud/apps/relay/src/postgres-pool-pressure.ts @@ -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() + +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 { 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): Promise { + try { + return await connection + } catch (error) { + if (typeof error === 'object' && error !== null) poolAcquireFailures.add(error) + throw error + } +} + export function emptyPostgresPoolPressureCounts(): PostgresPoolPressureCounts { return emptyCounts() } diff --git a/cloud/apps/relay/src/postgres-query-failure-postgres.test.ts b/cloud/apps/relay/src/postgres-query-failure-postgres.test.ts index df082de289b..01f14028f97 100644 --- a/cloud/apps/relay/src/postgres-query-failure-postgres.test.ts +++ b/cloud/apps/relay/src/postgres-query-failure-postgres.test.ts @@ -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 }) diff --git a/cloud/apps/relay/src/postgres-query-failure.test.ts b/cloud/apps/relay/src/postgres-query-failure.test.ts index 7b42b6f5cb1..c0dca423bab 100644 --- a/cloud/apps/relay/src/postgres-query-failure.test.ts +++ b/cloud/apps/relay/src/postgres-query-failure.test.ts @@ -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') }) diff --git a/cloud/apps/relay/src/postgres-query-failure.ts b/cloud/apps/relay/src/postgres-query-failure.ts index 26b536c5134..fc8b8e9fe75 100644 --- a/cloud/apps/relay/src/postgres-query-failure.ts +++ b/cloud/apps/relay/src/postgres-query-failure.ts @@ -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, diff --git a/cloud/apps/relay/src/relay-region-app.test.ts b/cloud/apps/relay/src/relay-region-app.test.ts index 54e8da670b8..a35c1aaef0e 100644 --- a/cloud/apps/relay/src/relay-region-app.test.ts +++ b/cloud/apps/relay/src/relay-region-app.test.ts @@ -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): RequestInit { diff --git a/cloud/docs/relay-database-failure-diagnostics.md b/cloud/docs/relay-database-failure-diagnostics.md index 26d3d847a17..1c356f95fae 100644 --- a/cloud/docs/relay-database-failure-diagnostics.md +++ b/cloud/docs/relay-database-failure-diagnostics.md @@ -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