Files
orca/cloud/apps/relay/src/postgres-lost-reply.test.ts
T
Jinwoo Hong e72044a936 fix(relay): a lost database reply ends its connection within statement timeout + 10 s (#26829)
* fix(relay): a lost database reply ends its connection within statement timeout + 2 s

The request pool sets query_timeout to the statement timeout plus 2 s. A
read timeout poisons its transaction: later statements fail at once,
COMMIT never runs (even when the operation caught the error), no ROLLBACK
queues behind the dead statement, and the client is released with the
error so pg-pool destroys it. Autocommit statements destroy their client
too. The server bounds an orphaned idle backend with idle_session_timeout
30 s. A read timeout is answered 503 and never retried, and a renewal
batch that loses its reply fails whole instead of fanning out.

* fix(relay): read timeout margin 10 s, configurable, so routine 5-7 s database stalls never trip it

A whole-VM stall delays replies the server already timed. With a 2 s
margin the read timeout fired inside routine stalls, destroying healthy
clients and failing requests that succeed today. The margin is now 10 s
(ORCA_RELAY_POSTGRES_READ_TIMEOUT_MARGIN_MS), and a real-server test holds
a reply 6.5 s and requires it delivered on the same connection. The fix
level rises to 2 here, with the lost-reply fix.

* docs(relay): name the startup retry that can see a read timeout, and why it is safe

Boot open retries only an unreachable database. The director's startup
cell reconcile does retry a lost reply, which is safe: it re-runs upserts
and limit-change deletes that converge on the same rows.

* fix(relay): answer 503, not 500, when Postgres ends the session mid-request

Staging B1: pg_terminate_backend during /v1/assign returned 500 29 times.
57P01/57P02 and 08000/08003 join the transient SQLSTATEs; pg's
'Connection terminated' and ECONNRESET count only when the database layer
threw them. transaction() still never retries them.

* fix(relay): answer 503 when the pool acquire fails on a dead socket

Staging B1 re-test: a Cloud SQL restart failed PostgresDatabase.transaction's
acquire with 'write EPIPE', answered 500. An acquire failure with EPIPE,
ECONNRESET, ECONNREFUSED, ETIMEDOUT or EHOSTUNREACH is now a pool connect
failure (no statement ran), and acquire failures count as database-layer
errors. EPIPE mid-statement is treated like ECONNRESET.
2026-10-09 18:00:10 -04:00

125 lines
4.8 KiB
TypeScript

import { EventEmitter } from 'node:events'
import { describe, expect, it, vi } from 'vitest'
import { isRelayDatabaseTransientError, PostgresDatabase } from './database.js'
import {
isFencedRelayDatabaseRejection,
POSTGRES_READ_TIMEOUT_MESSAGE
} from './relay-database-rejection-fence.js'
// pg's query_timeout firing: the statement's reply never arrived.
const readTimeout = () => new Error(POSTGRES_READ_TIMEOUT_MESSAGE)
class FakePoolClient extends EventEmitter {
readonly statements: string[] = []
readonly released: Array<Error | boolean | undefined> = []
constructor(private readonly timesOut: (sql: string) => boolean) {
super()
}
query = vi.fn(async (sql: string) => {
this.statements.push(sql)
if (this.timesOut(sql)) throw readTimeout()
return { rows: [{ one: 1 }], rowCount: 1 }
})
release = (error?: Error | boolean): void => {
this.released.push(error)
}
}
function databaseOver(timesOut: (sql: string) => boolean) {
const clients: FakePoolClient[] = []
const database = new PostgresDatabase({
totalCount: 1,
idleCount: 0,
waitingCount: 0,
connect: async () => {
const client = new FakePoolClient(timesOut)
clients.push(client)
return client
}
} as never)
return { database, clients }
}
describe('a lost PostgreSQL reply', () => {
it('ends a bounded locked statement with nothing else sent on its connection', async () => {
const { database, clients } = databaseOver((sql) => sql.includes('FOR UPDATE'))
const failure = await database
.transaction(
async (transaction) =>
await transaction.queryLocked('SELECT id FROM cells WHERE id = ?', ['c1'], {
lockTimeoutMs: 200
})
)
.catch((error: unknown) => error)
expect(failure).toEqual(readTimeout())
// Not retried, no lock_timeout restore, no ROLLBACK, no COMMIT behind the dead statement.
expect(clients).toHaveLength(1)
expect(clients[0]?.statements).toEqual([
'BEGIN',
"SET LOCAL lock_timeout = '200ms'",
'SELECT id FROM cells WHERE id = $1 FOR UPDATE'
])
// Released with the error, so pg-pool destroys it instead of reusing it.
expect(clients[0]?.released).toEqual([failure])
// Answered 503 like a dropped connection, and survivable if nothing awaited it.
expect(isRelayDatabaseTransientError(failure)).toBe(true)
expect(isFencedRelayDatabaseRejection(failure)).toBe(true)
})
it('never commits after an operation that caught the timeout and carried on', async () => {
const { database, clients } = databaseOver((sql) => sql === 'UPDATE cells SET n = n + 1')
const failure = await database
.transaction(async (transaction) => {
await transaction.query('UPDATE cells SET n = n + 1').catch(() => undefined)
// Every later statement on the poisoned transaction fails at once, unsent.
await expect(transaction.query('SELECT 1')).rejects.toEqual(readTimeout())
return 'carried on'
})
.catch((error: unknown) => error)
expect(failure).toEqual(readTimeout())
expect(clients[0]?.statements).toEqual(['BEGIN', 'UPDATE cells SET n = n + 1'])
expect(clients[0]?.released).toEqual([failure])
})
it('treats a lost COMMIT reply as an unknown outcome: no ROLLBACK, no retry', async () => {
const { database, clients } = databaseOver((sql) => sql === 'COMMIT')
await expect(
database.transaction(async (transaction) => await transaction.query('SELECT 1'))
).rejects.toEqual(readTimeout())
expect(clients).toHaveLength(1)
expect(clients[0]?.statements).toEqual(['BEGIN', 'SELECT 1', 'COMMIT'])
expect(clients[0]?.released[0]).toEqual(readTimeout())
})
it('destroys the client of a timed-out autocommit statement and serves the next one', async () => {
let first = true
const { database, clients } = databaseOver(() => {
const timesOut = first
first = false
return timesOut
})
vi.spyOn(console, 'warn').mockImplementation(() => {})
await expect(database.query('SELECT 1')).rejects.toEqual(readTimeout())
await expect(database.query('SELECT 1')).resolves.toEqual([{ one: 1 }])
expect(clients.map((client) => client.released)).toEqual([[readTimeout()], [undefined]])
})
it('still rolls back and retries an ordinary server error', async () => {
let failures = 1
const { database, clients } = databaseOver(() => false)
const result = await database.transaction(async (transaction) => {
if (failures-- > 0) throw Object.assign(new Error('deadlock detected'), { code: '40P01' })
return await transaction.query('SELECT 1')
})
expect(result).toEqual([{ one: 1 }])
expect(clients.map((client) => client.statements)).toEqual([
['BEGIN', 'ROLLBACK'],
['BEGIN', 'SELECT 1', 'COMMIT']
])
expect(clients.map((client) => client.released)).toEqual([[undefined], [undefined]])
})
})