diff --git a/mobile/app/connection-log.tsx b/mobile/app/connection-log.tsx index ef2fe3840ca..65ce724b31e 100644 --- a/mobile/app/connection-log.tsx +++ b/mobile/app/connection-log.tsx @@ -51,7 +51,7 @@ export default function NativeConnectionLogRoute() { const selectedId = resolveDiagnosticsHostId(hosts, params.hostId, manualSelection, routeKey) const selected = hosts.find((host) => host.id === selectedId) ?? null const { client, state } = useHostClient(selected?.id) - const { desktopAppVersion } = useHostStatusGates({ + const { desktopAppVersion, statusPending } = useHostStatusGates({ hostId: selected?.id, client, connState: state @@ -78,9 +78,13 @@ export default function NativeConnectionLogRoute() { const device = useMemo( () => selected - ? createNativeDiagnosticsOperations(selected, clientContext, desktopAppVersion) + ? createNativeDiagnosticsOperations( + selected, + clientContext, + statusPending ? null : desktopAppVersion + ) : null, - [selected, clientContext, desktopAppVersion] + [selected, clientContext, desktopAppVersion, statusPending] ) return ( diff --git a/mobile/src/diagnostics/connection-diagnostics-analysis.test.ts b/mobile/src/diagnostics/connection-diagnostics-analysis.test.ts index ab40b3511b2..151f0d880db 100644 --- a/mobile/src/diagnostics/connection-diagnostics-analysis.test.ts +++ b/mobile/src/diagnostics/connection-diagnostics-analysis.test.ts @@ -195,6 +195,30 @@ describe('diagnoseConnection', () => { }) }) + it('does not reuse an earlier endpoint failure after a delayed deadline', () => { + expect( + diagnoseConnection({ + endpoint: 'ws://100.88.90.25:6768', + state: 'reconnecting', + activePath: 'tailscale', + entries: [ + { ...event('WebSocket connect timeout'), code: 'connect-timeout', path: 'tailscale' }, + { + ...event('WebSocket connect interrupted'), + id: 'delayed', + ts: 2, + code: 'suspended-dial', + path: 'tailscale' + } + ] + }) + ).toEqual({ + likelyCause: 'Connection deadline delivery was delayed; the app may have been suspended.', + nextStep: 'Orca is re-dialing to check the connection. Keep the app open while it retries.', + reportability: 'none' + }) + }) + it('keys reportability to the current structured incident', () => { const args = { endpoint: 'ws://192.168.1.2:6768', diff --git a/mobile/src/diagnostics/connection-diagnostics-analysis.ts b/mobile/src/diagnostics/connection-diagnostics-analysis.ts index a91bdde7355..f6b00c5411e 100644 --- a/mobile/src/diagnostics/connection-diagnostics-analysis.ts +++ b/mobile/src/diagnostics/connection-diagnostics-analysis.ts @@ -78,6 +78,14 @@ function diagnoseFailure( return relayDial } + if (failure?.code === 'suspended-dial') { + return { + likelyCause: 'Connection deadline delivery was delayed; the app may have been suspended.', + nextStep: 'Orca is re-dialing to check the connection. Keep the app open while it retries.', + reportability: 'none' + } + } + if (/liveness-timeout|liveness timeout|connection health check failed/i.test(evidence)) { const relayLiveness = failure?.code === 'liveness-timeout' && failure.path === 'relay' const structuredDirectLiveness = @@ -257,7 +265,7 @@ function diagnosticEvidence(entry: ConnectionLogEntry): string { } function isDiagnosticFailure(entry: ConnectionLogEntry): boolean { - return /relay director resolve failed \((?:401|503)\)|liveness-timeout|liveness timeout|connection health check failed|relay-dial-failed|relay dial failed|relay-session-failed|active relay session failed|authentication-rejected|unauthorized|pairing may be revoked|connect-timeout|websocket connect timeout|handshake-timeout|handshake timeout/i.test( + return /suspended-dial|relay director resolve failed \((?:401|503)\)|liveness-timeout|liveness timeout|connection health check failed|relay-dial-failed|relay dial failed|relay-session-failed|active relay session failed|authentication-rejected|unauthorized|pairing may be revoked|connect-timeout|websocket connect timeout|handshake-timeout|handshake timeout/i.test( diagnosticEvidence(entry) ) } diff --git a/mobile/src/diagnostics/connection-diagnostics-report.test.ts b/mobile/src/diagnostics/connection-diagnostics-report.test.ts index e50fe90d362..264c772d47e 100644 --- a/mobile/src/diagnostics/connection-diagnostics-report.test.ts +++ b/mobile/src/diagnostics/connection-diagnostics-report.test.ts @@ -28,7 +28,8 @@ describe('buildConnectionDiagnosticsReport', () => { }) expect(report).toContain('App: Orca Mobile 0.0.29 · ios 26.5.1') - expect(report).toContain('Host Orca version: 1.4.191') + expect(report).toContain('Host Orca version: unknown (not currently connected)') + expect(report).not.toContain('1.4.191') expect(report).toContain('Endpoint: 100.65.9.106:6768 (Tailscale)') expect(report).toContain('State: reconnecting (reconnect attempts: 12)') expect(report).toContain('(5m 0s ago)') @@ -67,11 +68,13 @@ describe('buildConnectionDiagnosticsReport', () => { lastConnectedAt: null, platform: 'ios 26', appVersion: '0.0.60', + desktopAppVersion: '1.4.197', bridgeProtocolVersion: 1, entries: [], nowMs: NOW }).split('\n') expect(lines.slice(2, 4)).toEqual(['App: Orca Mobile 0.0.60 · ios 26', 'Bridge protocol: 1']) + expect(lines).toContain('Host Orca version: 1.4.197') }) it('explains the most likely cause and redacts credentials before copying', () => { diff --git a/mobile/src/diagnostics/connection-diagnostics-report.ts b/mobile/src/diagnostics/connection-diagnostics-report.ts index 973d6ca320e..1cf640a9b86 100644 --- a/mobile/src/diagnostics/connection-diagnostics-report.ts +++ b/mobile/src/diagnostics/connection-diagnostics-report.ts @@ -46,8 +46,11 @@ export function buildConnectionDiagnosticsReport(args: { lines.push(`Generated: ${new Date(now).toISOString()}`) lines.push(`App: Orca Mobile ${args.appVersion} · ${args.platform}`) lines.push(`Bridge protocol: ${args.bridgeProtocolVersion}`) - const desktopAppVersion = normalizeHostAppVersion(args.desktopAppVersion) - lines.push(`Host Orca version: ${desktopAppVersion ?? 'unknown'}`) + const desktopAppVersion = + args.state === 'connected' ? normalizeHostAppVersion(args.desktopAppVersion) : null + lines.push( + `Host Orca version: ${desktopAppVersion ?? (args.state === 'connected' ? 'unknown' : 'unknown (not currently connected)')}` + ) lines.push(`Host: ${redactConnectionLogText(args.hostName)}`) lines.push( `Endpoint: ${formatEndpoint(args.endpoint)}${isTailscaleEndpoint(args.endpoint) ? ' (Tailscale)' : ''}` diff --git a/mobile/src/diagnostics/native-diagnostics-operations.test.ts b/mobile/src/diagnostics/native-diagnostics-operations.test.ts new file mode 100644 index 00000000000..a9eb226fd97 --- /dev/null +++ b/mobile/src/diagnostics/native-diagnostics-operations.test.ts @@ -0,0 +1,97 @@ +import { beforeEach, describe, expect, it, vi } from 'vitest' +import type { ConnectionState, HostProfile } from '../transport/types' +import { createNativeDiagnosticsOperations } from './native-diagnostics-operations' + +const logStore = vi.hoisted(() => ({ + hydrate: vi.fn<() => Promise>(), + get: () => [] +})) + +vi.mock('react-native', () => ({ Platform: { OS: 'ios', Version: '26' } })) +vi.mock('expo-constants', () => ({ default: { expoConfig: { version: '0.0.60' } } })) +vi.mock('../transport/persisted-connection-log-store', () => ({ connectionLogStore: logStore })) + +const host: HostProfile = { + id: 'host-a', + name: 'Desktop', + endpoint: 'ws://desktop.invalid:6768', + deviceToken: 'token', + publicKeyB64: 'key', + lastConnected: 1_000 +} + +function createContext() { + let state: ConnectionState = 'connected' + let lastConnectedAt: number | null = 1_000 + return { + getState: () => state, + getReconnectAttempt: () => 0, + getLastConnectedAt: () => lastConnectedAt, + getActivePath: () => 'lan' as const, + getPendingPath: () => null, + setConnection(next: ConnectionState, connectedAt: number | null) { + state = next + lastConnectedAt = connectedAt + } + } +} + +describe('native connection diagnostic reports', () => { + beforeEach(() => { + logStore.hydrate.mockReset().mockResolvedValue(undefined) + }) + + it('keeps the live version while its connection remains current', async () => { + const device = createNativeDiagnosticsOperations(host, createContext(), '1.4.197') + const { report } = await device.report() + expect(report).toContain('State: connected') + expect(report).toContain('Host Orca version: 1.4.197') + }) + + it('omits a captured version when hydration crosses a reconnect', async () => { + let finishHydration = () => {} + logStore.hydrate.mockReturnValue( + new Promise((resolve) => { + finishHydration = resolve + }) + ) + const context = createContext() + const device = createNativeDiagnosticsOperations(host, context, '1.4.197') + const pendingReport = device.report() + context.setConnection('reconnecting', 1_000) + context.setConnection('connected', 2_000) + finishHydration() + const { report } = await pendingReport + expect(report).toContain('State: connected') + expect(report).toContain('Host Orca version: unknown') + expect(report).not.toContain('1.4.197') + }) + + it('does not promote a disconnected version when a connection opens during hydration', async () => { + let finishHydration = () => {} + logStore.hydrate.mockReturnValue( + new Promise((resolve) => { + finishHydration = resolve + }) + ) + const context = createContext() + context.setConnection('disconnected', 1_000) + const device = createNativeDiagnosticsOperations(host, context, '1.4.197') + const pendingReport = device.report() + context.setConnection('connected', 1_000) + finishHydration() + const { report } = await pendingReport + expect(report).toContain('State: connected') + expect(report).toContain('Host Orca version: unknown') + expect(report).not.toContain('1.4.197') + }) + + it('keeps disconnected reports explicit even with a captured version', async () => { + const context = createContext() + context.setConnection('disconnected', 1_000) + const device = createNativeDiagnosticsOperations(host, context, '1.4.197') + const { report } = await device.report() + expect(report).toContain('Host Orca version: unknown (not currently connected)') + expect(report).not.toContain('1.4.197') + }) +}) diff --git a/mobile/src/diagnostics/native-diagnostics-operations.ts b/mobile/src/diagnostics/native-diagnostics-operations.ts index 4b9d838f81e..2fb79ae35f1 100644 --- a/mobile/src/diagnostics/native-diagnostics-operations.ts +++ b/mobile/src/diagnostics/native-diagnostics-operations.ts @@ -3,7 +3,6 @@ import Constants from 'expo-constants' import type { HostProfile } from '../transport/types' import type { RpcClientContextValue } from '../transport/rpc-client-context-contract' import { connectionLogStore } from '../transport/persisted-connection-log-store' -import { loadHostAppVersion } from '../transport/host-app-version-store' import { readConnectionDiagnosticsSnapshot } from './connection-diagnostics-screen-data' import { getReportableConnectionIncidentId } from './connection-diagnostics-analysis' import { buildConnectionDiagnosticsReport } from './connection-diagnostics-report' @@ -13,14 +12,18 @@ import { BRIDGE_PROTOCOL_VERSION } from '../mobile-web-shell/bridge/bridge-frame export function createNativeDiagnosticsOperations( host: HostProfile, - context: RpcClientContextValue, + context: Pick< + RpcClientContextValue, + 'getState' | 'getReconnectAttempt' | 'getLastConnectedAt' | 'getActivePath' | 'getPendingPath' + >, liveDesktopAppVersion?: string | null ): DiagnosticsDeviceOperations { + const versionConnectedAt = + context.getState(host.id) === 'connected' ? context.getLastConnectedAt(host.id) : null return { async report() { const appVersion = Constants.expoConfig?.version ?? 'unknown' const platform = `${Platform.OS} ${Platform.Version ?? ''}`.trim() - const desktopAppVersion = liveDesktopAppVersion ?? (await loadHostAppVersion(host.id)) const snapshot = await readConnectionDiagnosticsSnapshot(context, connectionLogStore, host.id) return { report: buildConnectionDiagnosticsReport({ @@ -31,7 +34,10 @@ export function createNativeDiagnosticsOperations( lastConnectedAt: snapshot.lastConnectedAt, platform, appVersion, - desktopAppVersion, + desktopAppVersion: + versionConnectedAt !== null && snapshot.lastConnectedAt === versionConnectedAt + ? liveDesktopAppVersion + : null, entries: snapshot.entries, activePath: snapshot.activePath, pendingPath: snapshot.pendingPath, diff --git a/mobile/src/transport/connection-revival-triggers.test.ts b/mobile/src/transport/connection-revival-triggers.test.ts index 30efcd4f9bd..108710317fa 100644 --- a/mobile/src/transport/connection-revival-triggers.test.ts +++ b/mobile/src/transport/connection-revival-triggers.test.ts @@ -1,5 +1,6 @@ import { beforeEach, describe, expect, it, vi } from 'vitest' import { subscribeConnectionRevivalTriggers } from './connection-revival-triggers' +import { startSocketDeadlineClock } from './socket-deadline-clock' type AppStateListener = (next: string) => void type NetworkSnapshot = { isConnected?: boolean; type?: string } @@ -13,6 +14,7 @@ const networkRemove = vi.fn() vi.mock('react-native', () => ({ AppState: { + currentState: 'active', addEventListener: (_event: string, listener: AppStateListener) => { appStateListener = listener return { remove: appStateRemove } @@ -55,6 +57,27 @@ describe('subscribeConnectionRevivalTriggers', () => { expect(nudge).toHaveBeenCalledTimes(1) }) + it('keeps elapsed background time when a device sleep pauses the monotonic clock', async () => { + let wall = 1_000 + let monotonic = 50 + const wallClock = vi.spyOn(Date, 'now').mockImplementation(() => wall) + const monotonicClock = vi.spyOn(performance, 'now').mockImplementation(() => monotonic) + const unsubscribe = await subscribeAndSeed(nudge) + const elapsed = startSocketDeadlineClock() + try { + appStateListener?.('background') + wall += 3 * 60 * 60_000 + monotonic += 12_000 + appStateListener?.('active') + expect(elapsed()).toBe(3 * 60 * 60_000) + expect(nudge).toHaveBeenCalledTimes(1) + } finally { + unsubscribe() + wallClock.mockRestore() + monotonicClock.mockRestore() + } + }) + it('nudges when the network comes back online', async () => { await subscribeAndSeed(nudge) networkListener?.({ isConnected: false, type: 'NONE' }) diff --git a/mobile/src/transport/connection-revival-triggers.ts b/mobile/src/transport/connection-revival-triggers.ts index a7e5bb8578b..2585c8bc032 100644 --- a/mobile/src/transport/connection-revival-triggers.ts +++ b/mobile/src/transport/connection-revival-triggers.ts @@ -1,5 +1,6 @@ import { AppState } from 'react-native' import { addNetworkStateListener, getNetworkStateAsync, type NetworkState } from 'expo-network' +import { recordSocketDeadlineAppState } from './socket-deadline-clock' // Why: Android/iOS suspend JS timers and silently kill sockets while the app // is backgrounded, and network handoffs (Wi-Fi → cellular) kill the TCP path @@ -9,7 +10,9 @@ import { addNetworkStateListener, getNetworkStateAsync, type NetworkState } from export function subscribeConnectionRevivalTriggers( nudge: (reason: 'app-resume' | 'network-change') => void ): () => void { + recordSocketDeadlineAppState(AppState.currentState) const appStateSub = AppState.addEventListener('change', (next) => { + recordSocketDeadlineAppState(next) if (next === 'active') { nudge('app-resume') } diff --git a/mobile/src/transport/rpc-client-socket-session.ts b/mobile/src/transport/rpc-client-socket-session.ts index fdcbe12fd6b..976e8f304b6 100644 --- a/mobile/src/transport/rpc-client-socket-session.ts +++ b/mobile/src/transport/rpc-client-socket-session.ts @@ -4,6 +4,8 @@ import { createDirectSocketFraming, type DirectSocketFraming } from './direct-so import { isRpcResponse } from './rpc-response-shape' import { isStaleRpcSocketEvent, logRpcSocketClose } from './rpc-socket-close-evidence' import { describeSocketEvent, redactSocketEndpoint } from './socket-event-debug' +import { reportSocketDeadline, type SocketDeadlineKind } from './socket-deadline-suspension' +import { startSocketDeadlineClock } from './socket-deadline-clock' import type { ConnectionLogEmitter, ConnectionState, RpcRequest, RpcResponse } from './types' const CONNECT_TIMEOUT_MS = 12_000 @@ -233,44 +235,45 @@ 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 elapsedMs = startSocketDeadlineClock() + const timer = setTimeout(() => { + if (kind === 'connect') { + this.connectTimer = null + } else { + this.handshakeTimer = null + } + if ( + this.options.getCurrentSocket() !== this.socket || + (kind === 'connect' + ? this.socket.readyState !== WEBSOCKET_CONNECTING_STATE + : this.authenticated) + ) { 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, + elapsedMs: elapsedMs(), + timeoutMs, + ...(kind === 'connect' ? { attempt: this.options.getReconnectAttempt() } : {}) + }, + this.options.emitLog, + () => this.options.onForcedClose(this) ) - this.options.onForcedClose(this) - }, HANDSHAKE_TIMEOUT_MS) + }, timeoutMs) + if (kind === 'connect') { + this.connectTimer = timer + } else { + this.handshakeTimer = timer + } } private clearConnectTimer(): void { diff --git a/mobile/src/transport/rpc-client-synthesized-close-diagnostics.test.ts b/mobile/src/transport/rpc-client-synthesized-close-diagnostics.test.ts index 7b75593f40e..1231a200ebf 100644 --- a/mobile/src/transport/rpc-client-synthesized-close-diagnostics.test.ts +++ b/mobile/src/transport/rpc-client-synthesized-close-diagnostics.test.ts @@ -3,6 +3,9 @@ // never costs us the auth-failed latch when the real close lands late. import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' import { connect } from './rpc-client' +import { diagnoseConnection } from '../diagnostics/connection-diagnostics-analysis' +import type { ConnectionLogEntry } from './types' +import { recordSocketDeadlineAppState } from './socket-deadline-clock' vi.mock('./direct-e2ee-framing-policy', () => import('./legacy-direct-framing-test-policy')) @@ -87,6 +90,7 @@ describe('synthesized close diagnostics', () => { beforeEach(() => { vi.useFakeTimers() + recordSocketDeadlineAppState('active') sockets.length = 0 globalThis.WebSocket = WedgedWebSocket as unknown as typeof WebSocket logSpy = vi.spyOn(console, 'log').mockImplementation(() => {}) @@ -98,6 +102,117 @@ describe('synthesized close diagnostics', () => { globalThis.WebSocket = originalWebSocket }) + it.each(['connect', 'handshake'] as const)( + 'redials a suspended %s deadline without blaming the endpoint', + async (kind) => { + let elapsed = 0 + const clock = vi.spyOn(performance, 'now').mockImplementation(() => elapsed) + const entries: ConnectionLogEntry[] = [] + const client = connect('ws://desktop.invalid', 'token', 'server-key', { + onLog: (entry) => entries.push(entry) + }) + if (kind === 'handshake') { + lastSocket().open() + } + const timeout = kind === 'connect' ? 12_000 : 5_000 + try { + elapsed = 164 * 60_000 + vi.setSystemTime(Date.now() + elapsed - timeout) + await vi.advanceTimersByTimeAsync(timeout) + expect(client.getState()).toBe('reconnecting') + expect(entries.some((entry) => entry.code === 'suspended-dial')).toBe(true) + expect(entries.some((entry) => entry.code === `${kind}-timeout`)).toBe(false) + expect( + diagnoseConnection({ + endpoint: 'ws://desktop.invalid', + state: client.getState(), + entries + }).likelyCause + ).not.toContain('endpoint did not answer') + await vi.advanceTimersByTimeAsync(500) + expect(sockets).toHaveLength(2) + } finally { + client.close() + clock.mockRestore() + } + } + ) + + it('does not blame the endpoint when device sleep pauses the monotonic clock', async () => { + let elapsed = 0 + const clock = vi.spyOn(performance, 'now').mockImplementation(() => elapsed) + const entries: ConnectionLogEntry[] = [] + const client = connect('ws://desktop.invalid', 'token', 'server-key', { + onLog: (entry) => entries.push(entry) + }) + try { + recordSocketDeadlineAppState('background') + elapsed = 12_000 + vi.setSystemTime(Date.now() + 3 * 60 * 60_000) + recordSocketDeadlineAppState('active') + await vi.advanceTimersByTimeAsync(12_000) + expect(client.getState()).toBe('reconnecting') + expect(entries.some((entry) => entry.code === 'suspended-dial')).toBe(true) + expect(entries.some((entry) => entry.code === 'connect-timeout')).toBe(false) + } finally { + client.close() + clock.mockRestore() + } + }) + + it('lets the next on-time failure replace a delayed deadline diagnosis', async () => { + let elapsed = 0 + const clock = vi.spyOn(performance, 'now').mockImplementation(() => elapsed) + const entries: ConnectionLogEntry[] = [] + const client = connect('ws://desktop.invalid', 'token', 'server-key', { + onLog: (entry) => entries.push(entry) + }) + try { + elapsed = 164 * 60_000 + await vi.advanceTimersByTimeAsync(12_000) + expect(entries.some((entry) => entry.code === 'suspended-dial')).toBe(true) + elapsed += 500 + await vi.advanceTimersByTimeAsync(500) + expect(sockets).toHaveLength(2) + elapsed += 12_000 + await vi.advanceTimersByTimeAsync(12_000) + expect(entries.filter((entry) => entry.code === 'connect-timeout')).toHaveLength(1) + expect( + diagnoseConnection({ + endpoint: 'ws://desktop.invalid', + state: client.getState(), + entries + }).likelyCause + ).toContain('endpoint did not answer') + } finally { + client.close() + clock.mockRestore() + } + }) + + it.each([3 * 60 * 60_000, -3 * 60 * 60_000])( + 'keeps an on-time connect timeout when the wall clock shifts by %i ms', + async (wallShift) => { + let elapsed = 0 + const clock = vi.spyOn(performance, 'now').mockImplementation(() => elapsed) + const entries: ConnectionLogEntry[] = [] + const client = connect('ws://desktop.invalid', 'token', 'server-key', { + onLog: (entry) => entries.push(entry) + }) + try { + elapsed = 12_000 + vi.setSystemTime(Date.now() + wallShift) + await vi.advanceTimersByTimeAsync(12_000) + expect(client.getState()).toBe('reconnecting') + expect(entries.some((entry) => entry.code === 'connect-timeout')).toBe(true) + expect(entries.some((entry) => entry.code === 'suspended-dial')).toBe(false) + } finally { + client.close() + clock.mockRestore() + } + } + ) + it('records the close clock when a handshake timeout synthesizes the close', async () => { const client = connect('ws://desktop.invalid', 'token', 'server-key') lastSocket().open() 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 00000000000..688bab6ef9f --- /dev/null +++ b/mobile/src/transport/socket-deadline-clock.test.ts @@ -0,0 +1,84 @@ +import { afterEach, expect, it, vi } from 'vitest' +import { recordSocketDeadlineAppState, startSocketDeadlineClock } from './socket-deadline-clock' + +afterEach(() => { + recordSocketDeadlineAppState('active') + vi.restoreAllMocks() +}) + +function createClock() { + let wallMs = 1_000 + let monotonicMs = 10 + vi.spyOn(Date, 'now').mockImplementation(() => wallMs) + vi.spyOn(performance, 'now').mockImplementation(() => monotonicMs) + return { + set: (nextWallMs: number, nextMonotonicMs: number) => { + wallMs = nextWallMs + monotonicMs = nextMonotonicMs + } + } +} + +it('does not inherit an earlier foreground loss into a fresh foreground deadline', () => { + const clock = createClock() + recordSocketDeadlineAppState('background') + clock.set(10_801_000, 12_010) + recordSocketDeadlineAppState('active') + const elapsed = startSocketDeadlineClock() + clock.set(21_601_000, 24_010) + expect(elapsed()).toBe(12_000) +}) + +it('handles a deadline armed outside foreground despite a paused monotonic clock', () => { + const clock = createClock() + recordSocketDeadlineAppState('inactive') + const elapsed = startSocketDeadlineClock() + clock.set(10_801_000, 12_010) + expect(elapsed()).toBe(10_800_000) +}) + +it('does not shorten elapsed monotonic time after a backwards background wall-clock step', () => { + const clock = createClock() + const elapsed = startSocketDeadlineClock() + recordSocketDeadlineAppState('background') + clock.set(-10_800_000, 12_010) + expect(elapsed()).toBe(12_000) +}) + +it('excludes a foreground wall jump after a brief inactive transition', () => { + const clock = createClock() + const elapsed = startSocketDeadlineClock() + clock.set(2_000, 1_010) + recordSocketDeadlineAppState('inactive') + clock.set(2_100, 1_110) + recordSocketDeadlineAppState('active') + clock.set(10_813_000, 12_010) + expect(elapsed()).toBe(12_000) +}) + +it('counts only sleep after a deadline armed partway through a background segment', () => { + const clock = createClock() + recordSocketDeadlineAppState('inactive') + clock.set(61_000, 10) + const elapsed = startSocketDeadlineClock() + clock.set(121_000, 10) + recordSocketDeadlineAppState('active') + expect(elapsed()).toBe(60_000) +}) + +it('accumulates sleep across background segments without counting foreground clock changes', () => { + const clock = createClock() + const elapsed = startSocketDeadlineClock() + clock.set(10_801_000, 1_010) + recordSocketDeadlineAppState('inactive') + clock.set(10_831_000, 1_010) + recordSocketDeadlineAppState('background') + clock.set(10_861_000, 1_010) + recordSocketDeadlineAppState('active') + clock.set(21_662_000, 2_010) + recordSocketDeadlineAppState('background') + clock.set(21_692_000, 2_010) + expect(elapsed()).toBe(92_000) + recordSocketDeadlineAppState('active') + expect(elapsed()).toBe(92_000) +}) diff --git a/mobile/src/transport/socket-deadline-clock.ts b/mobile/src/transport/socket-deadline-clock.ts new file mode 100644 index 00000000000..b7a109ac7b1 --- /dev/null +++ b/mobile/src/transport/socket-deadline-clock.ts @@ -0,0 +1,38 @@ +type SocketDeadlineClockReading = { wallMs: number; monotonicMs: number } + +let outsideForegroundSince: SocketDeadlineClockReading | null = null +let completedSleepGapMs = 0 + +function readSocketDeadlineClock(): SocketDeadlineClockReading { + return { wallMs: Date.now(), monotonicMs: performance.now() } +} + +function sleepGapMs(start: SocketDeadlineClockReading, end: SocketDeadlineClockReading): number { + return Math.max(0, end.wallMs - start.wallMs - (end.monotonicMs - start.monotonicMs)) +} + +function totalSleepGapMs(now: SocketDeadlineClockReading): number { + return ( + completedSleepGapMs + (outsideForegroundSince ? sleepGapMs(outsideForegroundSince, now) : 0) + ) +} + +export function recordSocketDeadlineAppState(state: string | null | undefined): void { + if (state === 'background' || state === 'inactive') { + outsideForegroundSince ??= readSocketDeadlineClock() + } else if (state === 'active' && outsideForegroundSince) { + completedSleepGapMs += sleepGapMs(outsideForegroundSince, readSocketDeadlineClock()) + outsideForegroundSince = null + } +} + +export function startSocketDeadlineClock(): () => number { + const armed = readSocketDeadlineClock() + const armedSleepGapMs = totalSleepGapMs(armed) + return () => { + const now = readSocketDeadlineClock() + const monotonicElapsedMs = now.monotonicMs - armed.monotonicMs + // Only background segments can supplement native clocks that pause during device sleep. + return monotonicElapsedMs + Math.max(0, totalSleepGapMs(now) - armedSleepGapMs) + } +} 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 00000000000..ec43cdae5c7 --- /dev/null +++ b/mobile/src/transport/socket-deadline-suspension.test.ts @@ -0,0 +1,44 @@ +import { describe, expect, it } from 'vitest' +import { describeSocketDeadline } from './socket-deadline-suspension' + +describe('socket deadline diagnostics', () => { + it.each([ + { kind: 'connect', timeoutMs: 12_000, code: 'connect-timeout' }, + { kind: 'handshake', timeoutMs: 5_000, code: 'handshake-timeout' } + ] as const)( + 'keeps ordinary $kind deadlines through the grace boundary', + ({ kind, timeoutMs, code }) => { + const report = describeSocketDeadline({ kind, timeoutMs, elapsedMs: timeoutMs + 60_000 }) + expect(report).toMatchObject({ suspended: false, level: 'error', code }) + } + ) + + it('classifies the reported 2h44m connect gap as suspension', () => { + const report = describeSocketDeadline({ + kind: 'connect', + timeoutMs: 12_000, + elapsedMs: Date.parse('2026-09-04T15:40:52.242Z') - Date.parse('2026-09-04T12:56:55.512Z') + }) + expect(report).toMatchObject({ + suspended: true, + level: 'warn', + code: 'suspended-dial', + detail: + 'Connection deadline delayed for 2h44m; app may have been suspended. Connection state unknown, re-dialing' + }) + expect(report.detail).not.toContain('endpoint unreachable') + }) + + it('classifies a handshake timer beyond the grace boundary as suspension', () => { + const report = describeSocketDeadline({ + kind: 'handshake', + timeoutMs: 5_000, + elapsedMs: 65_001 + }) + expect(report).toMatchObject({ + suspended: true, + code: 'suspended-dial', + title: 'Handshake interrupted' + }) + }) +}) diff --git a/mobile/src/transport/socket-deadline-suspension.ts b/mobile/src/transport/socket-deadline-suspension.ts new file mode 100644 index 00000000000..7bcf3830592 --- /dev/null +++ b/mobile/src/transport/socket-deadline-suspension.ts @@ -0,0 +1,92 @@ +import type { ConnectionDiagnosticCode, ConnectionLogEmitter, ConnectionLogLevel } from './types' + +// Allow ordinary scheduling delays before treating a deadline as suspended. +const SUSPENSION_SLACK_MS = 60_000 + +export type SocketDeadlineKind = 'connect' | 'handshake' + +export type SocketDeadlineInput = { + kind: SocketDeadlineKind + elapsedMs: number + timeoutMs: number + attempt?: number +} + +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.elapsedMs + const suspended = elapsedLooksFrozen(elapsedMs, input.timeoutMs) + const consoleFields = { + timeoutMs: input.timeoutMs, + elapsedMs, + ...(input.attempt === undefined ? {} : { attempt: input.attempt }) + } + if (suspended) { + return { + suspended: true, + level: 'warn', + code: 'suspended-dial', + title: input.kind === 'connect' ? 'WebSocket connect interrupted' : 'Handshake interrupted', + detail: `Connection deadline delayed for ${formatSuspendedElapsed(elapsedMs)}; app may have been suspended. Connection state unknown, re-dialing`, + consoleMessage: `[net] ${input.kind} deadline delivery delayed`, + 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 4d83a5cb762..706e08cdb37 100644 --- a/mobile/src/transport/types.ts +++ b/mobile/src/transport/types.ts @@ -52,6 +52,7 @@ export type ConnectionDiagnosticCode = | 'client-session-started' | 'app-resumed' | 'network-changed' + | 'suspended-dial' | 'connect-timeout' | 'handshake-timeout' | 'authentication-rejected'