diff --git a/mobile/src/diagnostics/connection-diagnostics-analysis.test.ts b/mobile/src/diagnostics/connection-diagnostics-analysis.test.ts index ab40b3511b27..a1599d2af511 100644 --- a/mobile/src/diagnostics/connection-diagnostics-analysis.test.ts +++ b/mobile/src/diagnostics/connection-diagnostics-analysis.test.ts @@ -195,6 +195,26 @@ describe('diagnoseConnection', () => { }) }) + it('does not blame the host when a dial timer fires after suspension', () => { + expect( + diagnoseConnection({ + endpoint: 'ws://100.88.90.25:6768', + state: 'connecting', + activePath: 'tailscale', + entries: [ + { + ...event( + 'WebSocket connect interrupted', + 'App suspended for 2h44m; connection state unknown, re-dialing' + ), + level: 'warn', + code: 'suspended-dial' + } + ] + }).likelyCause + ).toBe('No single failure cause can be determined from the recorded events.') + }) + it('keys reportability to the current structured incident', () => { const args = { endpoint: 'ws://192.168.1.2:6768', diff --git a/mobile/src/transport/rpc-client-socket-session.ts b/mobile/src/transport/rpc-client-socket-session.ts index bc8f9d13e2cd..4ebbf4899713 100644 --- a/mobile/src/transport/rpc-client-socket-session.ts +++ b/mobile/src/transport/rpc-client-socket-session.ts @@ -9,6 +9,13 @@ import { import { isRpcResponse } from './rpc-response-shape' import { isStaleRpcSocketEvent, logRpcSocketClose } from './rpc-socket-close-evidence' import { describeSocketEvent, redactSocketEndpoint } from './socket-event-debug' +import { + releaseSocketTimer, + rememberSocketDeadlineClock, + startSocketDeadlineClock, + takeSocketDeadline +} from './socket-deadline-clock' +import { reportSocketDeadline, type SocketDeadlineKind } from './socket-deadline-suspension' import type { ConnectionLogEmitter, ConnectionState, RpcResponse } from './types' import { websocketPayloadToUint8 } from './websocket-payload-bytes' @@ -87,14 +94,8 @@ export class RpcClientSocketSession { } clearTimers(): void { - if (this.connectTimer) { - clearTimeout(this.connectTimer) - this.connectTimer = null - } - if (this.handshakeTimer) { - clearTimeout(this.handshakeTimer) - this.handshakeTimer = null - } + this.connectTimer = releaseSocketTimer(this.connectTimer) + this.handshakeTimer = releaseSocketTimer(this.handshakeTimer) } clearKey(): void { @@ -248,58 +249,54 @@ export class RpcClientSocketSession { } private armConnectTimeout(): void { - this.connectTimer = setTimeout(() => { - this.connectTimer = null - if ( - this.options.getCurrentSocket() === this.socket && - this.socket.readyState === WEBSOCKET_CONNECTING_STATE - ) { - console.log('[net] connect-timeout fired (onopen never arrived)', { - attempt: this.options.getReconnectAttempt(), - timeoutMs: CONNECT_TIMEOUT_MS - }) - this.options.emitLog( - 'error', - 'WebSocket connect timeout', - `No TCP/WS handshake within ${CONNECT_TIMEOUT_MS / 1000}s — endpoint unreachable?`, - { code: 'connect-timeout' } - ) - this.options.onForcedClose(this) - } - }, CONNECT_TIMEOUT_MS) + this.armSocketDeadline('connect', CONNECT_TIMEOUT_MS) } private armHandshakeTimeout(): void { - this.handshakeTimer = setTimeout(() => { - this.handshakeTimer = null - if (this.options.getCurrentSocket() !== this.socket || this.authenticated) { + this.armSocketDeadline('handshake', HANDSHAKE_TIMEOUT_MS) + } + + private armSocketDeadline(kind: SocketDeadlineKind, timeoutMs: number): void { + const timer = setTimeout(() => { + const sample = takeSocketDeadline(timer) + if (kind === 'connect') { + this.connectTimer = null + } else { + this.handshakeTimer = null + } + const current = this.options.getCurrentSocket() === this.socket + const pending = + kind === 'connect' + ? current && this.socket.readyState === WEBSOCKET_CONNECTING_STATE + : current && !this.authenticated + if (!pending) { return } - console.log('[net] handshake-timeout fired (e2ee_authenticated never arrived)', { - timeoutMs: HANDSHAKE_TIMEOUT_MS - }) - this.options.emitLog( - 'error', - 'Handshake timeout', - `No e2ee_ready/e2ee_authenticated within ${HANDSHAKE_TIMEOUT_MS / 1000}s`, - { code: 'handshake-timeout' } + reportSocketDeadline( + { + kind, + ...sample, + timeoutMs, + ...(kind === 'connect' ? { attempt: this.options.getReconnectAttempt() } : {}) + }, + this.options.emitLog, + () => this.options.onForcedClose(this) ) - this.options.onForcedClose(this) - }, HANDSHAKE_TIMEOUT_MS) + }, timeoutMs) + rememberSocketDeadlineClock(timer, startSocketDeadlineClock()) + if (kind === 'connect') { + this.connectTimer = timer + } else { + this.handshakeTimer = timer + } } private clearConnectTimer(): void { - if (this.connectTimer) { - clearTimeout(this.connectTimer) - this.connectTimer = null - } + this.connectTimer = releaseSocketTimer(this.connectTimer) } private clearHandshakeTimer(): void { - if (this.handshakeTimer) { - clearTimeout(this.handshakeTimer) - this.handshakeTimer = null - } + this.handshakeTimer = releaseSocketTimer(this.handshakeTimer) } private isStale(eventName: string): boolean { diff --git a/mobile/src/transport/socket-deadline-clock.test.ts b/mobile/src/transport/socket-deadline-clock.test.ts new file mode 100644 index 000000000000..e62ab4691006 --- /dev/null +++ b/mobile/src/transport/socket-deadline-clock.test.ts @@ -0,0 +1,135 @@ +import { describe, expect, it, vi } from 'vitest' +import { + releaseSocketTimer, + rememberSocketDeadlineClock, + startSocketDeadlineClock, + takeSocketDeadline +} from './socket-deadline-clock' +import { describeSocketDeadline } from './socket-deadline-suspension' + +const appState = vi.hoisted(() => ({ + currentState: 'active', + listeners: new Set<(state: string) => void>() +})) + +vi.mock('react-native', () => ({ + AppState: { + get currentState() { + return appState.currentState + }, + addEventListener: (_event: string, listener: (state: string) => void) => { + appState.listeners.add(listener) + return { + remove: () => { + appState.listeners.delete(listener) + } + } + } + } +})) + +describe('startSocketDeadlineClock', () => { + it('reports a wall-clock jump while the app stays active as a host timeout', () => { + appState.currentState = 'active' + appState.listeners.clear() + let wallMs = 1_000 + let monotonicMs = 50 + const clock = startSocketDeadlineClock( + () => wallMs, + () => monotonicMs + ) + wallMs += 3 * 60 * 60 * 1000 + monotonicMs += 12_000 + const report = describeSocketDeadline({ + kind: 'connect', + timeoutMs: 12_000, + ...clock.finish() + }) + + expect(report.code).toBe('connect-timeout') + expect(appState.listeners.size).toBe(0) + }) + + it('keeps a host timeout when a short foreground loss does not delay the clocks', () => { + appState.currentState = 'active' + appState.listeners.clear() + let wallMs = 50_000 + let monotonicMs = 10 + const clock = startSocketDeadlineClock( + () => wallMs, + () => monotonicMs + ) + for (const listener of appState.listeners) { + listener('background') + } + wallMs -= 5_000 + monotonicMs += 12_000 + const report = describeSocketDeadline({ + kind: 'connect', + timeoutMs: 12_000, + ...clock.finish() + }) + + expect(report.code).toBe('connect-timeout') + expect(report.detail).toContain('endpoint unreachable') + }) + + it('keeps an on-budget timeout when a transient inactive state has ended', () => { + appState.currentState = 'active' + appState.listeners.clear() + let wallMs = 1_000 + let monotonicMs = 50 + const clock = startSocketDeadlineClock( + () => wallMs, + () => monotonicMs + ) + for (const listener of appState.listeners) { + listener('inactive') + listener('active') + } + wallMs += 12_000 + monotonicMs += 12_000 + + const report = describeSocketDeadline({ + kind: 'connect', + timeoutMs: 12_000, + ...clock.finish() + }) + + expect(report.code).toBe('connect-timeout') + }) + + it('detects suspension when the watcher starts after the app is already backgrounded', () => { + appState.currentState = 'background' + appState.listeners.clear() + let wallMs = 1_000 + let monotonicMs = 50 + const clock = startSocketDeadlineClock( + () => wallMs, + () => monotonicMs + ) + wallMs += 3 * 60 * 60 * 1000 + monotonicMs += 12_000 + + const report = describeSocketDeadline({ + kind: 'handshake', + timeoutMs: 5_000, + ...clock.finish() + }) + + expect(report.code).toBe('suspended-dial') + expect(appState.listeners.size).toBe(0) + }) + + it('drops the foreground watch when the timer is cleared', () => { + appState.currentState = 'active' + appState.listeners.clear() + const timer = setTimeout(() => undefined, 60_000) + rememberSocketDeadlineClock(timer, startSocketDeadlineClock()) + expect(appState.listeners.size).toBe(1) + + expect(releaseSocketTimer(timer)).toBeNull() + expect(appState.listeners.size).toBe(0) + expect(takeSocketDeadline(timer).leftForeground).toBe(false) + }) +}) diff --git a/mobile/src/transport/socket-deadline-clock.ts b/mobile/src/transport/socket-deadline-clock.ts new file mode 100644 index 000000000000..d7f28469ce06 --- /dev/null +++ b/mobile/src/transport/socket-deadline-clock.ts @@ -0,0 +1,95 @@ +import { AppState } from 'react-native' + +export type SocketDeadlineSample = { + armedAtMs: number + firedAtMs: number + monotonicElapsedMs: number + leftForeground: boolean +} + +type DeadlineTimer = ReturnType + +type SocketDeadlineClock = { + finish: () => SocketDeadlineSample +} + +const boundClocks = new Map() + +function defaultMonotonicNow(): number { + if (typeof performance !== 'undefined' && typeof performance.now === 'function') { + return performance.now() + } + return Date.now() +} + +function watchForegroundLoss(onLeave: () => void): () => void { + const subscription = AppState.addEventListener('change', (state) => { + if (state === 'background' || state === 'inactive') { + onLeave() + } + }) + if (AppState.currentState === 'background' || AppState.currentState === 'inactive') { + onLeave() + } + return () => { + subscription.remove() + } +} + +export function startSocketDeadlineClock( + now: () => number = Date.now, + monotonicNow: () => number = defaultMonotonicNow, + watchLeave: (onLeave: () => void) => () => void = watchForegroundLoss +): SocketDeadlineClock { + const armedAtMs = now() + const armedMonotonicMs = monotonicNow() + let leftForeground = false + let stopped = false + const stopWatch = watchLeave(() => { + leftForeground = true + }) + return { + finish() { + if (!stopped) { + stopped = true + stopWatch() + } + return { + armedAtMs, + firedAtMs: now(), + monotonicElapsedMs: monotonicNow() - armedMonotonicMs, + leftForeground + } + } + } +} + +export function rememberSocketDeadlineClock( + timer: DeadlineTimer, + clock: SocketDeadlineClock +): void { + boundClocks.set(timer, clock) +} + +export function takeSocketDeadline(timer: DeadlineTimer): SocketDeadlineSample { + const clock = boundClocks.get(timer) + boundClocks.delete(timer) + if (!clock) { + const firedAtMs = Date.now() + return { + armedAtMs: firedAtMs, + firedAtMs, + monotonicElapsedMs: 0, + leftForeground: false + } + } + return clock.finish() +} + +export function releaseSocketTimer(timer: DeadlineTimer | null): null { + if (timer) { + clearTimeout(timer) + takeSocketDeadline(timer) + } + return null +} diff --git a/mobile/src/transport/socket-deadline-suspension.test.ts b/mobile/src/transport/socket-deadline-suspension.test.ts new file mode 100644 index 000000000000..0226e7bb7e1f --- /dev/null +++ b/mobile/src/transport/socket-deadline-suspension.test.ts @@ -0,0 +1,164 @@ +import { describe, expect, it, vi } from 'vitest' +import { describeSocketDeadline, reportSocketDeadline } from './socket-deadline-suspension' + +const CONNECT_TIMEOUT_MS = 12_000 +const HANDSHAKE_TIMEOUT_MS = 5_000 +const SUSPENSION_SLACK_MS = 60_000 + +describe('describeSocketDeadline', () => { + it('keeps a deadline that fires on its budget as a host timeout', () => { + const armedAtMs = 1_000 + const report = describeSocketDeadline({ + kind: 'connect', + armedAtMs, + firedAtMs: armedAtMs + CONNECT_TIMEOUT_MS, + timeoutMs: CONNECT_TIMEOUT_MS, + attempt: 2 + }) + + expect(report).toMatchObject({ + suspended: false, + level: 'error', + code: 'connect-timeout', + title: 'WebSocket connect timeout', + detail: 'No TCP/WS handshake within 12s — endpoint unreachable?', + consoleMessage: '[net] connect-timeout fired (onopen never arrived)' + }) + }) + + it('does not classify an on-budget deadline as suspension after foreground loss', () => { + const report = describeSocketDeadline({ + kind: 'connect', + armedAtMs: 1_000, + firedAtMs: 1_000 + CONNECT_TIMEOUT_MS, + timeoutMs: CONNECT_TIMEOUT_MS, + monotonicElapsedMs: CONNECT_TIMEOUT_MS, + leftForeground: true + }) + + expect(report.suspended).toBe(false) + expect(report.code).toBe('connect-timeout') + }) + + it('keeps a handshake that fires just past its budget as a handshake timeout', () => { + const armedAtMs = 5_000 + const report = describeSocketDeadline({ + kind: 'handshake', + armedAtMs, + firedAtMs: armedAtMs + HANDSHAKE_TIMEOUT_MS + SUSPENSION_SLACK_MS, + timeoutMs: HANDSHAKE_TIMEOUT_MS + }) + + expect(report.suspended).toBe(false) + expect(report.code).toBe('handshake-timeout') + expect(report.detail).toBe('No e2ee_ready/e2ee_authenticated within 5s') + }) + + it('treats a timer that fires hours late as suspension, not an unreachable host', () => { + const armedAtMs = Date.parse('2026-09-04T12:56:55.512Z') + const firedAtMs = Date.parse('2026-09-04T15:40:52.242Z') + const report = describeSocketDeadline({ + kind: 'connect', + armedAtMs, + firedAtMs, + timeoutMs: CONNECT_TIMEOUT_MS, + attempt: 2 + }) + + expect(report).toMatchObject({ + suspended: true, + level: 'warn', + code: 'suspended-dial', + title: 'WebSocket connect interrupted', + detail: 'App suspended for 2h44m; connection state unknown, re-dialing' + }) + expect(report.detail).not.toContain('endpoint unreachable') + expect(report.consoleMessage).not.toContain('connect-timeout') + }) + + it('keeps a wall-clock jump as a host timeout when the monotonic clock stays on budget', () => { + const armedAtMs = 1_000 + const report = describeSocketDeadline({ + kind: 'connect', + armedAtMs, + firedAtMs: armedAtMs + 3 * 60 * 60 * 1000, + timeoutMs: CONNECT_TIMEOUT_MS, + monotonicElapsedMs: CONNECT_TIMEOUT_MS, + leftForeground: false + }) + + expect(report.suspended).toBe(false) + expect(report.code).toBe('connect-timeout') + }) + + it('does not treat foreground loss and a backward wall-clock step as suspension alone', () => { + const armedAtMs = 50_000 + const report = describeSocketDeadline({ + kind: 'connect', + armedAtMs, + firedAtMs: armedAtMs - 5_000, + timeoutMs: CONNECT_TIMEOUT_MS, + monotonicElapsedMs: CONNECT_TIMEOUT_MS, + leftForeground: true + }) + + expect(report.suspended).toBe(false) + expect(report.code).toBe('connect-timeout') + expect(report.detail).toContain('endpoint unreachable') + }) + + it('reads suspension when the wall clock and the monotonic clock both run long', () => { + const armedAtMs = 0 + const report = describeSocketDeadline({ + kind: 'connect', + armedAtMs, + firedAtMs: CONNECT_TIMEOUT_MS + SUSPENSION_SLACK_MS + 1, + timeoutMs: CONNECT_TIMEOUT_MS, + monotonicElapsedMs: CONNECT_TIMEOUT_MS + SUSPENSION_SLACK_MS + 1, + leftForeground: false + }) + + expect(report.code).toBe('suspended-dial') + expect(report.detail).toContain('App suspended for') + }) + + it('uses the same suspension reading for a frozen handshake timer', () => { + const armedAtMs = 0 + const report = describeSocketDeadline({ + kind: 'handshake', + armedAtMs, + firedAtMs: HANDSHAKE_TIMEOUT_MS + SUSPENSION_SLACK_MS + 1, + timeoutMs: HANDSHAKE_TIMEOUT_MS + }) + + expect(report.code).toBe('suspended-dial') + expect(report.title).toBe('Handshake interrupted') + expect(report.detail).not.toContain('handshake timeout') + }) +}) + +describe('reportSocketDeadline', () => { + it('still closes the socket after logging a suspended dial', () => { + const emitLog = vi.fn() + const close = vi.fn() + + reportSocketDeadline( + { + kind: 'connect', + armedAtMs: 0, + firedAtMs: CONNECT_TIMEOUT_MS + SUSPENSION_SLACK_MS + 1, + timeoutMs: CONNECT_TIMEOUT_MS + }, + emitLog, + close + ) + + expect(emitLog).toHaveBeenCalledWith( + 'warn', + 'WebSocket connect interrupted', + expect.stringContaining('connection state unknown, re-dialing'), + { code: 'suspended-dial' } + ) + expect(close).toHaveBeenCalledOnce() + }) +}) diff --git a/mobile/src/transport/socket-deadline-suspension.ts b/mobile/src/transport/socket-deadline-suspension.ts new file mode 100644 index 000000000000..e5f920283797 --- /dev/null +++ b/mobile/src/transport/socket-deadline-suspension.ts @@ -0,0 +1,109 @@ +import type { ConnectionDiagnosticCode, ConnectionLogEmitter, ConnectionLogLevel } from './types' + +/** + * A timer that fires this far past its budget was frozen with the process. + * A live 12s connect timeout still lands near its budget, so it stays a host miss. + */ +const SUSPENSION_SLACK_MS = 60_000 + +export type SocketDeadlineKind = 'connect' | 'handshake' + +export type SocketDeadlineInput = { + kind: SocketDeadlineKind + armedAtMs: number + firedAtMs: number + timeoutMs: number + attempt?: number + /** Elapsed on a clock that ignores wall-clock steps. Omitted keeps the wall-clock reading. */ + monotonicElapsedMs?: number + /** The app left the foreground while this deadline was armed. */ + leftForeground?: boolean +} + +export type SocketDeadlineReport = { + suspended: boolean + level: ConnectionLogLevel + code: ConnectionDiagnosticCode + title: string + detail: string + consoleMessage: string + consoleFields: { timeoutMs: number; elapsedMs: number; attempt?: number } +} + +function elapsedLooksFrozen(elapsedMs: number, timeoutMs: number): boolean { + return elapsedMs > timeoutMs + SUSPENSION_SLACK_MS +} + +export function describeSocketDeadline(input: SocketDeadlineInput): SocketDeadlineReport { + const elapsedMs = input.firedAtMs - input.armedAtMs + const wallFrozen = elapsedLooksFrozen(elapsedMs, input.timeoutMs) + const monotonicFrozen = + input.monotonicElapsedMs !== undefined && + elapsedLooksFrozen(input.monotonicElapsedMs, input.timeoutMs) + // A foreground loss supports suspension only when at least one clock also ran long. + // Without an AppState event, both clocks must run long to distinguish a wall-clock step. + const suspended = + (input.leftForeground === true && (wallFrozen || monotonicFrozen)) || + (input.monotonicElapsedMs === undefined ? wallFrozen : wallFrozen && monotonicFrozen) + const consoleFields = { + timeoutMs: input.timeoutMs, + elapsedMs, + ...(input.attempt === undefined ? {} : { attempt: input.attempt }) + } + if (suspended) { + const duration = wallFrozen ? ` for ${formatSuspendedElapsed(elapsedMs)}` : '' + return { + suspended: true, + level: 'warn', + code: 'suspended-dial', + title: input.kind === 'connect' ? 'WebSocket connect interrupted' : 'Handshake interrupted', + detail: `App suspended${duration}; connection state unknown, re-dialing`, + consoleMessage: `[net] ${input.kind} deadline fired after suspension`, + consoleFields + } + } + if (input.kind === 'connect') { + return { + suspended: false, + level: 'error', + code: 'connect-timeout', + title: 'WebSocket connect timeout', + detail: `No TCP/WS handshake within ${input.timeoutMs / 1000}s — endpoint unreachable?`, + consoleMessage: '[net] connect-timeout fired (onopen never arrived)', + consoleFields + } + } + return { + suspended: false, + level: 'error', + code: 'handshake-timeout', + title: 'Handshake timeout', + detail: `No e2ee_ready/e2ee_authenticated within ${input.timeoutMs / 1000}s`, + consoleMessage: '[net] handshake-timeout fired (e2ee_authenticated never arrived)', + consoleFields + } +} + +export function reportSocketDeadline( + input: SocketDeadlineInput, + emitLog: ConnectionLogEmitter, + close: () => void +): void { + const report = describeSocketDeadline(input) + console.log(report.consoleMessage, report.consoleFields) + emitLog(report.level, report.title, report.detail, { code: report.code }) + close() +} + +function formatSuspendedElapsed(elapsedMs: number): string { + const totalMinutes = Math.max(1, Math.round(elapsedMs / 60_000)) + const hours = Math.floor(totalMinutes / 60) + const minutes = totalMinutes % 60 + if (hours > 0 && minutes > 0) { + return `${hours}h${minutes}m` + } + if (hours > 0) { + return `${hours}h` + } + return `${minutes}m` +} diff --git a/mobile/src/transport/types.ts b/mobile/src/transport/types.ts index d9c9271c79d0..4cb2027d3c9a 100644 --- a/mobile/src/transport/types.ts +++ b/mobile/src/transport/types.ts @@ -54,6 +54,7 @@ export type ConnectionDiagnosticCode = | 'network-changed' | 'connect-timeout' | 'handshake-timeout' + | 'suspended-dial' | 'authentication-rejected' | 'socket-closed' | 'liveness-timeout'