diff --git a/cloud/apps/relay/src/app.ts b/cloud/apps/relay/src/app.ts index 978e544f5ff..0dcd3a68f9a 100644 --- a/cloud/apps/relay/src/app.ts +++ b/cloud/apps/relay/src/app.ts @@ -27,10 +27,11 @@ import { createRegionalRehomeTokenVerifier, createRuntimeTokenVerifier } from './admin-token-verifier.js' -import type { - CellFenceAttemptEvidence, - RelayAssignment, - RelayAssignmentStore +import { + RelayHomeCellUnavailableError, + type CellFenceAttemptEvidence, + type RelayAssignment, + type RelayAssignmentStore } from './assignment-store.js' import { AssignmentRejectionLogWindow } from './assignment-rejection-log-window.js' import { CELL_ADMISSION_STATES } from './cell-admission-selector.js' @@ -361,16 +362,17 @@ export function createRelayApp( } } } catch (error) { - if (isRelayAssignmentCapacityError(error) || isRelayDatabaseTransientError(error)) { + if (isRelayAssignmentUnavailableError(error) || isRelayDatabaseTransientError(error)) { logAssignmentRejection({ route: 'assign', lane, hinted: Boolean(body.data.reconnect), relayHostId: claims.relayHostId, - reason: operationError(error) + reason: operationError(error), + ...homeCellRejectionDetail(error) }) } - if (isRelayAssignmentCapacityError(error)) { + if (isRelayAssignmentUnavailableError(error)) { if (lane === 'placement') { operations.recordRegionSelection?.({ targetRegion, fallback: false }) } @@ -389,11 +391,13 @@ export function createRelayApp( fallback: lane === 'placement' && assignment.region !== targetRegion }) // Grant-side counterpart of the rejection log: reconnect grants are rare - // enough to log and make "which cell is this host on" answerable. - if (lane === 'sticky') { + // enough to log and make "which cell is this host on" answerable. The + // placement-lane ones matter most — they are the only record that a host + // whose sticky lane failed verification landed anywhere at all. + if (body.data.reconnect) { console.warn( - `[orca-relay] assignment granted lane=sticky host=${relayHostLogDigest(claims.relayHostId)}` + - ` cell=${assignment.cellId}` + `[orca-relay] assignment granted lane=${lane} hinted=true` + + ` host=${relayHostLogDigest(claims.relayHostId)} cell=${assignment.cellId}` ) } const lease = await new SignJWT({ @@ -466,16 +470,17 @@ export function createRelayApp( leaseExpiresAt: assignment.leaseExpiresAt }) } catch (error) { - if (isRelayAssignmentCapacityError(error) || isRelayDatabaseTransientError(error)) { + if (isRelayAssignmentUnavailableError(error) || isRelayDatabaseTransientError(error)) { logAssignmentRejection({ route: 'resolve', lane: 'none', hinted: false, relayHostId: body.data.relayHostId, - reason: operationError(error) + reason: operationError(error), + ...homeCellRejectionDetail(error) }) } - if (isRelayAssignmentCapacityError(error)) { + if (isRelayAssignmentUnavailableError(error)) { return context.json({ error: operationError(error) }, 503) } if (isRelayDatabaseTransientError(error)) return rejectPublicAssignment(context) @@ -1948,25 +1953,41 @@ function logAssignmentRejection(input: { hinted: boolean relayHostId: string reason: string + cause?: string + cell?: string suppressed?: number }): void { console.warn( `[orca-relay] assignment rejected route=${input.route} lane=${input.lane}` + ` hinted=${input.hinted} reason=${input.reason}` + ` host=${relayHostLogDigest(input.relayHostId)}` + + (input.cause === undefined ? '' : ` cause=${input.cause}`) + + (input.cell === undefined ? '' : ` cell=${input.cell}`) + (input.suppressed === undefined ? '' : ` suppressed=${input.suppressed}`) ) } -function isRelayAssignmentCapacityError(error: unknown): boolean { +// The home-cell reason is not capacity, but it is the same answer to the client: +// retry, the director cannot place you right now. +function isRelayAssignmentUnavailableError(error: unknown): boolean { return ( error instanceof Error && - ['relay_capacity_exhausted', 'relay_connection_headroom_exhausted'].includes( - error.message - ) + [ + 'relay_capacity_exhausted', + 'relay_connection_headroom_exhausted', + 'relay_home_cell_unavailable' + ].includes(error.message) ) } +function homeCellRejectionDetail( + error: unknown +): { cause: string; cell: string } | Record { + return error instanceof RelayHomeCellUnavailableError + ? { cause: error.unavailableCause, cell: error.cellId } + : {} +} + function isCanonicalRelayOrigin(value: string): boolean { const url = new URL(value) const loopback = ['127.0.0.1', 'localhost', '::1', '[::1]'].includes(url.hostname) diff --git a/cloud/apps/relay/src/assignment-home-cell-unavailable.test.ts b/cloud/apps/relay/src/assignment-home-cell-unavailable.test.ts new file mode 100644 index 00000000000..5b2be7ff02f --- /dev/null +++ b/cloud/apps/relay/src/assignment-home-cell-unavailable.test.ts @@ -0,0 +1,136 @@ +import { afterEach, describe, expect, it } from 'vitest' +import { RelayAssignmentStore, RelayHomeCellUnavailableError } from './assignment-store.js' +import type { RelayCellConfig } from './config.js' +import { openInMemoryRelayDatabase, type RelayDatabase } from './database.js' + +const HEARTBEAT_TTL_MS = 45_000 +const START_MS = 100 +const IDENTITY = { userId: 'user-1', relayHostId: 'host000000000001' } + +// A connection-limited cell is what makes the committed fence mandatory, and +// that is the branch which used to answer "capacity exhausted". +const FENCED_CELL: RelayCellConfig = { + id: 'home', + url: 'https://home.example.com', + capacityRequests: 1_000, + connectionHardCap: 600, + connectionUnobservedBound: 50 +} + +const databases: RelayDatabase[] = [] + +afterEach(async () => { + for (const database of databases.splice(0)) await database.close() +}) + +interface Harness { + store: RelayAssignmentStore + heartbeat: (cell: RelayCellConfig, ready: boolean) => Promise + setNow: (value: number) => void +} + +async function setup(cells: RelayCellConfig[] = [FENCED_CELL]): Promise { + const database = await openInMemoryRelayDatabase() + databases.push(database) + let now = START_MS + const store = new RelayAssignmentStore(database, () => now, { + requireLiveCells: true, + heartbeatTtlMs: HEARTBEAT_TTL_MS + }) + await store.reconcileCells(cells, true) + const heartbeat = async (cell: RelayCellConfig, ready: boolean): Promise => { + await store.recordCellHeartbeat({ + cellId: cell.id, + cellUrl: cell.url, + cellIncarnation: `1111111${cells.indexOf(cell)}-1111-4111-8111-111111111111`, + startedAt: 50, + ready, + observedRequests: 0, + ...(cell.connectionHardCap === undefined + ? {} + : { + totalConnections: 0, + inFlightConnections: 0, + reservedConnectionUnits: 0, + enforcedConnectionUnits: 0, + connectionHardCap: cell.connectionHardCap, + connectionUnobservedBound: cell.connectionUnobservedBound + }) + }) + } + for (const cell of cells) await heartbeat(cell, true) + return { store, heartbeat, setNow: (value: number) => (now = value) } +} + +async function assignFailure(store: RelayAssignmentStore): Promise { + return await store.assign(IDENTITY).then( + () => new Error('assign unexpectedly succeeded'), + (error: unknown) => error + ) +} + +function homeCellError(error: unknown): RelayHomeCellUnavailableError { + expect(error).toBeInstanceOf(RelayHomeCellUnavailableError) + // oxlint-disable-next-line typescript/consistent-type-assertions -- SAFETY: the assertion above. + return error as RelayHomeCellUnavailableError +} + +describe('home cell unavailable', () => { + it('names a readiness failure rather than reporting fleet capacity', async () => { + const { store, heartbeat, setNow } = await setup() + await store.assign(IDENTITY) + setNow(START_MS + 1_000) + await heartbeat(FENCED_CELL, false) + + const error = homeCellError(await assignFailure(store)) + + expect(error.message).toBe('relay_home_cell_unavailable') + expect(error.unavailableCause).toBe('not_ready') + expect(error.cellId).toBe(FENCED_CELL.id) + }) + + it('names a heartbeat gap as unheard even though the cell last reported ready', async () => { + const { store, setNow } = await setup() + await store.assign(IDENTITY) + setNow(START_MS + HEARTBEAT_TTL_MS + 1) + + expect(homeCellError(await assignFailure(store)).unavailableCause).toBe('unheard') + }) + + it('names a drained cell as draining ahead of its heartbeat gap', async () => { + const { store, setNow } = await setup() + await store.assign(IDENTITY) + await store.configureCell(FENCED_CELL, false) + setNow(START_MS + HEARTBEAT_TTL_MS + 1) + + expect(homeCellError(await assignFailure(store)).unavailableCause).toBe('draining') + }) + + it('still reports capacity exhaustion when the fleet has no headroom', async () => { + const { store } = await setup([{ ...FENCED_CELL, capacityRequests: 1 }]) + await store.assign(IDENTITY) + + await expect( + store.assign({ userId: 'user-2', relayHostId: 'host000000000002' }) + ).rejects.toThrow('relay_capacity_exhausted') + }) + + it('rehomes instead of rejecting when the unavailable cell needs no fence', async () => { + const home: RelayCellConfig = { + id: 'home', + url: 'https://home.example.com', + capacityRequests: 1_000 + } + const spare: RelayCellConfig = { + id: 'spare', + url: 'https://spare.example.com', + capacityRequests: 1_000 + } + const { store, heartbeat, setNow } = await setup([home, spare]) + expect((await store.assign(IDENTITY)).cellId).toBe(home.id) + setNow(START_MS + 1_000) + await heartbeat(home, false) + + expect((await store.assign(IDENTITY)).cellId).toBe(spare.id) + }) +}) diff --git a/cloud/apps/relay/src/assignment-rejection-logging.test.ts b/cloud/apps/relay/src/assignment-rejection-logging.test.ts index b00d791fce9..d84a813d46c 100644 --- a/cloud/apps/relay/src/assignment-rejection-logging.test.ts +++ b/cloud/apps/relay/src/assignment-rejection-logging.test.ts @@ -1,5 +1,5 @@ import { afterEach, describe, expect, it, vi } from 'vitest' -import type { RelayAssignment } from './assignment-store.js' +import { RelayHomeCellUnavailableError, type RelayAssignment } from './assignment-store.js' import type { RelayConfig } from './config.js' const fakes = vi.hoisted(() => ({ @@ -52,6 +52,39 @@ describe('assignment rejection logging', () => { expect(line).not.toContain(host) }) + it('separates an unavailable home cell from capacity and names its cause', async () => { + const host = 'cccccccccccccccc' + const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined) + const app = createRelayApp(config(), { + store: {} as never, + assignments: { + assign: vi.fn(async () => { + throw new RelayHomeCellUnavailableError('cell-asia-1', 'not_ready') + }), + // The sticky lane refuses a host whose home cell is not live, so this + // arrives hinted on the placement lane. + resolve: vi.fn(async () => null) + } as never, + drain: vi.fn(), + ready: vi.fn(async () => true) + }) + + const response = await app.request('/v1/assign', assignmentRequest(host, { reconnect: true })) + + expect(response.status).toBe(503) + expect(await response.json()).toEqual({ error: 'relay_home_cell_unavailable' }) + const line = warn.mock.calls.map((call) => String(call[0])).find((entry) => + entry.includes('assignment rejected') + ) + expect(line).toContain('lane=placement') + expect(line).toContain('hinted=true') + expect(line).toContain('reason=relay_home_cell_unavailable') + expect(line).toContain('cause=not_ready') + expect(line).toContain('cell=cell-asia-1') + expect(line).not.toContain('relay_capacity_exhausted') + expect(line).not.toContain(host) + }) + it('logs an unhinted placement rejection without the raw host id', async () => { const host = 'gggggggggggggggg' const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined) @@ -221,6 +254,31 @@ describe('assignment grant logging', () => { expect(line).not.toContain(host) }) + it('logs a hinted grant served by the placement lane', async () => { + const host = 'rrrrrrrrrrrrrrrr' + const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined) + const app = createRelayApp(config(), { + store: {} as never, + assignments: { + assign: vi.fn(async () => assignment('cell-new', host)), + resolve: vi.fn(async () => null) + } as never, + drain: vi.fn(), + ready: vi.fn(async () => true) + }) + + const response = await app.request('/v1/assign', assignmentRequest(host, { reconnect: true })) + + expect(response.status).toBe(200) + const line = warn.mock.calls.map((call) => String(call[0])).find((entry) => + entry.includes('assignment granted') + ) + expect(line).toContain('lane=placement') + expect(line).toContain('hinted=true') + expect(line).toContain('cell=cell-new') + expect(line).not.toContain(host) + }) + it('does not log unhinted placement grants', async () => { const host = 'pppppppppppppppp' const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined) diff --git a/cloud/apps/relay/src/assignment-store.ts b/cloud/apps/relay/src/assignment-store.ts index 17b25ad1ad2..48d91e21b20 100644 --- a/cloud/apps/relay/src/assignment-store.ts +++ b/cloud/apps/relay/src/assignment-store.ts @@ -391,6 +391,25 @@ class AssignmentInventoryScopeChanged extends Error { } } +// Why a reason of its own: a host whose home cell is fenced-but-unattested is +// refused regardless of fleet headroom, so reporting it as capacity sends +// operators after capacity that was never short. Every cell boot and every +// readiness dip produces these. +export type RelayHomeCellUnavailableCause = + | 'draining' + | 'booting' + | 'unheard' + | 'not_ready' + +export class RelayHomeCellUnavailableError extends Error { + constructor( + readonly cellId: string, + readonly unavailableCause: RelayHomeCellUnavailableCause + ) { + super('relay_home_cell_unavailable') + } +} + // Debt holds connection headroom for a control that may still arrive shortly // after its director-side timeout. Nothing legitimately arrives minutes late // (attach deadline 10s, orphan grace 30s); unretired debt from hosts that @@ -921,7 +940,10 @@ export class RelayAssignmentStore { )) && !(await this.cellHasCommittedFence(transaction, current.cellId, now)) ) { - throw new Error('relay_capacity_exhausted') + throw new RelayHomeCellUnavailableError( + current.cellId, + await this.homeCellUnavailableCause(transaction, current.cellId, now) + ) } forcedDeadReassignment = true } @@ -2673,7 +2695,13 @@ export class RelayAssignmentStore { ) if (assignment.cellId !== text(row, 'cell_id')) moved++ } catch (error) { - if (!(error instanceof Error && error.message === 'relay_capacity_exhausted')) throw error + // One unplaceable host must not end the sweep for the rest. + if ( + !(error instanceof RelayHomeCellUnavailableError) && + !(error instanceof Error && error.message === 'relay_capacity_exhausted') + ) { + throw error + } } } return moved @@ -7135,6 +7163,31 @@ export class RelayAssignmentStore { return rows.length === 1 } + // Reports which of `cellIsLive`'s conditions failed, so the rejection log + // separates an expected drain or boot from a cell whose readiness went out + // from under its hosts. + private async homeCellUnavailableCause( + database: RelayDatabase, + cellId: string, + now: number + ): Promise { + const row = ( + await database.query( + `SELECT cell.enabled, runtime.last_heartbeat_at + FROM relay_cells cell + LEFT JOIN relay_cell_runtime runtime ON runtime.cell_id = cell.cell_id + WHERE cell.cell_id = ?`, + [cellId] + ) + )[0] + if (!row) return 'booting' + if (integer(row, 'enabled') === 0) return 'draining' + const heartbeatAt = optionalInteger(row, 'last_heartbeat_at') + if (heartbeatAt === undefined) return 'booting' + // Readiness is all that is left: `cellIsLive` already refused this cell. + return heartbeatAt <= now - this.heartbeatTtlMs ? 'unheard' : 'not_ready' + } + private async cellHasActiveFence(cellId: string): Promise { const rows = await this.database.query( `SELECT fence.cell_id FROM relay_cell_fences fence diff --git a/cloud/dev/scripts/relay-load-connection-failure.mjs b/cloud/dev/scripts/relay-load-connection-failure.mjs index 0238740b5a2..a189f62c44a 100644 --- a/cloud/dev/scripts/relay-load-connection-failure.mjs +++ b/cloud/dev/scripts/relay-load-connection-failure.mjs @@ -1,12 +1,20 @@ +// A refused home cell is not fleet capacity, so it gets its own bucket rather +// than inflating the capacity count a run is read for. +const ASSIGNMENT_REJECTION_BUCKETS = { + relay_capacity_exhausted: 'assignment_capacity_exhausted', + relay_connection_headroom_exhausted: 'assignment_capacity_exhausted', + relay_home_cell_unavailable: 'assignment_home_cell_unavailable' +} + export function relayLoadFailureReason(error) { const message = error instanceof Error ? error.message : String(error) const tokenExchange = /^relay token exchange failed: ([1-5][0-9]{2})$/.exec(message) if (tokenExchange) return `token_http_${tokenExchange[1]}` const assignment = - /^relay assignment failed: ([1-5][0-9]{2})(?: (relay_capacity_exhausted|relay_connection_headroom_exhausted))?$/.exec( - message - ) - if (assignment?.[1] === '503' && assignment[2]) return 'assignment_capacity_exhausted' + /^relay assignment failed: ([1-5][0-9]{2})(?: (relay_[a-z_]+))?$/.exec(message) + if (assignment?.[1] === '503' && assignment[2]) { + return ASSIGNMENT_REJECTION_BUCKETS[assignment[2]] ?? `assignment_http_${assignment[1]}` + } if (assignment) return `assignment_http_${assignment[1]}` const closed = /^control closed: ([0-9]{4})\b/.exec(message) if (closed) return `control_close_${closed[1]}` diff --git a/cloud/dev/scripts/relay-load-control-peer.mjs b/cloud/dev/scripts/relay-load-control-peer.mjs index bb954a5d150..a075d6bf4e7 100644 --- a/cloud/dev/scripts/relay-load-control-peer.mjs +++ b/cloud/dev/scripts/relay-load-control-peer.mjs @@ -11,9 +11,10 @@ const { buildHostProofMacInput, HOST_CHALLENGE_PLAINTEXT_DOMAIN } = await import requireFromRelay.resolve('@orca-cloud/relay-contract') ) -const CAPACITY_ASSIGNMENT_ERRORS = [ +const REPORTABLE_ASSIGNMENT_ERRORS = [ 'relay_capacity_exhausted', - 'relay_connection_headroom_exhausted' + 'relay_connection_headroom_exhausted', + 'relay_home_cell_unavailable' ] function waitForOpen(socket, timeoutMs = 10_000) { @@ -744,7 +745,7 @@ export class RelayLoadControlPeer { 'relay assignment timeout', (status, errorCode) => `relay assignment failed: ${status}${errorCode ? ` ${errorCode}` : ''}`, - CAPACITY_ASSIGNMENT_ERRORS + REPORTABLE_ASSIGNMENT_ERRORS ) if ( typeof body.cellUrl !== 'string' ||