From b07c4032ea336b088fe8ca364644c84c960cc0e7 Mon Sep 17 00:00:00 2001 From: Jinwoo Hong <73622457+Jinwoo-H@users.noreply.github.com> Date: Mon, 14 Sep 2026 20:07:24 -0400 Subject: [PATCH] Log bounded PostgreSQL acquisition and execution failure diagnostics (#20749) --- cloud/apps/relay/src/database.ts | 18 ++- .../postgres-query-failure-postgres.test.ts | 70 +++++++++++ .../relay/src/postgres-query-failure.test.ts | 109 ++++++++++++++++++ .../apps/relay/src/postgres-query-failure.ts | 55 +++++++++ .../relay-database-failure-diagnostics.md | 29 +++++ 5 files changed, 279 insertions(+), 2 deletions(-) create mode 100644 cloud/apps/relay/src/postgres-query-failure-postgres.test.ts create mode 100644 cloud/apps/relay/src/postgres-query-failure.test.ts create mode 100644 cloud/apps/relay/src/postgres-query-failure.ts create mode 100644 cloud/docs/relay-database-failure-diagnostics.md diff --git a/cloud/apps/relay/src/database.ts b/cloud/apps/relay/src/database.ts index dee6a16e523..84069646b33 100644 --- a/cloud/apps/relay/src/database.ts +++ b/cloud/apps/relay/src/database.ts @@ -11,6 +11,7 @@ import { } from './postgres-pool-pressure.js' import { applyPostgresSchema } from './postgres-schema-startup.js' import { POSTGRES_STATEMENT_STATS_MIGRATION } from './postgres-statement-stats.js' +import { reportPostgresQueryFailure } from './postgres-query-failure.js' import { CellInventoryHoldSamples, emptyCellInventoryHoldCounts, @@ -910,12 +911,25 @@ class PostgresDatabase implements RelayDatabase { } async query(sql: string, params: unknown[] = []): Promise { - const client = await this.pressure.connect() + const startedAt = performance.now() + let phase: 'acquire' | 'execute' = 'acquire' + let client: pg.PoolClient | undefined try { + client = await this.pressure.connect() + phase = 'execute' const result = await client.query(postgresSql(sql), params) return returnsRows(sql) ? (result.rows as SqlRow[]) : [{ changes: result.rowCount ?? 0 }] + } catch (error) { + reportPostgresQueryFailure({ + error, + phase, + sql, + elapsedMs: performance.now() - startedAt, + pool: this.pool + }) + throw error } finally { - client.release() + client?.release() } } diff --git a/cloud/apps/relay/src/postgres-query-failure-postgres.test.ts b/cloud/apps/relay/src/postgres-query-failure-postgres.test.ts new file mode 100644 index 00000000000..df082de289b --- /dev/null +++ b/cloud/apps/relay/src/postgres-query-failure-postgres.test.ts @@ -0,0 +1,70 @@ +import { afterAll, afterEach, beforeAll, describe, expect, it, vi } from 'vitest' +import { openRelayDatabase, type RelayDatabase } from './database.js' + +const databaseUrl = process.env.ORCA_RELAY_TEST_POSTGRES_URL +const describePostgres = databaseUrl ? describe : describe.skip + +describePostgres('real PostgreSQL query failure phases', () => { + let database: RelayDatabase + + beforeAll(async () => { + database = await openRelayDatabase({ + databaseUrl, + dataDir: '', + poolMax: 1, + statementTimeoutMs: 50 + }) + }) + afterAll(async () => { + await database.close() + }) + afterEach(() => { + vi.restoreAllMocks() + }) + + it('distinguishes a server statement timeout and leaves the pool usable', async () => { + const log = vi.spyOn(console, 'warn').mockImplementation(() => undefined) + await expect(database.query('SELECT pg_sleep(0.2)')).rejects.toMatchObject({ code: '57014' }) + expect(JSON.parse(log.mock.calls[0]![0] as string)).toMatchObject({ + event: 'orca_relay_postgres_query_failed', + phase: 'execute', + code: '57014', + connectionTimeout: false + }) + expect(await database.query('SELECT 1 AS ok')).toEqual([{ ok: 1 }]) + }) + + it('distinguishes queue acquisition timeout without running the statement', async () => { + const log = vi.spyOn(console, 'warn').mockImplementation(() => undefined) + let acquired!: () => void + const ready = new Promise((resolve) => { + acquired = resolve + }) + let release!: () => void + const wait = new Promise((resolve) => { + release = resolve + }) + const holder = database.transaction(async () => { + acquired() + await wait + }) + await ready + try { + await expect(database.query('SELECT pg_sleep(0.2)')).rejects.toThrow( + 'timeout exceeded when trying to connect' + ) + expect(JSON.parse(log.mock.calls[0]![0] as string)).toMatchObject({ + event: 'orca_relay_postgres_query_failed', + phase: 'acquire', + code: 'unknown', + connectionTimeout: true, + poolTotal: 1, + poolIdle: 0 + }) + } finally { + release() + await holder + } + expect(await database.query('SELECT 1 AS ok')).toEqual([{ ok: 1 }]) + }) +}) diff --git a/cloud/apps/relay/src/postgres-query-failure.test.ts b/cloud/apps/relay/src/postgres-query-failure.test.ts new file mode 100644 index 00000000000..7b42b6f5cb1 --- /dev/null +++ b/cloud/apps/relay/src/postgres-query-failure.test.ts @@ -0,0 +1,109 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' + +const fakes = vi.hoisted(() => ({ + connectError: undefined as unknown, + query: vi.fn(async (_sql: string, _params?: unknown[]) => ({ rows: [], rowCount: 0 })), + release: vi.fn() +})) + +vi.mock('pg', () => ({ + default: { + Pool: class { + totalCount = 10 + idleCount = 0 + waitingCount = 7 + on = vi.fn() + async connect() { + if (fakes.connectError) throw fakes.connectError + return { query: fakes.query, release: fakes.release } + } + async end() {} + } + } +})) + +import { openRelayDatabase, type RelayDatabase } from './database.js' + +describe('PostgreSQL query failure diagnostics', () => { + let database: RelayDatabase + const sql = 'WITH assignment_state AS MATERIALIZED (SELECT $1) SELECT * FROM assignment_state' + + beforeEach(async () => { + fakes.connectError = undefined + fakes.query.mockReset().mockResolvedValue({ rows: [], rowCount: 0 }) + vi.spyOn(console, 'warn').mockImplementation(() => undefined) + database = await openRelayDatabase({ databaseUrl: 'postgres://unused', dataDir: '' }) + fakes.query.mockClear() + fakes.release.mockClear() + vi.mocked(console.warn).mockClear() + }) + + afterEach(async () => { + await database.close() + vi.restoreAllMocks() + }) + + it('identifies acquisition failure without issuing SQL or changing the error', async () => { + const error = new Error('timeout exceeded when trying to connect: private detail') + fakes.connectError = error + await expect(database.query(sql, ['private-token'])).rejects.toBe(error) + expect(fakes.query).not.toHaveBeenCalled() + expect(fakes.release).not.toHaveBeenCalled() + expect(JSON.parse(vi.mocked(console.warn).mock.calls[0]![0] as string)).toEqual({ + event: 'orca_relay_postgres_query_failed', + phase: 'acquire', + operation: 'control-renewal', + code: 'unknown', + connectionTimeout: true, + elapsedMs: expect.any(Number), + poolTotal: 10, + poolIdle: 0, + poolWaiting: 7 + }) + expect(JSON.stringify(vi.mocked(console.warn).mock.calls)).not.toContain('private') + }) + + it.each(['57014', '55P03', 'ECONNRESET'])( + 'identifies execute failure %s and releases its client', + async (code) => { + 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) + expect(fakes.query).toHaveBeenCalledOnce() + expect(fakes.release).toHaveBeenCalledOnce() + expect(JSON.parse(vi.mocked(console.warn).mock.calls[0]![0] as string)).toMatchObject({ + phase: 'execute', + operation: 'control-renewal', + code, + connectionTimeout: false + }) + 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('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(log).not.toContain('private') + }) + + it('keeps the original error and releases the client if logging fails', async () => { + const error = new Error('database failure') + fakes.query.mockRejectedValueOnce(error) + vi.mocked(console.warn).mockImplementationOnce(() => { + throw new Error('logger failure') + }) + await expect(database.query(sql)).rejects.toBe(error) + expect(fakes.release).toHaveBeenCalledOnce() + }) + + it('does not log successful queries', async () => { + await database.query(sql) + expect(console.warn).not.toHaveBeenCalled() + expect(fakes.release).toHaveBeenCalledOnce() + }) +}) diff --git a/cloud/apps/relay/src/postgres-query-failure.ts b/cloud/apps/relay/src/postgres-query-failure.ts new file mode 100644 index 00000000000..26b536c5134 --- /dev/null +++ b/cloud/apps/relay/src/postgres-query-failure.ts @@ -0,0 +1,55 @@ +type QueryFailurePhase = 'acquire' | 'execute' + +const ERROR_CODES = new Set([ + '57014', + '55P03', + '40P01', + '40001', + '53300', + '57P01', + '57P02', + '57P03', + '08000', + '08001', + '08003', + '08006', + 'ECONNRESET', + 'ECONNREFUSED', + 'ETIMEDOUT', + 'EPIPE' +]) + +export function reportPostgresQueryFailure(input: { + error: unknown + phase: QueryFailurePhase + sql: string + elapsedMs: number + pool: { totalCount: number; idleCount: number; waitingCount: number } +}): void { + // Emit only bounded categories: error messages and SQL can contain credentials or identities. + try { + 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') + console.warn( + JSON.stringify({ + event: 'orca_relay_postgres_query_failed', + phase: input.phase, + operation: /^\s*WITH\s+assignment_state\s+AS\s+MATERIALIZED\b/i.test(input.sql) + ? 'control-renewal' + : 'other', + code, + connectionTimeout, + elapsedMs: Math.max(0, Math.round(input.elapsedMs)), + poolTotal: input.pool.totalCount, + poolIdle: input.pool.idleCount, + poolWaiting: input.pool.waitingCount + }) + ) + } catch { + // Diagnostics must not replace the original database failure. + } +} diff --git a/cloud/docs/relay-database-failure-diagnostics.md b/cloud/docs/relay-database-failure-diagnostics.md new file mode 100644 index 00000000000..26d3d847a17 --- /dev/null +++ b/cloud/docs/relay-database-failure-diagnostics.md @@ -0,0 +1,29 @@ +# Relay database failure phases + +`orca_relay_postgres_query_failed` separates failure to acquire a pooled connection +(`phase=acquire`) from failure after acquisition (`phase=execute`). It covers +`PostgresDatabase.query`, including the single-statement control-renewal CTE. +Statements inside explicit transactions use a different query path and are not +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. + +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 +and pool pressure, and with independent PostgreSQL wait samples. Establishing the +failure phase does not by itself establish why the pool backed up. + +For production observation, use an immutable image through the same-cap workflow +on one cell, with fresh monitor evidence and the exact predecessor digest. Verify +the serving digest and health, then inspect these events during a naturally +occurring failure. Do not deliberately induce a production database failure. +Rollback uses the same workflow and predecessor image; no schema or database +configuration changes are involved. Do not change rehome limits, timeouts, pool +sizes, or renewal scheduling merely to collect this evidence.