feat(mobile): time relay dial stages so diagnostics say where a slow connect went (#19245)

* feat(mobile): time relay dial stages so diagnostics say where a slow connect went

A 10s connect was unattributable from a shared report. Relay dial stages carried
no timestamps, so nothing could tell "the cell never answered relay-hello" from
"the E2EE handshake was slow", and the per-state dweltMs the client already
computed went only to console.log — invisible without a debug build.

RelayDialStageTracker now stamps each stage entry from a monotonic clock
(performance.now where present, wall clock otherwise) and returns the duration of
the stage it just left. The session logs one entry per stage, and settles the
in-flight stage on connect, failure, or close, so a dial that dies mid-way still
names the stage it never finished. dweltMs joins the same buffer as a structured
field instead of console.

Durations ride the existing per-host log buffer and its cap, so memory is
unchanged and no new storage appears. The report derives two lines from them: the
latest dial's stage breakdown (a reconnect loop must not average away the attempt
being reported) and total dwell per connection state. Both are numbers and
closed-enum names, and the entries still pass through the existing redaction.

* fix(mobile): never let a diagnostics sink break a dial, and pin timing names to their enums

Review follow-ups on the dial-stage timing work.

The stage timing emitted on the confirm's success path ran inside the try that
calls fail(), so an onLog sink that threw would have turned a good connect into a
failed session. The same hazard existed on the direct path, where the dwell emit
sits in publish() ahead of the listener loop and the connect waiters. Both sink
calls are now isolated: a broken sink loses a log line and nothing else.

The persisted-log validator accepted any string as a timing name, and the report
echoes that name unredacted. Names are now checked against the closed enum for
their kind, backed by Record<Union, true> tables so adding a stage or a state
breaks the build rather than silently widening what a corrupted store can inject.

Entry volume: every reconnect cycle walks four connection states, so logging each
one would roughly double what a slow-connect report holds against the unchanged
200-entry per-host cap. Transitions under 100ms are therefore not buffered. They
cannot be where a slow connect spent its time, and console still shows all of
them. States that flap slowly, which is the case support cares about, still land
in the log.

RpcClientConnectionState takes an optional clock so dwell thresholds are testable
without sleeping.

* fix(mobile): reject a negative stored stage duration when hydrating the log

A persisted timing only had to be finite to survive hydration, so a corrupted
`ms: -1` reached the diagnostics report, where the dial summary sums the stage
durations and a negative would subtract from the total. Producers clamp at 0
(`elapsedMs`), so anything below it is corruption. 0 itself still hydrates: a
stage the dial passes through instantly is real.

* refactor(mobile): move the relay liveness profile out of the session so the dial log fits

* fix(mobile): never let the liveness-timeout log line keep a dead relay connected

* test(mobile): prove the throwing timeout sink was actually reached
This commit is contained in:
Jinwoo Hong
2026-09-07 13:52:15 -04:00
committed by GitHub
parent ceafdcad2f
commit 83b1558ecc
19 changed files with 865 additions and 49 deletions
@@ -1,8 +1,36 @@
import { describe, expect, it } from 'vitest'
import { buildConnectionDiagnosticsReport } from './connection-diagnostics-report'
import type { ConnectionLogEntry } from '../transport/types'
const NOW = Date.UTC(2026, 6, 9, 22, 0, 0)
function stageEntry(
id: string,
ts: number,
name: string,
ms: number,
complete: boolean
): ConnectionLogEntry {
return {
id,
ts,
level: complete ? 'info' : 'warn',
path: 'relay',
message: `Relay dial stage ${name} ${complete ? 'finished' : 'did not finish'}`,
timing: { kind: 'relay-dial-stage', name, ms, complete }
}
}
function stateEntry(id: string, ts: number, name: string, ms: number): ConnectionLogEntry {
return {
id,
ts,
level: 'info',
message: `Connection state ${name} → connected`,
timing: { kind: 'connection-state', name, ms, complete: true }
}
}
describe('buildConnectionDiagnosticsReport', () => {
it('summarizes a failing Tailscale host with its log', () => {
const report = buildConnectionDiagnosticsReport({
@@ -68,13 +96,28 @@ describe('buildConnectionDiagnosticsReport', () => {
activePath: 'tailscale',
pendingPath: 'relay',
entries: [
{
id: 'relay-stage-opening',
ts: NOW - 6_000,
level: 'info',
path: 'relay',
message: 'Relay dial stage opening finished',
detail: '118ms — resumeToken=secret-resume-token',
timing: { kind: 'relay-dial-stage', name: 'opening', ms: 118, complete: true }
},
{
id: 'relay-failure',
ts: NOW - 5_000,
level: 'error',
message: 'Relay: relay dial failed',
detail:
'RelayDirectorHttpError: relay director resolve failed (503); retry after 30000ms; resumeToken=secret-resume-token'
'RelayDirectorHttpError: relay director resolve failed (503); retry after 30000ms; resumeToken=secret-resume-token',
timing: {
kind: 'relay-dial-stage',
name: 'awaiting-hello',
ms: 9_100,
complete: false
}
}
],
nowMs: NOW
@@ -87,6 +130,9 @@ describe('buildConnectionDiagnosticsReport', () => {
expect(report).toContain('Next step: Keep Orca open; recovery should retry automatically.')
expect(report).toContain('resumeToken=[redacted]')
expect(report).not.toContain('secret-resume-token')
expect(report).toContain(
'Relay dial stages: opening 118ms · awaiting-hello 9.1s (did not finish) — total 9.2s'
)
})
it('redacts quoted JSON credentials and never echoes an invalid endpoint', () => {
@@ -116,6 +162,52 @@ describe('buildConnectionDiagnosticsReport', () => {
expect(report).not.toContain('bearer-secret')
})
it('breaks a slow connect down by dial stage and connection state', () => {
const report = buildConnectionDiagnosticsReport({
hostName: 'Host 6',
endpoint: 'ws://192.168.1.50:6768',
state: 'connected',
reconnectAttempts: 2,
lastConnectedAt: NOW,
platform: 'ios 26.5.1',
appVersion: '0.0.47',
entries: [
stageEntry('a1', NOW - 30_000, 'opening', 90, false),
stateEntry('s1', NOW - 29_000, 'connecting', 12_000),
stageEntry('b1', NOW - 20_000, 'opening', 120, true),
stageEntry('b2', NOW - 19_000, 'awaiting-hello', 6_400, true),
stageEntry('b3', NOW - 13_000, 'handshaking', 240, true),
stageEntry('b4', NOW - 12_000, 'confirming', 1_180, true),
stateEntry('s2', NOW - 11_000, 'connecting', 8_000)
],
nowMs: NOW
})
// Only the latest dial is broken out, so a reconnect loop cannot average away
// the attempt the reporter is complaining about.
expect(report).toContain(
'Relay dial stages (latest of 2): opening 120ms · awaiting-hello 6.4s · handshaking 240ms · confirming 1.2s — total 7.9s'
)
expect(report).toContain('Connection state dwell: connecting 20.0s ×2')
})
it('omits the timing lines when nothing recorded a phase duration', () => {
const report = buildConnectionDiagnosticsReport({
hostName: 'Host 7',
endpoint: 'ws://192.168.1.50:6768',
state: 'connected',
reconnectAttempts: 0,
lastConnectedAt: NOW,
platform: 'ios 26.5.1',
appVersion: '0.0.47',
entries: [{ id: 'plain', ts: NOW, level: 'info', message: 'Authenticated' }],
nowMs: NOW
})
expect(report).not.toContain('Relay dial stages')
expect(report).not.toContain('Connection state dwell')
})
it('bounds a single event line before submission while preserving its identity', () => {
const report = buildConnectionDiagnosticsReport({
hostName: 'Host 5',
@@ -8,6 +8,7 @@ import { normalizeHostAppVersion } from '../transport/host-app-version-store'
import { formatEndpoint } from './host-reachability'
import { diagnoseConnection } from './connection-diagnostics-analysis'
import { redactConnectionLogEntry, redactConnectionLogText } from './connection-log-redaction'
import { summarizeConnectionLogTimings } from './connection-log-timing-summary'
const MAX_EVENT_LINE_BYTES = 2 * 1024
const EVENT_TRUNCATION_MARKER = ' … [truncated]'
@@ -59,6 +60,7 @@ export function buildConnectionDiagnosticsReport(args: {
? 'Last connected: never this session'
: `Last connected: ${new Date(args.lastConnectedAt).toISOString()} (${formatAgo(now - args.lastConnectedAt)} ago)`
)
lines.push(...summarizeConnectionLogTimings(entries))
lines.push('')
lines.push(`Likely cause: ${diagnosis.likelyCause}`)
lines.push(`Next step: ${diagnosis.nextStep}`)
@@ -0,0 +1,66 @@
import type { ConnectionLogEntry, ConnectionLogTiming } from '../transport/types'
// Why: a report that only says "connecting for 10s" cannot be triaged. These lines
// turn the per-phase timings the transport now records into the two questions
// support actually asks: which relay dial stage ate the time, and how long the
// client sat in each connection state.
export function summarizeConnectionLogTimings(entries: readonly ConnectionLogEntry[]): string[] {
const timings = entries.flatMap((entry) => (entry.timing ? [entry.timing] : []))
const lines: string[] = []
const dials = groupRelayDials(timings.filter((timing) => timing.kind === 'relay-dial-stage'))
const latestDial = dials.at(-1)
if (latestDial) {
const label =
dials.length > 1 ? `Relay dial stages (latest of ${dials.length})` : 'Relay dial stages'
const total = latestDial.reduce((sum, timing) => sum + timing.ms, 0)
lines.push(
`${label}: ${latestDial.map(formatStageTiming).join(' · ')} — total ${formatDurationMs(total)}`
)
}
const states = totalPerName(timings.filter((timing) => timing.kind === 'connection-state'))
if (states.length > 0) {
lines.push(
`Connection state dwell: ${states
.map(
({ name, ms, count }) => `${name} ${formatDurationMs(ms)}${count > 1 ? ` ×${count}` : ''}`
)
.join(' · ')}`
)
}
return lines
}
// Relay dial stages are strictly ordered and every dial starts in 'opening', so an
// 'opening' timing opens a new group. Reporting only the latest keeps a reconnect
// loop from averaging away the attempt the reporter is complaining about.
function groupRelayDials(timings: readonly ConnectionLogTiming[]): ConnectionLogTiming[][] {
const dials: ConnectionLogTiming[][] = []
for (const timing of timings) {
if (timing.name === 'opening' || dials.length === 0) {
dials.push([])
}
dials.at(-1)!.push(timing)
}
return dials
}
function totalPerName(
timings: readonly ConnectionLogTiming[]
): { name: string; ms: number; count: number }[] {
const totals = new Map<string, { name: string; ms: number; count: number }>()
for (const timing of timings) {
const total = totals.get(timing.name) ?? { name: timing.name, ms: 0, count: 0 }
total.ms += timing.ms
total.count += 1
totals.set(timing.name, total)
}
return [...totals.values()]
}
function formatStageTiming(timing: ConnectionLogTiming): string {
return `${timing.name} ${formatDurationMs(timing.ms)}${timing.complete ? '' : ' (did not finish)'}`
}
function formatDurationMs(ms: number): string {
return ms < 1000 ? `${Math.round(ms)}ms` : `${(ms / 1000).toFixed(1)}s`
}
@@ -16,6 +16,29 @@ describe('connection log buffer', () => {
expect(store.get('host-b').map((e) => e.id)).toEqual(['log-2'])
})
it('retains phase timings through redaction and evicts them with the cap', () => {
const store = createConnectionLogStore(2)
store.append('host-a', {
...entry(1),
timing: { kind: 'connection-state', name: 'reconnecting', ms: 800, complete: true }
})
store.append('host-a', {
...entry(2),
detail: '4280ms in connecting; resumeToken=secret-resume-token',
timing: { kind: 'connection-state', name: 'connecting', ms: 4_280, complete: true }
})
store.append('host-a', {
...entry(3),
timing: { kind: 'relay-dial-stage', name: 'awaiting-hello', ms: 9_100, complete: false }
})
expect(store.get('host-a').map((e) => e.timing)).toEqual([
{ kind: 'connection-state', name: 'connecting', ms: 4_280, complete: true },
{ kind: 'relay-dial-stage', name: 'awaiting-hello', ms: 9_100, complete: false }
])
expect(store.get('host-a')[0]!.detail).toBe('4280ms in connecting; resumeToken=[redacted]')
})
it('drops the oldest entries past the cap', () => {
const store = createConnectionLogStore(3)
for (let i = 1; i <= 5; i++) {
@@ -0,0 +1,77 @@
import { describe, expect, it } from 'vitest'
import { DirectConnectionLog } from './direct-connection-log'
import { RpcClientConnectionState } from './rpc-client-connection-state'
import type { ConnectionLogEntry, ConnectionState } from './types'
function openStateWithLog(sink?: (entry: ConnectionLogEntry) => void) {
const entries: ConnectionLogEntry[] = []
const log = new DirectConnectionLog(
'ws://192.168.1.50:6768',
sink ?? ((entry) => entries.push(entry))
)
let now = 0
const state = new RpcClientConnectionState({
endpoint: 'ws://192.168.1.50:6768',
getReconnectAttempt: () => 0,
isClosed: () => false,
onStateDwell: log.stateDwell,
now: () => now
})
const publishAfter = (elapsedMs: number, next: ConnectionState): void => {
now += elapsedMs
state.publish(next)
}
return { entries, state, publishAfter }
}
describe('connection state dwell logging', () => {
it('records the time spent in each state as a structured log entry', () => {
const { entries, publishAfter } = openStateWithLog()
publishAfter(300, 'connecting')
publishAfter(4_200, 'handshaking')
publishAfter(250, 'connected')
expect(entries.map((entry) => entry.timing)).toEqual([
{ kind: 'connection-state', name: 'disconnected', ms: 300, complete: true },
{ kind: 'connection-state', name: 'connecting', ms: 4_200, complete: true },
{ kind: 'connection-state', name: 'handshaking', ms: 250, complete: true }
])
expect(entries[1]!.message).toBe('Connection state connecting → handshaking')
expect(entries[1]!.detail).toBe('4200ms in connecting')
})
it('skips transitions too short to explain a slow connect', () => {
const { entries, publishAfter } = openStateWithLog()
publishAfter(99, 'connecting')
publishAfter(100, 'handshaking')
expect(entries.map((entry) => entry.timing?.name)).toEqual(['connecting'])
})
it('does not log a dwell when the state does not change', () => {
const { entries, publishAfter } = openStateWithLog()
publishAfter(500, 'connecting')
publishAfter(500, 'connecting')
expect(entries).toHaveLength(1)
})
it('still publishes the state when the log sink throws', () => {
const seen: ConnectionState[] = []
const { state, publishAfter } = openStateWithLog(() => {
throw new Error('sink exploded')
})
state.addListener((next) => seen.push(next))
const connected = state.waitForConnected()
publishAfter(500, 'connecting')
publishAfter(500, 'connected')
expect(seen).toEqual(['connecting', 'connected'])
expect(state.get()).toBe('connected')
return expect(connected).resolves.toBeUndefined()
})
})
+27 -1
View File
@@ -4,9 +4,15 @@ import type {
ConnectionLogEntry,
ConnectionLogLevel,
ConnectionLogSink,
ConnectionState,
MobileConnectionDiagnosticPath
} from './types'
// Why: every reconnect cycle walks four states, and the per-host buffer is capped.
// Logging sub-100ms transitions would halve the history a report can show while
// telling support nothing — those states are never where a slow connect spent time.
const MIN_LOGGED_DWELL_MS = 100
export class DirectConnectionLog {
private sequence = 0
private readonly path: MobileConnectionDiagnosticPath
@@ -22,7 +28,7 @@ export class DirectConnectionLog {
level: ConnectionLogLevel,
message: string,
detail?: string,
evidence?: Pick<ConnectionLogEntry, 'code' | 'path'>
evidence?: Pick<ConnectionLogEntry, 'code' | 'path' | 'timing'>
): void => {
this.sink?.({
id: `log-${++this.sequence}-${Date.now()}`,
@@ -44,6 +50,26 @@ export class DirectConnectionLog {
)
}
// Why: how long the client sat in each ConnectionState used to go only to
// console, so a shared diagnostics report could not show where a slow connect
// spent its seconds.
stateDwell = (previous: ConnectionState, next: ConnectionState, dweltMs: number): void => {
if (dweltMs < MIN_LOGGED_DWELL_MS) {
return
}
this.emit('info', `Connection state ${previous}${next}`, `${dweltMs}ms in ${previous}`, {
timing: { kind: 'connection-state', name: previous, ms: dweltMs, complete: true }
})
}
retryScheduled = (message: string, detail?: string): void => {
this.emit('info', message, detail, { code: 'retry-scheduled' })
}
authenticationRejected = (message: string, detail?: string): void => {
this.emit('warn', message, detail, { code: 'authentication-rejected' })
}
connected = (): void => {
this.emit('success', 'Authenticated', 'Channel ready for RPC', { code: 'direct-connected' })
}
+4 -5
View File
@@ -48,14 +48,14 @@ export class DirectRpcClient implements RpcClient {
this.reconnect = new RpcClientReconnectSchedule({
openConnection: () => this.openConnection(),
rejectConnectWaiters: (reason) => this.connectionState.rejectWaiters(reason),
emitLog: (message, detail) =>
this.connectionLog.emit('info', message, detail, { code: 'retry-scheduled' })
emitLog: this.connectionLog.retryScheduled
})
this.connectionState = new RpcClientConnectionState({
endpoint,
initialListener: options.onStateChange,
getReconnectAttempt: () => this.reconnect.getAttempt(),
isClosed: () => this.intentionallyClosed
isClosed: () => this.intentionallyClosed,
onStateDwell: this.connectionLog.stateDwell
})
this.streams = new RpcClientStreamRegistry({
nextId: () => this.nextId(),
@@ -102,8 +102,7 @@ export class DirectRpcClient implements RpcClient {
this.authenticationRetry = new RpcClientAuthenticationRetry({
endpoint,
stopLiveness: () => this.stopLiveness(),
emitWarning: (message, detail) =>
this.connectionLog.emit('warn', message, detail, { code: 'authentication-rejected' }),
emitWarning: this.connectionLog.authenticationRejected,
retry: (reason) => this.retryAuthentication(reason),
latchFailure: (reason) => this.latchAuthenticationFailure(reason)
})
@@ -174,6 +174,22 @@ describe('mobile relay RPC session liveness', () => {
)
})
it('still terminates a dead relay when the log sink throws on the timeout line', async () => {
const onLog = vi.fn<ConnectionLogSink>(() => {
throw new Error('sink exploded')
})
const session = await authenticateSession(onLog)
session.notifyForeground('focus')
await vi.advanceTimersByTimeAsync(4_000)
await vi.advanceTimersByTimeAsync(4_000)
// The line was attempted and threw; the session still came down.
expect(onLog).toHaveBeenCalledWith(expect.objectContaining({ code: 'liveness-timeout' }))
expect(session.getState()).toBe('disconnected')
expect(fakes.close).toHaveBeenCalledOnce()
})
it('disconnects after two fair foreground misses', async () => {
const onLog = vi.fn<ConnectionLogSink>()
const session = await authenticateSession(onLog)
@@ -9,25 +9,18 @@ import { MobileE2EEAuthenticationError } from './mobile-e2ee-v2-physical-channel
import { markRpcDeliveryUnknown } from './rpc-delivery-ambiguity'
import { openRpcRequestBudget, resolvePostConnectRequestTimeout } from './rpc-request-budget'
import { isRpcResponse } from './rpc-response-shape'
import { RelayDialStageLog } from './relay-dial-stage-log'
import { RelayDialStageTracker, type RelayDialStageSource } from './relay-dial-stage'
import { RelayPendingRequests } from './relay-pending-requests'
import { RpcSessionLivenessWatchdog } from './rpc-session-liveness-watchdog'
import { createRelaySessionLivenessWatchdog } from './relay-session-liveness-profile'
import { settleMobileRuntimeCapabilities } from './mobile-runtime-capability-negotiation'
import type { RelayHostCloseReason } from '../../../src/shared/relay-host-close-reason'
import type { RpcClient } from './rpc-client'
import type { ConnectionLogSink, ConnectionState, RpcResponse } from './types'
// Ordinary foreground checks: two 4s misses, at most one voluntary probe per 10s.
const RELAY_PROBE = { timeoutMs: 4_000, missedProbeLimit: 2, minIntervalMs: 10_000 }
// A socket that died while the process was suspended must be admitted before the
// user reads the screen as broken. Two 2s misses, not one: the first frame after a
// resume rides a cold radio, and a single slow answer is not proof of a dead link.
const RELAY_RESUME_PROBE = { timeoutMs: 2_000, missedProbeLimit: 2 }
// Bounds the confirm exactly as migrateTo's own wait used to, so the supervisor's
// mutex is never held for the full request timeout waiting on a silent cell.
const RELAY_CONFIRM_TIMEOUT_MS = 12_000
// Foreground-only sweep so a silently-dead relay surfaces without a user action.
const RELAY_IDLE_PROBE_MS = 25_000
let relayRpcSessionSequence = 0
export type MobileRelayRpcSession = RpcClient &
@@ -80,6 +73,7 @@ export function connectMobileRelayRpcSession(args: {
settleResumeConfirmed = resolve
})
const dialStage = new RelayDialStageTracker()
const dialStageLog = new RelayDialStageLog(dialStage, logSessionId, args.onLog)
const streams = new MobileRelayRpcStreams({
nextId: () => pending.nextId(),
sendFrame,
@@ -94,7 +88,7 @@ export function connectMobileRelayRpcSession(args: {
desktopPublicKeyB64: args.desktopPublicKeyB64,
createSocket: args.createSocket,
onHostCloseReason: args.onHostCloseReason,
onOpen: () => dialStage.advance('awaiting-hello'),
onOpen: () => dialStageLog.enter('awaiting-hello'),
onHello: (hello) => {
if (
hello.credentialKind !== 'resume' ||
@@ -105,7 +99,7 @@ export function connectMobileRelayRpcSession(args: {
}
attachDeadlineAt = hello.leaseExpiresAt
resumeExpiresAt = hello.resumeExpiresAt
dialStage.advance('handshaking')
dialStageLog.enter('handshaking')
publishState('handshaking')
},
onAuthenticated: () => publishAuthenticated(),
@@ -159,30 +153,14 @@ export function connectMobileRelayRpcSession(args: {
whenResumeConfirmed: () => resumeConfirmed,
getFailure: () => failure
}
const livenessWatchdog = new RpcSessionLivenessWatchdog({
transport: 'relay',
idleProbeMs: RELAY_IDLE_PROBE_MS,
probeTimeoutMs: RELAY_PROBE.timeoutMs,
missedProbeLimit: RELAY_PROBE.missedProbeLimit,
voluntaryProbeMinIntervalMs: RELAY_PROBE.minIntervalMs,
urgentProbeTimeoutMs: RELAY_RESUME_PROBE.timeoutMs,
urgentMissedProbeLimit: RELAY_RESUME_PROBE.missedProbeLimit,
shouldIdleProbe: () => args.isForeground?.() ?? true,
const livenessWatchdog = createRelaySessionLivenessWatchdog({
isForeground: args.isForeground,
sendProbe: () =>
state === 'connected' &&
sendFrame({ id: pending.nextId(), method: 'status.get', params: undefined }),
onTimeout: (evidence) => {
args.onLog?.({
id: `relay-liveness-${logSessionId}-${++logSequence}`,
ts: Date.now(),
level: 'error',
code: 'liveness-timeout',
path: 'relay',
message: 'Relay health check failed',
detail: `${evidence.reason}; ${evidence.missedProbes}/${evidence.missedProbeLimit} probes missed; last authenticated activity ${evidence.lastInboundAgeMs}ms ago`
})
},
terminate: () => fail(new Error('relay session liveness timeout'))
terminate: () => fail(new Error('relay session liveness timeout')),
onLog: args.onLog,
nextLogId: () => `relay-liveness-${logSessionId}-${++logSequence}`
})
return client
@@ -193,7 +171,7 @@ export function connectMobileRelayRpcSession(args: {
if (closed) {
return
}
dialStage.advance('confirming')
dialStageLog.enter('confirming')
void confirmResume().then(settleResumeConfirmed, settleResumeConfirmed)
// Why: an unanswered advisory says nothing, but a frame that never reached the
// wire proves the socket cannot carry traffic — that alone still fails.
@@ -224,6 +202,9 @@ export function connectMobileRelayRpcSession(args: {
}
resumeConfirmation = result.resumeConfirmation
resumeExpiresAt = result.resumeConfirmation.resumeExpiresAt
// The dial's last stage ends when the desktop has confirmed the resume, not when
// 'connected' was published at authentication ahead of it.
dialStageLog.settle(true)
} catch (error) {
fail(asError(error))
}
@@ -325,6 +306,7 @@ export function connectMobileRelayRpcSession(args: {
}
closed = true
settleResumeConfirmed()
dialStageLog.settle(false, error.message)
livenessWatchdog.stop(livenessIdentity)
streams.clear()
link.close()
+15
View File
@@ -0,0 +1,15 @@
// Why: connection phase durations must never go negative. Date.now() can jump
// backwards (NTP or a user clock change) mid-dial, which would turn a slow stage
// into a negative one in the diagnostics report. performance.now() is monotonic
// and Hermes exposes it; hosts without it fall back to wall clock.
const hasPerformanceNow =
typeof performance === 'object' && performance !== null && typeof performance.now === 'function'
export const monotonicNowMs: () => number = hasPerformanceNow
? () => performance.now()
: () => Date.now()
/** Whole milliseconds between two monotonic reads, clamped so a fallback wall-clock jump can't go negative. */
export function elapsedMs(startedAt: number, endedAt: number = monotonicNowMs()): number {
return Math.max(0, Math.round(endedAt - startedAt))
}
@@ -23,6 +23,89 @@ describe('persisted connection log store', () => {
vi.resetModules()
})
// 'negotiating' is not a dial stage and 'confirming' is a dial stage rather than a
// connection state; the report echoes the name, so neither may survive. A negative
// duration is corruption too: producers clamp at 0, and the report sums these, so a
// negative would subtract from a dial total.
it('rehydrates well-formed phase timings and drops corrupt names and durations', async () => {
vi.mocked(AsyncStorage.getItem).mockResolvedValue(
JSON.stringify([
{
id: 'stage-ok',
ts: 900,
level: 'info',
message: 'Relay dial stage awaiting-hello finished',
timing: { kind: 'relay-dial-stage', name: 'awaiting-hello', ms: 6_400, complete: true }
},
{
id: 'stage-corrupt',
ts: 950,
level: 'info',
message: 'Relay dial stage handshaking finished',
timing: { kind: 'relay-dial-stage', name: 'handshaking', ms: 'soon' }
},
{
id: 'stage-unknown-name',
ts: 960,
level: 'info',
message: 'Relay dial stage negotiating finished',
timing: { kind: 'relay-dial-stage', name: 'negotiating', ms: 12, complete: true }
},
{
id: 'state-borrowed-stage-name',
ts: 970,
level: 'info',
message: 'Connection state confirming → connected',
timing: { kind: 'connection-state', name: 'confirming', ms: 12, complete: true }
},
{
id: 'state-unknown-kind',
ts: 980,
level: 'info',
message: 'Something else',
timing: { kind: 'wall-clock', name: 'connecting', ms: 12, complete: true }
},
{
id: 'stage-negative-ms',
ts: 985,
level: 'info',
message: 'Relay dial stage opening finished',
timing: { kind: 'relay-dial-stage', name: 'opening', ms: -1, complete: true }
},
{
id: 'state-negative-ms',
ts: 990,
level: 'info',
message: 'Connection state connecting → connected',
timing: { kind: 'connection-state', name: 'connecting', ms: -0.5, complete: true }
},
{
id: 'stage-zero-ms',
ts: 995,
level: 'info',
message: 'Relay dial stage confirming finished',
timing: { kind: 'relay-dial-stage', name: 'confirming', ms: 0, complete: true }
}
])
)
vi.resetModules()
const { connectionLogStore } = await import('./persisted-connection-log-store')
await connectionLogStore.hydrate('host-timings')
// 0 survives: a stage the dial passed through instantly is real, not corruption.
expect(connectionLogStore.get('host-timings').map((entry) => entry.id)).toEqual([
'stage-ok',
'stage-zero-ms'
])
expect(connectionLogStore.get('host-timings')[0]!.timing).toEqual({
kind: 'relay-dial-stage',
name: 'awaiting-hello',
ms: 6_400,
complete: true
})
})
it('keeps a new client-session boundary when a restart shares the prior timestamp', async () => {
const stored: ConnectionLogEntry[] = [
{
@@ -1,6 +1,7 @@
import AsyncStorage from '@react-native-async-storage/async-storage'
import { createConnectionLogStore } from './connection-log-buffer'
import type { ConnectionLogEntry } from './types'
import { RELAY_DIAL_STAGE_NAMES } from './relay-dial-stage'
import { CONNECTION_STATE_NAMES, type ConnectionLogEntry, type ConnectionLogTiming } from './types'
const STORAGE_PREFIX = 'orca.mobile.connection-log.v1.'
const clientSessionId = `${Date.now().toString(36)}-${Math.random().toString(36).slice(2)}`
@@ -72,6 +73,30 @@ function isConnectionLogEntry(value: unknown): value is ConnectionLogEntry {
entry.level === 'warn' ||
entry.level === 'error') &&
typeof entry.message === 'string' &&
(entry.detail === undefined || typeof entry.detail === 'string')
(entry.detail === undefined || typeof entry.detail === 'string') &&
(entry.timing === undefined || isConnectionLogTiming(entry.timing))
)
}
// Why: the report echoes the phase name and formats the duration directly, so a
// corrupted stored timing must not reach it. The name is checked against the closed
// enum for its kind, not just "is a string", and the duration must be one a producer
// could have written — `elapsedMs` clamps at 0, so a negative is corruption.
function isConnectionLogTiming(value: unknown): value is ConnectionLogTiming {
if (!value || typeof value !== 'object') {
return false
}
const timing = value as Partial<ConnectionLogTiming>
if (timing.kind !== 'relay-dial-stage' && timing.kind !== 'connection-state') {
return false
}
const names = timing.kind === 'relay-dial-stage' ? RELAY_DIAL_STAGE_NAMES : CONNECTION_STATE_NAMES
return (
typeof timing.name === 'string' &&
Object.hasOwn(names, timing.name) &&
typeof timing.ms === 'number' &&
Number.isFinite(timing.ms) &&
timing.ms >= 0 &&
typeof timing.complete === 'boolean'
)
}
@@ -0,0 +1,55 @@
import type {
RelayDialStage,
RelayDialStageTracker,
RelayDialStageTiming
} from './relay-dial-stage'
import type { ConnectionLogSink } from './types'
// Why: support needs per-stage durations for a slow dial, and the name of the stage
// a failed dial died in, without a debug build. Timing only — advancing the tracker
// stays the session's call.
export class RelayDialStageLog {
private sequence = 0
constructor(
private readonly tracker: RelayDialStageTracker,
private readonly sessionId: string,
private readonly sink?: ConnectionLogSink
) {}
enter(stage: RelayDialStage): void {
this.record(this.tracker.advance(stage))
}
settle(complete: boolean, failureDetail?: string): void {
this.record(this.tracker.settle(complete), failureDetail)
}
private record(timing: RelayDialStageTiming | null, failureDetail?: string): void {
if (!timing) {
return
}
// Why: this runs inside the dial's success and failure paths. A sink that
// throws must not turn a good connect into a failed one.
try {
this.sink?.({
id: `relay-dial-stage-${this.sessionId}-${++this.sequence}`,
ts: Date.now(),
level: timing.complete ? 'info' : 'warn',
path: 'relay',
message: `Relay dial stage ${timing.stage} ${
timing.complete ? 'finished' : 'did not finish'
}`,
detail: `${timing.ms}ms${failureDetail ? `${failureDetail}` : ''}`,
timing: {
kind: 'relay-dial-stage',
name: timing.stage,
ms: timing.ms,
complete: timing.complete
}
})
} catch {
// Diagnostics only; a broken sink is not worth failing a dial over.
}
}
}
@@ -0,0 +1,219 @@
import { beforeEach, describe, expect, it, vi } from 'vitest'
import { RelayDialStageTracker } from './relay-dial-stage'
import type { ConnectionLogEntry } from './types'
const fakes = vi.hoisted(() => ({
linkOptions: null as null | {
onOpen(): void
onHello(value: unknown): void
onAuthenticated(): void
onText(value: string): void
onBinary(value: Uint8Array): void
onError(error: Error): void
},
sendText: vi.fn(() => true),
close: vi.fn()
}))
vi.mock('./mobile-relay-e2ee-link', () => ({
MobileRelayE2eeLink: class {
constructor(options: NonNullable<typeof fakes.linkOptions>) {
fakes.linkOptions = options
}
sendText = fakes.sendText
close = fakes.close
}
}))
import { connectMobileRelayRpcSession } from './mobile-relay-rpc-session'
const relay = {
v: 1 as const,
directorUrl: 'https://relay.onorca.dev',
cellUrl: 'https://relay-c1.onorca.dev',
assignmentEpoch: 7,
relayHostId: 'AbCdEf0123_-xyZ9',
e2eeFraming: 2 as const
}
function openSession(entries: ConnectionLogEntry[]) {
return connectMobileRelayRpcSession({
relay,
resumeToken: 'resume-secret',
resumeCredentialVersion: 3,
resumeConfirmReqId: 'confirm-1',
deviceToken: 'device-token',
desktopPublicKeyB64: 'AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=',
requestTimeoutMs: 1000,
onLog: (entry) => entries.push(entry)
})
}
function stageTimings(entries: readonly ConnectionLogEntry[]) {
return entries.flatMap((entry) =>
entry.timing?.kind === 'relay-dial-stage' ? [entry.timing] : []
)
}
describe('RelayDialStageTracker timings', () => {
it('times every stage it passes through without going negative', () => {
// A clock that steps backwards proves the report can never show a negative stage.
const reads = [0, 120, 4_400, 4_300, 5_500]
let index = 0
const tracker = new RelayDialStageTracker(() => reads[index++]!)
expect(tracker.advance('awaiting-hello')).toEqual({
stage: 'opening',
ms: 120,
complete: true
})
expect(tracker.advance('handshaking')).toEqual({
stage: 'awaiting-hello',
ms: 4_280,
complete: true
})
expect(tracker.advance('confirming')).toEqual({
stage: 'handshaking',
ms: 0,
complete: true
})
expect(tracker.settle(true)).toEqual({ stage: 'confirming', ms: 1_200, complete: true })
expect(tracker.getDialStage()).toBe('confirming')
})
it('re-advancing to the current stage is not a transition', () => {
const tracker = new RelayDialStageTracker(() => 0)
expect(tracker.advance('opening')).toBeNull()
})
it('settles once, so a failure after connecting cannot re-time the last stage', () => {
let now = 0
const tracker = new RelayDialStageTracker(() => now)
tracker.advance('awaiting-hello')
now = 900
expect(tracker.settle(true)).toEqual({ stage: 'awaiting-hello', ms: 900, complete: true })
now = 90_000
expect(tracker.settle(false)).toBeNull()
})
})
function requestIdAt(call: number): string {
return (JSON.parse(fakes.sendText.mock.calls[call]![0] as string) as { id: string }).id
}
async function driveToConnected(session: {
getState(): string
whenResumeConfirmed(): Promise<void>
}): Promise<void> {
fakes.linkOptions!.onOpen()
fakes.linkOptions!.onHello({
type: 'relay-hello',
ok: true,
credentialKind: 'resume',
leaseExpiresAt: Date.now() + 60_000,
acceptedCredentialVersion: 3,
acceptedAs: 'current',
resumeExpiresAt: Date.now() + 300_000
})
fakes.linkOptions!.onAuthenticated()
// 'connected' is published at authentication; the resume confirm and the capability
// advisory are both already on the wire, so answer them in the order they were sent.
await vi.waitFor(() => expect(session.getState()).toBe('connected'))
expect(fakes.sendText).toHaveBeenCalledTimes(2)
fakes.linkOptions!.onText(
JSON.stringify({
id: requestIdAt(0),
ok: true,
result: {
v: 1,
relay,
resumeConfirmation: {
v: 1,
reqId: 'confirm-1',
currentVersion: 3,
acceptedAs: 'current',
renewed: true,
resumeExpiresAt: Date.now() + 300_000
}
},
_meta: { runtimeId: 'runtime-1' }
})
)
fakes.linkOptions!.onText(
JSON.stringify({ id: requestIdAt(1), ok: true, result: {}, _meta: { runtimeId: 'runtime-1' } })
)
await session.whenResumeConfirmed()
}
describe('relay dial stage timings in the connection log', () => {
beforeEach(() => {
fakes.sendText.mockClear()
fakes.close.mockClear()
})
it('records the stages a failed dial reached plus the stage it died in', () => {
const entries: ConnectionLogEntry[] = []
openSession(entries)
fakes.linkOptions!.onOpen()
fakes.linkOptions!.onError(new Error('relay dial failed'))
const timings = stageTimings(entries)
expect(timings.map((timing) => timing.name)).toEqual(['opening', 'awaiting-hello'])
expect(timings.map((timing) => timing.complete)).toEqual([true, false])
for (const timing of timings) {
expect(timing.ms).toBeGreaterThanOrEqual(0)
}
expect(entries.at(-1)!.message).toContain('awaiting-hello did not finish')
expect(entries.at(-1)!.detail).toContain('relay dial failed')
expect(entries.at(-1)!.path).toBe('relay')
})
it('records every stage of a dial that reaches connected, all complete', async () => {
const entries: ConnectionLogEntry[] = []
const session = openSession(entries)
await driveToConnected(session)
const timings = stageTimings(entries)
expect(timings.map((timing) => timing.name)).toEqual([
'opening',
'awaiting-hello',
'handshaking',
'confirming'
])
expect(timings.every((timing) => timing.complete)).toBe(true)
expect(timings.every((timing) => timing.ms >= 0)).toBe(true)
// A later teardown must not append a second timing for 'confirming'.
session.close()
expect(stageTimings(entries)).toHaveLength(4)
})
it('reaches connected even when the log sink throws on every stage', async () => {
const session = connectMobileRelayRpcSession({
relay,
resumeToken: 'resume-secret',
resumeCredentialVersion: 3,
resumeConfirmReqId: 'confirm-1',
deviceToken: 'device-token',
desktopPublicKeyB64: 'AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=',
requestTimeoutMs: 1000,
onLog: () => {
throw new Error('sink exploded')
}
})
await driveToConnected(session)
expect(session.getState()).toBe('connected')
expect(session.getFailure()).toBeNull()
})
it('marks a dial that never opened its socket as stuck in opening', () => {
const entries: ConnectionLogEntry[] = []
openSession(entries)
fakes.linkOptions!.onError(new Error('websocket refused'))
expect(stageTimings(entries)).toEqual([
{ kind: 'relay-dial-stage', name: 'opening', ms: expect.any(Number), complete: false }
])
})
})
+47 -2
View File
@@ -1,3 +1,5 @@
import { elapsedMs, monotonicNowMs } from './monotonic-clock'
// Where a relay dial is waiting, so a bound can tell "the cell never answered the
// upgrade" from "the cell took the dial and is slow" — the two look identical from
// ConnectionState, which stays 'connecting' until relay-hello arrives.
@@ -12,6 +14,23 @@ export type RelayDialStage =
// E2EE authenticated; waiting on the desktop's resume confirmation.
| 'confirming'
// Exhaustive by construction: adding a stage to the union breaks this table, so a
// persisted-log validator can never silently start accepting an unknown stage.
export const RELAY_DIAL_STAGE_NAMES: Record<RelayDialStage, true> = {
opening: true,
'awaiting-hello': true,
handshaking: true,
confirming: true
}
// How long a dial spent in one stage. `complete` is false when the dial left the
// stage by dying in it, so a report can name the stage that never finished.
export type RelayDialStageTiming = {
stage: RelayDialStage
ms: number
complete: boolean
}
export type RelayDialStageSource = {
getDialStage(): RelayDialStage
onDialStageChange(listener: (stage: RelayDialStage) => void): () => void
@@ -27,8 +46,14 @@ export function relayDialStageSource(session: object): RelayDialStageSource | nu
export class RelayDialStageTracker implements RelayDialStageSource {
private stage: RelayDialStage = 'opening'
private stageEnteredAt: number
private settled = false
private readonly listeners = new Set<(stage: RelayDialStage) => void>()
constructor(private readonly now: () => number = monotonicNowMs) {
this.stageEnteredAt = now()
}
getDialStage(): RelayDialStage {
return this.stage
}
@@ -38,14 +63,34 @@ export class RelayDialStageTracker implements RelayDialStageSource {
return () => this.listeners.delete(listener)
}
advance(stage: RelayDialStage): void {
/** Returns the timing of the stage just left, or null when nothing was timed. */
advance(stage: RelayDialStage): RelayDialStageTiming | null {
if (this.stage === stage) {
return
return null
}
const now = this.now()
const timing = this.settled ? null : this.closeStage(true, now)
this.stage = stage
this.stageEnteredAt = now
for (const listener of this.listeners) {
listener(stage)
}
return timing
}
// Close the stage the dial is sitting in: `true` once it reached the runtime,
// `false` when it died there. Idempotent, so a failure on an already-connected
// session cannot re-time the last dial stage.
settle(complete: boolean): RelayDialStageTiming | null {
if (this.settled) {
return null
}
this.settled = true
return this.closeStage(complete, this.now())
}
private closeStage(complete: boolean, now: number): RelayDialStageTiming {
return { stage: this.stage, ms: elapsedMs(this.stageEnteredAt, now), complete }
}
}
@@ -0,0 +1,54 @@
import {
RpcSessionLivenessWatchdog,
type LivenessTimeoutEvidence
} from './rpc-session-liveness-watchdog'
import type { ConnectionLogSink } from './types'
// Ordinary foreground checks: two 4s misses, at most one voluntary probe per 10s.
const RELAY_PROBE = { timeoutMs: 4_000, missedProbeLimit: 2, minIntervalMs: 10_000 }
// A socket that died while the process was suspended must be admitted before the
// user reads the screen as broken. Two 2s misses, not one: the first frame after a
// resume rides a cold radio, and a single slow answer is not proof of a dead link.
const RELAY_RESUME_PROBE = { timeoutMs: 2_000, missedProbeLimit: 2 }
// Foreground-only sweep so a silently-dead relay surfaces without a user action.
const RELAY_IDLE_PROBE_MS = 25_000
// The relay session's probe budget and its timeout log line, kept apart from the
// session so the dial/RPC code and the liveness policy can each be read on its own.
export function createRelaySessionLivenessWatchdog(args: {
isForeground?: () => boolean
sendProbe: () => boolean
terminate: () => void
onLog?: ConnectionLogSink
nextLogId: () => string
}): RpcSessionLivenessWatchdog {
return new RpcSessionLivenessWatchdog({
transport: 'relay',
idleProbeMs: RELAY_IDLE_PROBE_MS,
probeTimeoutMs: RELAY_PROBE.timeoutMs,
missedProbeLimit: RELAY_PROBE.missedProbeLimit,
voluntaryProbeMinIntervalMs: RELAY_PROBE.minIntervalMs,
urgentProbeTimeoutMs: RELAY_RESUME_PROBE.timeoutMs,
urgentMissedProbeLimit: RELAY_RESUME_PROBE.missedProbeLimit,
shouldIdleProbe: () => args.isForeground?.() ?? true,
sendProbe: args.sendProbe,
onTimeout: (evidence: LivenessTimeoutEvidence) => {
// Why: the watchdog terminates the session right after this returns. A sink
// that throws must not keep a dead relay 'connected'.
try {
args.onLog?.({
id: args.nextLogId(),
ts: Date.now(),
level: 'error',
code: 'liveness-timeout',
path: 'relay',
message: 'Relay health check failed',
detail: `${evidence.reason}; ${evidence.missedProbes}/${evidence.missedProbeLimit} probes missed; last authenticated activity ${evidence.lastInboundAgeMs}ms ago`
})
} catch {
// Diagnostics only.
}
},
terminate: args.terminate
})
}
@@ -1,3 +1,4 @@
import { elapsedMs, monotonicNowMs } from './monotonic-clock'
import { redactSocketEndpoint } from './socket-event-debug'
import type { ConnectionState } from './types'
@@ -12,16 +13,19 @@ type ConnectionStateOptions = {
initialListener?: (state: ConnectionState) => void
getReconnectAttempt: () => number
isClosed: () => boolean
onStateDwell?: (previous: ConnectionState, next: ConnectionState, dweltMs: number) => void
now?: () => number
}
export class RpcClientConnectionState {
private state: ConnectionState = 'disconnected'
private lastConnectedAt: number | null = null
private stateEnteredAt = Date.now()
private stateEnteredAt: number
private readonly listeners = new Set<(state: ConnectionState) => void>()
private readonly waiters: ConnectWaiter[] = []
constructor(private readonly options: ConnectionStateOptions) {
this.stateEnteredAt = this.now()
if (options.initialListener) {
this.listeners.add(options.initialListener)
}
@@ -40,9 +44,14 @@ export class RpcClientConnectionState {
return
}
const previous = this.state
const dweltMs = Date.now() - this.stateEnteredAt
const dweltMs = elapsedMs(this.stateEnteredAt, this.now())
this.state = next
this.stateEnteredAt = Date.now()
this.stateEnteredAt = this.now()
try {
this.options.onStateDwell?.(previous, next, dweltMs)
} catch {
// Diagnostics only; a broken log sink must not abort the state publish.
}
console.log('[net] state', {
from: previous,
to: next,
@@ -103,6 +112,10 @@ export class RpcClientConnectionState {
return () => this.listeners.delete(listener)
}
private now(): number {
return (this.options.now ?? monotonicNowMs)()
}
private resolveWaiters(): void {
for (const waiter of this.waiters.splice(0)) {
if (waiter.timeout) {
@@ -67,7 +67,9 @@ describe('mobile rpc-client connection logs', () => {
onLog: (entry) => logs.push(entry)
})
expect(logs[0]?.detail).toBe('desktop.example:7443')
expect(logs).toContainEqual(
expect.objectContaining({ message: 'Opening WebSocket', detail: 'desktop.example:7443' })
)
expect(JSON.stringify(logs)).not.toContain('password')
client.close()
})
+23 -1
View File
@@ -58,6 +58,17 @@ export type ConnectionDiagnosticCode =
| 'relay-credential-unavailable'
| 'host-open-failed'
// Why: a 10s connect used to read as one opaque "connecting" span. Attaching the
// duration of the phase an entry closes out lets the report say where the time
// went. Diagnostics only — nothing schedules from these.
export type ConnectionLogTiming = {
kind: 'relay-dial-stage' | 'connection-state'
name: string
ms: number
// False when the phase never finished (the dial died inside it).
complete: boolean
}
export type ConnectionLogEntry = {
id: string
ts: number
@@ -68,6 +79,7 @@ export type ConnectionLogEntry = {
detail?: string
code?: ConnectionDiagnosticCode
path?: MobileConnectionDiagnosticPath
timing?: ConnectionLogTiming
}
export type ConnectionLogSink = (entry: ConnectionLogEntry) => void
@@ -76,7 +88,7 @@ export type ConnectionLogEmitter = (
level: ConnectionLogLevel,
message: string,
detail?: string,
evidence?: Pick<ConnectionLogEntry, 'code' | 'path'>
evidence?: Pick<ConnectionLogEntry, 'code' | 'path' | 'timing'>
) => void
export type ConnectionState =
@@ -87,6 +99,16 @@ export type ConnectionState =
| 'reconnecting'
| 'auth-failed'
// Exhaustive by construction; see RELAY_DIAL_STAGE_NAMES for why.
export const CONNECTION_STATE_NAMES: Record<ConnectionState, true> = {
connecting: true,
handshaking: true,
connected: true,
disconnected: true,
reconnecting: true,
'auth-failed': true
}
// Why: a user-attention nudge must not tear down a healthy relay (probe it); only a
// network-change nudge marks the socket suspect enough to replace it.
export type ForegroundNudgeReason = 'focus' | 'app-resume' | 'network-change'