From 7fa124de5e6eccf1f7ee84d911013be368c2eabc Mon Sep 17 00:00:00 2001 From: Neil <4138956+nwparker@users.noreply.github.com> Date: Tue, 10 Nov 2026 16:19:45 -0800 Subject: [PATCH] relay edge: silent host at authorization expiry closes 4408; dead-control diagnostics (#40929) * relay edge: a keepalive host already silent when its authorization expires closes 4408 At token exp + 60 s, a keepalive control that went silent (asleep, offline) had its silence probe pending, so the expiry check closed it 4401. Production showed these as 4401 'never refreshed' closes with the host silent for ~5-6 minutes, inflating the auth-failure count and hiding drops from the 4408 comparison with the cells. Such a host now closes 4408 (orphan time back-dated as for any silence close). Local e2e K4 (fails without the change: 4401). 48/48. * relay edge: handshake time on control_active, control age and silence on dead-control closes At 1%, many new controls went silent at or right after activation and were closed minutes later, with no rebound from a retry. To tell a desktop that gave up the connect (15 s deadline, e.g. a slow first hello on a new object) from one that died later: control_active double2 = ms from the upgrade to activation; new silence_close (seconds silent, where found, keepalive/legacy, age); auth_expired_close double3 = control age. --- cloud/apps/relay-edge/src/host-relay-base.ts | 3 +++ .../apps/relay-edge/src/host-relay-control.ts | 10 ++++++- .../relay-edge/src/host-relay-handshake.ts | 3 ++- cloud/apps/relay-edge/src/host-relay.ts | 15 +++++++++-- cloud/apps/relay-edge/src/metrics.ts | 8 ++++-- .../relay-edge/test/harness-mvp-object.ts | 4 +-- .../relay-edge/test/mvp-object-hardening.ts | 26 +++++++++++++++++++ cloud/apps/relay-edge/test/mvp-object.ts | 4 +-- 8 files changed, 63 insertions(+), 10 deletions(-) diff --git a/cloud/apps/relay-edge/src/host-relay-base.ts b/cloud/apps/relay-edge/src/host-relay-base.ts index f3f34839b10..d550b6ca840 100644 --- a/cloud/apps/relay-edge/src/host-relay-base.ts +++ b/cloud/apps/relay-edge/src/host-relay-base.ts @@ -45,6 +45,9 @@ export type ControlAttachment = { clientKeepalive?: boolean // A keepalive control found silent: one relay ping sent at this time (see probeSilentControls). probeAt?: number + // Upgrade and activation times, for metrics (absent on attachments from before these fields). + openedAt?: number + activeAt?: number } export type Attachment = ControlAttachment export type Conn = { diff --git a/cloud/apps/relay-edge/src/host-relay-control.ts b/cloud/apps/relay-edge/src/host-relay-control.ts index 16697097b1c..2cc2756c22c 100644 --- a/cloud/apps/relay-edge/src/host-relay-control.ts +++ b/cloud/apps/relay-edge/src/host-relay-control.ts @@ -28,8 +28,16 @@ export abstract class HostRelayControl extends HostRelayHandshake { // Where the host is going away anyway (export, erase, drain, a new control of the same host): a // silent control is closed now. Its orphan time is the latest the ping alarm would have found it, // so rebind and the orphan grace are never shorter than before. + // A control closed for silence: value = seconds silent, label = where it was found, reason = + // keepalive | legacy; double2 = seconds since it became active (-1 if unknown). + protected deadControlMetric(a: ControlAttachment, now: number, seen: number, found: 'alarm' | 'on_demand' | 'expired'): void { + const ageS = a.activeAt === undefined ? -1 : Math.round((now - a.activeAt) / 1000) + metric(this.env, 'silence_close', Math.round((now - seen) / 1000), found, [ageS], this.keepalive(a) ? 'keepalive' : 'legacy', a.place) + } + protected async closeSilentControls(now = Date.now()): Promise { - for (const { ws, seen } of this.silentControls(now)) { + for (const { ws, a, seen } of this.silentControls(now)) { + this.deadControlMetric(a, now, seen, 'on_demand') this.close(ws, RELAY_CLOSE_CODE.PEER_DROPPED, 'control silence timeout') await this.onSocketGone(ws, RELAY_CLOSE_CODE.PEER_DROPPED, '', Math.min(now, seen + this.config.silenceTimeoutMs + this.config.pingIntervalMs)) } diff --git a/cloud/apps/relay-edge/src/host-relay-handshake.ts b/cloud/apps/relay-edge/src/host-relay-handshake.ts index 22614a1fe85..1d9995d44bf 100644 --- a/cloud/apps/relay-edge/src/host-relay-handshake.ts +++ b/cloud/apps/relay-edge/src/host-relay-handshake.ts @@ -157,6 +157,7 @@ export abstract class HostRelayHandshake extends HostRelayBase { }) const leaseExpiresAt = now + LEASE_BASE_MS + Math.round((Math.random() * 2 - 1) * LEASE_JITTER_MS) a.phase = 'active' + a.activeAt = now a.generation = generation a.lastPongAt = now a.lastPingAt = now @@ -191,7 +192,7 @@ export abstract class HostRelayHandshake extends HostRelayBase { }) // After the ack, which strict shipped parsers must see unchanged; only hosts that asked get it. if (a.clientKeepalive) { this.send(ws, { type: 'keepalive-offer', v: 1, intervalMs: this.config.pingIntervalMs }) } - metric(this.env, 'control_active', 1, rebind ? 'rebind' : 'new', [], a.clientKeepalive ? 'keepalive' : 'legacy', a.place) + metric(this.env, 'control_active', 1, rebind ? 'rebind' : 'new', [a.openedAt === undefined ? -1 : now - a.openedAt], a.clientKeepalive ? 'keepalive' : 'legacy', a.place) await this.reschedule() } } diff --git a/cloud/apps/relay-edge/src/host-relay.ts b/cloud/apps/relay-edge/src/host-relay.ts index 14f5a0f544f..bc6095bc33a 100644 --- a/cloud/apps/relay-edge/src/host-relay.ts +++ b/cloud/apps/relay-edge/src/host-relay.ts @@ -145,7 +145,8 @@ export class HostRelay extends HostRelayPhones { claims, origin, caps: [...parseRelayHostCapabilities(request.headers.get('x-orca-host-capabilities') ?? '')], - deadline: Date.now() + RELAY_PROTOCOL_LIMITS.firstFrameDeadlineMs + deadline: Date.now() + RELAY_PROTOCOL_LIMITS.firstFrameDeadlineMs, + openedAt: Date.now() }) await this.reschedule() return new Response(null, { status: 101, webSocket: client }) @@ -180,15 +181,25 @@ export class HostRelay extends HostRelayPhones { continue } if (now - seen > this.config.silenceTimeoutMs && (!this.keepalive(a) || now - a.probeAt! >= KEEPALIVE_PROBE_MS - 50)) { + this.deadControlMetric(a, now, seen, 'alarm') this.close(ws, RELAY_CLOSE_CODE.PEER_DROPPED, 'control silence timeout') await this.onSocketGone(ws, RELAY_CLOSE_CODE.PEER_DROPPED, '') continue } // Same order as the cells' heartbeat: expired auth past its grace, then the 6 h lease. if (now > a.claims.exp + CONTROL_CONTINUITY_LIMITS.expiredAuthExistingSpliceGraceMs) { + // A host already silent past the limit is gone (asleep, offline): it closes as one, so + // drop counts stay comparable with the cells, whose pings would have closed it earlier. + // Its probe is cut short: the expired authorization ends the socket either way. + if (now - seen > this.config.silenceTimeoutMs) { + this.deadControlMetric(a, now, seen, 'expired') + this.close(ws, RELAY_CLOSE_CODE.PEER_DROPPED, 'control silence timeout') + await this.onSocketGone(ws, RELAY_CLOSE_CODE.PEER_DROPPED, '', Math.min(now, seen + this.config.silenceTimeoutMs + this.config.pingIntervalMs)) + continue + } const sinceRefreshS = a.lastRefreshAt === undefined ? -1 : Math.round((now - a.lastRefreshAt) / 1000) const seenAgoS = Math.round((now - seen) / 1000) - metric(this.env, 'auth_expired_close', sinceRefreshS, a.lastRefreshAt === undefined ? 'never' : 'refreshed', [seenAgoS], this.keepalive(a) ? 'keepalive' : 'legacy', a.place) + metric(this.env, 'auth_expired_close', sinceRefreshS, a.lastRefreshAt === undefined ? 'never' : 'refreshed', [seenAgoS, a.activeAt === undefined ? -1 : Math.round((now - a.activeAt) / 1000)], this.keepalive(a) ? 'keepalive' : 'legacy', a.place) this.close(ws, RELAY_CLOSE_CODE.BAD_OUTER_CREDENTIAL, 'relay authorization expired') await this.onSocketGone(ws, RELAY_CLOSE_CODE.BAD_OUTER_CREDENTIAL, '') continue diff --git a/cloud/apps/relay-edge/src/metrics.ts b/cloud/apps/relay-edge/src/metrics.ts index febc2bab77c..ea76d7f7f2c 100644 --- a/cloud/apps/relay-edge/src/metrics.ts +++ b/cloud/apps/relay-edge/src/metrics.ts @@ -2,7 +2,8 @@ import type { Env } from './env' export type MetricEvent = - // label 'new' | 'rebind'; reason 'keepalive' | 'legacy' (took the keepalive offer or not). + // label 'new' | 'rebind'; reason 'keepalive' | 'legacy' (took the keepalive offer or not); + // double2 = ms from the upgrade to activation (the desktop gives up a connect after 15 s). | 'control_active' | 'control_close' | 'phone_open' @@ -27,8 +28,11 @@ export type MetricEvent = | 'control_upgrade' // Control closed 4401 for expired authorization: value = seconds since its last extending // refresh, label 'refreshed'; -1 and label 'never' when this socket never extended its token. - // double2 = seconds since the host's last inbound frame or keepalive; reason 'keepalive' | 'legacy'. + // double2 = seconds since the host's last inbound frame or keepalive, double3 = seconds since the + // control became active (-1 if unknown); reason 'keepalive' | 'legacy'. | 'auth_expired_close' + // Control closed for silence (deadControlMetric, host-relay-control.ts). + | 'silence_close' // Pre-auth socket refused by the per-source limiter: label 'phone' | 'data' | 'health'. Unpushed-host phones: 'not_on_edge'. | 'preauth_limited' | 'not_on_edge' diff --git a/cloud/apps/relay-edge/test/harness-mvp-object.ts b/cloud/apps/relay-edge/test/harness-mvp-object.ts index 89ec43b1e7c..69530b07307 100644 --- a/cloud/apps/relay-edge/test/harness-mvp-object.ts +++ b/cloud/apps/relay-edge/test/harness-mvp-object.ts @@ -47,14 +47,14 @@ export function newHost(): Host { } } -export async function mint(key: KeyLike, relayHostId: string, issuer = ISSUER): Promise { +export async function mint(key: KeyLike, relayHostId: string, issuer = ISSUER, expiresIn = '5m'): Promise { return new SignJWT({ purpose: 'host-control', prof: `prof-${USER}`, relayHostId }) .setProtectedHeader({ alg: 'ES256', kid: REMOTE ? 'spike' : 'mvp' }) .setSubject(USER) .setIssuer(issuer) .setAudience('orca-relay') .setIssuedAt() - .setExpirationTime('5m') + .setExpirationTime(expiresIn) .sign(key) } diff --git a/cloud/apps/relay-edge/test/mvp-object-hardening.ts b/cloud/apps/relay-edge/test/mvp-object-hardening.ts index 5bd6553acab..1e86d0058ee 100644 --- a/cloud/apps/relay-edge/test/mvp-object-hardening.ts +++ b/cloud/apps/relay-edge/test/mvp-object-hardening.ts @@ -128,6 +128,32 @@ export async function keepaliveProbeCheck(key: KeyLike): Promise { } } +// K4: a keepalive host gone silent when its authorization expires closes as a dropped host (4408), +// not 4401, so edge drop counts stay comparable with the cells (their pings would have closed it). +export async function keepaliveExpiredSilentCheck(key: KeyLike): Promise { + const host = newHost() + await assign(host.relayHostId, 'edge', EPOCH, []) + const started = Date.now() + // Alive for 50 s, then silent: the silence probe (sent ~9 s later) is still pending when the + // 3 s token passes its 60 s grace at ~63 s, so the expiry check is what closes it. + const c = control(host, await mint(key, host.relayHostId, undefined, '3s'), EPOCH, { + caps: `${SHIPPED_CAPS},client-keepalive-v1`, + drop: () => Date.now() - started > 50_000 + }) + await c.client.connect() + try { + const closed = await waitFor(() => c.events.closes.length > 0, 3_000 + 60_000 + 15_000) + const after = Date.now() - started + record( + 'K4 silent keepalive host at token expiry: closed 4408 (not 4401)', + closed && c.events.closes.includes(4408) && !c.events.closes.includes(4401) && after >= 59_000, + `closedAfter=${after}ms pings=${c.events.pings} closes=${c.events.closes}` + ) + } finally { + c.client.closeNow() + } +} + // F5: POST /__admin/drain sends the host's controls back to the director (drain frame, 4503). export async function drainCheck(key: KeyLike): Promise { const host = newHost() diff --git a/cloud/apps/relay-edge/test/mvp-object.ts b/cloud/apps/relay-edge/test/mvp-object.ts index 5558bb2d179..f9a436c1d37 100644 --- a/cloud/apps/relay-edge/test/mvp-object.ts +++ b/cloud/apps/relay-edge/test/mvp-object.ts @@ -41,7 +41,7 @@ import { waitFor, type Host } from './harness-mvp-object' -import { drainCheck, heartbeatCheck, keepaliveCheck, keepaliveProbeCheck, objectHealthCheck } from './mvp-object-hardening' +import { drainCheck, heartbeatCheck, keepaliveCheck, keepaliveExpiredSilentCheck, keepaliveProbeCheck, objectHealthCheck } from './mvp-object-hardening' import { replayCheck, rotationCheck } from './mvp-object-replay' async function mainRemote(): Promise { @@ -107,7 +107,7 @@ async function main(): Promise { await sleep(500) } await run(host, privateKey, () => jwksHits) - await Promise.all([heartbeatCheck(privateKey), keepaliveCheck(privateKey), keepaliveProbeCheck(privateKey), drainCheck(privateKey), replayCheck(), rotationCheck()]) + await Promise.all([heartbeatCheck(privateKey), keepaliveCheck(privateKey), keepaliveProbeCheck(privateKey), keepaliveExpiredSilentCheck(privateKey), drainCheck(privateKey), replayCheck(), rotationCheck()]) await sweepCheck() await preAuthCheck(stateDir) await objectHealthCheck(stateDir)