diff --git a/apps/fxblox-web/src/app/DebugBanner.tsx b/apps/fxblox-web/src/app/DebugBanner.tsx index a861365..d7b18be 100644 --- a/apps/fxblox-web/src/app/DebugBanner.tsx +++ b/apps/fxblox-web/src/app/DebugBanner.tsx @@ -1,7 +1,13 @@ // Port of the debug-mode banner in apps/box/src/app/App.tsx (Share.share → navigator.share / clipboard). +// +// Tapping it shares the debug id AND the diagnostics ring buffer (`clientLogger`), so a report about the +// wallet hand-off — where every second is counted from the tab coming back to the front — arrives with the +// timestamped lines that say where the seconds went, instead of a description of what the screen looked like. import { useToast, useShare } from '@functionland/fx-ui'; import { useTranslation } from 'react-i18next'; import { isDebugModeActive, useSettingsStore } from '@/stores/useSettingsStore'; +import { formatLogLines } from '@/utils/clientLogger'; +import { env } from '@/config/env'; export function DebugBanner() { const { t } = useTranslation(); @@ -12,7 +18,9 @@ export function DebugBanner() { if (!debugMode || !isDebugModeActive(debugMode)) return null; const onShare = async () => { - const result = await share({ title: t('shell.debug.share'), text: debugMode.uniqueId }); + const log = formatLogLines(); + const text = [`debug id: ${debugMode.uniqueId}`, `build: ${env.APP_VERSION} #${env.GIT_SHA}`, '', log || '(no log lines yet)'].join('\n'); + const result = await share({ title: t('shell.debug.share'), text }); if (result === 'copied') queueToast({ type: 'success', title: t('shell.debug.copied') }); else if (result === 'failed') queueToast({ type: 'error', title: t('shell.debug.shareFailed') }); diff --git a/apps/fxblox-web/src/components/setup/WalletSigner.tsx b/apps/fxblox-web/src/components/setup/WalletSigner.tsx index b3a0001..7e95c0e 100644 --- a/apps/fxblox-web/src/components/setup/WalletSigner.tsx +++ b/apps/fxblox-web/src/components/setup/WalletSigner.tsx @@ -44,6 +44,7 @@ import { useTranslation } from 'react-i18next'; import { FxBox, FxButton, FxSpinner, FxText } from '@functionland/fx-ui'; import { useColorMode } from '@/stores/useSettingsStore'; import { getAppKit, setAppKitTheme } from '@/wallet/appkit'; +import { diag } from '@/wallet/diag'; import { signChainCode } from '@/wallet/signChainCode'; import { connectedWalletLink } from '@/wallet/walletLink'; import { @@ -94,6 +95,21 @@ export const WALLET_STUCK_MS = 12000; */ export const REDIRECT_GRACE_MS = 5000; +/** Chrome's transient-activation flag at the moment of an app-switch — whether a navigation would be allowed. */ +function userActivation(): string { + const ua = (navigator as Navigator & { userActivation?: { isActive: boolean } }).userActivation; + return ua ? String(ua.isActive) : 'n/a'; +} + +/** The wallet AppKit stored as the deep-link target — native scheme or universal link, which changes the hop. */ +function readDeepLinkChoice(): string { + try { + return localStorage.getItem('WALLETCONNECT_DEEPLINK_CHOICE') ?? 'none'; + } catch { + return 'unreadable'; + } +} + export interface WalletSignerProps { password: string; disabled: boolean; @@ -163,6 +179,14 @@ export default function WalletSigner({ }, []); useRelayWake(wallet.provider ?? universalProvider); + // Every state flip AppKit reports, timestamped against the last return to this tab: the raw material for + // finding where the seconds go between "I approved in the wallet" and "the page noticed". + useEffect(() => { + diag( + `[wallet] connected=${wallet.connected} connecting=${wallet.connecting} account=${wallet.account ? 'yes' : 'no'} provider=${wallet.provider ? 'yes' : 'no'} relay=${String(isRelayConnected(wallet.provider ?? universalProvider))}`, + ); + }, [wallet.connected, wallet.connecting, wallet.account, wallet.provider, universalProvider]); + // The parent swaps the password field for a spinner while we are busy. `readyToSign` is NOT busy — the user // has to see the button to press it — so it deliberately does not count. useEffect(() => { @@ -200,7 +224,7 @@ export default function WalletSigner({ const onVisibilityChange = () => { if (document.visibilityState !== 'visible') return; if (!wentToWalletRef.current) return; - console.log('[sign] back on this page with the request still out — the wallet showed nothing'); + diag('[sign] back on this page with the request still out — the wallet showed nothing'); setWalletShowedNothing(true); }; document.addEventListener('visibilitychange', onVisibilityChange); @@ -215,7 +239,7 @@ export default function WalletSigner({ if (!awaitingConnectionRef.current) return; if (!wallet.connected || !wallet.account || !wallet.provider) return; awaitingConnectionRef.current = false; - console.log('Wallet connected after modal — waiting for the sign tap'); + diag('[wallet] session connected after the chooser — waiting for the sign tap'); setPhase('readyToSign'); }, [wallet.connected, wallet.account, wallet.provider]); @@ -237,7 +261,7 @@ export default function WalletSigner({ const { wallet: w, password: pwd } = latest.current; // Not connected yet: open the chooser and stop. The signature needs its own tap (file header). if (!w.connected || !w.account) { - console.log('Wallet not connected, opening AppKit modal...'); + diag('[wallet] not connected — opening the chooser'); awaitingConnectionRef.current = true; setPhase('connecting'); try { @@ -256,6 +280,10 @@ export default function WalletSigner({ cancelledRef.current = false; setPhase('signing'); setRequestLink(null); + const signStartedAt = Date.now(); + diag( + `[sign] tap — relay=${String(isRelayConnected(w.provider))} deeplinkChoice=${readDeepLinkChoice()} activation=${userActivation()}`, + ); // Hold WalletConnect's own app-switch back so it cannot cut the publish off mid-flight, then hop ourselves // once the relay has acknowledged the request. Both are no-ops for an extension wallet, which never leaves // the page. See walletRedirect.ts for what goes wrong without this. @@ -264,6 +292,9 @@ export default function WalletSigner({ let settled = false; const unsubscribe = onceSessionRequestSent(w.provider, (event) => { const link = requestLinkFrom(capture, href, event); + diag( + `[sign] request on the relay after ${Date.now() - signStartedAt}ms — id=${event.id} captured=${capture.captured() ? 'yes' : 'no'} sawOpen=${capture.sawOpen()} link=${link ?? 'NONE'}`, + ); if (!link) return; setRequestLink(link); // `session_request_sent` is not a success signal — the engine emits it even when the publish REJECTED @@ -273,7 +304,7 @@ export default function WalletSigner({ // transient user activation, which is measured in seconds. setTimeout(() => { if (settled) { - console.log('[sign] not opening the wallet: the request already settled'); + diag('[sign] not opening the wallet: the request already settled'); return; } // With the socket down the request is not on the relay, whatever the publish reported — the engine @@ -281,7 +312,7 @@ export default function WalletSigner({ // its splash screen with nothing to show. Wake the socket instead and leave the user here, where the // button and the hint are. if (isRelayConnected(latest.current.wallet.provider) === false) { - console.log('[sign] not opening the wallet: relay socket is down, waking it instead'); + diag('[sign] not opening the wallet: relay socket is down, waking it instead'); wakeRelay(latest.current.wallet.provider); return; } @@ -291,22 +322,23 @@ export default function WalletSigner({ // remaining case is a navigation in a shape we did not recognise: the wallet is already in front, and // hopping again would bounce the user twice. if (capture.captured() || !capture.sawOpen()) { - console.log('[sign] opening the wallet on the request:', link); + diag(`[sign] opening the wallet on the request: ${link} activation=${userActivation()}`); wentToWalletRef.current = true; hopToWallet(link); } else { - console.log('[sign] not opening the wallet: something already navigated'); + diag('[sign] not opening the wallet: something already navigated'); } }, 0); }); try { if (!w.provider) throw new Error('Provider not available'); const signature = await signChainCode(w.provider, w.account, pwd); + diag(`[sign] signature arrived ${Date.now() - signStartedAt}ms after the tap`); if (cancelledRef.current) throw new Error('Cancelled by user'); latest.current.onSignature(signature); setPhase('idle'); } catch (err) { - console.log(err); + diag('[sign] failed:', err); setPhase('idle'); latest.current.onError(err); } finally { @@ -345,7 +377,7 @@ export default function WalletSigner({ const openWallet = useCallback(() => { const link = requestLinkRef.current ?? connectedWalletLink(latest.current.wallet.provider); if (!link) return; - console.log('[sign] opening the wallet by hand:', link); + diag(`[sign] opening the wallet by hand: ${link} activation=${userActivation()}`); wentToWalletRef.current = true; hopToWallet(link); }, []); diff --git a/apps/fxblox-web/src/i18n/locales/en/shell.json b/apps/fxblox-web/src/i18n/locales/en/shell.json index 9de5f73..06b0053 100644 --- a/apps/fxblox-web/src/i18n/locales/en/shell.json +++ b/apps/fxblox-web/src/i18n/locales/en/shell.json @@ -69,9 +69,9 @@ }, "debug": { "banner": "Debug mode is enabled {{id}}", - "share": "Share your debug Id", - "copied": "Debug id copied to the clipboard", - "shareFailed": "Could not share the debug id" + "share": "Share your debug Id and log", + "copied": "Debug id and log copied to the clipboard", + "shareFailed": "Could not share the debug id and log" }, "pwa": { "updateTitle": "New version available", diff --git a/apps/fxblox-web/src/i18n/locales/zh/shell.json b/apps/fxblox-web/src/i18n/locales/zh/shell.json index c2bd111..1be71ee 100644 --- a/apps/fxblox-web/src/i18n/locales/zh/shell.json +++ b/apps/fxblox-web/src/i18n/locales/zh/shell.json @@ -69,9 +69,9 @@ }, "debug": { "banner": "调试模式已启用 {{id}}", - "share": "分享您的调试 ID", - "copied": "调试 ID 已复制到剪贴板", - "shareFailed": "无法分享调试 ID" + "share": "分享您的调试 ID 和日志", + "copied": "调试 ID 和日志已复制到剪贴板", + "shareFailed": "无法分享调试 ID 和日志" }, "pwa": { "updateTitle": "有新版本可用", diff --git a/apps/fxblox-web/src/wallet/__tests__/relayWake.test.ts b/apps/fxblox-web/src/wallet/__tests__/relayWake.test.ts index 531194a..0dd11fc 100644 --- a/apps/fxblox-web/src/wallet/__tests__/relayWake.test.ts +++ b/apps/fxblox-web/src/wallet/__tests__/relayWake.test.ts @@ -10,6 +10,11 @@ interface RelayerState { /** Flip `connected` to true once `transportOpen` resolves, the way a healthy dial behaves. */ opensSuccessfully?: boolean; withRestart?: boolean; + /** + * Expose `onProviderDisconnect` — the relayer's own "socket closed, dial a fresh one" path. `fresh` says + * whether that fresh dial comes up (after a short delay, like the real 100 ms reconnect timer) or never. + */ + withFastDisconnect?: false | 'fresh' | 'never'; } function providerWithRelayer(state: RelayerState = {}) { @@ -19,6 +24,7 @@ function providerWithRelayer(state: RelayerState = {}) { wedged = false, opensSuccessfully = false, withRestart = true, + withFastDisconnect = false, } = state; const relayer: Record = { connected, connecting }; const transportOpen = vi.fn(() => @@ -31,9 +37,20 @@ function providerWithRelayer(state: RelayerState = {}) { const restartTransport = vi.fn(async () => { relayer.connected = true; }); + const onProviderDisconnect = vi.fn(async () => { + relayer.connected = false; + if (withFastDisconnect === 'fresh') setTimeout(() => (relayer.connected = true), 120); + }); relayer.transportOpen = transportOpen; if (withRestart) relayer.restartTransport = restartTransport; - return { transportOpen, restartTransport, relayer, provider: { client: { core: { relayer } } } }; + if (withFastDisconnect) relayer.onProviderDisconnect = onProviderDisconnect; + return { + transportOpen, + restartTransport, + onProviderDisconnect, + relayer, + provider: { client: { core: { relayer } } }, + }; } /** jsdom reports 'visible' by default; this flips it for the duration of one assertion. */ @@ -71,6 +88,35 @@ describe('wakeRelay', () => { expect(transportOpen).not.toHaveBeenCalled(); }); + it('after a background stint, prefers dropping the socket for a fresh one over a polite restart', async () => { + // `restartTransport()` asks a dead socket to close and waits up to 2 s for a handshake a suspended TCP + // connection never completes. `onProviderDisconnect()` is what the relayer runs when a socket's `close` + // fires on its own: drop it and dial a fresh one 100 ms later — the truthful treatment of a socket that + // is, in fact, gone. No two-second wait. + const { provider, restartTransport, onProviderDisconnect, relayer } = providerWithRelayer({ + connected: true, + withFastDisconnect: 'fresh', + }); + await wakeRelay(provider, { afterBackground: true }); + expect(onProviderDisconnect).toHaveBeenCalledTimes(1); + expect(restartTransport).not.toHaveBeenCalled(); + expect(relayer.connected).toBe(true); + }); + + it('falls back to the polite restart when the fresh socket does not come up within the bound', async () => { + vi.useFakeTimers(); + const { provider, restartTransport, onProviderDisconnect, relayer } = providerWithRelayer({ + connected: true, + withFastDisconnect: 'never', + }); + const done = wakeRelay(provider, { afterBackground: true }); + await vi.advanceTimersByTimeAsync(WAKE_TIMEOUT_MS + 200); + await done; + expect(onProviderDisconnect).toHaveBeenCalledTimes(1); + expect(restartTransport).toHaveBeenCalledTimes(1); + expect(relayer.connected).toBe(true); + }); + it('after a background stint, a socket that is honestly down takes the normal path', async () => { const { provider, transportOpen, restartTransport } = providerWithRelayer({ opensSuccessfully: true }); await wakeRelay(provider, { afterBackground: true }); diff --git a/apps/fxblox-web/src/wallet/diag.ts b/apps/fxblox-web/src/wallet/diag.ts new file mode 100644 index 0000000..4db428c --- /dev/null +++ b/apps/fxblox-web/src/wallet/diag.ts @@ -0,0 +1,41 @@ +/** + * Wallet / relay diagnostics that a user can actually hand back. + * + * Every theory about the "connecting for seconds after I approved" delay and the "MetaMask sits on its splash + * screen" hang has so far been argued from code reading, because the only evidence was `console.log` lines + * on a phone nobody had a debugger attached to. This routes the same lines into the `clientLogger` ring + * buffer, timestamped relative to the moment the tab came back to the front — which is the moment every one + * of those seconds is counted from — so the debug-mode banner can copy them out in one tap. + * + * Always on. The ring buffer is 500 lines in memory and costs nothing; gating this on debug mode would mean + * the one report that matters was taken with it off. + */ +import { appendLog } from '@/utils/clientLogger'; + +let returnedAt: number | null = null; + +/** The tab just came back to the front. Subsequent lines carry "+Nms since return". */ +export function markReturn(): void { + returnedAt = Date.now(); +} + +function sinceReturn(): string { + return returnedAt === null ? '' : ` (+${Date.now() - returnedAt}ms since return)`; +} + +function render(a: unknown): string { + if (typeof a === 'string') return a; + if (a instanceof Error) return `${a.name}: ${a.message}`; + try { + return JSON.stringify(a); + } catch { + return String(a); + } +} + +/** Log to the console AND the shareable ring buffer. */ +export function diag(...args: unknown[]): void { + const line = args.map(render).join(' ') + sinceReturn(); + console.log(line); + appendLog('log', line); +} diff --git a/apps/fxblox-web/src/wallet/relayWake.ts b/apps/fxblox-web/src/wallet/relayWake.ts index 077a32c..2eaebee 100644 --- a/apps/fxblox-web/src/wallet/relayWake.ts +++ b/apps/fxblox-web/src/wallet/relayWake.ts @@ -67,6 +67,7 @@ * `BACKGROUND_STINT_MS` is a flick between tabs, not a trip to a wallet, and is left alone. */ import { useEffect, useRef } from 'react'; +import { diag, markReturn } from './diag'; /** * How long to let the polite `transportOpen()` run before assuming it is awaiting a frozen attempt. @@ -100,6 +101,11 @@ interface RelayerLike { transportOpen(): Promise; /** Present since core 2.x; guarded anyway so a shape change degrades to the polite path. */ restartTransport?(): Promise; + /** + * What the relayer runs when its socket's `close` event fires: drop the socket, stop the subscriber, + * dial a FRESH socket 100 ms later. Guarded like `restartTransport`; see `wakeRelay` for why it is used. + */ + onProviderDisconnect?(): Promise; } function relayerFrom(provider: unknown): RelayerLike | null { @@ -133,22 +139,57 @@ const settleAfter = (ms: number): Promise => * has no relay). Never rejects: a relay that cannot be reached is not something the caller can act on, and the * next real request reports it properly, with the context of what the user was trying to do. */ +/** Poll `connected` until it flips or the bound expires. */ +async function untilConnected(relayer: RelayerLike, boundMs: number): Promise { + const deadline = Date.now() + boundMs; + while (!relayer.connected && Date.now() < deadline) await settleAfter(100); + return relayer.connected; +} + export async function wakeRelay(provider: unknown, opts: WakeRelayOptions = {}): Promise { const relayer = relayerFrom(provider); if (!relayer) return; + const startedAt = Date.now(); if (relayer.connected) { // `readyState === OPEN` is the socket's opinion, and after a background stint it is not worth having — - // Android suspends the connection underneath it without a word. Restart rather than wait for Chrome's - // TCP stack to find out (file header). Off the background path a live socket is left alone as before. - if (!opts.afterBackground || typeof relayer.restartTransport !== 'function') return; - console.log('[relay] back from the background — restarting a socket that claims to be open'); + // Android suspends the connection underneath it without a word. Off the background path a live socket + // is left alone as before. + if (!opts.afterBackground) return; + // Two ways to replace it. `restartTransport()` is the polite one: it asks the dead socket to close and + // waits up to 2 s for a close handshake that a suspended TCP connection will never complete — two + // seconds of the very delay this exists to remove. `onProviderDisconnect()` is what the relayer runs when + // a socket's `close` event fires on its own: drop it, stop the subscriber, dial a fresh socket 100 ms + // later. The dead socket is abandoned rather than closed, its listeners already detached by + // `createProvider()`, so its eventual close reaches nobody. That is the truthful treatment of a socket + // that is, in fact, gone. The polite path stays as the fallback if the fast one does not get the socket + // up within the bound. + if (typeof relayer.onProviderDisconnect === 'function') { + diag('[relay] back from the background: socket claims OPEN — dropping it for a fresh one'); + await relayer.onProviderDisconnect().catch(() => undefined); + if (await untilConnected(relayer, WAKE_TIMEOUT_MS)) { + diag(`[relay] fresh socket up in ${Date.now() - startedAt}ms`); + return; + } + diag('[relay] fresh socket not up within the bound — restarting the transport'); + } else { + diag('[relay] back from the background: socket claims OPEN — restarting the transport'); + } + if (typeof relayer.restartTransport !== 'function') return; await relayer.restartTransport().catch(() => undefined); + diag(`[relay] transport restart finished in ${Date.now() - startedAt}ms, connected=${relayer.connected}`); return; } + diag(`[relay] socket is down (connecting=${relayer.connecting}) — opening the transport`); // Bounded, because this call awaits any in-flight attempt — including one Android froze (see header). await Promise.race([relayer.transportOpen().catch(() => undefined), settleAfter(WAKE_TIMEOUT_MS)]); - if (relayer.connected || typeof relayer.restartTransport !== 'function') return; + if (relayer.connected) { + diag(`[relay] transport open in ${Date.now() - startedAt}ms`); + return; + } + if (typeof relayer.restartTransport !== 'function') return; + diag('[relay] transportOpen did not get the socket up within the bound — restarting the transport'); await relayer.restartTransport().catch(() => undefined); + diag(`[relay] transport restart finished in ${Date.now() - startedAt}ms, connected=${relayer.connected}`); } /** @@ -165,11 +206,17 @@ export function useRelayWake(provider: unknown): void { const onVisibilityChange = () => { if (document.visibilityState === 'hidden') { hiddenAt = Date.now(); + diag('[tab] hidden'); return; } if (document.visibilityState !== 'visible') return; - const afterBackground = hiddenAt !== null && Date.now() - hiddenAt >= BACKGROUND_STINT_MS; + const hiddenFor = hiddenAt === null ? null : Date.now() - hiddenAt; + const afterBackground = hiddenFor !== null && hiddenFor >= BACKGROUND_STINT_MS; hiddenAt = null; + markReturn(); + diag( + `[tab] visible after ${hiddenFor ?? '?'}ms hidden; relay provider ${latest.current ? 'present' : 'MISSING'}`, + ); void wakeRelay(latest.current, { afterBackground }); }; document.addEventListener('visibilitychange', onVisibilityChange);