mirror of
https://github.com/stablyai/orca.git
synced 2026-10-30 16:47:34 +00:00
feat(relay): count and log phone-path failures, and every attach deadline (#30656)
* feat(relay): add the per-cell phonePath switch, effective only in reserve mode Step 6 of the relay redesign keys every phone-path change on this switch. The cell reports the effective value in runtime status, and the flag tool refuses phonePath=memory unless the cell is reserve, and a reserve flip that would turn phones over unnamed. * feat(relay): resume paired phones from one device read on memory cells With phonePath=memory in reserve mode, a phone resume is admitted from one device read and the cell's own seat, and takes no activity leases. A refused device closes 4401, a failed read 4503, and only a missing device row falls through to the invite path. A phone whose host has no seat gets one assignment read: 4409 when the row names another cell or the read fails, otherwise 4404. * feat(relay): keep a memory resume's basis in the cell and confirm it from one read A phone resumed on the memory path keeps its connection basis in the cell, not in relay_connection_bases. Its confirm rereads the device row once, renews it only when less than 29 days remain, and always answers a current-version confirm renewed:true with the expiry the database holds. Confirms route by where their basis lives, so a flip between accept and confirm completes either way. Retries answer from a 10-min in-memory result map. * test(relay): roll a memory phone cell back with confirms in flight Flipping back by admitMode=db, phonePath=db or a dead-man trip leaves in-flight confirms to finish on their memory basis, writes no phone lease and leaks none, and evacuation still refuses the cell while Postgres records it as reserve. * feat(relay): batch a memory cell's resume-confirmed audit rows Memory confirms buffer their audit rows and the cell writes them as one multi-row insert every 5 s or 500 rows, idempotent by a per-event id. The buffer holds at most 5,000 rows and drops a row older than 10 minutes rather than retrying it, counting and logging both kinds of drop. * feat(relay): count and log phone-path failures, and every attach deadline The runtime metrics line gains phone refusals by close code, attach deadlines, accept database errors, resume confirm failures by code, completed accepts by phone path and the resume audit drop total. Every attach-deadline 4404 now logs what the cell knew of the desktop's control (pong age, ping outstanding, control age and round trip), so a half-open control can be told from a slow data dial. * fix(relay-ops): store phonePath=db as no key, so old images keep taking writes An explicit phonePath=db left in the switch file would make the flag tool refuse every later write after an image rollback, including a watcher's admitMode=db flip back. * fix(relay): log a failed no-seat read, recheck the switch after the device read A failed assignment read for a phone with no seat now logs a rate-limited line before its 4409. A switch that turned off during the device read sends the phone down today's path. resolveResume reuses the one-read lookup, so the expiry and grace rules have one copy. * fix(relay): log a failed memory renewal; test flips, replays and basis cleanup A renewal write that fails still answers the stored expiry, but now logs a rate-limited line so a persistently failing update is visible before phones age toward re-pairing. * test(relay): assert a rolled-back memory splice issues no statement when it closes * fix(relay): flush resume audit early only on crossing the batch size, drop the shutdown flush A failing database no longer takes a 500-row insert per confirm; retries wait for the 5 s timer. The shutdown flush raced the pool closing, so it is gone and the at most 5 s loss is documented. A stopped buffer no longer re-arms its timer.
This commit is contained in:
@@ -385,6 +385,22 @@ describe('the memory phone path', () => {
|
||||
await new Promise((resolve) => setTimeout(resolve, 50))
|
||||
expect(await confirm('confirm-1')).toMatchObject({ type: 'control-error', code: 'confirmation_not_active' })
|
||||
expect(reserve.phoneStatements()[0]).toBe('BEGIN')
|
||||
expect(warnings('orca_relay_resume_confirm_failed')).toEqual([
|
||||
{
|
||||
event: 'orca_relay_resume_confirm_failed',
|
||||
code: 'confirmation_not_active',
|
||||
phonePath: 'db',
|
||||
cellId: reserve.config.cellId
|
||||
}
|
||||
])
|
||||
})
|
||||
|
||||
it('does not count a lease release that failed after a committed confirm as a failed confirm', async () => {
|
||||
const { reserve, confirm } = await splicedPhone('db')
|
||||
vi.spyOn(reserve.relay.assignments, 'releaseActivity').mockRejectedValueOnce(new Error('connection terminated'))
|
||||
// As today, the desktop still hears the release failure.
|
||||
expect(await confirm('confirm-1')).toMatchObject({ type: 'control-error' })
|
||||
expect(warnings('orca_relay_resume_confirm_failed')).toEqual([])
|
||||
})
|
||||
|
||||
it('keeps the database confirm statement for statement while phonePath is db', async () => {
|
||||
|
||||
@@ -114,7 +114,9 @@ function harness(options: { random?: () => number; now?: () => number } = {}) {
|
||||
recordSql: vi.fn(),
|
||||
recordClientAcceptAbandoned: vi.fn(),
|
||||
recordClientAcceptCompleted: vi.fn(),
|
||||
recordControlRtt: vi.fn()
|
||||
recordControlRtt: vi.fn(),
|
||||
recordPhoneRejection: vi.fn(),
|
||||
recordPhoneAttachDeadline: vi.fn()
|
||||
} satisfies RelayRuntimeObserver
|
||||
const registry = new HostSessionRegistry(
|
||||
config,
|
||||
@@ -369,6 +371,40 @@ describe('client accept abandoned mid-DB-phase', () => {
|
||||
}
|
||||
})
|
||||
|
||||
it('logs and counts an attach deadline with what the cell knew of the control', async () => {
|
||||
let now = 1_700_000_000_000
|
||||
const h = harness({ now: () => now })
|
||||
await activeHost(h)
|
||||
const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined)
|
||||
const client = new FakeSocket()
|
||||
await h.registry.acceptClient(client as unknown as WebSocket, identity.relayHostId, 'credential')
|
||||
now += RELAY_PROTOCOL_LIMITS.hostAttachDeadlineMs
|
||||
vi.advanceTimersByTime(RELAY_PROTOCOL_LIMITS.hostAttachDeadlineMs)
|
||||
expect(client.close).toHaveBeenCalledWith(RELAY_CLOSE_CODE.HOST_OFFLINE, expect.any(String))
|
||||
expect(h.observer.recordPhoneAttachDeadline).toHaveBeenCalledOnce()
|
||||
expect(h.observer.recordPhoneRejection).toHaveBeenCalledWith(RELAY_CLOSE_CODE.HOST_OFFLINE)
|
||||
const lines = warn.mock.calls
|
||||
.map(([line]) => String(line))
|
||||
.filter((line) => line.includes('orca_relay_attach_deadline_offline'))
|
||||
expect(lines.map((line) => JSON.parse(line))).toEqual([
|
||||
{
|
||||
event: 'orca_relay_attach_deadline_offline',
|
||||
relayHostIdDigest: expect.any(String),
|
||||
credentialKind: 'resume',
|
||||
msSinceLastPong: RELAY_PROTOCOL_LIMITS.hostAttachDeadlineMs,
|
||||
pingOutstanding: false,
|
||||
controlAgeMs: RELAY_PROTOCOL_LIMITS.hostAttachDeadlineMs,
|
||||
controlRttMs: null,
|
||||
pong: 'fresh',
|
||||
cellId: config.cellId
|
||||
}
|
||||
])
|
||||
expect(lines[0]).not.toContain(identity.relayHostId)
|
||||
warn.mockRestore()
|
||||
h.registry.drain(0)
|
||||
vi.advanceTimersByTime(0)
|
||||
})
|
||||
|
||||
it('still opens the connection when the phone is holding on', async () => {
|
||||
const h = harness()
|
||||
const control = await activeHost(h)
|
||||
@@ -437,7 +473,8 @@ describe('successful client accept timing', () => {
|
||||
expect(ownerProbe).toHaveBeenCalledOnce()
|
||||
expect(h.observer.recordClientAcceptCompleted).toHaveBeenCalledWith({
|
||||
totalMs: 49,
|
||||
stageMs: { assignment: 5, credential: 7, activity: 11, attach: 23, basis: 3 }
|
||||
stageMs: { assignment: 5, credential: 7, activity: 11, attach: 23, basis: 3 },
|
||||
phonePath: 'db'
|
||||
})
|
||||
const line = log.mock.calls
|
||||
.map((call) => String(call[0]))
|
||||
|
||||
@@ -37,10 +37,10 @@ import { CellSeatLog, type CellSeatChange, type CellSeatFeedPage } from './cell-
|
||||
import { isRelayDatabaseTransientError } from './database.js'
|
||||
import { printableCloseReason } from './control-close-reason-text.js'
|
||||
import { ControlRenewalBatch } from './control-renewal-batch.js'
|
||||
import { RelayCredentialStore, type CredentialReservation } from './credential-store.js'
|
||||
import { RelayCredentialStore, RelayStoreError, type CredentialReservation } from './credential-store.js'
|
||||
import { HostCloseReasonMemory } from './host-close-reason-memory.js'
|
||||
import { MemoryResumeConfirmations } from './memory-resume-confirmations.js'
|
||||
import { PhoneAcceptLog } from './phone-accept-log.js'
|
||||
import { PhoneConnectionLog, type PhoneDatabaseCause } from './phone-connection-log.js'
|
||||
import {
|
||||
postProofCloseCause,
|
||||
PostProofCloseLog,
|
||||
@@ -304,7 +304,7 @@ export class HostSessionRegistry {
|
||||
private readonly drainSentHosts = new Set<string>()
|
||||
private readonly seatLog: CellSeatLog
|
||||
private readonly postProofCloses: PostProofCloseLog
|
||||
private readonly phoneAccepts: PhoneAcceptLog
|
||||
private readonly phoneConnections: PhoneConnectionLog
|
||||
private readonly memoryConfirmations: MemoryResumeConfirmations
|
||||
// Seat key -> the demoted control socket. Its own set, not drainSentHosts: it ends with
|
||||
// that socket (close, rebind or a new join), so a later booking here is a fresh seat.
|
||||
@@ -450,9 +450,9 @@ export class HostSessionRegistry {
|
||||
) {
|
||||
this.seatLog = new CellSeatLog(undefined, now)
|
||||
this.postProofCloses = new PostProofCloseLog(observer)
|
||||
this.phoneAccepts = new PhoneAcceptLog(config.cellId)
|
||||
this.phoneConnections = new PhoneConnectionLog(config.cellId)
|
||||
this.memoryConfirmations = new MemoryResumeConfirmations(store, now, (error) =>
|
||||
this.phoneAccepts.renewalFailed(isRelayDatabaseTransientError(error) ? 'database_transient' : 'error')
|
||||
this.recordRenewalFailure(error)
|
||||
)
|
||||
}
|
||||
|
||||
@@ -862,9 +862,8 @@ export class HostSessionRegistry {
|
||||
} catch (error) {
|
||||
// Never the invite path: an unread device is not a missing one.
|
||||
capacityReservation?.release()
|
||||
this.phoneAccepts.databaseError(
|
||||
isRelayDatabaseTransientError(error) ? 'database_transient' : 'error'
|
||||
)
|
||||
this.observer.recordPhoneAcceptDatabaseError?.()
|
||||
this.phoneConnections.databaseError(databaseCause(error))
|
||||
this.rejectClient(socket, RELAY_CLOSE_CODE.DRAINING)
|
||||
return
|
||||
}
|
||||
@@ -981,6 +980,7 @@ export class HostSessionRegistry {
|
||||
capacityReservation?.release()
|
||||
this.failReservationBestEffort(reservation)
|
||||
if (credentialActivityId) this.releaseActivityBestEffort(identity, credentialActivityId)
|
||||
this.recordAttachDeadline(session, reservation)
|
||||
this.rejectClient(socket, RELAY_CLOSE_CODE.HOST_OFFLINE)
|
||||
}, RELAY_PROTOCOL_LIMITS.hostAttachDeadlineMs)
|
||||
const pending: PendingConnection = {
|
||||
@@ -1075,9 +1075,9 @@ export class HostSessionRegistry {
|
||||
relayHostId: reservation.relayHostId
|
||||
})
|
||||
elsewhere = row !== null && row.cellId !== this.config.cellId
|
||||
if (row?.cellId === this.config.cellId) this.phoneAccepts.missRowNamesHere(reservation.relayHostId)
|
||||
if (row?.cellId === this.config.cellId) this.phoneConnections.missRowNamesHere(reservation.relayHostId)
|
||||
} catch (error) {
|
||||
this.phoneAccepts.missReadError(isRelayDatabaseTransientError(error) ? 'database_transient' : 'error')
|
||||
this.phoneConnections.missReadError(databaseCause(error))
|
||||
elsewhere = true
|
||||
}
|
||||
if (elsewhere) {
|
||||
@@ -1271,13 +1271,14 @@ export class HostSessionRegistry {
|
||||
basis: nonNegativeMs(helloAt - attachedAt)
|
||||
}
|
||||
const totalMs = nonNegativeMs(helloAt - pending.timing.startedAt)
|
||||
this.observer.recordClientAcceptCompleted?.({ totalMs, stageMs })
|
||||
this.observer.recordClientAcceptCompleted?.({ totalMs, stageMs, phonePath: pending.phonePath })
|
||||
console.log(
|
||||
JSON.stringify({
|
||||
event: 'orca_relay_client_accept_completed',
|
||||
...this.logIdentity(),
|
||||
...this.sessionPlacementLogFields(session),
|
||||
credentialKind: pending.reservation.credentialKind,
|
||||
phonePath: pending.phonePath,
|
||||
stageMs,
|
||||
totalMs,
|
||||
relayHostIdDigest: relayHostLogDigest(session.relayHostId)
|
||||
@@ -2488,12 +2489,21 @@ export class HostSessionRegistry {
|
||||
if (type === 'device-resume-confirm') {
|
||||
const request = DeviceResumeConfirmSchema.parse(payload(raw, type))
|
||||
const confirm = { ...identity, ...request, owningControlGeneration: session.generation }
|
||||
if (this.memoryConfirmations.owns(confirm)) {
|
||||
send(session.socket, 'device-resume-confirmed', await this.memoryConfirmations.confirm(confirm))
|
||||
return
|
||||
const phonePath = this.memoryConfirmations.owns(confirm) ? 'memory' : 'db'
|
||||
let result
|
||||
try {
|
||||
result =
|
||||
phonePath === 'memory'
|
||||
? await this.memoryConfirmations.confirm(confirm)
|
||||
: await this.store.confirmResume(confirm)
|
||||
} catch (error) {
|
||||
this.recordConfirmFailure(error, phonePath)
|
||||
throw error
|
||||
}
|
||||
// After a committed confirm: a failed release is not a failed confirm.
|
||||
if (phonePath === 'db') {
|
||||
await this.assignments.releaseActivity(identity, `confirmation:${request.basisConnId}`)
|
||||
}
|
||||
const result = await this.store.confirmResume(confirm)
|
||||
await this.assignments.releaseActivity(identity, `confirmation:${request.basisConnId}`)
|
||||
send(session.socket, 'device-resume-confirmed', result)
|
||||
return
|
||||
}
|
||||
@@ -2519,6 +2529,32 @@ export class HostSessionRegistry {
|
||||
}
|
||||
}
|
||||
|
||||
private recordRenewalFailure(error: unknown): void {
|
||||
this.observer.recordResumeRenewalFailure?.()
|
||||
this.phoneConnections.renewalFailed(databaseCause(error))
|
||||
}
|
||||
|
||||
// Never the raw message as a key: pg errors can carry the database URL.
|
||||
private recordConfirmFailure(error: unknown, phonePath: 'db' | 'memory'): void {
|
||||
const code = error instanceof RelayStoreError ? error.code : databaseCause(error)
|
||||
this.observer.recordResumeConfirmFailure?.(code)
|
||||
this.phoneConnections.confirmFailed(code, phonePath)
|
||||
}
|
||||
|
||||
private recordAttachDeadline(session: HostSession, reservation: CredentialReservation): void {
|
||||
const now = this.now()
|
||||
const msSinceLastPong = now - session.lastPongAt
|
||||
this.observer.recordPhoneAttachDeadline?.()
|
||||
this.phoneConnections.attachDeadline(session.relayHostId, {
|
||||
credentialKind: reservation.credentialKind,
|
||||
msSinceLastPong,
|
||||
pingOutstanding: session.pendingPingAt !== null,
|
||||
controlAgeMs: now - session.controlWiredAt,
|
||||
controlRttMs: session.controlRttSamplesMs.at(-1) ?? null,
|
||||
pong: msSinceLastPong > RELAY_PROTOCOL_LIMITS.controlPingIntervalMs ? 'stale' : 'fresh'
|
||||
})
|
||||
}
|
||||
|
||||
private sendControlError(session: HostSession, reqId: string | undefined, code: string): void {
|
||||
if (session.socket) send(session.socket, 'control-error', { ...(reqId ? { reqId } : {}), code })
|
||||
}
|
||||
@@ -2531,6 +2567,7 @@ export class HostSessionRegistry {
|
||||
code: number,
|
||||
hostCloseReason?: RelayHostCloseReason | null
|
||||
): void {
|
||||
this.observer.recordPhoneRejection?.(code)
|
||||
send(socket, 'relay-hello', { ok: false, code })
|
||||
closeRelayWebSocket(socket, code, hostCloseReason ?? 'relay connection rejected')
|
||||
}
|
||||
@@ -2595,3 +2632,7 @@ export class HostSessionRegistry {
|
||||
}
|
||||
|
||||
export type RelayIdentityKey = { userId: string; relayHostId: string }
|
||||
|
||||
function databaseCause(error: unknown): PhoneDatabaseCause {
|
||||
return isRelayDatabaseTransientError(error) ? 'database_transient' : 'error'
|
||||
}
|
||||
|
||||
@@ -1,61 +0,0 @@
|
||||
import { AssignmentRejectionLogWindow } from './assignment-rejection-log-window.js'
|
||||
import { relayHostLogDigest } from './relay-host-log-digest.js'
|
||||
|
||||
// The memory phone path's two accept anomalies. A stuck database or a lost ledger write repeats
|
||||
// per phone dial, so per event one line opens the window and one closing line carries the rest.
|
||||
export const PHONE_ACCEPT_LOG_WINDOW_MS = 60_000
|
||||
|
||||
export type PhoneAcceptDatabaseCause = 'database_transient' | 'error'
|
||||
|
||||
type PhoneAcceptAnomaly =
|
||||
| { event: 'orca_relay_client_accept_db_error'; cause: PhoneAcceptDatabaseCause }
|
||||
| { event: 'orca_relay_client_miss_row_names_here'; relayHostIdDigest: string }
|
||||
| { event: 'orca_relay_client_miss_read_error'; cause: PhoneAcceptDatabaseCause }
|
||||
| { event: 'orca_relay_resume_renewal_failed'; cause: PhoneAcceptDatabaseCause }
|
||||
|
||||
export class PhoneAcceptLog {
|
||||
private readonly window: AssignmentRejectionLogWindow<PhoneAcceptAnomaly>
|
||||
|
||||
constructor(
|
||||
private readonly cellId: string,
|
||||
private readonly warn: (line: string) => void = (line) => console.warn(line),
|
||||
schedule?: (callback: () => void, delayMs: number) => () => void
|
||||
) {
|
||||
this.window = new AssignmentRejectionLogWindow<PhoneAcceptAnomaly>({
|
||||
windowMs: PHONE_ACCEPT_LOG_WINDOW_MS,
|
||||
onWindowClosed: ({ suppressed, sample }) => this.write(sample, suppressed),
|
||||
schedule
|
||||
})
|
||||
}
|
||||
|
||||
// The one device read failed; the phone was closed 4503 and never took the invite path.
|
||||
databaseError(cause: PhoneAcceptDatabaseCause): void {
|
||||
this.record({ event: 'orca_relay_client_accept_db_error', cause })
|
||||
}
|
||||
|
||||
// No seat, yet the row names this cell: the 4404 may be stale (a lost reserve ledger write).
|
||||
missRowNamesHere(relayHostId: string): void {
|
||||
this.record({
|
||||
event: 'orca_relay_client_miss_row_names_here',
|
||||
relayHostIdDigest: relayHostLogDigest(relayHostId)
|
||||
})
|
||||
}
|
||||
|
||||
// The no-seat assignment read failed; the phone was closed 4409 to re-resolve.
|
||||
missReadError(cause: PhoneAcceptDatabaseCause): void {
|
||||
this.record({ event: 'orca_relay_client_miss_read_error', cause })
|
||||
}
|
||||
|
||||
// A due renewal write failed; the confirm still answered the stored expiry.
|
||||
renewalFailed(cause: PhoneAcceptDatabaseCause): void {
|
||||
this.record({ event: 'orca_relay_resume_renewal_failed', cause })
|
||||
}
|
||||
|
||||
private record(anomaly: PhoneAcceptAnomaly): void {
|
||||
if (this.window.admit(anomaly.event, anomaly)) this.write(anomaly, 0)
|
||||
}
|
||||
|
||||
private write(anomaly: PhoneAcceptAnomaly, suppressed: number): void {
|
||||
this.warn(JSON.stringify({ ...anomaly, cellId: this.cellId, ...(suppressed > 0 ? { suppressed } : {}) }))
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,86 @@
|
||||
import { AssignmentRejectionLogWindow } from './assignment-rejection-log-window.js'
|
||||
import { relayHostLogDigest } from './relay-host-log-digest.js'
|
||||
|
||||
// Phone-connection anomalies that repeat per dial (a stuck database, a lost ledger write, a
|
||||
// half-open control): per kind, one line opens the window and one closing line carries the rest.
|
||||
export const PHONE_CONNECTION_LOG_WINDOW_MS = 60_000
|
||||
|
||||
export type PhoneDatabaseCause = 'database_transient' | 'error'
|
||||
|
||||
// What the cell knew of the desktop's control when a phone's attach deadline passed: a stale
|
||||
// pong is a half-open control, a fresh one a slow or failing desktop data dial.
|
||||
export type AttachDeadlineEvidence = {
|
||||
credentialKind: 'invite' | 'resume'
|
||||
msSinceLastPong: number
|
||||
pingOutstanding: boolean
|
||||
controlAgeMs: number
|
||||
controlRttMs: number | null
|
||||
pong: 'stale' | 'fresh'
|
||||
}
|
||||
|
||||
type PhoneConnectionAnomaly =
|
||||
| { event: 'orca_relay_client_accept_db_error'; cause: PhoneDatabaseCause }
|
||||
| { event: 'orca_relay_client_miss_row_names_here'; relayHostIdDigest: string }
|
||||
| { event: 'orca_relay_client_miss_read_error'; cause: PhoneDatabaseCause }
|
||||
| { event: 'orca_relay_resume_renewal_failed'; cause: PhoneDatabaseCause }
|
||||
| ({ event: 'orca_relay_attach_deadline_offline'; relayHostIdDigest: string } & AttachDeadlineEvidence)
|
||||
| { event: 'orca_relay_resume_confirm_failed'; code: string; phonePath: 'db' | 'memory' }
|
||||
|
||||
export class PhoneConnectionLog {
|
||||
private readonly window: AssignmentRejectionLogWindow<PhoneConnectionAnomaly>
|
||||
|
||||
constructor(
|
||||
private readonly cellId: string,
|
||||
private readonly warn: (line: string) => void = (line) => console.warn(line),
|
||||
schedule?: (callback: () => void, delayMs: number) => () => void
|
||||
) {
|
||||
this.window = new AssignmentRejectionLogWindow<PhoneConnectionAnomaly>({
|
||||
windowMs: PHONE_CONNECTION_LOG_WINDOW_MS,
|
||||
onWindowClosed: ({ suppressed, sample }) => this.write(sample, suppressed),
|
||||
schedule
|
||||
})
|
||||
}
|
||||
|
||||
// The one device read failed; the phone was closed 4503 and never took the invite path.
|
||||
databaseError(cause: PhoneDatabaseCause): void {
|
||||
this.record(cause, { event: 'orca_relay_client_accept_db_error', cause })
|
||||
}
|
||||
|
||||
// No seat, yet the row names this cell: the 4404 may be stale (a lost reserve ledger write).
|
||||
missRowNamesHere(relayHostId: string): void {
|
||||
this.record('', {
|
||||
event: 'orca_relay_client_miss_row_names_here',
|
||||
relayHostIdDigest: relayHostLogDigest(relayHostId)
|
||||
})
|
||||
}
|
||||
|
||||
// The no-seat assignment read failed; the phone was closed 4409 to re-resolve.
|
||||
missReadError(cause: PhoneDatabaseCause): void {
|
||||
this.record(cause, { event: 'orca_relay_client_miss_read_error', cause })
|
||||
}
|
||||
|
||||
// A due renewal write failed; the confirm still answered the stored expiry.
|
||||
renewalFailed(cause: PhoneDatabaseCause): void {
|
||||
this.record(cause, { event: 'orca_relay_resume_renewal_failed', cause })
|
||||
}
|
||||
|
||||
attachDeadline(relayHostId: string, evidence: AttachDeadlineEvidence): void {
|
||||
this.record(`${evidence.credentialKind}:${evidence.pong}`, {
|
||||
event: 'orca_relay_attach_deadline_offline',
|
||||
relayHostIdDigest: relayHostLogDigest(relayHostId),
|
||||
...evidence
|
||||
})
|
||||
}
|
||||
|
||||
confirmFailed(code: string, phonePath: 'db' | 'memory'): void {
|
||||
this.record(`${code}:${phonePath}`, { event: 'orca_relay_resume_confirm_failed', code, phonePath })
|
||||
}
|
||||
|
||||
private record(kind: string, anomaly: PhoneConnectionAnomaly): void {
|
||||
if (this.window.admit(`${anomaly.event}:${kind}`, anomaly)) this.write(anomaly, 0)
|
||||
}
|
||||
|
||||
private write(anomaly: PhoneConnectionAnomaly, suppressed: number): void {
|
||||
this.warn(JSON.stringify({ ...anomaly, cellId: this.cellId, ...(suppressed > 0 ? { suppressed } : {}) }))
|
||||
}
|
||||
}
|
||||
@@ -534,6 +534,41 @@ describe('relay observability', () => {
|
||||
})
|
||||
})
|
||||
|
||||
it('counts the phone path, phone refusals by code and the step-6 failures per window', () => {
|
||||
const entries: Array<Record<string, unknown>> = []
|
||||
const observability = new RelayObservability(
|
||||
{ role: 'cell', cellId: 'production-gce-c28', region: 'asia-east2' },
|
||||
(entry) => entries.push(entry)
|
||||
)
|
||||
const stageMs = { assignment: 0, credential: 170, activity: 0, attach: 300, basis: 0 }
|
||||
observability.recordClientAcceptCompleted({ totalMs: 470, stageMs, phonePath: 'memory' })
|
||||
observability.recordClientAcceptCompleted({ totalMs: 3_600, stageMs, phonePath: 'db' })
|
||||
observability.recordPhoneRejection(4401)
|
||||
observability.recordPhoneRejection(4404)
|
||||
observability.recordPhoneRejection(4404)
|
||||
observability.recordPhoneAttachDeadline()
|
||||
observability.recordPhoneAcceptDatabaseError()
|
||||
observability.recordResumeConfirmFailure('reject-revoked')
|
||||
observability.recordResumeRenewalFailure()
|
||||
observability.flush({ ...counts, resumeAuditDropped: 3 })
|
||||
observability.flush(counts)
|
||||
expect(entries[0]).toMatchObject({
|
||||
clientAcceptsByPhonePathDelta: { memory: 1, db: 1 },
|
||||
phoneRejectionsByCodeDelta: { '4401': 1, '4404': 2 },
|
||||
phoneAttachDeadlinesDelta: 1,
|
||||
phoneAcceptDatabaseErrorsDelta: 1,
|
||||
resumeConfirmFailuresByCodeDelta: { 'reject-revoked': 1 },
|
||||
resumeRenewalFailuresDelta: 1,
|
||||
resumeAuditDropped: 3
|
||||
})
|
||||
expect(entries[1]).toMatchObject({
|
||||
phoneRejectionsByCodeDelta: {},
|
||||
phoneAttachDeadlinesDelta: 0,
|
||||
phoneAcceptDatabaseErrorsDelta: 0,
|
||||
resumeConfirmFailuresByCodeDelta: {}
|
||||
})
|
||||
})
|
||||
|
||||
it('summarises completed client accepts and control round trips per window', () => {
|
||||
const entries: Array<Record<string, unknown>> = []
|
||||
const observability = new RelayObservability(
|
||||
@@ -576,6 +611,7 @@ describe('relay observability', () => {
|
||||
clientAcceptsAbandonedByStageDelta: {},
|
||||
clientAcceptAbandonedMsMax: 0
|
||||
})
|
||||
expect(entries[0]).toMatchObject({ clientAcceptsByPhonePathDelta: {} })
|
||||
// An empty window publishes counts only: a zero percentile point is
|
||||
// indistinguishable from a real zero once Cloud Logging aggregates it.
|
||||
expect(entries[1]).toMatchObject({ clientAcceptCompletedDelta: 0, controlRttSamplesDelta: 0 })
|
||||
|
||||
@@ -18,6 +18,8 @@ export type RelayRuntimeCounts = {
|
||||
splices: number
|
||||
pendingSplices: number
|
||||
queuedBytes: number
|
||||
// Step 6: resume audit rows a memory cell dropped since boot; the watcher pages on any.
|
||||
resumeAuditDropped?: number
|
||||
}
|
||||
|
||||
export function observedRelayRequests(counts: RelayRuntimeCounts): number {
|
||||
@@ -105,6 +107,12 @@ export interface RelayRuntimeObserver {
|
||||
recordSpliceClose?(trigger: string): void
|
||||
recordClientAcceptAbandoned?(stage: RelayClientAcceptStage, elapsedMs: number): void
|
||||
recordClientAcceptCompleted?(sample: RelayClientAcceptSample): void
|
||||
// Step 6: every phone refusal by close code, and the phone-path failures the watcher reads.
|
||||
recordPhoneRejection?(code: number): void
|
||||
recordPhoneAttachDeadline?(): void
|
||||
recordPhoneAcceptDatabaseError?(): void
|
||||
recordResumeConfirmFailure?(code: string): void
|
||||
recordResumeRenewalFailure?(): void
|
||||
recordControlRtt?(rttMs: number): void
|
||||
recordHostPreAuth?(path: HostPreAuthPath, outcome: HostPreAuthOutcome, durationMs: number): void
|
||||
}
|
||||
@@ -163,6 +171,7 @@ export const RELAY_CLIENT_ACCEPT_TIMED_STAGES = [
|
||||
export type RelayClientAcceptSample = {
|
||||
totalMs: number
|
||||
stageMs: Record<RelayClientAcceptTimedStage, number>
|
||||
phonePath?: 'db' | 'memory'
|
||||
}
|
||||
|
||||
type RelayMetricDeltas = {
|
||||
@@ -207,6 +216,12 @@ type RelayMetricDeltas = {
|
||||
clientAcceptAbandonedMsMax: number
|
||||
clientAcceptTotalsMs: number[]
|
||||
clientAcceptStageSamplesMs: Record<RelayClientAcceptTimedStage, number[]>
|
||||
clientAcceptsByPhonePath: Record<string, number>
|
||||
phoneRejectionsByCode: Record<string, number>
|
||||
phoneAttachDeadlines: number
|
||||
phoneAcceptDatabaseErrors: number
|
||||
resumeConfirmFailuresByCode: Record<string, number>
|
||||
resumeRenewalFailures: number
|
||||
controlRttSamplesMs: number[]
|
||||
controlRttObserved: number
|
||||
controlRenewalLatenciesMs: number[]
|
||||
@@ -302,6 +317,12 @@ const emptyDeltas = (): RelayMetricDeltas => ({
|
||||
attach: [],
|
||||
basis: []
|
||||
},
|
||||
clientAcceptsByPhonePath: {},
|
||||
phoneRejectionsByCode: {},
|
||||
phoneAttachDeadlines: 0,
|
||||
phoneAcceptDatabaseErrors: 0,
|
||||
resumeConfirmFailuresByCode: {},
|
||||
resumeRenewalFailures: 0,
|
||||
controlRttSamplesMs: [],
|
||||
controlRttObserved: 0,
|
||||
controlRenewalLatenciesMs: [],
|
||||
@@ -550,12 +571,33 @@ export class RelayObservability implements RelayRuntimeObserver {
|
||||
}
|
||||
|
||||
recordClientAcceptCompleted(sample: RelayClientAcceptSample): void {
|
||||
if (sample.phonePath) increment(this.deltas.clientAcceptsByPhonePath, sample.phonePath)
|
||||
this.deltas.clientAcceptTotalsMs.push(sample.totalMs)
|
||||
for (const stage of RELAY_CLIENT_ACCEPT_TIMED_STAGES) {
|
||||
this.deltas.clientAcceptStageSamplesMs[stage].push(sample.stageMs[stage])
|
||||
}
|
||||
}
|
||||
|
||||
recordPhoneRejection(code: number): void {
|
||||
increment(this.deltas.phoneRejectionsByCode, String(code))
|
||||
}
|
||||
|
||||
recordPhoneAttachDeadline(): void {
|
||||
this.deltas.phoneAttachDeadlines += 1
|
||||
}
|
||||
|
||||
recordPhoneAcceptDatabaseError(): void {
|
||||
this.deltas.phoneAcceptDatabaseErrors += 1
|
||||
}
|
||||
|
||||
recordResumeConfirmFailure(code: string): void {
|
||||
increment(this.deltas.resumeConfirmFailuresByCode, code)
|
||||
}
|
||||
|
||||
recordResumeRenewalFailure(): void {
|
||||
this.deltas.resumeRenewalFailures += 1
|
||||
}
|
||||
|
||||
recordControlRtt(rttMs: number): void {
|
||||
const observedBefore = this.deltas.controlRttObserved++
|
||||
keepInReservoir(
|
||||
@@ -683,6 +725,13 @@ export class RelayObservability implements RelayRuntimeObserver {
|
||||
clientAcceptsAbandonedByStageDelta: deltas.clientAcceptsAbandonedByStage,
|
||||
clientAcceptAbandonedMsMax: roundMs(deltas.clientAcceptAbandonedMsMax),
|
||||
clientAcceptCompletedDelta: deltas.clientAcceptTotalsMs.length,
|
||||
clientAcceptsByPhonePathDelta: deltas.clientAcceptsByPhonePath,
|
||||
// Phone refusals by close code; attach deadlines are the 4404s sent with the control still up.
|
||||
phoneRejectionsByCodeDelta: deltas.phoneRejectionsByCode,
|
||||
phoneAttachDeadlinesDelta: deltas.phoneAttachDeadlines,
|
||||
phoneAcceptDatabaseErrorsDelta: deltas.phoneAcceptDatabaseErrors,
|
||||
resumeConfirmFailuresByCodeDelta: deltas.resumeConfirmFailuresByCode,
|
||||
resumeRenewalFailuresDelta: deltas.resumeRenewalFailures,
|
||||
// Accepts are sparse: publishing a zero percentile for every empty window
|
||||
// would pin the p50 at 0 forever and collapse the p95 at low accept rates.
|
||||
...(deltas.clientAcceptTotalsMs.length === 0
|
||||
|
||||
@@ -876,6 +876,10 @@ export function createRelayServer(
|
||||
dataSockets.close()
|
||||
store.resumeAudit.stop()
|
||||
})
|
||||
const resumeAuditDropped = (): number => {
|
||||
const drops = store.resumeAudit.drops()
|
||||
return drops.overflow + drops.aged
|
||||
}
|
||||
const runtimeCounts = () => {
|
||||
const ledgerCounts = connectionLedger?.counts()
|
||||
return {
|
||||
@@ -883,6 +887,7 @@ export function createRelayServer(
|
||||
preAuthConnections,
|
||||
...sessions.runtimeCounts(),
|
||||
queuedBytes: queuedBytes.current(),
|
||||
...(config.role === 'cell' ? { resumeAuditDropped: resumeAuditDropped() } : {}),
|
||||
...(ledgerCounts
|
||||
? {
|
||||
inFlightConnections: ledgerCounts.inFlightConnections,
|
||||
|
||||
Reference in New Issue
Block a user