mirror of
https://github.com/stablyai/orca.git
synced 2026-10-31 00:57:45 +00:00
fix(mobile): distinguish delayed dial deadlines from unreachable hosts
Classify substantially delayed connect/handshake deadlines as interrupted instead of blaming endpoint reachability, retaining the existing close/retry path and ordinary timeout errors. Limit sleep-clock compensation to observed background segments and let fresh failures replace delayed evidence. Remove the stale host-version fallback and discard captured versions when report hydration crosses an observed reconnect. Independently reviewed; 128 focused tests, adjacent transport contracts and changed quality pass. Adapted from community PR #24425. Fixes #18829. Co-authored-by: Wooseong Kim <innocarpe@gmail.com> Co-authored-by: Cursor <cursoragent@cursor.com>
This commit is contained in:
co-authored by
Wooseong Kim
Cursor
parent
ec546de75a
commit
ea42a203a0
@@ -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 (
|
||||
|
||||
@@ -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',
|
||||
|
||||
@@ -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)
|
||||
)
|
||||
}
|
||||
|
||||
@@ -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', () => {
|
||||
|
||||
@@ -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)' : ''}`
|
||||
|
||||
@@ -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<void>>(),
|
||||
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<void>((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<void>((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')
|
||||
})
|
||||
})
|
||||
@@ -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,
|
||||
|
||||
@@ -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' })
|
||||
|
||||
@@ -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')
|
||||
}
|
||||
|
||||
@@ -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 {
|
||||
|
||||
@@ -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()
|
||||
|
||||
@@ -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)
|
||||
})
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
@@ -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'
|
||||
})
|
||||
})
|
||||
})
|
||||
@@ -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`
|
||||
}
|
||||
@@ -52,6 +52,7 @@ export type ConnectionDiagnosticCode =
|
||||
| 'client-session-started'
|
||||
| 'app-resumed'
|
||||
| 'network-changed'
|
||||
| 'suspended-dial'
|
||||
| 'connect-timeout'
|
||||
| 'handshake-timeout'
|
||||
| 'authentication-rejected'
|
||||
|
||||
Reference in New Issue
Block a user