diff --git a/mobile/src/diagnostics/connection-diagnostics-report.test.ts b/mobile/src/diagnostics/connection-diagnostics-report.test.ts index 991ec01f549..88794135209 100644 --- a/mobile/src/diagnostics/connection-diagnostics-report.test.ts +++ b/mobile/src/diagnostics/connection-diagnostics-report.test.ts @@ -56,6 +56,29 @@ describe('buildConnectionDiagnosticsReport', () => { expect(report).toContain('No connection events recorded.') }) + it('names the shell build and bridge version under the app line when given', () => { + const args = { + hostName: 'Host 3', + endpoint: 'ws://192.168.1.50:6768', + state: 'connected' as const, + reconnectAttempts: 0, + lastConnectedAt: null, + platform: 'ios 26', + appVersion: '0.0.60', + entries: [], + nowMs: NOW + } + const lines = buildConnectionDiagnosticsReport({ + ...args, + shell: { kind: 'ota', bridgeProtocolVersion: 1 } + }).split('\n') + expect(lines.slice(2, 4)).toEqual([ + 'App: Orca Mobile 0.0.60 · ios 26', + 'Shell: ota · bridge protocol 1' + ]) + expect(buildConnectionDiagnosticsReport(args)).not.toContain('Shell:') + }) + it('explains the most likely cause and redacts credentials before copying', () => { const report = buildConnectionDiagnosticsReport({ hostName: 'Host 3', diff --git a/mobile/src/diagnostics/connection-diagnostics-report.ts b/mobile/src/diagnostics/connection-diagnostics-report.ts index 41c22014471..25c78e224b9 100644 --- a/mobile/src/diagnostics/connection-diagnostics-report.ts +++ b/mobile/src/diagnostics/connection-diagnostics-report.ts @@ -28,6 +28,8 @@ export function buildConnectionDiagnosticsReport(args: { entries: readonly ConnectionLogEntry[] activePath?: MobileConnectionDiagnosticPath pendingPath?: MobileConnectionDiagnosticPath | null + /** Which shell this binary is and the page bridge version it speaks; omitted by older callers. */ + shell?: { kind: 'ota' | 'native'; bridgeProtocolVersion: number } nowMs?: number }): string { const now = args.nowMs ?? Date.now() @@ -43,6 +45,9 @@ export function buildConnectionDiagnosticsReport(args: { lines.push('Orca Mobile connection diagnostics') lines.push(`Generated: ${new Date(now).toISOString()}`) lines.push(`App: Orca Mobile ${args.appVersion} · ${args.platform}`) + if (args.shell) { + lines.push(`Shell: ${args.shell.kind} · bridge protocol ${args.shell.bridgeProtocolVersion}`) + } const desktopAppVersion = normalizeHostAppVersion(args.desktopAppVersion) lines.push(`Host Orca version: ${desktopAppVersion ?? 'unknown'}`) lines.push(`Host: ${redactConnectionLogText(args.hostName)}`) diff --git a/mobile/src/diagnostics/native-diagnostics-operations.ts b/mobile/src/diagnostics/native-diagnostics-operations.ts index 2b7b7fe6f0b..39e614b43ce 100644 --- a/mobile/src/diagnostics/native-diagnostics-operations.ts +++ b/mobile/src/diagnostics/native-diagnostics-operations.ts @@ -9,6 +9,8 @@ import { getReportableConnectionIncidentId } from './connection-diagnostics-anal import { buildConnectionDiagnosticsReport } from './connection-diagnostics-report' import { submitConnectionDiagnostics } from './connection-diagnostics-submission' import type { DiagnosticsDeviceOperations } from './diagnostics-device-operations' +import { mobileShellBuildKind } from '../storage/preferences' +import { BRIDGE_PROTOCOL_VERSION } from '../mobile-web-shell/bridge/bridge-frame-fields' export function createNativeDiagnosticsOperations( host: HostProfile, @@ -33,7 +35,8 @@ export function createNativeDiagnosticsOperations( desktopAppVersion, entries: snapshot.entries, activePath: snapshot.activePath, - pendingPath: snapshot.pendingPath + pendingPath: snapshot.pendingPath, + shell: { kind: mobileShellBuildKind(), bridgeProtocolVersion: BRIDGE_PROTOCOL_VERSION } }), appVersion, platform, diff --git a/mobile/src/mobile-web-shell/MobileWebShellScreen.test.tsx b/mobile/src/mobile-web-shell/MobileWebShellScreen.test.tsx index f285ec7076e..69fa1bbaceb 100644 --- a/mobile/src/mobile-web-shell/MobileWebShellScreen.test.tsx +++ b/mobile/src/mobile-web-shell/MobileWebShellScreen.test.tsx @@ -47,6 +47,7 @@ import { readBridgeHostMessage } from './bridge/bridge-envelope' import { MobileWebShellScreen } from './MobileWebShellScreen' +import { connectionLogStore } from '../transport/persisted-connection-log-store' import type { MobileWebShellSessionState } from './mobile-web-shell-session-contract' import type { ReactTestInstance, ReactTestRenderer } from 'react-test-renderer' @@ -244,8 +245,12 @@ describe('the hybrid shell screen', () => { // page re-posting `ready` on its backoff for as long as the screen is open. dependencies.snapshotUnreadable = true const warned = vi.spyOn(console, 'warn').mockImplementation(() => undefined) + const logged = () => connectionLogStore.get('host-1').map((entry) => entry.message) + const before = logged().length await renderScreen(readyState('session-one')) expect(dependencies.reportShellFailure.mock.calls).toEqual([['document-load-failed']]) + // Named in the exported log, not only as the generic failure it causes. + expect(logged().slice(before)).toEqual(['Web shell: host profile unreadable']) warned.mockRestore() }) diff --git a/mobile/src/mobile-web-shell/MobileWebShellScreen.tsx b/mobile/src/mobile-web-shell/MobileWebShellScreen.tsx index 34c150921ba..ea58f9876e3 100644 --- a/mobile/src/mobile-web-shell/MobileWebShellScreen.tsx +++ b/mobile/src/mobile-web-shell/MobileWebShellScreen.tsx @@ -38,6 +38,8 @@ import { storageReadParamsSchema, type BridgeNativeVerb } from './bridge/bridge- import { SHELL_OPENING_LABEL, ShellPageCover, ShellWaitingFrame } from './ShellWaitingFrame' import { ShellDownloadProgress } from './ShellDownloadProgress' import { pageSafeAreaInsets, usePublishedSafeAreaInsets } from './page-safe-area-insets' +import { hostProfileUnreadableLine, pageFaultLine } from './shell-lifecycle-log' +import { recordShellLifecycleLine } from './shell-lifecycle-line-recorder' function failureMessage(reason: MobileWebShellFailureCause): string { switch (reason) { @@ -245,6 +247,7 @@ export function MobileWebShellScreen({ // handler on the other, and neither has anywhere to put a throw. onPageFault: (error) => { console.warn('[web-shell] the page faulted', error) + recordShellLifecycleLine(hostId, pageFaultLine(error)) reportShellFailure('document-load-failed') }, // The `init` this ready is answered with is already built from the app's writes, which reach @@ -266,6 +269,7 @@ export function MobileWebShellScreen({ // `document-load-failed` because that is what happens: the document loads and the page refuses // the session, so no tree is ever built. The refetch it costs is wasted on a route this shell // produced, and the second report is terminal, which is the failure screen this deserves. + // Logged by the host's `route-refused` diagnostic, which carries the issue, in the same call. onRouteRefused: (issue) => { console.warn('[web-shell] refused to open this screen', issue) reportShellFailure('document-load-failed') @@ -341,6 +345,12 @@ export function MobileWebShellScreen({ reportShellFailure('document-load-failed') } }, [reportShellFailure, unreadable]) + // Log-only and separate, so the failure effect above keeps its own dependencies. + useEffect(() => { + if (unreadable) { + recordShellLifecycleLine(hostId, hostProfileUnreadableLine()) + } + }, [hostId, unreadable]) if (state.kind === 'native-route') { return fallback diff --git a/mobile/src/mobile-web-shell/bridge-diagnostic-log.test.ts b/mobile/src/mobile-web-shell/bridge-diagnostic-log.test.ts index c7f96afedf4..84c9c021050 100644 --- a/mobile/src/mobile-web-shell/bridge-diagnostic-log.test.ts +++ b/mobile/src/mobile-web-shell/bridge-diagnostic-log.test.ts @@ -18,6 +18,16 @@ function lines(): string[] { } describe('the bridge diagnostic log', () => { + it('hands the connection log the same once-per-key diagnostics as the console', () => { + const reported: string[] = [] + const report = createBridgeDiagnosticReporter((diagnostic) => reported.push(diagnostic.kind)) + report({ kind: 'frame-after-close' }) + report({ kind: 'frame-after-close' }) + report({ kind: 'notify-refused', name: 'fault', why: 'ungranted' }) + expect(reported).toEqual(['frame-after-close', 'notify-refused']) + expect(lines()).toHaveLength(2) + }) + it('names the notification it refused and why, for each refusal', () => { const report = createBridgeDiagnosticReporter() report({ kind: 'notify-refused', name: 'fault', why: 'before-ready' }) diff --git a/mobile/src/mobile-web-shell/bridge-diagnostic-log.ts b/mobile/src/mobile-web-shell/bridge-diagnostic-log.ts index 34ae56fa24b..6c6793008cc 100644 --- a/mobile/src/mobile-web-shell/bridge-diagnostic-log.ts +++ b/mobile/src/mobile-web-shell/bridge-diagnostic-log.ts @@ -24,7 +24,10 @@ function diagnosticKey(diagnostic: BridgeHostDiagnostic): string { * says why. The host already holds `post-failed` to one; this is the same bound for the kinds it * does not, and a new host starts the count over because a new page is new evidence. */ -export function createBridgeDiagnosticReporter(): (diagnostic: BridgeHostDiagnostic) => void { +export function createBridgeDiagnosticReporter( + // Gets the same once-per-key diagnostics as the console, for the exported connection log. + onReported?: (diagnostic: BridgeHostDiagnostic) => void +): (diagnostic: BridgeHostDiagnostic) => void { const reported = new Set() return (diagnostic) => { const key = diagnosticKey(diagnostic) @@ -32,6 +35,7 @@ export function createBridgeDiagnosticReporter(): (diagnostic: BridgeHostDiagnos return } reported.add(key) + onReported?.(diagnostic) if (diagnostic.kind === 'refused') { console.warn('[web-shell-bridge] refused a page frame', diagnostic.refusal) return diff --git a/mobile/src/mobile-web-shell/shell-bridge-log-lines.test.ts b/mobile/src/mobile-web-shell/shell-bridge-log-lines.test.ts new file mode 100644 index 00000000000..243dda5d9b5 --- /dev/null +++ b/mobile/src/mobile-web-shell/shell-bridge-log-lines.test.ts @@ -0,0 +1,45 @@ +import { describe, expect, it } from 'vitest' +import { bridgeDiagnosticLine, frameWithoutHostLine } from './shell-bridge-log-lines' + +describe('shell bridge log lines', () => { + it('skips routine bridge kinds and names the specific failure for the rest', () => { + expect( + bridgeDiagnosticLine({ + kind: 'terminal-backlog', + id: 't', + coalescedFrames: 0, + deliveredFrames: 0, + peakPendingBytes: 0, + ended: null + }) + ).toBeNull() + expect( + bridgeDiagnosticLine({ kind: 'notify-refused', name: 'fault', why: 'ungranted' }) + ).toEqual({ + level: 'warn', + code: 'web-shell-bridge', + message: 'Web shell bridge: notify-refused', + detail: 'ungranted' + }) + const gone = new Error('view gone') + gone.name = 'BridgeViewGoneError' + expect(bridgeDiagnosticLine({ kind: 'post-failed', error: gone })?.detail).toBe( + 'error=BridgeViewGoneError' + ) + expect(bridgeDiagnosticLine({ kind: 'post-failed', error: 'nope' })?.detail).toBe( + 'error=string' + ) + expect( + bridgeDiagnosticLine({ kind: 'route-refused', issue: 'Invalid path /Users/bob/wt' })?.detail + ).toBe('issue=Invalid path [path]') + }) + + it('says which half a frame with no bridge host was waiting on', () => { + expect(frameWithoutHostLine({ clientReady: false, snapshotReady: true })).toEqual({ + level: 'warn', + code: 'web-shell-page', + message: 'Web shell: page frame with no bridge host', + detail: 'client=null snapshot=ok' + }) + }) +}) diff --git a/mobile/src/mobile-web-shell/shell-bridge-log-lines.ts b/mobile/src/mobile-web-shell/shell-bridge-log-lines.ts new file mode 100644 index 00000000000..54d950f1ccf --- /dev/null +++ b/mobile/src/mobile-web-shell/shell-bridge-log-lines.ts @@ -0,0 +1,61 @@ +import type { BridgeHostDiagnostic } from './bridge-host-contract' +import type { ShellLifecycleLine } from './shell-lifecycle-line-recorder' +import { maskUserText } from './shell-log-path-masking' + +/** Bridge-side shell log lines: host diagnostics and frames that found no host to answer them. */ + +/** Null for routine kinds; the caller already bounds each key to one line per host. */ +export function bridgeDiagnosticLine(diagnostic: BridgeHostDiagnostic): ShellLifecycleLine | null { + // Retired terminal streams are routine and one per stream; they would crowd out the log. + if (diagnostic.kind === 'terminal-backlog') { + return null + } + const detail = bridgeDiagnosticDetail(diagnostic) + return { + level: 'warn', + code: 'web-shell-bridge', + message: `Web shell bridge: ${diagnostic.kind}`, + ...(detail === undefined ? {} : { detail }) + } +} + +/** A page frame arrived while no bridge host was built, so it was dropped unanswered. */ +export function frameWithoutHostLine(facts: { + clientReady: boolean + snapshotReady: boolean +}): ShellLifecycleLine { + return { + level: 'warn', + code: 'web-shell-page', + message: 'Web shell: page frame with no bridge host', + detail: `client=${facts.clientReady ? 'ok' : 'null'} snapshot=${facts.snapshotReady ? 'ok' : 'null'}` + } +} + +function bridgeDiagnosticDetail(diagnostic: BridgeHostDiagnostic): string | undefined { + switch (diagnostic.kind) { + case 'refused': + return diagnostic.refusal + case 'notify-refused': + case 'navigate-back-refused': + return diagnostic.why + case 'post-failed': + return `error=${maskUserText(errorName(diagnostic.error))}` + case 'route-refused': + return `issue=${maskUserText(diagnostic.issue)}` + case 'notify-failed': + case 'frame-after-dispose': + case 'frame-after-close': + case 'storage-refused': + case 'route-update-refused': + case 'binary-lane-refused': + case 'binary-frame-dropped': + case 'terminal-backlog': + // Their payloads name keys, ids or schema text that is not needed to place a stall. + return undefined + } +} + +function errorName(error: unknown): string { + return error instanceof Error ? error.name : typeof error +} diff --git a/mobile/src/mobile-web-shell/shell-lifecycle-line-recorder.ts b/mobile/src/mobile-web-shell/shell-lifecycle-line-recorder.ts new file mode 100644 index 00000000000..a2ed1b4743a --- /dev/null +++ b/mobile/src/mobile-web-shell/shell-lifecycle-line-recorder.ts @@ -0,0 +1,39 @@ +import { connectionLogStore } from '../transport/persisted-connection-log-store' +import type { ConnectionLogEntry } from '../transport/types' + +/** + * Sparse OTA shell milestones for the per-host connection log, so an exported report says where a + * workspace open stalled. Diagnostics only: nothing here feeds back into the session. + * + * The store holds 200 entries shared with connection events and every page route mounts its own + * shell, so a healthy open writes one line (the paint); the rest are failures and one-shot stall + * warnings. Route paths, generation directories and error stacks stay out: they can name user paths. + */ +export type ShellLifecycleLine = Required> & + Pick + +let lineSequence = 0 + +// Lines a host flapping between unreachable and dialling would repeat every cycle per mounted shell. +const FLAPPING_MESSAGES: ReadonlySet = new Set([ + 'Web shell: checking host', + 'Web shell: host unreachable and no app cached' +]) +// Per host, the flapping lines already written since the last other shell line for it. +const flappingWritten = new Map>() + +export function recordShellLifecycleLine(hostId: string, line: ShellLifecycleLine): void { + if (FLAPPING_MESSAGES.has(line.message)) { + const written = flappingWritten.get(hostId) ?? new Set() + if (written.has(line.message)) { + return + } + written.add(line.message) + flappingWritten.set(hostId, written) + } else { + flappingWritten.delete(hostId) + } + const ts = Date.now() + lineSequence += 1 + connectionLogStore.append(hostId, { id: `web-shell-${ts}-${lineSequence}`, ts, ...line }) +} diff --git a/mobile/src/mobile-web-shell/shell-lifecycle-log.test.ts b/mobile/src/mobile-web-shell/shell-lifecycle-log.test.ts new file mode 100644 index 00000000000..a7c13b20039 --- /dev/null +++ b/mobile/src/mobile-web-shell/shell-lifecycle-log.test.ts @@ -0,0 +1,383 @@ +import { describe, expect, it, vi } from 'vitest' +import { buildConnectionDiagnosticsReport } from '../diagnostics/connection-diagnostics-report' +import type { ConnectionLogEntry } from '../transport/types' +import { + CACHED, + MANIFEST, + createMobileWebShellSession, + gates, + ROUTE, + stamp +} from './mobile-web-shell-session-test-fixtures' +import { reduceMobileWebShellSession } from './mobile-web-shell-session' +import type { + MobileWebShellSession, + MobileWebShellSessionEvent +} from './mobile-web-shell-session-contract' +import { connectionLogStore } from '../transport/persisted-connection-log-store' +import { bridgeDiagnosticLine, frameWithoutHostLine } from './shell-bridge-log-lines' +import { recordShellLifecycleLine, type ShellLifecycleLine } from './shell-lifecycle-line-recorder' +import { + EMPTY_SHELL_LOG_TRACE, + pageFaultLine, + shellSessionStepLines, + shellStallLine, + traceShellStep, + type ShellLogTrace +} from './shell-lifecycle-log' + +vi.mock('@react-native-async-storage/async-storage', () => ({ + default: { getItem: vi.fn(async () => null), setItem: vi.fn(async () => undefined) } +})) + +type Pending = Parameters[1] + +/** Replays events through the real reducer, collecting what each step would log. */ +type Replayed = { + session: MobileWebShellSession + trace: ShellLogTrace + lines: ShellLifecycleLine[] +} + +function replay( + events: readonly Pending[], + from: Omit = { + session: createMobileWebShellSession(ROUTE), + trace: EMPTY_SHELL_LOG_TRACE + } +): Replayed { + let { session, trace } = from + const lines: ShellLifecycleLine[] = [] + for (const pending of events) { + const event: MobileWebShellSessionEvent = stamp(session.flow, pending) + const next = reduceMobileWebShellSession(session, event).session + trace = traceShellStep(trace, session, event, next) + lines.push(...shellSessionStepLines(session, event, next, trace)) + session = next + } + return { session, trace, lines } +} + +function stall(replayed: Omit): ShellLifecycleLine | null { + return shellStallLine(replayed.session.state, replayed.session, replayed.trace) +} + +const ACTIVATED = { + type: 'activated', + generationDirectory: '/Users/someone/Library/Caches/gen-1', + sessionId: 'session-one', + buildId: MANIFEST.buildId, + totalBytes: MANIFEST.totalBytes, + elapsedMs: 1234 +} as const + +const DOWNLOAD_OPEN: readonly Pending[] = [ + { type: 'gates-changed', gates: gates() }, + { type: 'cache-read', generation: null }, + { type: 'manifest-read', manifest: MANIFEST }, + { + type: 'fetch-progress', + completedAssets: 1, + totalAssets: MANIFEST.totalAssets, + receivedBytes: 10, + totalBytes: MANIFEST.totalBytes + }, + { + type: 'fetch-progress', + completedAssets: 2, + totalAssets: MANIFEST.totalAssets, + receivedBytes: 20, + totalBytes: MANIFEST.totalBytes + }, + { type: 'download-staged' }, + ACTIVATED +] + +function present(line: ShellLifecycleLine | null): ShellLifecycleLine[] { + expect(line).not.toBeNull() + return line === null ? [] : [line] +} + +function summary(lines: readonly ShellLifecycleLine[]): string[] { + return lines.map( + (line) => `${line.code} ${line.message}${line.detail ? ` | ${line.detail}` : ''}` + ) +} + +const PAGE_LOAD: readonly Pending[] = [ + { type: 'document-started' }, + { type: 'document-loaded' }, + { type: 'page-ready' } +] + +const BUILD = MANIFEST.buildId.slice(0, 8) + +describe('shell lifecycle log lines', () => { + it('writes exactly one line for a healthy cached open: the paint', () => { + const { lines } = replay([ + { type: 'gates-changed', gates: gates() }, + { type: 'cache-read', generation: CACHED }, + { type: 'manifest-read', manifest: MANIFEST }, + ACTIVATED, + ...PAGE_LOAD, + { type: 'page-ready' }, + { type: 'page-painted' }, + { type: 'page-painted' }, + { type: 'page-back-claim', claimed: true } + ]) + expect(summary(lines)).toEqual([ + `web-shell-page Web shell: page painted | source=cache build=${BUILD} activatedMs=1234` + ]) + }) + + it('adds only the download milestones to a downloading open, and no progress ticks', () => { + const { lines } = replay([...DOWNLOAD_OPEN, ...PAGE_LOAD, { type: 'page-painted' }]) + expect(summary(lines)).toEqual([ + `web-shell-flow Web shell: downloading app | ${MANIFEST.totalAssets} assets, ${MANIFEST.totalBytes} bytes`, + 'web-shell-flow Web shell: activating app | source=download', + `web-shell-page Web shell: page painted | source=download build=${BUILD} activatedMs=1234` + ]) + // The generation directory names a device path and never reaches the log. + expect(JSON.stringify(lines)).not.toContain('/Users/someone') + }) + + it('logs nothing for a route that stays native, the normal case for native screens', () => { + const { session, lines } = replay([ + { type: 'gates-changed', gates: gates({ hostCapabilities: [] }) } + ]) + expect(session.state.kind).toBe('native-route') + expect(lines).toEqual([]) + }) + + it('logs a missed ready deadline, the failure it causes and the recovery flow', () => { + const opened = replay(DOWNLOAD_OPEN) + const { lines } = replay([{ type: 'document-loaded' }, { type: 'page-ready-deadline' }], opened) + expect(summary(lines)).toEqual([ + 'web-shell-page Web shell: page never said ready before the deadline', + 'web-shell-flow Web shell: checking host' + ]) + }) + + it('logs a view failure but not the remount it earns', () => { + const opened = replay(DOWNLOAD_OPEN) + const { lines } = replay( + [ + { type: 'shell-failed', reason: 'render-process-gone' }, + { type: 'remounted', sessionId: 'session-two' } + ], + opened + ) + expect(summary(lines)).toEqual([ + 'web-shell-page Web shell: page load failed | reason=render-process-gone' + ]) + }) + + it('ignores results from a superseded flow', () => { + const opened = replay(DOWNLOAD_OPEN) + const { lines } = replay( + [ + { type: 'page-ready-deadline', flow: opened.session.flow - 1 }, + { ...ACTIVATED, flow: 0 } + ], + opened + ) + expect(lines).toEqual([]) + }) + + it('logs a failed download with its closed reason code', () => { + const { lines } = replay([ + { type: 'gates-changed', gates: gates() }, + { type: 'cache-read', generation: null }, + { type: 'download-failed', cause: { reason: 'connection-lost', hostCode: null } } + ]) + expect(summary(lines)).toEqual([ + 'web-shell-flow Web shell: app download failed | reason=connection-lost', + 'web-shell-flow Web shell: failed | reason=download-failed retried=no' + ]) + }) +}) + +describe('shell stall lines', () => { + it('names what a checking session waits on: the gates, then the cache', () => { + const fresh = replay([]) + expect(stall(fresh)).toMatchObject({ + code: 'web-shell-stalled', + message: 'Web shell: still checking host after 15s', + detail: 'gates=none cache=unread' + }) + expect( + stall(replay([{ type: 'gates-changed', gates: gates({ reachability: 'connecting' }) }])) + ).toMatchObject({ detail: 'gates=dialling cache=unread' }) + const opened = replay([{ type: 'gates-changed', gates: gates() }]) + expect(opened.session.state.kind).toBe('checking') + expect(stall(opened)).toMatchObject({ detail: 'gates=open cache=unread' }) + // An empty cache leaves `cached` null, so only the trace can tell the manifest wait apart. + const awaitingManifest = replay([{ type: 'cache-read', generation: null }], opened) + expect(stall(awaitingManifest)).toMatchObject({ detail: 'gates=open cache=read' }) + }) + + it('names how far a stalled download got', () => { + const fetching = replay(DOWNLOAD_OPEN.slice(0, 4)) + expect(stall(fetching)).toMatchObject({ + message: 'Web shell: download made no progress for 15s', + detail: `assets=1/${MANIFEST.totalAssets} bytes=10/${MANIFEST.totalBytes}` + }) + }) + + it('names an activation that never finished', () => { + expect(stall(replay(DOWNLOAD_OPEN.slice(0, 6)))).toMatchObject({ + message: 'Web shell: still activating after 15s', + detail: 'source=download' + }) + }) + + it('tells a page that keeps refusing init from one that took it and never drew', () => { + const opened = replay(DOWNLOAD_OPEN) + expect(stall(opened)).toMatchObject({ + message: 'Web shell: page has not drawn after 15s', + detail: `build=${BUILD} page ready=no readyAsks=0 documentLoaded=no` + }) + const refusing = replay([...PAGE_LOAD, { type: 'page-ready' }, { type: 'page-ready' }], opened) + expect(stall(refusing)).toMatchObject({ + detail: `build=${BUILD} page ready=yes readyAsks=3 documentLoaded=yes` + }) + // A replacement document starts its own count. + const reloaded = replay([{ type: 'document-started' }, { type: 'page-ready' }], refusing) + expect(stall(reloaded)).toMatchObject({ + detail: `build=${BUILD} page ready=yes readyAsks=1 documentLoaded=no` + }) + expect(stall(replay([{ type: 'page-painted' }], reloaded))).toBeNull() + }) + + it('stays quiet for states nobody waits in', () => { + expect( + stall(replay([{ type: 'gates-changed', gates: gates({ hostCapabilities: [] }) }])) + ).toBeNull() + }) +}) + +describe('shell failure details', () => { + it('keeps device paths out of a page fault', () => { + expect( + pageFaultLine({ + category: 'TypeError', + message: 'x is undefined at file:///var/mobile/app/index.js:1\n at /Users/me/secret.js', + isRpcDeliveryUnknown: false + }).detail + ).toBe('TypeError: x is undefined at [path]') + }) +}) + +describe('recording shell lines', () => { + it('writes a flapping host line once until a different shell line is written', () => { + const host = 'flapping-host' + const checking = replay([ + { type: 'gates-changed', gates: gates({ reachability: 'unreachable' }) }, + { type: 'cache-read', generation: null }, + { type: 'gates-changed', gates: gates({ reachability: 'connecting' }) } + ]).lines + expect(summary(checking)).toEqual([ + 'web-shell-flow Web shell: host unreachable and no app cached', + 'web-shell-flow Web shell: checking host' + ]) + for (let cycle = 0; cycle < 3; cycle += 1) { + for (const line of checking) { + recordShellLifecycleLine(host, line) + } + } + const messages = () => connectionLogStore.get(host).map((entry) => entry.message) + expect(messages()).toEqual([ + 'Web shell: host unreachable and no app cached', + 'Web shell: checking host' + ]) + recordShellLifecycleLine(host, frameWithoutHostLine({ clientReady: true, snapshotReady: true })) + recordShellLifecycleLine(host, checking[1]!) + recordShellLifecycleLine('other-host', checking[1]!) + expect(messages().slice(2)).toEqual([ + 'Web shell: page frame with no bridge host', + 'Web shell: checking host' + ]) + expect(connectionLogStore.get('other-host')).toHaveLength(1) + }) +}) + +describe('shell lifecycle lines in the exported report', () => { + function entries(lines: readonly ShellLifecycleLine[]): ConnectionLogEntry[] { + return lines.map((line, index) => ({ id: `e${index}`, ts: 1_000 + index * 1_000, ...line })) + } + + it('shows where a connected session stalled without changing the connection verdict', () => { + const opened = replay(DOWNLOAD_OPEN) + const page = replay(PAGE_LOAD, opened) + const report = buildConnectionDiagnosticsReport({ + hostName: 'Desk', + endpoint: 'ws://192.168.1.2:6768', + state: 'connected', + reconnectAttempts: 0, + lastConnectedAt: 500, + platform: 'ios', + appVersion: '0.0.56', + entries: entries([...opened.lines, ...page.lines, ...present(stall(page))]), + shell: { kind: 'ota', bridgeProtocolVersion: 1 }, + nowMs: 60_000 + }) + expect(report).toContain('Shell: ota · bridge protocol 1') + expect(report).toContain('Likely cause: Connection is healthy.') + expect(report).toContain('[web-shell-flow] Web shell: activating app') + expect(report).toContain( + `[warn] [web-shell-stalled] Web shell: page has not drawn after 15s — build=${BUILD} page ready=yes readyAsks=1 documentLoaded=yes` + ) + }) + + it('never reads shell lines as a connection failure', () => { + const failed = replay([ + { type: 'gates-changed', gates: gates() }, + { type: 'cache-read', generation: null }, + { type: 'download-failed', cause: { reason: 'connection-lost', hostCode: null } } + ]) + const report = buildConnectionDiagnosticsReport({ + hostName: 'Desk', + endpoint: 'ws://192.168.1.2:6768', + state: 'disconnected', + reconnectAttempts: 1, + lastConnectedAt: null, + platform: 'ios', + appVersion: '0.0.56', + entries: entries([ + ...failed.lines, + ...present(stall(replay(DOWNLOAD_OPEN.slice(0, 6)))), + ...present(stall(replay([]))), + ...present(bridgeDiagnosticLine({ kind: 'refused', refusal: 'oversized' })), + frameWithoutHostLine({ clientReady: false, snapshotReady: false }) + ]), + nowMs: 60_000 + }) + expect(report).toContain( + 'Likely cause: No single failure cause can be determined from the recorded events.' + ) + }) + + it('leaves an earlier connection failure as the likely cause', () => { + const timeout: ConnectionLogEntry = { + id: 'timeout', + ts: 500, + level: 'error', + code: 'connect-timeout', + message: 'WebSocket connect timeout' + } + const report = buildConnectionDiagnosticsReport({ + hostName: 'Desk', + endpoint: 'ws://192.168.1.2:6768', + state: 'disconnected', + reconnectAttempts: 1, + lastConnectedAt: null, + platform: 'ios', + appVersion: '0.0.56', + entries: [timeout, ...entries(replay(DOWNLOAD_OPEN).lines)], + nowMs: 60_000 + }) + expect(report).toContain( + 'Likely cause: The saved direct endpoint did not answer before the connection timeout.' + ) + }) +}) diff --git a/mobile/src/mobile-web-shell/shell-lifecycle-log.ts b/mobile/src/mobile-web-shell/shell-lifecycle-log.ts new file mode 100644 index 00000000000..0ee08fdd508 --- /dev/null +++ b/mobile/src/mobile-web-shell/shell-lifecycle-log.ts @@ -0,0 +1,272 @@ +import type { BridgeErrorCapture } from './bridge/bridge-error-capture' +import { gateVerdict } from './mobile-web-shell-gates' +import type { + MobileWebShellSession, + MobileWebShellSessionEvent, + MobileWebShellSessionState +} from './mobile-web-shell-session-contract' +import type { ShellLifecycleLine } from './shell-lifecycle-line-recorder' +import { maskUserText } from './shell-log-path-masking' + +/** Session-side shell log lines: reducer steps, one-shot stalls and page-reported failures. */ + +const BUILD_ID_PREFIX_LENGTH = 8 + +/** + * How long a parked waiting state lasts before the log says so. Armed per state object, so for + * `ready` it starts at activation and outlasts the 10 s ready deadline, which starts at document load. + */ +export const SHELL_STALL_LOG_MS = 15_000 + +/** What the reducer does not keep but a log line needs; tracked beside the session, log-only. */ +export type ShellLogTrace = { + /** The flow whose cache read answered, so a stall can say whether it waits on the cache. */ + readonly cacheReadFlow: number | null + readonly openedFrom: 'download' | 'cache' | null + /** The page's `ready` asks for this document: more than one means it keeps refusing `init`. */ + readonly readyAsks: number + readonly documentLoaded: boolean +} + +export const EMPTY_SHELL_LOG_TRACE: ShellLogTrace = { + cacheReadFlow: null, + openedFrom: null, + readyAsks: 0, + documentLoaded: false +} + +export function traceShellStep( + trace: ShellLogTrace, + before: MobileWebShellSession, + event: MobileWebShellSessionEvent, + after: MobileWebShellSession +): ShellLogTrace { + if ('flow' in event && event.flow !== before.flow) { + return trace + } + switch (event.type) { + case 'cache-read': + return { ...trace, cacheReadFlow: event.flow } + case 'activated': + return { + ...trace, + readyAsks: 0, + documentLoaded: false, + openedFrom: before.state.kind === 'activating' ? before.state.source : null + } + case 'remounted': + case 'document-started': + return { ...trace, readyAsks: 0, documentLoaded: false } + case 'document-loaded': + return after.state.kind === 'ready' ? { ...trace, documentLoaded: true } : trace + case 'page-ready': + return after.state.kind === 'ready' ? { ...trace, readyAsks: trace.readyAsks + 1 } : trace + case 'gates-changed': + case 'manifest-read': + case 'fetch-progress': + case 'download-staged': + case 'download-failed': + case 'shell-failed': + case 'retry-pressed': + case 'page-painted': + case 'page-back-claim': + case 'page-ready-deadline': + case 'layout-changed': + return trace + } +} + +/** What one reducer step is worth logging; empty for most steps. `trace` is the post-step one. */ +export function shellSessionStepLines( + before: MobileWebShellSession, + event: MobileWebShellSessionEvent, + after: MobileWebShellSession, + trace: ShellLogTrace +): ShellLifecycleLine[] { + // A superseded flow's result changed nothing and says nothing about this one. + if ('flow' in event && event.flow !== before.flow) { + return [] + } + const lines = [...eventLines(before, event, trace)] + const transition = transitionLine(before.state, after.state) + if (transition !== null) { + lines.push(transition) + } + return lines +} + +/** The one-shot warning for a session parked in a waiting state, or null when not parked. */ +export function shellStallLine( + state: MobileWebShellSessionState, + session: Pick, + trace: ShellLogTrace +): ShellLifecycleLine | null { + const seconds = `${SHELL_STALL_LOG_MS / 1000}s` + switch (state.kind) { + case 'checking': { + const gates = session.gates === null ? 'none' : gateVerdict(session.gates).kind + const cache = trace.cacheReadFlow === session.flow ? 'read' : 'unread' + return stallLine( + `Web shell: still checking host after ${seconds}`, + `gates=${gates} cache=${cache}` + ) + } + case 'fetching': + // Each progress tick is a new state and re-arms the timer, so this means no progress. + return stallLine( + `Web shell: download made no progress for ${seconds}`, + `assets=${state.completedAssets}/${state.totalAssets} bytes=${state.receivedBytes}/${state.totalBytes}` + ) + case 'activating': + return stallLine(`Web shell: still activating after ${seconds}`, `source=${state.source}`) + case 'ready': + return session.pagePainted + ? null + : stallLine( + `Web shell: page has not drawn after ${seconds}`, + `build=${buildPrefix(state.buildId)} page ready=${yesNo(session.pageReady)} readyAsks=${trace.readyAsks} documentLoaded=${yesNo(trace.documentLoaded)}` + ) + case 'native-route': + case 'wall': + case 'failed': + case 'offline': + return null + } +} + +export function pageFaultLine(error: BridgeErrorCapture): ShellLifecycleLine { + const firstLine = error.message.split(/\r?\n/, 1)[0] ?? '' + return pageLine( + 'warn', + 'Web shell: page faulted', + `${error.category}: ${maskUserText(firstLine)}` + ) +} + +/** The profile read behind `init` rejected, so no bridge host can be built for this screen. */ +export function hostProfileUnreadableLine(): ShellLifecycleLine { + return pageLine('warn', 'Web shell: host profile unreadable') +} + +function eventLines( + before: MobileWebShellSession, + event: MobileWebShellSessionEvent, + trace: ShellLogTrace +): ShellLifecycleLine[] { + if (event.type === 'download-failed') { + const code = event.cause.hostCode === null ? '' : ` code=${event.cause.hostCode}` + return [ + flowLine('warn', 'Web shell: app download failed', `reason=${event.cause.reason}${code}`) + ] + } + // Every page signal below is only accepted while a generation is on screen. + if (before.state.kind !== 'ready') { + return [] + } + switch (event.type) { + case 'shell-failed': + return [pageLine('warn', 'Web shell: page load failed', `reason=${event.reason}`)] + case 'page-painted': + // The one line a healthy open writes; `activatedMs` is flow start to activation, not to paint. + return before.pagePainted + ? [] + : [ + pageLine( + 'success', + 'Web shell: page painted', + `source=${trace.openedFrom ?? 'unknown'} build=${buildPrefix(before.state.buildId)} activatedMs=${before.state.elapsedMs}` + ) + ] + case 'page-ready-deadline': + return before.pageReady + ? [] + : [pageLine('warn', 'Web shell: page never said ready before the deadline')] + case 'document-started': + case 'document-loaded': + case 'page-ready': + case 'gates-changed': + case 'cache-read': + case 'manifest-read': + case 'fetch-progress': + case 'download-staged': + case 'activated': + case 'remounted': + case 'page-back-claim': + case 'layout-changed': + case 'retry-pressed': + // Healthy-path signals; the paint line or a stall line's detail stands in for them. + return [] + } +} + +function transitionLine( + before: MobileWebShellSessionState, + after: MobileWebShellSessionState +): ShellLifecycleLine | null { + if (before.kind === after.kind) { + return null + } + switch (after.kind) { + case 'checking': + return flowLine('info', 'Web shell: checking host') + case 'offline': + return flowLine('warn', 'Web shell: host unreachable and no app cached') + case 'fetching': + return flowLine( + 'info', + 'Web shell: downloading app', + `${after.totalAssets} assets, ${after.totalBytes} bytes` + ) + case 'activating': + // A cache activation is immediate and shows up as the paint line's source. + return after.source === 'download' + ? flowLine('info', 'Web shell: activating app', 'source=download') + : null + case 'ready': + case 'native-route': + // `ready` is logged at paint; native is every native screen's normal outcome. + return null + case 'wall': { + const side = 'side' in after.verdict ? ` side=${after.verdict.side}` : '' + return flowLine( + 'warn', + 'Web shell: blocked by version check', + `reason=${after.verdict.reason}${side}` + ) + } + case 'failed': + return flowLine( + 'error', + 'Web shell: failed', + `reason=${after.reason} retried=${after.retriedOnce ? 'yes' : 'no'}` + ) + } +} + +function buildPrefix(buildId: string): string { + return buildId.slice(0, BUILD_ID_PREFIX_LENGTH) +} + +function yesNo(value: boolean): string { + return value ? 'yes' : 'no' +} + +function flowLine( + level: ShellLifecycleLine['level'], + message: string, + detail?: string +): ShellLifecycleLine { + return { level, code: 'web-shell-flow', message, ...(detail === undefined ? {} : { detail }) } +} + +function pageLine( + level: ShellLifecycleLine['level'], + message: string, + detail?: string +): ShellLifecycleLine { + return { level, code: 'web-shell-page', message, ...(detail === undefined ? {} : { detail }) } +} + +function stallLine(message: string, detail: string): ShellLifecycleLine { + return { level: 'warn', code: 'web-shell-stalled', message, detail } +} diff --git a/mobile/src/mobile-web-shell/shell-log-path-masking.test.ts b/mobile/src/mobile-web-shell/shell-log-path-masking.test.ts new file mode 100644 index 00000000000..2e1986f9880 --- /dev/null +++ b/mobile/src/mobile-web-shell/shell-log-path-masking.test.ts @@ -0,0 +1,21 @@ +import { describe, expect, it } from 'vitest' +import { maskUserText } from './shell-log-path-masking' + +describe('shell log path masking', () => { + it('masks absolute paths wherever they start, including spaced and Windows ones', () => { + expect(maskUserText("open '/var/mobile/Containers/a.db' failed")).toBe("open '[path]' failed") + expect(maskUserText('at f (/Users/me/secret.js:1)')).toBe('at f ([path])') + expect(maskUserText('bad `/Users/me/x.js` here')).toBe('bad `[path]` here') + expect(maskUserText('path="/home/bob/x" [/Users/bob/y]')).toBe('path="[path]" [[path]]') + expect(maskUserText('read C:\\Users\\bob\\x.txt and \\\\srv\\share\\y')).toBe( + 'read [path] and [path]' + ) + expect(maskUserText('key:~/notes.txt')).toBe('key:[path]') + expect(maskUserText('open C:\\Users\\John Doe\\proj\\x.ts failed')).toBe('open [path] failed') + expect(maskUserText('at /Users/Jane Q/My Proj/a.js and more')).toBe('at [path] and more') + expect(maskUserText('a,/Users/x/y')).toBe('a,[path]') + expect(maskUserText('Cannot read properties of undefined')).toBe( + 'Cannot read properties of undefined' + ) + }) +}) diff --git a/mobile/src/mobile-web-shell/shell-log-path-masking.ts b/mobile/src/mobile-web-shell/shell-log-path-masking.ts new file mode 100644 index 00000000000..4d0350757b7 --- /dev/null +++ b/mobile/src/mobile-web-shell/shell-log-path-masking.ts @@ -0,0 +1,15 @@ +const MASKED_TEXT_MAX_CHARS = 160 + +/** Absolute paths and file URLs masked, then clamped: page and schema text can quote user paths. */ +export function maskUserText(text: string): string { + const masked = text + .replace(/file:\/\/[^\s)'"`\]]+/g, '[path]') + // A following word that still holds a separator is the same path (`C:\Users\John Doe\x`). + .replace( + /(^|[\s'"`([=:,])(?:~?\/|[A-Za-z]:[\\/]|\\\\)[^\s)'"`\]]+(?: [^\s)'"`\]]*[\\/][^\s)'"`\]]*)*/g, + '$1[path]' + ) + return masked.length > MASKED_TEXT_MAX_CHARS + ? `${masked.slice(0, MASKED_TEXT_MAX_CHARS)}…` + : masked +} diff --git a/mobile/src/mobile-web-shell/use-mobile-web-shell-bridge.test.ts b/mobile/src/mobile-web-shell/use-mobile-web-shell-bridge.test.ts index 67bc07fba2c..13876aa0d53 100644 --- a/mobile/src/mobile-web-shell/use-mobile-web-shell-bridge.test.ts +++ b/mobile/src/mobile-web-shell/use-mobile-web-shell-bridge.test.ts @@ -45,6 +45,7 @@ import { useMobileWebShellBridge, type MobileWebShellBridgeView } from './use-mobile-web-shell-bridge' +import { connectionLogStore } from '../transport/persisted-connection-log-store' const ID = bridgeId(1) const DIRECTORY = '/caches/mobile-web/deadbeef/generations/a1b2' @@ -425,6 +426,24 @@ describe('the bridge channel', () => { await mounted.deliver(clientFrame({ type: 'ready' })) expect(mounted.posted).toEqual([]) }) + + it('logs a frame it dropped for want of a host once per session, naming what is missing', async () => { + doubles.client = null + const dropped = () => + connectionLogStore + .get('host-1') + .filter((entry) => entry.message === 'Web shell: page frame with no bridge host') + const before = dropped().length + const mounted = await mount(readyState('session-one')) + await mounted.deliver(clientFrame({ type: 'ready' })) + await mounted.deliver(clientFrame({ type: 'ready' })) + expect(dropped().slice(before)).toEqual([ + expect.objectContaining({ detail: 'client=null snapshot=ok' }) + ]) + await mounted.update(readyState('session-two')) + await mounted.deliver(clientFrame({ type: 'ready' })) + expect(dropped().slice(before)).toHaveLength(2) + }) }) describe('teardown', () => { diff --git a/mobile/src/mobile-web-shell/use-mobile-web-shell-bridge.ts b/mobile/src/mobile-web-shell/use-mobile-web-shell-bridge.ts index 1f20a1b81b8..0db8fd8af2b 100644 --- a/mobile/src/mobile-web-shell/use-mobile-web-shell-bridge.ts +++ b/mobile/src/mobile-web-shell/use-mobile-web-shell-bridge.ts @@ -5,6 +5,8 @@ import type { } from '../../modules/orca-mobile-web-shell/src' import { useHostClient } from '../transport/client-context' import { createBridgeDiagnosticReporter } from './bridge-diagnostic-log' +import { bridgeDiagnosticLine, frameWithoutHostLine } from './shell-bridge-log-lines' +import { recordShellLifecycleLine } from './shell-lifecycle-line-recorder' import type { BridgeInitRoute } from './bridge/bridge-envelope' import type { BridgeClearableRouteParam } from './bridge/bridge-route-update' import type { BridgeSafeAreaInsets } from './bridge/bridge-safe-area-insets' @@ -169,6 +171,10 @@ export function useMobileWebShellBridge(args: MobileWebShellBridgeArgs): MobileW // Held rather than depended on, for the reason every prop above is: the identity settles with the // client, and taking it as a dependency would tear a live page session down to re-read a string. const clientIdRef = useRef(clientId) + // Read only by the dropped-frame log line, which says which of the two a host waits on. + const clientRef = useRef(client) + // The session a dropped frame was last logged for, so a page re-asking `ready` logs once. + const droppedFrameLoggedRef = useRef(null) // Commit-phase and declared above the host's effect, so the host is built against what this // render passed: a native frame can land between a commit and a passive effect. // @@ -178,6 +184,7 @@ export function useMobileWebShellBridge(args: MobileWebShellBridgeArgs): MobileW useLayoutEffect(() => { argsRef.current = args clientIdRef.current = clientId + clientRef.current = client }) const snapshot = args.snapshot @@ -214,7 +221,12 @@ export function useMobileWebShellBridge(args: MobileWebShellBridgeArgs): MobileW ? Promise.reject(new BridgeViewGoneError()) : mounted.handle.postBridgeMessage(json) }, - onDiagnostic: createBridgeDiagnosticReporter(), + onDiagnostic: createBridgeDiagnosticReporter((diagnostic) => { + const line = bridgeDiagnosticLine(diagnostic) + if (line !== null) { + recordShellLifecycleLine(latest.hostId, line) + } + }), onNavigate: (href) => argsRef.current.onNavigate(href), onNavigateBack: () => argsRef.current.onNavigateBack(), onExternalLink: (url) => argsRef.current.onExternalLink(url), @@ -256,6 +268,20 @@ export function useMobileWebShellBridge(args: MobileWebShellBridgeArgs): MobileW (event: MobileWebShellBridgeMessageEvent) => { const mounted = hostRef.current if (mounted === null || mounted.sessionId !== sessionId) { + if ( + mounted === null && + sessionId !== null && + droppedFrameLoggedRef.current !== sessionId + ) { + droppedFrameLoggedRef.current = sessionId + recordShellLifecycleLine( + argsRef.current.hostId, + frameWithoutHostLine({ + clientReady: clientRef.current !== null, + snapshotReady: argsRef.current.snapshot !== null + }) + ) + } return } mounted.host.receive(event.nativeEvent.json) diff --git a/mobile/src/mobile-web-shell/use-mobile-web-shell-session.test.ts b/mobile/src/mobile-web-shell/use-mobile-web-shell-session.test.ts index df01ca7e70d..31502505594 100644 --- a/mobile/src/mobile-web-shell/use-mobile-web-shell-session.test.ts +++ b/mobile/src/mobile-web-shell/use-mobile-web-shell-session.test.ts @@ -67,6 +67,9 @@ const doubles = vi.hoisted((): Doubles => { }) vi.mock('expo-crypto', () => ({ getRandomBytes: (length: number) => new Uint8Array(length) })) +vi.mock('@react-native-async-storage/async-storage', () => ({ + default: { getItem: async () => null, setItem: async () => undefined } +})) vi.mock('expo-file-system', () => ({ Directory: class {}, File: class {}, Paths: { cache: '' } })) vi.mock('../transport/mobile-endpoint-supervisor-support', () => ({ encodeBase64Url: () => 'session-id' @@ -95,6 +98,8 @@ vi.mock('../transport/mobile-web-bundle-fetch', () => ({ import { BRIDGE_READY_RETRY_MAX_MS } from './bridge/bridge-client-init-handshake' import { PAGE_READY_DEADLINE_MS } from './mobile-web-shell-runtime' +import { SHELL_STALL_LOG_MS } from './shell-lifecycle-log' +import { connectionLogStore } from '../transport/persisted-connection-log-store' import { useMobileWebShellSession } from './use-mobile-web-shell-session' const HOST_ID = 'host-1' @@ -214,21 +219,28 @@ type Mounted = { handshakes: () => readonly boolean[] documentLoaded: () => void pageReady: () => void + pagePainted: () => void timers: ReturnType } +function live(timers: readonly ArmedTimer[]): ArmedTimer[] { + return timers.filter((timer) => !timer.cancelled) +} + async function mount(store: GenerationStore): Promise { const timers = createTimerSeam() const handle: { retry: () => void documentLoaded: () => void pageReady: () => void + pagePainted: () => void states: MobileWebShellSessionState[] handshakes: boolean[] } = { retry: () => {}, documentLoaded: () => {}, pageReady: () => {}, + pagePainted: () => {}, states: [], handshakes: [] } @@ -246,6 +258,7 @@ async function mount(store: GenerationStore): Promise { handle.retry = session.retry handle.documentLoaded = session.reportDocumentLoaded handle.pageReady = session.reportPageReady + handle.pagePainted = session.reportPagePainted handle.states.push(session.state) handle.handshakes.push(session.pageReady) return null @@ -266,6 +279,7 @@ async function mount(store: GenerationStore): Promise { handshakes: () => handle.handshakes, documentLoaded: () => handle.documentLoaded(), pageReady: () => handle.pageReady(), + pagePainted: () => handle.pagePainted(), timers } } @@ -471,7 +485,11 @@ describe('the wait for the page to speak', () => { await act(async () => { mounted.documentLoaded() }) - expect(mounted.timers.armed.map((timer) => timer.delayMs)).toEqual([PAGE_READY_DEADLINE_MS]) + // The other live timer is the log-only stall warning; the checking one was cancelled. + expect(live(mounted.timers.armed).map((timer) => timer.delayMs)).toEqual([ + SHELL_STALL_LOG_MS, + PAGE_READY_DEADLINE_MS + ]) await act(async () => { mounted.timers.fire() }) @@ -523,7 +541,9 @@ describe('the wait for the page to speak', () => { }) // The race is real on a device: the page's first frame crosses the bridge while the WebView's // own load callback is still in the native queue. - expect(mounted.timers.armed).toHaveLength(0) + expect( + mounted.timers.armed.filter((timer) => timer.delayMs === PAGE_READY_DEADLINE_MS) + ).toEqual([]) await act(async () => { mounted.tree.unmount() }) @@ -579,6 +599,74 @@ describe('the wait for the page to speak', () => { }) }) + it('logs one stall warning for a page that never draws, without moving the session', async () => { + const logged = () => connectionLogStore.get(HOST_ID) + const before = logged().length + const mounted = await ready() + await act(async () => { + mounted.documentLoaded() + mounted.pageReady() + }) + const stallTimers = live(mounted.timers.armed).filter( + (timer) => timer.delayMs === SHELL_STALL_LOG_MS + ) + // A page signal that leaves the cover up re-arms nothing. + expect(stallTimers).toHaveLength(1) + await act(async () => { + stallTimers[0]?.run() + }) + expect(mounted.states().at(-1)?.kind).toBe('ready') + expect(logged().slice(before)).toEqual([ + expect.objectContaining({ + message: 'Web shell: page has not drawn after 15s', + detail: expect.stringContaining('page ready=yes readyAsks=1 documentLoaded=yes') + }) + ]) + }) + + it('writes one line for a healthy open, on paint', async () => { + const before = connectionLogStore.get(HOST_ID).length + const mounted = await ready() + await act(async () => { + mounted.documentLoaded() + mounted.pageReady() + mounted.pagePainted() + }) + expect( + connectionLogStore + .get(HOST_ID) + .slice(before) + .map((entry) => `${entry.message} | ${entry.detail}`) + ).toEqual([expect.stringMatching(/^Web shell: page painted \| source=cache build=\S{1,8} /)]) + expect(live(mounted.timers.armed).filter((t) => t.delayMs === SHELL_STALL_LOG_MS)).toEqual([]) + await act(async () => { + mounted.tree.unmount() + }) + }) + + it("logs a stall for the first open's checking state, which no transition line covers", async () => { + const before = connectionLogStore.get(HOST_ID).length + const fake = createFakeStore() + const mounted = await mount(fake.store) + expect(mounted.states().at(-1)?.kind).toBe('checking') + const stallTimers = live(mounted.timers.armed).filter( + (timer) => timer.delayMs === SHELL_STALL_LOG_MS + ) + expect(stallTimers).toHaveLength(1) + await act(async () => { + stallTimers[0]?.run() + }) + expect(connectionLogStore.get(HOST_ID).slice(before)).toEqual([ + expect.objectContaining({ + message: 'Web shell: still checking host after 15s', + detail: 'gates=open cache=unread' + }) + ]) + await act(async () => { + mounted.tree.unmount() + }) + }) + it('cancels the armed deadline when the session it belongs to is torn down', async () => { const mounted = await ready() await act(async () => { diff --git a/mobile/src/mobile-web-shell/use-mobile-web-shell-session.ts b/mobile/src/mobile-web-shell/use-mobile-web-shell-session.ts index dca736d415c..0d917fdd564 100644 --- a/mobile/src/mobile-web-shell/use-mobile-web-shell-session.ts +++ b/mobile/src/mobile-web-shell/use-mobile-web-shell-session.ts @@ -12,6 +12,14 @@ import { } from './mobile-web-shell-runtime' import { readMobileWebShellReachability } from './mobile-web-shell-reachability' import { shellPageBackClaimed } from './shell-page-back-claim' +import { recordShellLifecycleLine } from './shell-lifecycle-line-recorder' +import { + EMPTY_SHELL_LOG_TRACE, + SHELL_STALL_LOG_MS, + shellSessionStepLines, + shellStallLine, + traceShellStep +} from './shell-lifecycle-log' import { shellPageFrame, type ShellPageFrame } from './shell-page-frame' import { createMobileWebShellSession, @@ -102,6 +110,9 @@ export function useMobileWebShellSession(args: { // Cancelled on the same bump, for the same reason: an armed deadline belongs to the generation it // was armed under, and the epoch check alone would leave a real timer alive until it fired. const timersRef = useRef void>>(new Set()) + // The log's host for `dispatch`, which is stable; moved with the session rebuild below. + const hostIdRef = useRef(hostId) + const logTraceRef = useRef(EMPTY_SHELL_LOG_TRACE) const runEffectRef = useRef< ((epoch: number, flow: number, effect: MobileWebShellSessionEffect) => void) | null >(null) @@ -111,6 +122,11 @@ export function useMobileWebShellSession(args: { return } const stepped = reduceMobileWebShellSession(sessionRef.current, event) + const trace = traceShellStep(logTraceRef.current, sessionRef.current, event, stepped.session) + logTraceRef.current = trace + for (const line of shellSessionStepLines(sessionRef.current, event, stepped.session, trace)) { + recordShellLifecycleLine(hostIdRef.current, line) + } sessionRef.current = stepped.session setState(stepped.session.state) setPageReady(stepped.session.pageReady) @@ -218,6 +234,8 @@ export function useMobileWebShellSession(args: { useEffect(() => { // A new host is a new session: the old one's latches, cache handle and in-flight work all go. invalidate() + hostIdRef.current = hostId + logTraceRef.current = EMPTY_SHELL_LOG_TRACE sessionRef.current = createMobileWebShellSession(routePathname, wide) startedAtRef.current = runtime.now() setState(sessionRef.current.state) @@ -226,6 +244,20 @@ export function useMobileWebShellSession(args: { return invalidate }, [hostId, invalidate, routePathname, runtime]) + // Log-only: one warning per parked state object, cancelled by any state, paint, host or route change. + // `CHECKING` is one shared object, so checking-to-checking steps keep the first open's timer. + useEffect(() => { + if (shellStallLine(state, sessionRef.current, logTraceRef.current) === null) { + return + } + return runtime.setTimer(() => { + const line = shellStallLine(state, sessionRef.current, logTraceRef.current) + if (line !== null) { + recordShellLifecycleLine(hostIdRef.current, line) + } + }, SHELL_STALL_LOG_MS) + }, [hostId, pageFrame, routePathname, runtime, state]) + useEffect(() => { dispatch(epochRef.current, { type: 'layout-changed', wide }) }, [dispatch, wide]) diff --git a/mobile/src/transport/types.ts b/mobile/src/transport/types.ts index d9c9271c79d..4d83a5cb762 100644 --- a/mobile/src/transport/types.ts +++ b/mobile/src/transport/types.ts @@ -64,6 +64,11 @@ export type ConnectionDiagnosticCode = | 'direct-connected' | 'relay-credential-unavailable' | 'host-open-failed' + // OTA web shell lifecycle; diagnostics only, never read as connection failures. + | 'web-shell-flow' + | 'web-shell-page' + | 'web-shell-stalled' + | 'web-shell-bridge' export type ConnectionLogEntry = { id: string