fix(mobile-relay): resolve on persistent 4404 and make deferral logs readable

This commit is contained in:
Neil
2026-11-13 03:30:47 -08:00
parent 4245b59765
commit a2e95cafe5
11 changed files with 427 additions and 14 deletions
@@ -0,0 +1,55 @@
import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'
import { createRelayDeferralLog } from './mobile-relay-deferral-log'
import { RelayReconnectController } from '../../transport/relay/mobile-relay-reconnect-controller'
import { RelayOuterError } from '../../transport/encryption/mobile-relay-e2ee-link'
describe('relay recovery deferral log', () => {
beforeEach(() => vi.useFakeTimers())
afterEach(() => vi.useRealTimers())
it('writes one line per reason per 30s and counts the rest', () => {
const log = vi.fn()
const logDeferral = createRelayDeferralLog(log, Date.now)
for (let i = 0; i < 20; i++) {
logDeferral({ reason: 'cooldown', remainingMs: 9_000 - i * 1_000 })
vi.advanceTimersByTime(1_000)
}
expect(log).toHaveBeenCalledTimes(1)
expect(log).toHaveBeenLastCalledWith('recovery deferred by cooldown', 'retryInMs=9000')
vi.advanceTimersByTime(10_000)
logDeferral({ reason: 'cooldown', remainingMs: 4_000 })
expect(log).toHaveBeenLastCalledWith(
'recovery deferred by cooldown',
'retryInMs=4000 suppressedSinceLastLine=19'
)
})
it('logs a change of gate at once', () => {
const log = vi.fn()
const logDeferral = createRelayDeferralLog(log, Date.now)
logDeferral({ reason: 'cooldown', remainingMs: 1_000 })
logDeferral({ reason: 'fresh-credential', remainingMs: 60_000 })
expect(log).toHaveBeenLastCalledWith(
'recovery deferred by gate=fresh-credential',
'retryInMs=60000'
)
})
it('reports the gate in force and the time left until its reprobe', () => {
const controller = new RelayReconnectController(
{
now: Date.now,
// Midpoint jitter: the first gate reprobe lands at 60s.
randomBytes: () => new Uint8Array([128, 0]),
setTimer: (callback, delay) => setTimeout(callback, delay),
clearTimer: clearTimeout
},
() => {}
)
expect(controller.deferral()).toBeNull()
controller.registerFailure(new RelayOuterError(4401))
vi.advanceTimersByTime(20_000)
expect(controller.deferral()).toEqual({ reason: 'fresh-credential', remainingMs: 40_000 })
})
})
@@ -0,0 +1,29 @@
import type { RelayRecoveryLog } from './mobile-relay-recovery-log'
import type { RelayReconnectController } from '../../transport/relay/mobile-relay-reconnect-controller'
type RelayRecoveryDeferral = NonNullable<ReturnType<RelayReconnectController['deferral']>>
// Every direct-dial state flap re-enters relay recovery and hits the same cooldown, so an
// unroutable LAN address once wrote this line every few seconds. Log a reason change at once and
// otherwise one line per window, counting what it stood for.
const DEFERRAL_LOG_INTERVAL_MS = 30_000
export function createRelayDeferralLog(
log: RelayRecoveryLog,
now: () => number = Date.now
): (deferral: RelayRecoveryDeferral) => void {
let last: { reason: RelayRecoveryDeferral['reason']; at: number } | null = null
let suppressed = 0
return ({ reason, remainingMs }) => {
const at = now()
if (last?.reason === reason && at - last.at < DEFERRAL_LOG_INTERVAL_MS) {
suppressed += 1
return
}
const kind = reason === 'cooldown' ? 'cooldown' : `gate=${reason}`
const repeats = suppressed > 0 ? ` suppressedSinceLastLine=${suppressed}` : ''
log(`recovery deferred by ${kind}`, `retryInMs=${remainingMs}${repeats}`)
last = { reason, at }
suppressed = 0
}
}
@@ -0,0 +1,103 @@
import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'
import {
dependencies,
FakeLogicalClient,
FakeRelaySession,
host,
relay
} from './mobile-endpoint-supervisor-test-fakes'
import { MobileEndpointSupervisor } from './mobile-endpoint-supervisor'
import { RelayOuterError } from '../encryption/mobile-relay-e2ee-link'
import { RelayDirectorResolveTimeoutError } from '../relay/mobile-relay-resume-director'
import type { MobileEndpointSupervisorDependencies } from './mobile-endpoint-supervisor-contract'
import type { ConnectionLogEntry } from '../../diagnostics/connection/connection-log-types'
vi.mock('react-native', () => ({ Platform: { OS: 'ios' } }))
vi.mock('expo-secure-store', () => ({ WHEN_UNLOCKED_THIS_DEVICE_ONLY: 'when-unlocked' }))
vi.mock('expo-crypto', () => ({ getRandomBytes: (length: number) => new Uint8Array(length) }))
const hostOfflineSession = () =>
new FakeRelaySession('disconnected', new RelayOuterError(4404, false, ''))
async function startOffLan(overrides: Partial<MobileEndpointSupervisorDependencies>) {
const logical = new FakeLogicalClient('disconnected', 'lan')
const logs: ConnectionLogEntry[] = []
const deps = dependencies({
openRelay: vi.fn(hostOfflineSession),
onLog: (entry) => logs.push(entry),
// Full-width jitter: 4404 retries wait the full 15s.
randomBytes: () => new Uint8Array([255, 255]),
...overrides
})
const supervisor = new MobileEndpointSupervisor(logical, host.id, relay, deps)
await supervisor.start()
await vi.advanceTimersByTimeAsync(0)
return { logical, deps, logs, supervisor }
}
describe('mobile endpoint supervisor on persistent host-offline', () => {
beforeEach(() => {
vi.useFakeTimers()
vi.setSystemTime(new Date('2026-11-13T12:00:00Z'))
vi.spyOn(console, 'log').mockImplementation(() => {})
})
afterEach(() => {
vi.useRealTimers()
vi.restoreAllMocks()
})
it('asks the director on the second 4404 and adopts the cell it names', async () => {
const moved = { ...relay, cellUrl: 'https://relay-hk.onorca.dev' }
const openRelay = vi
.fn()
.mockImplementationOnce(hostOfflineSession)
.mockImplementationOnce(hostOfflineSession)
.mockImplementation(() => new FakeRelaySession('connected'))
const resolveRelay = vi.fn(async () => moved)
const { logical, deps, supervisor } = await startOffLan({ openRelay, resolveRelay })
expect(openRelay).toHaveBeenCalledTimes(1)
expect(resolveRelay).not.toHaveBeenCalled()
await vi.advanceTimersByTimeAsync(15_000)
expect(resolveRelay).toHaveBeenCalledOnce()
expect(resolveRelay).toHaveBeenCalledWith(expect.objectContaining({ timeoutMs: 5_000 }))
expect(deps.setRelayRouting).toHaveBeenCalledWith(host.id, moved)
expect(openRelay).toHaveBeenLastCalledWith(
moved,
expect.anything(),
expect.any(String),
expect.any(Function)
)
expect(logical.getActivePath()).toBe('relay')
supervisor.stop()
})
it('gives the next resolve 10s after one times out', async () => {
const resolveRelay = vi.fn(async (_input: { timeoutMs?: number }) => {
throw new RelayDirectorResolveTimeoutError(5_000)
})
const { supervisor } = await startOffLan({ resolveRelay })
await vi.advanceTimersByTimeAsync(60_000)
const budgets = resolveRelay.mock.calls.map(([input]) => input.timeoutMs)
expect(budgets.length).toBeGreaterThanOrEqual(2)
expect(budgets[0]).toBe(5_000)
expect(budgets.slice(1).every((timeoutMs) => timeoutMs === 10_000)).toBe(true)
supervisor.stop()
})
it('logs cooldown deferrals with their remaining time, at most once per window', async () => {
const { logical, logs, supervisor } = await startOffLan({})
// An unroutable LAN address fails fast; each direct state flap re-enters relay recovery.
for (let i = 0; i < 10; i++) {
logical.publishState('reconnecting')
logical.publishState('disconnected')
await vi.advanceTimersByTimeAsync(1_000)
}
const deferrals = logs.filter((entry) => entry.message.startsWith('Relay: recovery deferred'))
expect(deferrals).toHaveLength(1)
expect(deferrals[0].message).toBe('Relay: recovery deferred by cooldown')
expect(deferrals[0].detail).toMatch(/^retryInMs=\d+$/)
supervisor.stop()
})
})
@@ -9,6 +9,7 @@ import {
createRelayRecoveryLog,
type RelayRecoveryLog
} from '../../diagnostics/connection/mobile-relay-recovery-log'
import { createRelayDeferralLog } from '../../diagnostics/connection/mobile-relay-deferral-log'
import {
mobileRelayCredentialNeedsRotation,
rotateMobileRelayCredential
@@ -41,6 +42,8 @@ export class MobileEndpointSupervisor {
private readonly relayReconnect: RelayReconnectController
private readonly leaseRotation: RelayLeaseRotationTimer
private readonly logRelay: RelayRecoveryLog
// Lazy: logRelay is assigned in the constructor.
private readonly logDeferral = createRelayDeferralLog((m, d) => this.logRelay(m, d))
private readonly directProbe: DirectReturnProbe
private readonly directGrace: MobileRelayDirectGraceTimer
private readonly backgroundGrace: MobileRelayBackgroundGrace
@@ -220,12 +223,13 @@ export class MobileEndpointSupervisor {
return
}
// Share cooldown across overlapping resume, revival and lease failures to prevent reconnect churn.
if (this.relayReconnect.shouldDefer()) {
const deferral = this.relayReconnect.deferral()
if (deferral) {
if (ownsRecovery) {
// Without a dial, no session was disproven; keep intent queued for forced recovery after cooldown.
this.pendingReplace = true
}
this.logRelay('recovery deferred by cooldown or gate')
this.logDeferral(deferral)
return
}
this.operationInFlight = true
@@ -0,0 +1,96 @@
import { describe, expect, it, vi } from 'vitest'
import {
dialRelayThroughDirectorFallback,
RelayDialAbortedError,
RelayHostOfflineStreak
} from './mobile-relay-director-fallback'
import { RelayOuterError } from '../encryption/mobile-relay-e2ee-link'
const relay = {
v: 1 as const,
directorUrl: 'https://relay.onorca.dev',
cellUrl: 'https://relay-edge.onorca.dev',
assignmentEpoch: 7,
relayHostId: 'AbCdEf0123_-xyZ9',
e2eeFraming: 2 as const
}
const hostOffline = { ok: false as const, error: new RelayOuterError(4404) }
const attachTimeout = {
ok: false as const,
error: new RelayOuterError(4404, false, 'attach-timeout')
}
function dialer(results: { ok: boolean; error?: Error }[]) {
const streak = new RelayHostOfflineStreak()
const resolveRelay = vi.fn(async () => ({ ...relay, cellUrl: 'https://relay-hk.onorca.dev' }))
const queue = [...results]
const dial = vi.fn(async () => {
const next = queue.shift() ?? { ok: true }
return next.ok ? { ok: true as const } : { ok: false as const, error: next.error! }
})
const attempt = () =>
dialRelayThroughDirectorFallback({
resumeToken: 'A'.repeat(43),
hostOfflineStreak: streak,
relay: () => relay,
dial,
resolveRelay,
persistResolvedRelay: async () => {}
})
return { attempt, dial, resolveRelay }
}
describe('dialRelayThroughDirectorFallback on host-offline', () => {
it('resolves on the second consecutive 4404 and redials the resolved cell once', async () => {
const { attempt, dial, resolveRelay } = dialer([hostOffline, hostOffline, { ok: true }])
await expect(attempt()).resolves.toEqual(hostOffline)
expect(resolveRelay).not.toHaveBeenCalled()
await expect(attempt()).resolves.toEqual({ ok: true })
expect(resolveRelay).toHaveBeenCalledOnce()
expect(dial).toHaveBeenCalledTimes(3)
})
it('paces resolves to every other 4404 while the edge keeps answering it', async () => {
const { attempt, resolveRelay } = dialer(Array.from({ length: 8 }, () => hostOffline))
// Each resolve redials once; 4 recovery cycles = 6 dials incl. the 2 post-resolve redials.
for (let i = 0; i < 4; i++) {
await attempt()
}
expect(resolveRelay).toHaveBeenCalledTimes(2)
})
it('never resolves on attach timeouts, which prove the desktop is seated on this cell', async () => {
const { attempt, resolveRelay } = dialer([
attachTimeout,
attachTimeout,
hostOffline,
attachTimeout,
hostOffline
])
for (let i = 0; i < 5; i++) {
await attempt()
}
expect(resolveRelay).not.toHaveBeenCalled()
})
it('restarts the streak after a success or another failure, but not after a local abort', async () => {
const aborted = { ok: false as const, error: new RelayDialAbortedError() }
const { attempt, resolveRelay } = dialer([
hostOffline,
{ ok: true },
hostOffline,
{ ok: false, error: new RelayOuterError(4408) },
hostOffline,
aborted,
hostOffline
])
for (let i = 0; i < 6; i++) {
await attempt()
}
expect(resolveRelay).not.toHaveBeenCalled()
await attempt()
expect(resolveRelay).toHaveBeenCalledOnce()
})
})
@@ -1,6 +1,8 @@
import { RelayOuterError } from '../encryption/mobile-relay-e2ee-link'
import { MobileE2EEAuthenticationError } from '../encryption/mobile-e2ee-v2-physical-channel'
import { ReplacementAuthenticationTimeoutError } from './replacement-session-authentication'
import { isHostAttachTimeout } from './relay-recovery-failure-count'
import { MOBILE_RELAY_CLOSE_CODE } from '../../../../src/shared/remote-runtime/relay/mobile-relay-close-codes'
import type { MobileRelayEndpoint } from '../../../../src/shared/remote-runtime/relay/mobile-relay-credential-contract'
type RelayDialResult = { ok: true } | { ok: false; error: Error }
@@ -12,9 +14,34 @@ export class RelayDialAbortedError extends Error {
}
}
// An edge that still claims a desktop which moved answers 4404 until its fence lands, so the cell
// alone never reveals the move. Resolve on the second consecutive 4404 (attach timeouts excluded:
// the desktop was seated there), then count afresh so resolves stay at most every other dial.
export class RelayHostOfflineStreak {
private streak = 0
shouldResolve(result: RelayDialResult): boolean {
if (!result.ok && result.error instanceof RelayDialAbortedError) {
return false
}
const hostOffline =
!result.ok &&
result.error instanceof RelayOuterError &&
result.error.code === MOBILE_RELAY_CLOSE_CODE.HOST_OFFLINE &&
!isHostAttachTimeout(result.error)
this.streak = hostOffline ? this.streak + 1 : 0
if (this.streak < 2) {
return false
}
this.streak = 0
return true
}
}
// After a director-class failure, resolve/persist the assignment and retry this credential once.
export async function dialRelayThroughDirectorFallback(args: {
resumeToken: string
hostOfflineStreak?: RelayHostOfflineStreak
relay: () => MobileRelayEndpoint
dial: () => Promise<RelayDialResult>
resolveRelay: (input: {
@@ -25,10 +52,11 @@ export async function dialRelayThroughDirectorFallback(args: {
}): Promise<RelayDialResult> {
const first = await args.dial()
const relay = args.relay()
const persistentHostOffline = args.hostOfflineStreak?.shouldResolve(first) ?? false
if (
first.ok ||
first.error instanceof RelayDialAbortedError ||
!isDirectorResolutionFailure(first.error)
!(persistentHostOffline || isDirectorResolutionFailure(first.error))
) {
return first
}
@@ -33,6 +33,7 @@ export class RelayReconnectController {
private activeRelayConnectedAt: number | null = null
private nextAttemptAt = 0
private timer: ReturnType<typeof setTimeout> | null = null
private timerDueAt = 0
private activeSession: RetainableRelaySession | null = null
private recoveryGate: RecoveryGate | null = null
private gateReprobePending = false
@@ -177,7 +178,7 @@ export class RelayReconnectController {
return
}
if (this.recoveryGate) {
// Mint a gated tick’s pass token or shouldDefer would double the intended cadence.
// Mint a gated tick’s pass token or deferral() would double the intended cadence.
this.holdGate(true)
return
}
@@ -212,21 +213,23 @@ export class RelayReconnectController {
return failure ?? null
}
shouldDefer(): boolean {
// Null lets recovery dial now; otherwise the pending timer retries at remainingMs (diagnostics).
deferral(): { reason: RecoveryGate | 'cooldown'; remainingMs: number } | null {
if (this.recoveryGate) {
if (this.gateReprobePending) {
// Why: the slow reprobe tick gets exactly one attempt through the gate.
this.gateReprobePending = false
return false
return null
}
this.scheduleGateReprobe()
return true
const remainingMs = Math.max(0, this.timerDueAt - this.dependencies.now())
return { reason: this.recoveryGate, remainingMs }
}
if (this.dependencies.now() < this.nextAttemptAt) {
this.scheduleRetry()
return true
return { reason: 'cooldown', remainingMs: this.nextAttemptAt - this.dependencies.now() }
}
return false
return null
}
registerFailure(error: Error | null, scheduleRetry = true): void {
@@ -311,6 +314,7 @@ export class RelayReconnectController {
return
}
const delay = delayMs ?? Math.max(0, this.nextAttemptAt - this.dependencies.now())
this.timerDueAt = this.dependencies.now() + delay
this.timer = this.dependencies.setTimer(() => {
this.timer = null
this.onRetry()
@@ -325,6 +329,7 @@ export class RelayReconnectController {
if (this.timer) {
return
}
this.timerDueAt = this.dependencies.now() + delay
this.timer = this.dependencies.setTimer(() => {
this.timer = null
// Advance cadence once per fired tick, not on repeated arm attempts.
@@ -1,5 +1,10 @@
import { describe, expect, it, vi } from 'vitest'
import { resolveMobileRelayEndpoint } from './mobile-relay-resume-director'
import { afterEach, describe, expect, it, vi } from 'vitest'
import {
RelayDirectorHttpError,
RelayDirectorResolveTimeoutError,
RelayResolveTimeoutBudget,
resolveMobileRelayEndpoint
} from './mobile-relay-resume-director'
const relay = {
v: 1 as const,
@@ -53,4 +58,40 @@ describe('mobile relay resume director', () => {
).rejects.toThrow(/too large/)
}
})
afterEach(() => vi.useRealTimers())
it('names a timed-out resolve so the next one can get a longer budget', async () => {
vi.useFakeTimers()
const hanging = vi.fn(
(_url: string, init: RequestInit) =>
new Promise<Response>((_resolve, reject) => {
init.signal?.addEventListener('abort', () => reject(new Error('aborted')))
})
)
const resolving = resolveMobileRelayEndpoint({
relay,
resumeToken: 'A'.repeat(43),
fetchImpl: hanging,
timeoutMs: 5_000
})
const settled = expect(resolving).rejects.toBeInstanceOf(RelayDirectorResolveTimeoutError)
await vi.advanceTimersByTimeAsync(5_000)
await settled
})
})
describe('RelayResolveTimeoutBudget', () => {
it('widens 5s to 10s after a timeout and narrows again after a success', () => {
const budget = new RelayResolveTimeoutBudget()
expect(budget.timeoutMs).toBe(5_000)
budget.failed(new RelayDirectorHttpError(503, null))
expect(budget.timeoutMs).toBe(5_000)
budget.failed(new RelayDirectorResolveTimeoutError(5_000))
expect(budget.timeoutMs).toBe(10_000)
budget.failed(new RelayDirectorHttpError(503, null))
expect(budget.timeoutMs).toBe(10_000)
budget.succeeded()
expect(budget.timeoutMs).toBe(5_000)
})
})
@@ -17,6 +17,33 @@ export class RelayDirectorHttpError extends Error {
}
}
export class RelayDirectorResolveTimeoutError extends Error {
readonly name = 'RelayDirectorResolveTimeoutError'
constructor(readonly timeoutMs: number) {
super(`relay director resolve timed out after ${timeoutMs}ms`)
}
}
// On lossy networks a TCP connect alone can take 4s+, so a 5s budget can expire before TLS.
// Healthy resolves keep the short budget; after one times out, the next gets 10s until one succeeds.
export class RelayResolveTimeoutBudget {
private widened = false
get timeoutMs(): number {
return this.widened ? 10_000 : 5_000
}
succeeded(): void {
this.widened = false
}
// Other failures (HTTP status, bad body) say nothing about the budget.
failed(error: unknown): void {
this.widened ||= error instanceof RelayDirectorResolveTimeoutError
}
}
// 0 when the director asked for nothing, so it only ever floors a local backoff.
export function relayDirectorRetryAfterMs(error: Error | null): number {
return error instanceof RelayDirectorHttpError ? (error.retryAfterMs ?? 0) : 0
@@ -38,7 +65,8 @@ export async function resolveMobileRelayEndpoint(args: {
timeoutMs?: number
}): Promise<MobileRelayEndpoint> {
const controller = new AbortController()
const timer = setTimeout(() => controller.abort(), args.timeoutMs ?? 5000)
const timeoutMs = args.timeoutMs ?? 5000
const timer = setTimeout(() => controller.abort(), timeoutMs)
try {
const url = new URL('/v1/resolve', args.relay.directorUrl)
const response = await (args.fetchImpl ?? fetch)(url.toString(), {
@@ -74,6 +102,8 @@ export async function resolveMobileRelayEndpoint(args: {
cellUrl: resolved.cellUrl,
assignmentEpoch: resolved.assignmentEpoch
}
} catch (error) {
throw controller.signal.aborted ? new RelayDirectorResolveTimeoutError(timeoutMs) : error
} finally {
clearTimeout(timer)
}
@@ -2,8 +2,10 @@ import type { MobileEndpointSupervisorDependencies } from '../connection/mobile-
import {
dialRelayThroughDirectorFallback,
RelayDialAbortedError,
RelayHostOfflineStreak,
toError
} from './mobile-relay-director-fallback'
import { RelayResolveTimeoutBudget } from './mobile-relay-resume-director'
import { encodeBase64Url } from '../encryption/mobile-session-id-encoding'
import { persistResumeConfirmation } from './mobile-relay-credential-rotation'
import { relayFailureAllowsGraceRetry } from './relay-credential-eligibility'
@@ -22,6 +24,8 @@ function directWon(logical: StableLogicalRpcClient): boolean {
// Own candidate relays through cell resolution, logical migration and best-effort resume bookkeeping.
export class MobileRelaySessionEstablisher {
private relay: MobileRelayEndpoint
private readonly hostOfflineStreak = new RelayHostOfflineStreak()
private readonly resolveTimeout = new RelayResolveTimeoutBudget()
constructor(
private readonly args: {
@@ -88,13 +92,31 @@ export class MobileRelaySessionEstablisher {
dial(credential: { token: string; version: number }): Promise<EstablishResult> {
return dialRelayThroughDirectorFallback({
resumeToken: credential.token,
hostOfflineStreak: this.hostOfflineStreak,
relay: () => this.relay,
dial: () => this.establish(credential),
resolveRelay: this.args.resolveRelay,
resolveRelay: (input) => this.resolveRelay(input),
persistResolvedRelay: (resolved) => this.adoptRelay(resolved)
})
}
private async resolveRelay(input: {
relay: MobileRelayEndpoint
resumeToken: string
}): Promise<MobileRelayEndpoint> {
try {
const resolved = await this.args.resolveRelay({
...input,
timeoutMs: this.resolveTimeout.timeoutMs
})
this.resolveTimeout.succeeded()
return resolved
} catch (error) {
this.resolveTimeout.failed(error)
throw error
}
}
private async establish(credential: {
token: string
version: number
@@ -57,7 +57,7 @@ export class RelayRecoveryFailureCount {
}
// Attach timeout means desktop control was seated; retry the same cell rather than re-resolving its assignment.
function isHostAttachTimeout(error: Error | null): boolean {
export function isHostAttachTimeout(error: Error | null): boolean {
return (
error instanceof RelayOuterError &&
error.code === MOBILE_RELAY_CLOSE_CODE.HOST_OFFLINE &&