Log bounded PostgreSQL acquisition and execution failure diagnostics (#20749)

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<SqlRow[]> {
-    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()
     }
   }
 

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<void>((resolve) => {
+      acquired = resolve
+    })
+    let release!: () => void
+    const wait = new Promise<void>((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 }])
+  })
+})

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()
+  })
+})

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.
+  }
+}

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.