From 3be8bd2a7885fbd141f6cc12c2d2073f9a0ac56c Mon Sep 17 00:00:00 2001 From: Christophe Besson Date: Wed, 26 Aug 2026 10:27:45 +0200 Subject: debug(transport): opt-in WebRTC health tracing for mobile-lock investigation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Client (transport.js): a localStorage ring buffer of connection/ICE/ DataChannel state transitions, visibility changes, request timeouts, and periodic health pings — enabled once via ?trace=1 (persists), read back at any time via #mb-debug without devtools. Off by default, zero behavior change unless enabled. Node (webrtc_server.py): MESHBAY_WEBRTC_TRACE=1 gates ICE-state-change logging and a per-session heartbeat (message count, seconds since last message, ICE/connection state) every 30s. Debugging aid for the "stuck after several minutes of mobile screen lock" report — not a fix. Stays on this branch until confirmed useful/resolved. --- .../src/meshbay_hub/static/transport.js | 156 +++++++++++++++++++++ .../src/meshbay_node/transport/webrtc_server.py | 39 ++++++ 2 files changed, 195 insertions(+) (limited to 'packages') diff --git a/packages/meshbay-hub/src/meshbay_hub/static/transport.js b/packages/meshbay-hub/src/meshbay_hub/static/transport.js index 7535594..6c038f6 100644 --- a/packages/meshbay-hub/src/meshbay_hub/static/transport.js +++ b/packages/meshbay-hub/src/meshbay_hub/static/transport.js @@ -81,6 +81,103 @@ const ADMIN_OP_TYPES = new Set([ 'group_detach', 'invite_create', ]); +// ── Diagnostic trace (opt-in, off by default) ─────────────────────────────── +// Ring buffer of transport health events (connection/ICE/DataChannel state +// transitions, request timeouts, visibility changes, periodic health pings), +// persisted to localStorage so a connection that gets stuck can be inspected +// after the fact — the field case this exists for is a phone with no +// devtools attached. Added while chasing a report of the transport going +// unresponsive after a mobile screen lock of several minutes; kept in the +// tree afterward rather than ripped out, since the next hard-to-reproduce +// connection bug will want the same thing and it costs nothing while off. +// +// Enable once by opening the app with ?trace=1 in the URL — this persists in +// localStorage, so every later visit stays in trace mode until ?trace=0 +// clears it. Read the log back at any time by navigating to #mb-debug (e.g. +// https://meshbay.org/app/#mb-debug), which replaces the page with a plain +// text dump — no devtools required. +const TRACE_KEY = 'mb_trace'; +const TRACE_LOG_KEY = 'mb_trace_log'; +const TRACE_MAX = 500; +// How often to probe the channel with a ping while trace mode is on — purely +// diagnostic (to see when a health check starts failing), not a keepalive: +// must stay opt-in, never run by default. +const TRACE_PING_INTERVAL_MS = 25000; + +(function _initTraceFlag() { + try { + const params = new URLSearchParams(location.search); + if (params.has('trace')) { + if (params.get('trace') === '0') localStorage.removeItem(TRACE_KEY); + else localStorage.setItem(TRACE_KEY, '1'); + } + } catch { /* localStorage unavailable (private mode, etc.) — trace stays off */ } +})(); + +function traceEnabled() { + try { return localStorage.getItem(TRACE_KEY) === '1'; } catch { return false; } +} + +function trace(event, data) { + if (!traceEnabled()) return; + try { + const buf = JSON.parse(localStorage.getItem(TRACE_LOG_KEY) || '[]'); + buf.push({ t: new Date().toISOString(), event, ...data }); + while (buf.length > TRACE_MAX) buf.shift(); + localStorage.setItem(TRACE_LOG_KEY, JSON.stringify(buf)); + } catch { /* storage full or unavailable — tracing is best-effort */ } +} + +window.MeshBayTrace = { + enabled: traceEnabled, + dump() { + try { return JSON.parse(localStorage.getItem(TRACE_LOG_KEY) || '[]'); } catch { return []; } + }, + clear() { try { localStorage.removeItem(TRACE_LOG_KEY); } catch { /* ignore */ } }, +}; + +function _showTraceView() { + { + const renderTraceView = () => { + const log = window.MeshBayTrace.dump(); + const text = JSON.stringify(log, null, 2); + document.body.innerHTML = ''; + document.title = 'MeshBay — Diagnostic'; + const bar = document.createElement('div'); + bar.style.cssText = 'font-family:monospace;padding:8px;'; + const copyBtn = document.createElement('button'); + copyBtn.textContent = 'Copier'; + copyBtn.onclick = () => { navigator.clipboard.writeText(text).catch(() => {}); }; + const clearBtn = document.createElement('button'); + clearBtn.textContent = 'Vider'; + clearBtn.onclick = () => { window.MeshBayTrace.clear(); renderTraceView(); }; + const refreshBtn = document.createElement('button'); + refreshBtn.textContent = 'Rafraîchir'; + refreshBtn.onclick = renderTraceView; + const info = document.createElement('span'); + info.textContent = ` — ${log.length} évènement(s) — trace ${traceEnabled() ? 'active' : 'inactive'}`; + info.style.marginLeft = '8px'; + bar.append(copyBtn, clearBtn, refreshBtn, info); + const pre = document.createElement('pre'); + pre.style.cssText = 'font-family:monospace;font-size:11px;white-space:pre-wrap;' + + 'word-break:break-all;padding:8px;'; + pre.textContent = text; + document.body.append(bar, pre); + }; + renderTraceView(); + } +} + +// Fragment-only URL changes (typing #mb-debug into an already-loaded page, +// or a link to it) do not reload the document, so DOMContentLoaded alone +// would miss them — hashchange is what a same-document navigation fires. +if (location.hash === '#mb-debug') { + document.addEventListener('DOMContentLoaded', _showTraceView); +} +window.addEventListener('hashchange', () => { + if (location.hash === '#mb-debug') _showTraceView(); +}); + const JOIN_REFUSALS = { code_required: 'This node does not know this browser yet. Ask the node operator ' + 'for a pairing code (meshbay-node operator pair).', @@ -168,6 +265,7 @@ class MeshBayTransport { this._channel.onopen = () => { clearTimeout(timeout); this._connected = true; + trace('channel_open', {}); resolve(); }; }); @@ -175,6 +273,11 @@ class MeshBayTransport { this._channel.onmessage = (event) => this._onMessage(event.data); this._channel.onclose = (ev) => { console.warn('[MeshBay] DataChannel closed', this._channel?.readyState, ev); + trace('channel_close', { + readyState: this._channel?.readyState, + pc: this._pc?.connectionState, + ice: this._pc?.iceConnectionState, + }); this._connected = false; if (channelReject) channelReject(new Error('DataChannel closed')); for (const [, p] of this._pending) p.reject(new Error('DataChannel closed')); @@ -182,16 +285,63 @@ class MeshBayTransport { }; this._channel.onerror = (ev) => { console.error('[MeshBay] DataChannel error', ev); + trace('channel_error', { + pc: this._pc?.connectionState, + ice: this._pc?.iceConnectionState, + }); if (channelReject) channelReject(new Error('DataChannel error')); }; this._pc.onconnectionstatechange = () => { console.log('[MeshBay] PC state:', this._pc.connectionState); + trace('pc_state', { state: this._pc.connectionState }); }; this._pc.oniceconnectionstatechange = () => { console.log('[MeshBay] ICE state:', this._pc.iceConnectionState); + trace('ice_state', { state: this._pc.iceConnectionState }); }; + // Diagnostic-only: a periodic health ping and a resume-triggered one, so + // a trace captures exactly what state the connection was in right as the + // page comes back from being backgrounded/locked — never active unless + // trace mode is on (see TRACE_KEY above). + if (traceEnabled()) { + const healthPing = async (reason) => { + const before = { + pc: this._pc?.connectionState, + ice: this._pc?.iceConnectionState, + channel: this._channel?.readyState, + }; + const start = Date.now(); + try { + await this.ping(8000); + trace('health_ping', { reason, ok: true, rtt_ms: Date.now() - start, ...before }); + } catch (e) { + trace('health_ping', { reason, ok: false, error: String(e && e.message || e), + elapsed_ms: Date.now() - start, ...before }); + } + }; + const onVisibility = () => { + trace('visibility', { + state: document.visibilityState, + pc: this._pc?.connectionState, + ice: this._pc?.iceConnectionState, + channel: this._channel?.readyState, + }); + if (document.visibilityState === 'visible' && this._channel?.readyState === 'open') { + healthPing('resume'); + } + }; + document.addEventListener('visibilitychange', onVisibility); + const healthInterval = setInterval(() => { + if (this._channel?.readyState === 'open') healthPing('interval'); + }, TRACE_PING_INTERVAL_MS); + this._diagCleanup = () => { + document.removeEventListener('visibilitychange', onVisibility); + clearInterval(healthInterval); + }; + } + const offer = await this._pc.createOffer(); await this._pc.setLocalDescription(offer); @@ -1440,6 +1590,7 @@ class MeshBayTransport { get gekRaw() { return this._gekRaw; } close() { + if (this._diagCleanup) { this._diagCleanup(); this._diagCleanup = null; } if (this._channel) this._channel.close(); if (this._pc) this._pc.close(); this._connected = false; @@ -1456,6 +1607,11 @@ class MeshBayTransport { this._pending.delete(id); console.error('[MeshBay] Response timeout for', obj.type, 'after', timeoutMs, 'ms, channel=', this._channel?.readyState); + trace('send_timeout', { + reqType: obj.type, timeoutMs, + pc: this._pc?.connectionState, ice: this._pc?.iceConnectionState, + channel: this._channel?.readyState, + }); reject(new Error('Response timeout')); }, timeoutMs); this._pending.set(id, { diff --git a/packages/meshbay-node/src/meshbay_node/transport/webrtc_server.py b/packages/meshbay-node/src/meshbay_node/transport/webrtc_server.py index 6709fbc..724527b 100644 --- a/packages/meshbay-node/src/meshbay_node/transport/webrtc_server.py +++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc_server.py @@ -199,6 +199,20 @@ def _pack(obj: dict) -> bytes: return struct.pack(">I", len(data)) + data +# Opt-in, off by default: a per-session heartbeat log (message count, time +# since the last message, ICE state) and ICE-state-change logging, on top of +# the connectionstatechange logging that already runs unconditionally. Added +# while chasing a report of the browser side going unresponsive after a +# mobile screen lock; --log-level DEBUG was not the right knob for this, +# since it is already used for the per-message request/response tracing +# every group index lookup produces, and turning that on for days of normal +# operation just to catch one intermittent session is not viable. Set +# MESHBAY_WEBRTC_TRACE=1 in the node's environment for the duration of a +# debugging session. +_WEBRTC_TRACE = os.environ.get("MESHBAY_WEBRTC_TRACE") == "1" +_WEBRTC_TRACE_INTERVAL_S = 30.0 + + class _DataChannelBuffer: """ Accumulate DataChannel messages and extract length-prefixed msgpack. @@ -295,6 +309,9 @@ class WebRTCPeerSession: self._nonce_client: bytes = b"" self._admin_ops: dict[str, dict] = {} # op_id → pending admin operation self._uploads: dict[str, dict] = {} # filename → {next_index, bytes} + # Diagnostics only (_WEBRTC_TRACE): when the last DataChannel message + # arrived, so the heartbeat can report silence duration. + self._last_msg_at: float = 0.0 def _setup_channel(self, channel: RTCDataChannel) -> None: self._channel = channel @@ -305,6 +322,7 @@ class WebRTCPeerSession: if isinstance(message, str): message = message.encode() self._msg_count += 1 + self._last_msg_at = time.monotonic() if self._msg_count <= 3: log.info("WebRTC data received: %d bytes, msg #%d (peer=%s)", len(message), self._msg_count, self._peer_id) @@ -312,6 +330,22 @@ class WebRTCPeerSession: for msg in self._buffer.messages(): self._handle_message(msg) + if _WEBRTC_TRACE: + self._spawn(self._trace_heartbeat()) + + async def _trace_heartbeat(self) -> None: + """Diagnostics only (_WEBRTC_TRACE): periodic proof-of-life for this + session, so a gap in these lines pinpoints when the node stopped + hearing from a peer that (from its own side) may still look connected.""" + while True: + await asyncio.sleep(_WEBRTC_TRACE_INTERVAL_S) + silence = time.monotonic() - self._last_msg_at if self._last_msg_at else -1 + log.info( + "WebRTC heartbeat peer=%s msgs=%d silence=%.0fs pc=%s ice=%s", + self._peer_id, self._msg_count, silence, + self._pc.connectionState, self._pc.iceConnectionState, + ) + def _handle_message(self, msg: dict) -> None: mtype = msg.get("type") log.debug("WebRTC recv: %s", mtype) @@ -4353,6 +4387,11 @@ class WebRTCTransport: log.info("WebRTC DataChannel opened: %s (peer=%s)", channel.label, peer_id) session._setup_channel(channel) + if _WEBRTC_TRACE: + @pc.on("iceconnectionstatechange") + def on_ice_state_change(): + log.info("WebRTC ICE state: %s (peer=%s)", pc.iceConnectionState, peer_id) + @pc.on("connectionstatechange") async def on_state_change(): state = pc.connectionState -- cgit v1.2.3