From 27c0275e3ab90859678b40468dbaf351f601057f Mon Sep 17 00:00:00 2001 From: Jinwoo Hong <73622457+Jinwoo-H@users.noreply.github.com> Date: Wed, 14 Oct 2026 17:42:22 -0400 Subject: [PATCH] feat(mobile): log OTA shell lifecycle to the connection diagnostics (#28840) * feat(mobile): log OTA shell lifecycle to the connection diagnostics Exported connection logs showed nothing about the web shell, so a phone stuck on "Opening workspace" could not say whether it stalled activating the download, loading the page, or waiting for its first paint. Record sparse shell milestones, page signals, one-shot 15s stall warnings and bridge diagnostics into the per-host connection log. Diagnostics only. Refs STA-10545, #28626 * fix(mobile): cut shell log volume and pinpoint each waiting screen Every page route mounts its own shell, so four lines per healthy open evicted connection history from the 200-entry log. A healthy open now writes one line, on paint, carrying source, build and elapsed. The 15s stall line now also covers "Checking host" (gate verdict and whether the cache read answered) and a download with no progress. The "page has not drawn" line counts the page's ready asks and whether the document loaded, telling a page that keeps refusing init from one that took it and died. Frames dropped with no bridge host, an unreadable host profile, post-failed error names and route-refused issues are now logged; path masking catches quoted, bracketed and Windows paths. The exported report header names the shell build and bridge protocol. Diagnostics only: no behaviour, UI or wire change. Refs STA-10545 * fix(mobile): dedupe flapping shell lines and mask spaced paths A host with no cache flapping between unreachable and dialling wrote "checking host" and "host unreachable" every cycle per mounted shell; each is now written once per host until a different shell line lands. Path masking keeps going across a space while the next word still holds a separator, and accepts a comma before the path. The paint line's elapsed time is renamed activatedMs, which is what it measures. A route-only session rebuild re-arms the stall timer. Refs STA-10545 * refactor(mobile): split the shell log module by responsibility shell-lifecycle-log.ts passed the 300-line lint cap. The line type, recorder and flapping dedupe move to shell-lifecycle-line-recorder.ts, bridge diagnostic lines to shell-bridge-log-lines.ts, and user-path masking to shell-log-path-masking.ts, with tests split to match. No behaviour change. Refs STA-10545 --- .../connection-diagnostics-report.test.ts | 23 ++ .../connection-diagnostics-report.ts | 5 + .../native-diagnostics-operations.ts | 5 +- .../MobileWebShellScreen.test.tsx | 5 + .../mobile-web-shell/MobileWebShellScreen.tsx | 10 + .../bridge-diagnostic-log.test.ts | 10 + .../mobile-web-shell/bridge-diagnostic-log.ts | 6 +- .../shell-bridge-log-lines.test.ts | 45 ++ .../shell-bridge-log-lines.ts | 61 +++ .../shell-lifecycle-line-recorder.ts | 39 ++ .../shell-lifecycle-log.test.ts | 383 ++++++++++++++++++ .../mobile-web-shell/shell-lifecycle-log.ts | 272 +++++++++++++ .../shell-log-path-masking.test.ts | 21 + .../shell-log-path-masking.ts | 15 + .../use-mobile-web-shell-bridge.test.ts | 19 + .../use-mobile-web-shell-bridge.ts | 28 +- .../use-mobile-web-shell-session.test.ts | 92 ++++- .../use-mobile-web-shell-session.ts | 32 ++ mobile/src/transport/types.ts | 5 + 19 files changed, 1071 insertions(+), 5 deletions(-) create mode 100644 mobile/src/mobile-web-shell/shell-bridge-log-lines.test.ts create mode 100644 mobile/src/mobile-web-shell/shell-bridge-log-lines.ts create mode 100644 mobile/src/mobile-web-shell/shell-lifecycle-line-recorder.ts create mode 100644 mobile/src/mobile-web-shell/shell-lifecycle-log.test.ts create mode 100644 mobile/src/mobile-web-shell/shell-lifecycle-log.ts create mode 100644 mobile/src/mobile-web-shell/shell-log-path-masking.test.ts create mode 100644 mobile/src/mobile-web-shell/shell-log-path-masking.ts 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