From c594a1a67a3499bf8e329146ea9b106da506a714 Mon Sep 17 00:00:00 2001 From: ScreenTinker Date: Fri, 7 Aug 2026 18:31:18 -0500 Subject: [PATCH 1/4] Make the live debug log work on the web player, and so on BrightSign MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The dashboard's per-device "Debug logging" checkbox has always sent a `set_debug` command. The Android player honours it — DebugLog.* mirrors its tagged lines over the device socket while the box is ticked. The web player never implemented the command at all, so the panel opened, revealed itself, and streamed nothing but the three unconditional reporters (sync, pip, zone). A display could be failing loudly in its own console and look mute from the dashboard. In a browser that is a nuisance — press F12. On BrightSign it is the whole diagnostic surface: no console, no adb, no logcat, a panel on a wall. Rather than hand-instrument eighty-seven call sites to match Android's tag by tag, this streams the ring buffer the error trap at the top of has always filled: every console.log/warn/error, every uncaught error with file:line and stack, every unhandled rejection, every failed resource load. Turning the stream on also REPLAYS that backlog, so the operator sees the failure that happened before they opened the screen — the case they actually came to investigate, and one no log tail gives them. Replayed lines carry their real age, because the dashboard stamps on arrival and 200 lines would otherwise all claim to have happened this second. The bracket prefixes the player already uses ([wall], [bs], [group-sync]) become the tag column, so the panel reads the same shape as Android's, and the panel now colours by level — all four rendered identically before, so the one line explaining the fault sat in a wall of grey. Bounded three ways, because this sink is fed by console.*: - 40 lines/sec, over which lines are COUNTED and reported, not queued - auto-off after 30 min, for the checkbox nobody unticks - the dashboard also switches it off when the operator leaves the screen The reentrancy guard in pushLog is not theoretical: the sink runs inside the console wrapper, so a subscriber that logs anything would recurse until the stack gave out and the player would die of its own diagnostics. BrightSign host lines stand their direct emit down while the stream is on (the console path already carries them) but still go out unconditionally when it is off — the boot report is the one diagnostic nobody can ask for in advance, because it is over before the operator has a device to open. Verified on the XT245 on alpha: 34 lines across 7 tags, backlog replayed with real ages, levels intact, platform line reporting BOS 9.1.93.2 / XT245 / 1920x1200. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_014skWYXJUWhF73EvNPgB2AS --- frontend/js/views/device-detail.js | 16 ++ server/player/index.html | 196 +++++++++++++++++- server/test/player-live-debug-log.test.js | 232 ++++++++++++++++++++++ 3 files changed, 443 insertions(+), 1 deletion(-) create mode 100644 server/test/player-live-debug-log.test.js diff --git a/frontend/js/views/device-detail.js b/frontend/js/views/device-detail.js index b631355..7fd37ac 100644 --- a/frontend/js/views/device-detail.js +++ b/frontend/js/views/device-detail.js @@ -33,6 +33,11 @@ let shellHandler = null; let diagPollTimer = null; // polls a diag-smoothness widget's reported frame stats while the page is open let screenshotInterval = null; let remoteActive = false; +// Mirrors the Debug-logging checkbox so cleanup() can switch the device's stream back off. +// Without this, leaving the screen left the panel streaming into nothing: the device kept +// emitting, the dashboard kept relaying, and nobody was listening. The player carries its own +// auto-off as the backstop for the case this can't cover -- a tab that is killed, not closed. +let debugStreamOn = false; // Belt for the orphaned-stream fix: if the tab is hidden/closed/backgrounded while a Remote session // is live, stop it (the server also auto-stops on socket drop, but bfcache keeps the socket alive). @@ -189,6 +194,12 @@ export function render(container, deviceId) { const line = document.createElement('div'); const time = new Date(data.ts || Date.now()).toLocaleTimeString(); line.textContent = `${time} [${data.tag || ''}] ${data.message || ''}`; + // Every player sends a level and the panel used to render all four identically, so the one + // line that explains the fault sat in a wall of grey. Errors and warnings are why the + // operator opened this. + const LEVEL_COLOR = { e: '#f87171', w: '#fbbf24', d: '#64748b' }; + const tone = LEVEL_COLOR[(data.level || '').toLowerCase()]; + if (tone) line.style.color = tone; panel.appendChild(line); while (panel.childElementCount > 500) panel.removeChild(panel.firstChild); panel.scrollTop = panel.scrollHeight; @@ -1150,6 +1161,7 @@ function setupActions(device) { const enabled = e.target.checked; const panel = document.getElementById('debugLogPanel'); if (panel) panel.style.display = enabled ? 'block' : 'none'; + debugStreamOn = enabled; sendCommand(device.id, 'set_debug', { enabled }); }); @@ -2171,6 +2183,10 @@ export function cleanup() { if (shellHandler) off('shell-result', shellHandler); // #161 owner-tools listener if (screenshotInterval) clearInterval(screenshotInterval); if (remoteActive && currentDevice) stopRemote(currentDevice.id); + // Same reasoning as stopRemote above: an operator who navigates away has stopped watching, so + // the display should stop talking. Must run BEFORE currentDevice is cleared. + if (debugStreamOn && currentDevice) sendCommand(currentDevice.id, 'set_debug', { enabled: false }); + debugStreamOn = false; remoteActive = false; currentDevice = null; window._sendKey = null; diff --git a/server/player/index.html b/server/player/index.html index edd56cc..fd839a0 100644 --- a/server/player/index.html +++ b/server/player/index.html @@ -24,6 +24,12 @@ try { return Date.now(); } catch (e) { return new Date().getTime(); } } + // Live subscribers (the player's set_debug sink). Kept HERE rather than in the player + // script so entries recorded during boot -- before the player has even parsed -- reach a + // subscriber that registers later, via the backlog in window.__debugLog. + var subs = []; + var notifying = false; + function pushLog(entry) { try { entry.t = nowMs(); @@ -32,8 +38,22 @@ window.__debugLog.splice(0, window.__debugLog.length - MAX_LOG); } } catch (e) { /* we are the safety net; do not crash */ } + // Reentrancy guard, and it is not theoretical: this runs inside the console wrapper + // below, so a subscriber that logs anything at all -- directly, or through a library -- + // would call back in here and recurse until the stack gave out. The player would die of + // its own diagnostics. + if (notifying) return; + notifying = true; + try { + for (var s = 0; s < subs.length; s++) { + try { subs[s](entry); } catch (e) { /* one bad subscriber must not eat the rest */ } + } + } finally { notifying = false; } } window.__debugLog_push = pushLog; // shared pusher for debug-overlay.js + window.__debugLog_subscribe = function (fn) { + try { if (typeof fn === 'function') subs.push(fn); } catch (e) {} + }; pushLog({ type: 'init', @@ -542,7 +562,12 @@ if (!BS || typeof BS.onHostLog !== 'function') return; BS.onHostLog((line) => { try { - if (socket?.connected && config.deviceId) { + // While the live stream is ON the console.log below already reaches the dashboard + // through the debug sink, so emitting here too would show every host line twice. + // Host lines still go out unconditionally when it is OFF: the boot story is the one + // diagnostic nobody can ask for in advance, because it is over before the operator + // has a device to open. + if (!remoteDebug && socket?.connected && config.deviceId) { socket.emit('device:log', { device_id: config.deviceId, tag: line.tag, level: line.level, message: line.message @@ -555,6 +580,171 @@ } catch (e) { /* a bridge that throws here must not stop the player starting */ } } + /* ==================== Live remote debug (`set_debug`) ==================== + * + * The dashboard's per-device "Debug logging" checkbox sends a `set_debug` command and opens a + * live panel. The Android player has honoured it for a long time -- DebugLog.* mirrors its + * tagged lines to the dashboard while the box is ticked. The WEB player never implemented the + * command at all, so the panel opened, streamed nothing, and read as a display with nothing to + * say. In a browser that barely mattered: press F12. On a BrightSign it is the whole story -- + * there is no console, no adb, no logcat, and this panel is the only way to watch what the + * player thinks it is doing. + * + * Rather than hand-instrument eighty-odd call sites to match Android's tag-by-tag, this streams + * the ring buffer the error trap at the top of has always filled: every console.log/ + * warn/error, every uncaught error with file:line and stack, every unhandled rejection, every + * failed resource load, plus the host's own boot report on BrightSign. Turning the stream on + * also FLUSHES that backlog, so the operator sees the failure that happened BEFORE they opened + * the screen -- which is the case they actually came to investigate, and which tailing a log + * cannot give them. + */ + let remoteDebug = false; // is the stream on right now + let debugSubscribed = false; // ring-buffer subscription is permanent once made + let debugAutoOffTimer = null; + let debugWindowAt = 0, debugWindowCount = 0, debugSuppressed = 0; + + // Fed by console.*, so the ceiling has to assume the worst: a video that fails to decode and is + // retried every frame turns a diagnostic aid into a flood down the same socket as playback. + const DEBUG_MAX_LINES_PER_SEC = 40; + // Ticking the box and walking away must not leave a panel streaming for the rest of the week. + // The dashboard turns it off on teardown, but a closed laptop or a killed tab never sends that, + // and the device is the only party in a position to be sure. + const DEBUG_AUTO_OFF_MS = 30 * 60 * 1000; + + function debugSend(tag, level, message) { + if (!socket?.connected || !config.deviceId) return; + try { + socket.emit('device:log', { + device_id: config.deviceId, + tag: String(tag || 'player').slice(0, 64), + level: String(level || 'i').slice(0, 8), + message: String(message == null ? '' : message).slice(0, 2000), + }); + } catch (e) { /* a diagnostic that throws is worse than one that is missing */ } + } + + /* + * One live line, rate-limited. Over the cap the lines are COUNTED, not queued -- an operator + * needs to know output was dropped far more than they need the four hundredth copy of one + * message, and a queue would go on replaying the flood after it stopped. + */ + function debugEmitLine(tag, level, message) { + if (!remoteDebug) return; + const now = Date.now(); + if (now - debugWindowAt >= 1000) { + debugWindowAt = now; + const dropped = debugSuppressed; + debugWindowCount = 0; + debugSuppressed = 0; + if (dropped > 0) { + debugWindowCount++; + debugSend('debug', 'w', `${dropped} line(s) suppressed — rate limit`); + } + } + if (debugWindowCount >= DEBUG_MAX_LINES_PER_SEC) { debugSuppressed++; return; } + debugWindowCount++; + debugSend(tag, level, message); + } + + // The player already prefixes most of its console lines with [wall], [bs], [group-sync] and so + // on -- the same shape Android's tags have -- so lift that into the tag column and the panel + // reads the same on both platforms instead of being one long undifferentiated column. + const DEBUG_TAG_RE = /^\s*\[([a-zA-Z0-9/_.-]{1,24})\]\s*/; + function debugTagFor(entry) { + if (entry.tag) return String(entry.tag); + const m = DEBUG_TAG_RE.exec(entry.message || ''); + if (m) return m[1]; + if (entry.type === 'error' || entry.type === 'rejection') return 'error'; + if (entry.type === 'timing' || entry.type === 'init') return entry.type; + return 'player'; + } + + function debugLevelFor(entry) { + if (entry.level) return entry.level; + if (entry.type === 'console.error' || entry.type === 'error' || entry.type === 'rejection') return 'e'; + if (entry.type === 'console.warn') return 'w'; + return 'i'; + } + + // The non-console entry types carry structured fields rather than a message, and they are the + // valuable ones -- an uncaught error is worth nothing without its file, line and stack. + function debugMessageFor(entry) { + let msg = entry.message || ''; + if (entry.type === 'init') { + msg = `page ${entry.url || '?'} — screen ${entry.sw || '?'}x${entry.sh || '?'} — ${entry.ua || ''}`; + } else if (entry.type === 'timing') { + msg = `${entry.event} +${entry.sinceInit}ms`; + } else if (entry.type === 'error' || entry.type === 'rejection') { + if (entry.source) msg += ` @${entry.source}:${entry.line || 0}:${entry.col || 0}`; + if (entry.stack) msg += ` | ${String(entry.stack).replace(/\s+/g, ' ').slice(0, 400)}`; + } else if (!msg) { + msg = entry.type || ''; + } + return msg.replace(DEBUG_TAG_RE, ''); // already lifted into the tag column + } + + function debugSink(entry) { + if (!remoteDebug || !entry || entry.__stSent) return; + entry.__stSent = true; + debugEmitLine(debugTagFor(entry), debugLevelFor(entry), debugMessageFor(entry)); + } + + // What the operator needs before the first line means anything: which player this is, how big + // the screen really is, and -- on BrightSign -- that they are talking to the host at all. + function debugPlatformLine() { + const bits = []; + try { bits.push(`screen ${screen.width}x${screen.height}@${window.devicePixelRatio || 1}x`); } catch (e) {} + try { if (BS && BS.isBrightSign && BS.isBrightSign()) bits.push('BrightSign'); } catch (e) {} + try { bits.push(navigator.userAgent); } catch (e) {} + return bits.join(' — '); + } + + /* + * Replay what is already in the buffer. Deliberately bypasses the per-second cap: it is a + * one-shot burst bounded by the ring buffer itself (200 entries), and throttling it would drop + * exactly the history the operator turned the stream on to read. + */ + function debugFlushBacklog() { + let buf = []; + try { buf = (window.__debugLog || []).filter((e) => e && !e.__stSent); } catch (e) { return; } + debugSend('debug', 'i', `--- replaying ${buf.length} buffered line(s) from before the stream opened ---`); + const now = Date.now(); + for (const entry of buf) { + entry.__stSent = true; + // The dashboard timestamps each line on arrival, so a replayed line would claim to have + // happened just now. Carry the real age in the text instead of quietly lying about when + // the crash was. + const age = entry.t ? `(-${((now - entry.t) / 1000).toFixed(1)}s) ` : ''; + debugSend(debugTagFor(entry), debugLevelFor(entry), age + debugMessageFor(entry)); + } + debugSend('debug', 'i', '--- end of backlog, now live ---'); + } + + function setRemoteDebug(on) { + if (debugAutoOffTimer) { clearTimeout(debugAutoOffTimer); debugAutoOffTimer = null; } + if (!on) { + if (remoteDebug) debugEmitLine('debug', 'i', 'Remote debug logging OFF'); + remoteDebug = false; + return; + } + const wasOn = remoteDebug; + remoteDebug = true; + debugWindowAt = 0; debugWindowCount = 0; debugSuppressed = 0; + if (!debugSubscribed) { + debugSubscribed = true; + try { window.__debugLog_subscribe?.(debugSink); } catch (e) {} + } + if (!wasOn) { + debugSend('debug', 'i', `Remote debug logging ON — ${debugPlatformLine()}`); + debugFlushBacklog(); + } + debugAutoOffTimer = setTimeout(() => { + debugAutoOffTimer = null; + debugEmitLine('debug', 'w', `Remote debug logging auto-disabled after ${Math.round(DEBUG_AUTO_OFF_MS / 60000)} min`); + remoteDebug = false; + }, DEBUG_AUTO_OFF_MS); + } + function emitDeviceEvent(type, reason, detail) { try { if (!socket?.connected || !config.deviceId) return; @@ -1705,6 +1895,10 @@ if (v === null) console.warn('[volume] set_volume with no usable level/value:', JSON.stringify(data)); else setMediaVolume(v); } + // The dashboard's "Debug logging" checkbox. Accepts the flag at either depth: the command + // relay wraps it in `payload`, but the queued-command replay path and the public API have + // both been seen to deliver it flat. + if (data.type === 'set_debug') setRemoteDebug(!!(data.payload?.enabled ?? data.enabled)); }); // #129: real-time mute. Apply immediately if the toggled item is the one playing now; diff --git a/server/test/player-live-debug-log.test.js b/server/test/player-live-debug-log.test.js new file mode 100644 index 0000000..c1533a1 --- /dev/null +++ b/server/test/player-live-debug-log.test.js @@ -0,0 +1,232 @@ +'use strict'; + +/* + * The dashboard's per-device "Debug logging" checkbox, and the web player's half of it. + * + * The checkbox has always sent a `set_debug` command. The ANDROID player honours it — DebugLog.* + * mirrors its tagged lines over the device socket while the box is ticked. The web player never + * implemented the command at all: the panel opened, revealed itself, streamed nothing, and read as + * a display with nothing to say. Only the three unconditional reporters (sync, pip, zone) ever + * reached it, so a display could be failing loudly in its own console and look silent from here. + * + * In a browser that is a nuisance — press F12. On BrightSign it is the entire diagnostic surface: + * no console, no adb, no logcat, a panel on a wall. Which is why the fix streams the ring buffer + * the error trap at the top of already fills (console.*, uncaught errors with stacks, + * rejections, failed resource loads) rather than hand-instrumenting call sites to match Android's + * tag by tag — and why turning it on REPLAYS the backlog, since the fault the operator came to + * investigate happened before they opened the screen. + */ +const { test } = require('node:test'); +const assert = require('node:assert/strict'); +const fs = require('fs'); +const path = require('path'); + +const ROOT = path.join(__dirname, '..', '..'); +const read = (p) => fs.readFileSync(path.join(ROOT, p), 'utf8'); +const PLAYER = read('server/player/index.html'); +const DETAIL = read('frontend/js/views/device-detail.js'); + +// ------------------------------------------------------------------ the command is honoured + +test('the web player implements set_debug — the whole point', () => { + const handler = PLAYER.slice(PLAYER.indexOf("socket.on('device:command'"), PLAYER.indexOf("socket.on('device:mute-changed'")); + assert.match(handler, /data\.type === 'set_debug'/, 'the command the dashboard has always sent must be handled'); + assert.match(handler, /setRemoteDebug/); + // The relay wraps the flag in `payload`; other delivery paths have been seen to send it flat. + assert.match(handler, /payload\?\.enabled\s*\?\?\s*data\.enabled/, + 'both payload shapes must be accepted, or the checkbox silently does nothing'); +}); + +test('set_debug is not capability-gated, so a BrightSign can receive it', () => { + const caps = require('../lib/player-capabilities'); + assert.equal(caps.capabilityForCommand('set_debug'), null); + assert.equal(caps.commandAllowed({ android_version: 'BrightSign' }, 'set_debug').ok, true); +}); + +// ------------------------------------------------------------------ the ring buffer, live + +/* Run the error trap for real — it is ES5 and self-contained, so it executes standalone. */ +function loadTrap() { + const start = PLAYER.indexOf('', start)); + const win = {}; + const console_ = { log() {}, warn() {}, error() {} }; + const doc = { addEventListener() {} }; + win.addEventListener = () => {}; + new Function('window', 'console', 'document', 'navigator', 'screen', 'location', src)( + win, console_, doc, { userAgent: 'test' }, { width: 1920, height: 1080 }, { href: 'http://x/player' }, + ); + return { win, console: console_ }; +} + +test('a subscriber receives entries as they are recorded', () => { + const { win, console: c } = loadTrap(); + const seen = []; + win.__debugLog_subscribe((e) => seen.push(e)); + c.log('[wall] hello'); + assert.equal(seen.length, 1); + assert.equal(seen[0].type, 'console.log'); + assert.match(seen[0].message, /\[wall\] hello/); +}); + +test('THE RECURSION TRAP: a subscriber that logs cannot take the player down', () => { + // This sink is fed from inside the console wrapper. A subscriber that logs anything at all — + // directly, or through any library it touches — re-enters pushLog and recurses until the stack + // gives out, and the player dies of its own diagnostics. The guard is not theoretical. + const { win, console: c } = loadTrap(); + let calls = 0; + win.__debugLog_subscribe(() => { calls++; c.log('the subscriber logs too'); }); + assert.doesNotThrow(() => c.log('first')); + assert.equal(calls, 1, 'the reentrant log must not call subscribers again'); +}); + +test('one throwing subscriber does not eat the others', () => { + const { win, console: c } = loadTrap(); + const seen = []; + win.__debugLog_subscribe(() => { throw new Error('bad subscriber'); }); + win.__debugLog_subscribe((e) => seen.push(e)); + assert.doesNotThrow(() => c.log('x')); + assert.equal(seen.length, 1); +}); + +test('subscribing does not disturb the buffer the debug overlay reads', () => { + const { win, console: c } = loadTrap(); + win.__debugLog_subscribe(() => {}); + c.log('a'); + assert.ok(win.__debugLog.length >= 2, 'init + the line'); + assert.equal(typeof win.__debugLog_push, 'function', 'debug-overlay.js pusher must survive'); +}); + +// ------------------------------------------------------------------ what actually goes out + +// Pull the sink's helpers out of the player and run them against real ring-buffer entries. +function loadSink() { + const from = PLAYER.indexOf('const DEBUG_TAG_RE'); + const to = PLAYER.indexOf('function debugSink('); + const src = PLAYER.slice(from, to); + return new Function(`${src}; return { debugTagFor, debugLevelFor, debugMessageFor };`)(); +} + +test('a bracketed prefix becomes the tag, so the panel reads like Android\'s', () => { + const { debugTagFor, debugMessageFor } = loadSink(); + const e = { type: 'console.log', message: '[group-sync] drift 42ms' }; + assert.equal(debugTagFor(e), 'group-sync'); + assert.equal(debugMessageFor(e), 'drift 42ms', 'the prefix must not be repeated in the message'); +}); + +test('an untagged line still lands somewhere sensible', () => { + const { debugTagFor } = loadSink(); + assert.equal(debugTagFor({ type: 'console.log', message: 'Playing: clip.mp4' }), 'player'); + assert.equal(debugTagFor({ type: 'rejection', message: 'boom' }), 'error'); +}); + +test('levels survive, because an error that looks like a log is not a diagnostic', () => { + const { debugLevelFor } = loadSink(); + assert.equal(debugLevelFor({ type: 'console.error' }), 'e'); + assert.equal(debugLevelFor({ type: 'console.warn' }), 'w'); + assert.equal(debugLevelFor({ type: 'error' }), 'e'); + assert.equal(debugLevelFor({ type: 'rejection' }), 'e'); + assert.equal(debugLevelFor({ type: 'console.log' }), 'i'); + assert.equal(debugLevelFor({ type: 'console.log', level: 'w' }), 'w', 'an explicit level wins'); +}); + +test('an uncaught error carries its location and stack, or it is not worth sending', () => { + const { debugMessageFor } = loadSink(); + const msg = debugMessageFor({ + type: 'error', message: 'x is not a function', + source: 'http://h/player/index.html', line: 42, col: 7, stack: 'at a\n at b', + }); + assert.match(msg, /@http:\/\/h\/player\/index\.html:42:7/); + assert.match(msg, /at a at b/, 'the stack must be flattened onto one line, not dropped'); +}); + +test('the panel is told what kind of player it is looking at', () => { + const fn = PLAYER.slice(PLAYER.indexOf('function debugPlatformLine'), PLAYER.indexOf('function debugFlushBacklog')); + assert.match(fn, /screen\.width/); + assert.match(fn, /BS\.isBrightSign\(\)/, 'a BrightSign must identify itself — it is the platform with no other console'); + assert.match(fn, /userAgent/); +}); + +// ------------------------------------------------------------------ the backlog + +test('turning the stream on replays what already happened', () => { + // The operator is investigating a fault that is already over. A stream that starts empty makes + // them reproduce it, which on a panel on a wall may mean waiting days for it to recur. + const fn = PLAYER.slice(PLAYER.indexOf('function debugFlushBacklog'), PLAYER.indexOf('function setRemoteDebug')); + assert.match(fn, /window\.__debugLog/); + assert.match(fn, /__stSent/, 'a replayed line must be marked so the live sink does not send it twice'); + assert.match(fn, /debugSend\(/, 'the replay must bypass the per-second cap'); + assert.ok(!/debugEmitLine\(/.test(fn), 'rate-limiting the replay would drop the history it exists to deliver'); +}); + +test('a replayed line admits it is old rather than claiming to be now', () => { + // The dashboard stamps each line on arrival, so a 200-line replay would all read as this second + // and an operator would date the crash to when they opened the panel. + const fn = PLAYER.slice(PLAYER.indexOf('function debugFlushBacklog'), PLAYER.indexOf('function setRemoteDebug')); + assert.match(fn, /-\$\{\(\(now - entry\.t\)/, 'the real age must travel in the text'); +}); + +// ------------------------------------------------------------------ bounded + +test('the stream is rate-limited, and says so when it drops lines', () => { + // Fed by console.*: a video that fails to decode and retries every frame would otherwise flood + // the socket that also carries playback. + const fn = PLAYER.slice(PLAYER.indexOf('function debugEmitLine'), PLAYER.indexOf('const DEBUG_TAG_RE')); + assert.match(fn, /DEBUG_MAX_LINES_PER_SEC/); + assert.match(fn, /suppressed/, 'silent truncation would read as a player that went quiet'); + assert.ok(!/push\(|\.shift\(/.test(fn), 'dropped lines must be counted, not queued and replayed later'); + const cap = /const DEBUG_MAX_LINES_PER_SEC = (\d+)/.exec(PLAYER); + assert.ok(cap && Number(cap[1]) > 0 && Number(cap[1]) <= 200, `cap must be real, got ${cap && cap[1]}`); +}); + +test('a forgotten checkbox does not stream forever', () => { + const fn = PLAYER.slice(PLAYER.indexOf('function setRemoteDebug'), PLAYER.indexOf('function emitDeviceEvent')); + assert.match(fn, /DEBUG_AUTO_OFF_MS/); + assert.match(fn, /auto-disabled/, 'the stream stopping on its own must be visible, not mysterious'); + const ms = /const DEBUG_AUTO_OFF_MS = ([^;]+);/.exec(PLAYER); + const value = new Function(`return ${ms[1]}`)(); + assert.ok(value >= 5 * 60 * 1000 && value <= 60 * 60 * 1000, `auto-off must outlast a real session, got ${value}ms`); +}); + +test('leaving the device screen turns the device stream off', () => { + const fn = DETAIL.slice(DETAIL.indexOf('export function cleanup()')); + assert.match(fn, /set_debug'?,\s*\{ enabled: false \}/, 'the dashboard must stop what it started'); + assert.ok( + fn.indexOf('set_debug') < fn.indexOf('currentDevice = null'), + 'sent after currentDevice is cleared, this would address nobody', + ); +}); + +// ------------------------------------------------------------------ BrightSign host lines + +test('host lines are not sent twice while the stream is on', () => { + // wireHostDiagnostics emits directly AND console.logs; with the sink live the console.log is + // already a second path to the dashboard, so the direct emit has to stand down. + const fn = PLAYER.slice(PLAYER.indexOf('function wireHostDiagnostics'), PLAYER.indexOf('/* ==================== Live remote debug')); + assert.match(fn, /!remoteDebug && socket\?\.connected/, 'the direct emit must yield to the sink'); + assert.match(fn, /console\.log\(`\[host\/\$\{line\.tag\}\]/, 'and the console path must remain, since that is what the sink reads'); +}); + +test('the boot report still goes out with the stream OFF', () => { + // It is the one diagnostic nobody can ask for in advance: it is over before the operator has a + // device to open. Gating it behind the checkbox would lose it permanently. + const fn = PLAYER.slice(PLAYER.indexOf('function wireHostDiagnostics'), PLAYER.indexOf('/* ==================== Live remote debug')); + assert.match(fn, /socket\.emit\('device:log'/); + assert.ok(!/if \(!remoteDebug\) return/.test(fn), 'host logs must not be suppressed when debug is off'); +}); + +// ------------------------------------------------------------------ it cannot break playback + +test('nothing in the sink can stop the player', () => { + const from = PLAYER.indexOf('/* ==================== Live remote debug'); + const to = PLAYER.indexOf('function emitDeviceEvent'); + const block = PLAYER.slice(from, to); + assert.match(block, /function debugSend/); + const send = block.slice(block.indexOf('function debugSend'), block.indexOf('function debugEmitLine')); + assert.match(send, /try \{/, 'the socket emit must be guarded'); + assert.match(send, /catch \(e\)/); + // Every field is bounded before the wire; the server truncates too, but a player in a bad state + // should not be pushing megabytes at it. + assert.match(send, /slice\(0, 64\)/); + assert.match(send, /slice\(0, 2000\)/); +}); From 24e430b354c29f40deb49a826bb89c6775ffe61b Mon Sep 17 00:00:00 2001 From: ScreenTinker Date: Fri, 7 Aug 2026 19:12:16 -0500 Subject: [PATCH 2/4] One broken clip, one skip: stop media errors advancing the playlist N times MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Found the day the live debug log started working, which is the only reason anyone saw it. A BrightSign XT245 playing a 40s clip as a SINGLE-item playlist logged four `Video error` events at every loop boundary and then three back-to-back "Playing:" lines, with `play() rejected AbortError` and `muted-fallback play() also failed` in between as the second mount aborted the first. On a one-item playlist that just re-plays the same file, so it looked like nothing. On a real playlist the identical storm skips one item per surplus event. Silently. The operator sees a playlist that drops content and nothing says why. Same family as 234. Two independent defects produced it: 1. `video.onerror` had no once-guard — its sibling in the buffered path has `if (done) return`, this one didn't — so every event scheduled its own nextItem. 2. Every call site wrote `advanceTimer = setTimeout(...)` DIRECTLY. A second write before the first fired ORPHANED the earlier timer instead of cancelling it: still pending, no longer referenced, so renderContent's clearTimeout could only ever cancel the last one. All the others fired. That made a dozen sites capable of leaking a timer, not just the error handlers — so the fix is a scheduleAdvance() helper that clears before it arms, and a test asserting nothing assigns the timer directly ever again. The four error handlers (buffered/non-buffered x video/image) had drifted apart because they were four copies; they now share one mediaFailureSkip(), which also reports the actual MediaError code. The old line logged the DOM event ({"isTrusted":true}) and never touched el.error, so the log could say a video failed but never why. Third guard: an element that is still playable is not a failure. `error` fires with el.error set; an event carrying no MediaError against an element with frames buffered ahead of it did not fail at anything, and discarding a healthy item on that basis is worse than the event being reacted to. Anything genuinely unplayable (no MediaError AND nothing decoded) is still skipped, so a broken clip can never stall the playlist. Verified on the XT245: 150s of playback went from 2-3 advances and an AbortError pair per loop boundary to exactly one advance and zero AbortErrors, and the surviving diagnostic now names the real cause -- `code=3 DECODE`, four raw error events collapsing to one reported failure. All three guards are mutation-tested: removing any one of them fails a test. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_014skWYXJUWhF73EvNPgB2AS --- server/player/index.html | 79 ++++++-- .../player-media-error-multiadvance.test.js | 189 ++++++++++++++++++ 2 files changed, 249 insertions(+), 19 deletions(-) create mode 100644 server/test/player-media-error-multiadvance.test.js diff --git a/server/player/index.html b/server/player/index.html index fd839a0..4e4701c 100644 --- a/server/player/index.html +++ b/server/player/index.html @@ -854,6 +854,51 @@ // playback muted). let userHasInteracted = false; let advanceTimer = null; + + /* + * Arm the single advance timer. ALWAYS clear the outgoing one first. + * + * `advanceTimer` is one slot by design — renderContent clears it on every item change — but a + * dozen call sites used to write `advanceTimer = setTimeout(...)` directly, and a second write + * before the first fired ORPHANED the earlier timer instead of cancelling it: still pending, + * no longer referenced, so nothing could stop it. Every one of those fired, and each one + * advanced the playlist. + */ + function scheduleAdvance(fn, ms) { + if (advanceTimer) clearTimeout(advanceTimer); + advanceTimer = setTimeout(fn, ms); + return advanceTimer; + } + + const MEDIA_ERR_NAME = { 1: 'ABORTED', 2: 'NETWORK', 3: 'DECODE', 4: 'SRC_NOT_SUPPORTED' }; + + /* + * One broken item, one skip. + * + * A media element can raise `error` several times over for a single item, and each event used + * to schedule its own `nextItem`. On a SINGLE-item playlist that merely re-played the same + * clip, which is how this was finally noticed — a BrightSign XT245 logging four errors and + * three "Playing:" lines at every loop boundary. On a real playlist the identical storm SKIPS + * one item per surplus event, silently, and the operator sees a playlist that drops content. + * + * The second guard is that a media element still able to play is not a failure. `error` fires + * with `el.error` set; an event carrying no MediaError against an element with buffered frames + * ahead of it did not fail at anything, and discarding a healthy item on that basis is worse + * than the event we are reacting to. Anything genuinely unplayable (no MediaError AND nothing + * decoded) is still skipped, so a broken clip can never stall the playlist. + */ + function mediaFailureSkip(el, label, src, mayAdvance = true) { + const err = el && el.error; + if (!err && el && el.readyState >= 3) { + console.warn(`[media] ${label} raised error with no MediaError while playable (readyState=${el.readyState}) — ignored: ${src}`); + return; + } + if (el && el.__stFailed) return; // however many events it raises, one skip + if (el) el.__stFailed = true; + const detail = err ? `code=${err.code} ${MEDIA_ERR_NAME[err.code] || '?'}${err.message ? ' ' + err.message : ''}` : 'no MediaError'; + console.error(`[media] ${label} failed (${detail}) src=${src}`); + if (mayAdvance) scheduleAdvance(nextItem, 3000); // skip the broken item; hold the prior frame + } // Buffered widget swap (#directory-board black-cycle): build the next widget iframe // behind the current content and reveal it only on 'load', so a widget reload never // blanks the screen. WIDGET_SWAP_TIMEOUT_MS reveals anyway if 'load' never fires (a @@ -3275,7 +3320,7 @@ // schedule-awareness / Fix A preserved). function reevaluateHeldWidget() { if (nextActiveIndex(currentIndex) === currentIndex) { - advanceTimer = setTimeout(reevaluateHeldWidget, WIDGET_SOLO_REFRESH_MS); + scheduleAdvance(reevaluateHeldWidget, WIDGET_SOLO_REFRESH_MS); return; } nextItem(); @@ -3335,7 +3380,7 @@ const c = document.getElementById('playerContainer'); c.style.display = 'block'; c.appendChild(img); - advanceTimer = setTimeout(nextItem, (item.duration_sec || 10) * 1000); + scheduleAdvance(nextItem, (item.duration_sec || 10) * 1000); preloadNextImage(); } // ---- GL transition (feat/transition-engine). Every failure path hard-cuts — never a blank. ---- @@ -3479,7 +3524,7 @@ const dwellMs = (item.duration_sec || 10) * 1000; const container = document.getElementById('playerContainer'); runGlWipe(fromImg, toImg, t, dwellMs, - () => { advanceTimer = setTimeout(nextItem, dwellMs); }, // onStart: arm the dwell for overlap + () => { scheduleAdvance(nextItem, dwellMs); }, // onStart: arm the dwell for overlap () => { // mount: swap in the image, keep the armed timer toImg.style.cssText = 'width:100%;height:100%;object-fit:contain'; container.appendChild(toImg); @@ -3509,7 +3554,9 @@ const fail = () => { if (done) return; done = true; if (watchdog) clearTimeout(watchdog); - console.error('Image error'); advanceTimer = setTimeout(nextItem, 3000); // skip broken item; hold prior frame + // No element to inspect here: this is the load/watchdog failure path, so nothing decoded. + // `fail` is already `done`-guarded, so it runs at most once per render. + mediaFailureSkip(null, 'image', src); // skip broken item; hold prior frame }; // a hung load/decode must never stall the playlist: at 3s use what we have, else skip watchdog = setTimeout(() => { if (cached) swap(cached); else fail(); }, 3000); @@ -3578,7 +3625,7 @@ video.muted = (!userHasInteracted || !!item.muted); // autoplay policy + per-item mute (#129) if (!video.muted) video.volume = 1.0; video.onended = () => { if (!video.loop) nextItem(); }; - video.onerror = (e) => { console.error('Video error:', src, e); advanceTimer = setTimeout(nextItem, 3000); }; + video.onerror = () => mediaFailureSkip(video, 'video', src); video.play().catch(() => { video.muted = true; video.play().catch(() => {}); }); // autoplay-policy fallback setTimeout(() => { if (video.paused) { video.muted = true; video.play().catch(() => {}); } }, 2000); // last-resort kick }; @@ -3616,7 +3663,7 @@ video.addEventListener('error', () => { if (done) return; done = true; if (watchdog) clearTimeout(watchdog); - console.error('Video error:', src); advanceTimer = setTimeout(nextItem, 3000); // skip broken clip; hold prior frame + mediaFailureSkip(video, 'video(buffered)', src); // skip broken clip; hold prior frame }); // Watchdog caps the wait so a cold/slow clip hard-cuts (mount+play) instead of the boundary hanging // (mirrors renderImageBuffered's watchdog). @@ -3633,7 +3680,7 @@ if (advanceTimer) { clearTimeout(advanceTimer); advanceTimer = null; } // Defense in depth: a transition widget is normalized out server-side and must never render as // content. If a stale/legacy payload still carries one, skip it instead of mounting a blank iframe. - if (item && item.widget_type === 'transition') { advanceTimer = setTimeout(nextItem, 0); return; } + if (item && item.widget_type === 'transition') { scheduleAdvance(nextItem, 0); return; } // Fullscreen (non-wall) widget: buffered swap — never blank on reload. Runs BEFORE the // generic teardown (which would black the screen), and owns its own refresh/advance // timer below. Multi-zone widgets go through renderZones; wall+widget keeps the legacy @@ -3650,8 +3697,8 @@ // its duration; the first mount + every genuine transition still go through the // buffered swap. const held = nextActiveIndex(currentIndex) === currentIndex; - if (held) advanceTimer = setTimeout(reevaluateHeldWidget, WIDGET_SOLO_REFRESH_MS); - else advanceTimer = setTimeout(nextItem, (item.duration_sec || 30) * 1000); + if (held) scheduleAdvance(reevaluateHeldWidget, WIDGET_SOLO_REFRESH_MS); + else scheduleAdvance(nextItem, (item.duration_sec || 30) * 1000); } return; } @@ -3776,10 +3823,7 @@ // advances the index (and the tick seeks position % duration to stay aligned). video.loop = (playlist.length === 1) || !!groupSync; video.onended = () => { if (!video.loop && !isFollower) nextItem(); }; - video.onerror = (e) => { - console.error('Video error:', src, e); - if (!isFollower) advanceTimer = setTimeout(nextItem, 3000); - }; + video.onerror = () => mediaFailureSkip(video, 'video', src, !isFollower); video.onloadeddata = () => { console.log('[wall/audio] video loaded file=' + item.filename + ' role=' + (wallConfig ? (wallConfig.is_leader ? 'leader' : 'follower') : 'solo') + ' muted=' + video.muted + ' volume=' + video.volume); }; @@ -3813,13 +3857,10 @@ img.style.cssText = wallConfig ? 'width:100%;height:100%;object-fit:fill' : 'width:100%;height:100%;object-fit:contain'; - img.onerror = () => { - console.error('Image error'); - if (!isFollower) advanceTimer = setTimeout(nextItem, 3000); - }; + img.onerror = () => mediaFailureSkip(img, 'image', src, !isFollower); mount.appendChild(img); // Leader / single screen drives image advance; follower waits for sync - if (!isFollower) advanceTimer = setTimeout(nextItem, (item.duration_sec || 10) * 1000); + if (!isFollower) scheduleAdvance(nextItem, (item.duration_sec || 10) * 1000); } else if (item.widget_id) { const iframe = document.createElement('iframe'); iframe.src = `${serverUrl}/api/widgets/${item.widget_id}/render?device=${encodeURIComponent(config.deviceId||'')}&rev=${item.widget_rev||0}`; @@ -3830,7 +3871,7 @@ iframe.setAttribute('sandbox', 'allow-scripts'); mount.appendChild(iframe); if (PREVIEW_MODE && item.widget_type === 'webpage') addWebpageNote(mount); // #104 - if (!isFollower) advanceTimer = setTimeout(nextItem, (item.duration_sec || 30) * 1000); + if (!isFollower) scheduleAdvance(nextItem, (item.duration_sec || 30) * 1000); } } } diff --git a/server/test/player-media-error-multiadvance.test.js b/server/test/player-media-error-multiadvance.test.js new file mode 100644 index 0000000..d949713 --- /dev/null +++ b/server/test/player-media-error-multiadvance.test.js @@ -0,0 +1,189 @@ +'use strict'; + +/* + * A media error used to advance the playlist once PER ERROR EVENT. + * + * Found on a BrightSign XT245 the day the live debug log started working, which is the only reason + * anyone saw it: a 40s clip on a SINGLE-item playlist logged four `Video error` events at each loop + * boundary and then three back-to-back "Playing:" lines, with `play() rejected AbortError` and + * `muted-fallback play() also failed` in between as the second mount aborted the first. On a + * one-item playlist that just re-plays the same file, so it looked like nothing. + * + * On a REAL playlist the identical storm skips one item per surplus event. Silently. The operator + * sees a playlist that drops content and nothing anywhere says why. + * + * Two independent defects produced it: + * + * 1. `video.onerror` had no once-guard (its sibling in the buffered path has `if (done) return`), + * so every event scheduled its own `nextItem`. + * 2. Every call site wrote `advanceTimer = setTimeout(...)` DIRECTLY. A second write before the + * first fired ORPHANED the earlier timer rather than cancelling it — still pending, no longer + * referenced, so `renderContent`'s `clearTimeout(advanceTimer)` could only ever cancel the + * last one. All the others fired. + * + * (2) is the more dangerous half: it made every one of a dozen call sites capable of leaking a + * timer, not just the error handlers. + */ +const { test } = require('node:test'); +const assert = require('node:assert/strict'); +const fs = require('fs'); +const path = require('path'); + +const ROOT = path.join(__dirname, '..', '..'); +const PLAYER = fs.readFileSync(path.join(ROOT, 'server/player/index.html'), 'utf8'); + +/* + * Run the real helpers with a fake clock, so "how many advances happened" is a fact rather than a + * reading of the source. + */ +function harness() { + const src = PLAYER.slice(PLAYER.indexOf('let advanceTimer = null;'), PLAYER.indexOf('// Buffered widget swap')); + const timers = new Map(); + let seq = 0; + const advances = []; + const logs = []; + const env = { + setTimeout: (fn, ms) => { const id = ++seq; timers.set(id, { fn, ms }); return id; }, // seq = total ever armed + clearTimeout: (id) => { timers.delete(id); }, + nextItem: () => advances.push(true), + console: { error: (m) => logs.push(['e', m]), warn: (m) => logs.push(['w', m]), log: (m) => logs.push(['i', m]) }, + }; + const api = new Function( + 'setTimeout', 'clearTimeout', 'nextItem', 'console', + `${src}; return { scheduleAdvance, mediaFailureSkip, pending: () => arguments };`, + )(env.setTimeout, env.clearTimeout, env.nextItem, env.console); + + return { + ...api, + advances, + logs, + fireAll() { for (const [id, t] of [...timers]) { timers.delete(id); t.fn(); } }, + pendingCount: () => timers.size, + armedEver: () => seq, + }; +} + +const mediaError = (code) => ({ code, message: '' }); + +test('four error events on one clip cause ONE advance, not four', () => { + // The exact sequence the XT245 produced. + const h = harness(); + const video = { error: mediaError(3), readyState: 0 }; + for (let i = 0; i < 4; i++) h.mediaFailureSkip(video, 'video', 'clip.mp4'); + assert.equal(h.pendingCount(), 1, 'only one advance may be pending'); + h.fireAll(); + assert.equal(h.advances.length, 1, `four errors advanced the playlist ${h.advances.length} times`); +}); + +test('...which is what stops a real playlist silently dropping items', () => { + // Stated separately because this is the customer-visible consequence, and it is the reason the + // one-item repro was worth chasing at all. + const h = harness(); + const video = { error: mediaError(2), readyState: 0 }; + for (let i = 0; i < 7; i++) h.mediaFailureSkip(video, 'video', 'clip.mp4'); + h.fireAll(); + assert.equal(h.advances.length, 1, 'a 10-item playlist would otherwise skip 6 items'); +}); + +test('the FIRST failure wins: later events cannot postpone the skip', () => { + /* + * This is what the once-guard buys that clear-before-arm does not. + * + * `scheduleAdvance` cancels the outgoing timer, so N errors already collapse to ONE advance. But + * without the guard, each error also RE-ARMS the 3s skip — so a clip erroring faster than every + * 3 seconds pushes its own skip out forever and wedges the playlist on a broken item, which is + * the exact failure the 3s skip exists to prevent. Counting armings, not advances, is the only + * assertion that can tell those two implementations apart. + */ + const h = harness(); + const video = { error: mediaError(3), readyState: 0 }; + for (let i = 0; i < 4; i++) h.mediaFailureSkip(video, 'video', 'clip.mp4'); + assert.equal(h.armedEver(), 1, `the skip must be armed once, not re-armed per event (armed ${h.armedEver()}x)`); +}); + +test('and it is reported once, not once per event', () => { + // The live debug log is fed by console.*, so a handler that logs per event turns one broken clip + // into a flood in the panel an operator opened to find it. + const h = harness(); + const video = { error: mediaError(3), readyState: 0 }; + for (let i = 0; i < 6; i++) h.mediaFailureSkip(video, 'video', 'clip.mp4'); + assert.equal(h.logs.filter(([lv]) => lv === 'e').length, 1); +}); + +test('the MediaError code is reported, because "Video error" alone explains nothing', () => { + // The original line logged the DOM event ({"isTrusted":true}) and never touched el.error, so the + // live log could say a video failed but never why. + const h = harness(); + h.mediaFailureSkip({ error: mediaError(3), readyState: 0 }, 'video', 'clip.mp4'); + const line = h.logs.find(([lv]) => lv === 'e')[1]; + assert.match(line, /code=3/); + assert.match(line, /DECODE/, 'the code must be named — nobody remembers the MediaError numbers'); + assert.match(line, /clip\.mp4/); +}); + +test('a playable element that raises a bare error is NOT thrown away', () => { + // `error` fires with el.error set. An event carrying no MediaError against an element with + // frames buffered ahead of it did not fail at anything, and discarding a healthy item on that + // basis is worse than the event being reacted to. + const h = harness(); + h.mediaFailureSkip({ error: null, readyState: 4 }, 'video', 'clip.mp4'); + h.fireAll(); + assert.equal(h.advances.length, 0, 'a still-playing video must not be skipped'); + assert.match(h.logs.find(([lv]) => lv === 'w')[1], /no MediaError while playable/, 'but it must be visible'); +}); + +test('THE BICONDITIONAL: something genuinely unplayable is still skipped', () => { + // The guard above must not become a way for a broken clip to stall the playlist forever. No + // MediaError AND nothing decoded is a failure. + const h = harness(); + h.mediaFailureSkip({ error: null, readyState: 0 }, 'video', 'clip.mp4'); + h.fireAll(); + assert.equal(h.advances.length, 1, 'an undecodable clip must never wedge the playlist'); +}); + +test('the load/watchdog path has no element and still skips', () => { + const h = harness(); + h.mediaFailureSkip(null, 'image', 'broken.png'); + h.fireAll(); + assert.equal(h.advances.length, 1); +}); + +test('a follower is told nothing to advance — the leader drives it', () => { + const h = harness(); + h.mediaFailureSkip({ error: mediaError(4), readyState: 0 }, 'video', 'clip.mp4', false); + h.fireAll(); + assert.equal(h.advances.length, 0, 'a follower advancing itself would desync the wall'); + assert.ok(h.logs.some(([lv]) => lv === 'e'), 'but the failure is still reported'); +}); + +// ---------------------------------------------------------------- the orphaned-timer class + +test('arming twice cancels the first timer instead of orphaning it', () => { + const h = harness(); + h.scheduleAdvance(() => {}, 1000); + h.scheduleAdvance(() => {}, 2000); + assert.equal(h.pendingCount(), 1, 'the first timer must be cancelled, not abandoned still-pending'); +}); + +test('every call site goes through the helper — one leak is enough to bring the bug back', () => { + // The generic fix. A dozen sites wrote the timer directly; any one of them re-introduced by hand + // restores a timer that renderContent cannot cancel. + const body = PLAYER.slice(PLAYER.indexOf('function scheduleAdvance')); + const direct = body.split('\n').filter((l) => /advanceTimer\s*=\s*setTimeout\(/.test(l)); + assert.equal(direct.length, 1, `only scheduleAdvance itself may assign the timer; found ${direct.length}:\n${direct.join('\n')}`); + assert.match(PLAYER.slice(PLAYER.indexOf('function scheduleAdvance'), PLAYER.indexOf('const MEDIA_ERR_NAME')), + /if \(advanceTimer\) clearTimeout\(advanceTimer\)/, 'the helper must clear before it arms'); +}); + +test('every media error handler goes through the shared skip', () => { + // Four handlers existed (buffered + non-buffered, video + image) and they had drifted apart: + // only one carried a once-guard. Four copies is how they drifted in the first place. + for (const marker of ["video.onerror = () => mediaFailureSkip(video, 'video', src)", + "img.onerror = () => mediaFailureSkip(img, 'image', src, !isFollower)", + "mediaFailureSkip(video, 'video(buffered)', src)", + "mediaFailureSkip(null, 'image', src)"]) { + assert.ok(PLAYER.includes(marker), `handler not routed through the shared skip: ${marker}`); + } + assert.ok(!/console\.error\('Video error:'/.test(PLAYER), 'the old unguarded handler must be gone'); + assert.ok(!/console\.error\('Image error'\)/.test(PLAYER), 'and its image twin'); +}); From 047f95f40c29a02d86845203bbc699d6bd5db8c7 Mon Sep 17 00:00:00 2001 From: ScreenTinker Date: Fri, 7 Aug 2026 19:26:03 -0500 Subject: [PATCH 3/4] Freeze and copy the live debug log, and unstick the control row Three small things off the device page. The control row had margin-top but no margin-bottom, so the buttons sat flush on top of the STATUS card and the destructive ones read as part of the status panel. Freeze is the one with a decision in it: it holds the VIEW still and keeps buffering underneath rather than pausing the stream. The moment you freeze a log to read something is the exact moment the lines that explain it are still arriving, so dropping them would throw away the part you were about to want. Resume replays them in order. The held buffer is capped at the same 500 as the panel, and the status text says how many are waiting -- otherwise a frozen panel is indistinguishable from a device that went quiet, and silence reads as a symptom. Overflow says so too. Copy takes what is on screen (not the held lines -- the paste must agree with the panel) and stamps it with the device and an ISO timestamp, because a pasted log with no device in it is a log nobody can act on. It falls back to execCommand when navigator.clipboard is absent, which is every self-hosted dashboard on plain http: that is not a secure context, and the other copy buttons in this app quietly do nothing there. Clear earns its place next to Copy: without it you always copy 500 lines of history instead of the capture you just made. The hint promised the stream "turns off on its own when the device reconnects", which was never true and is not what happens now -- it turns off when you leave the screen, and on the device after 30 minutes. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_014skWYXJUWhF73EvNPgB2AS --- frontend/js/i18n/en.js | 11 +- frontend/js/views/device-detail.js | 134 +++++++++++++-- .../test/dashboard-debug-log-controls.test.js | 161 ++++++++++++++++++ 3 files changed, 290 insertions(+), 16 deletions(-) create mode 100644 server/test/dashboard-debug-log-controls.test.js diff --git a/frontend/js/i18n/en.js b/frontend/js/i18n/en.js index 2464929..20d2763 100644 --- a/frontend/js/i18n/en.js +++ b/frontend/js/i18n/en.js @@ -549,7 +549,16 @@ export default { 'device.form.notes_label': 'Notes', 'device.form.notes_placeholder': 'Location, setup details, etc.', 'device.debug.toggle': 'Debug logging (live)', - 'device.debug.hint': 'Streams player/zone logs from this device in real time. Turns off on its own when the device reconnects.', + 'device.debug.hint': 'Streams this display\'s log in real time, and replays what it buffered before you opened it. Turns off when you leave this screen, and on the device itself after 30 minutes.', + 'device.debug.freeze': 'Freeze', + 'device.debug.resume': 'Resume', + 'device.debug.copy': 'Copy', + 'device.debug.clear': 'Clear', + 'device.debug.held': 'frozen — {n} new line(s) waiting', + 'device.debug.held_max': 'frozen — {n} waiting (oldest now being dropped)', + 'device.debug.copied': 'Copied {n} line(s) to the clipboard', + 'device.debug.copy_empty': 'Nothing to copy yet', + 'device.debug.copy_failed': 'Could not reach the clipboard — select the log and copy manually', 'device.ota.toggle': 'Self-update (OTA)', 'device.ota.beta': 'Accept pre-release builds', 'device.ota.beta_hint': 'Puts this display on the pre-release channel: it receives the beta build if the server has one published, and keeps a test build instead of being updated back to the current release. Untick to move it back to the release build. Does nothing if no beta is published.', diff --git a/frontend/js/views/device-detail.js b/frontend/js/views/device-detail.js index 7fd37ac..d8371da 100644 --- a/frontend/js/views/device-detail.js +++ b/frontend/js/views/device-detail.js @@ -38,6 +38,76 @@ let remoteActive = false; // emitting, the dashboard kept relaying, and nobody was listening. The player carries its own // auto-off as the backstop for the case this can't cover -- a tab that is killed, not closed. let debugStreamOn = false; +let debugFrozen = false; +let debugHeld = []; // lines that arrived while frozen, replayed on resume +const DEBUG_PANEL_MAX = 500; // panel rows AND the held-while-frozen cap + +// Every player sends a level and the panel used to render all four identically, so the one line +// that explains the fault sat in a wall of grey. Errors and warnings are why the operator opened it. +const DEBUG_LEVEL_COLOR = { e: '#f87171', w: '#fbbf24', d: '#64748b' }; + +function debugLineText(d) { + return `${new Date(d.ts || Date.now()).toLocaleTimeString()} [${d.tag || ''}] ${d.message || ''}`; +} + +function appendDebugLine(d) { + const panel = document.getElementById('debugLogPanel'); + if (!panel) return; + const line = document.createElement('div'); + line.textContent = debugLineText(d); // textContent — no HTML injection + const tone = DEBUG_LEVEL_COLOR[(d.level || '').toLowerCase()]; + if (tone) line.style.color = tone; + panel.appendChild(line); + while (panel.childElementCount > DEBUG_PANEL_MAX) panel.removeChild(panel.firstChild); + panel.scrollTop = panel.scrollHeight; +} + +function updateDebugTools() { + const btn = document.getElementById('debugFreezeBtn'); + const status = document.getElementById('debugLogStatus'); + if (btn) btn.textContent = debugFrozen ? t('device.debug.resume') : t('device.debug.freeze'); + if (status) { + // Say how many are waiting, so freezing never feels like the device went quiet. + status.textContent = debugFrozen + ? (debugHeld.length >= DEBUG_PANEL_MAX + ? t('device.debug.held_max', { n: debugHeld.length }) + : t('device.debug.held', { n: debugHeld.length })) + : ''; + } +} + +function setDebugFrozen(frozen) { + debugFrozen = frozen; + if (!frozen) { + const held = debugHeld; + debugHeld = []; + for (const d of held) appendDebugLine(d); // resume shows what you missed, in order + } + updateDebugTools(); +} + +/* + * Clipboard with a fallback, because a self-hosted dashboard on plain http is NOT a secure context + * and `navigator.clipboard` is simply absent there — the copy buttons elsewhere in this app quietly + * do nothing in that case. A debug log is precisely what a self-hoster wants to paste into an issue. + */ +async function copyToClipboard(text) { + try { + if (navigator.clipboard && window.isSecureContext) { await navigator.clipboard.writeText(text); return true; } + } catch (e) { /* fall through to the legacy path */ } + try { + const ta = document.createElement('textarea'); + ta.value = text; + ta.setAttribute('readonly', ''); + ta.style.cssText = 'position:fixed;top:-1000px;left:-1000px;opacity:0'; + document.body.appendChild(ta); + ta.select(); + ta.setSelectionRange(0, ta.value.length); + const ok = document.execCommand('copy'); + document.body.removeChild(ta); + return ok; + } catch (e) { return false; } +} // Belt for the orphaned-stream fix: if the tab is hidden/closed/backgrounded while a Remote session // is live, stop it (the server also auto-stops on socket drop, but bfcache keeps the socket alive). @@ -189,20 +259,16 @@ export function render(container, deviceId) { // checkbox is on). Appended via textContent — no HTML injection. logHandler = (data) => { if (data.device_id !== deviceId) return; - const panel = document.getElementById('debugLogPanel'); - if (!panel) return; - const line = document.createElement('div'); - const time = new Date(data.ts || Date.now()).toLocaleTimeString(); - line.textContent = `${time} [${data.tag || ''}] ${data.message || ''}`; - // Every player sends a level and the panel used to render all four identically, so the one - // line that explains the fault sat in a wall of grey. Errors and warnings are why the - // operator opened this. - const LEVEL_COLOR = { e: '#f87171', w: '#fbbf24', d: '#64748b' }; - const tone = LEVEL_COLOR[(data.level || '').toLowerCase()]; - if (tone) line.style.color = tone; - panel.appendChild(line); - while (panel.childElementCount > 500) panel.removeChild(panel.firstChild); - panel.scrollTop = panel.scrollHeight; + // Frozen: HOLD the line rather than drop it. A log you froze to read something is the exact + // moment the lines that explain it are still arriving — pausing the stream would throw away + // the part you were about to want. + if (debugFrozen) { + debugHeld.push(data); + if (debugHeld.length > DEBUG_PANEL_MAX) debugHeld.shift(); + updateDebugTools(); + return; + } + appendDebugLine(data); }; on('device-status', statusHandler); @@ -367,7 +433,7 @@ async function loadDevice(deviceId, activeTab = null) { past everything to reach the one button you came for. Kept as a single wrapping row so a narrow screen reflows rather than clipping, and each button still renders only where the display can honour it. --> -
+
${can('system.reboot') ? ` + + + +
@@ -1161,10 +1237,36 @@ function setupActions(device) { const enabled = e.target.checked; const panel = document.getElementById('debugLogPanel'); if (panel) panel.style.display = enabled ? 'block' : 'none'; + const tools = document.getElementById('debugLogTools'); + if (tools) tools.style.display = enabled ? 'flex' : 'none'; debugStreamOn = enabled; + // Unticking and reticking should not resume into a frozen panel the operator forgot about. + if (!enabled) { debugFrozen = false; debugHeld = []; } + updateDebugTools(); sendCommand(device.id, 'set_debug', { enabled }); }); + document.getElementById('debugFreezeBtn')?.addEventListener('click', () => setDebugFrozen(!debugFrozen)); + + document.getElementById('debugClearBtn')?.addEventListener('click', () => { + const panel = document.getElementById('debugLogPanel'); + if (panel) panel.textContent = ''; + debugHeld = []; + updateDebugTools(); + }); + + document.getElementById('debugCopyBtn')?.addEventListener('click', async () => { + const panel = document.getElementById('debugLogPanel'); + // Copy what is ON SCREEN. Anything held while frozen is deliberately excluded — the operator + // is copying the capture they are looking at, and silently appending lines they have not seen + // would make the paste disagree with the panel. + const text = panel ? [...panel.children].map((el) => el.textContent).join('\n') : ''; + if (!text) { showToast(t('device.debug.copy_empty'), 'error'); return; } + const header = `${device.name || device.id} — ${device.platform || ''} ${device.hardware_model || ''} — ${new Date().toISOString()}`.trim(); + const ok = await copyToClipboard(`${header}\n${'-'.repeat(header.length)}\n${text}\n`); + showToast(ok ? t('device.debug.copied', { n: panel.childElementCount }) : t('device.debug.copy_failed'), ok ? 'success' : 'error'); + }); + document.getElementById('saveNotesBtn')?.addEventListener('click', async () => { try { await api.updateDevice(device.id, { @@ -2187,6 +2289,8 @@ export function cleanup() { // the display should stop talking. Must run BEFORE currentDevice is cleared. if (debugStreamOn && currentDevice) sendCommand(currentDevice.id, 'set_debug', { enabled: false }); debugStreamOn = false; + debugFrozen = false; + debugHeld = []; remoteActive = false; currentDevice = null; window._sendKey = null; diff --git a/server/test/dashboard-debug-log-controls.test.js b/server/test/dashboard-debug-log-controls.test.js new file mode 100644 index 0000000..2c32885 --- /dev/null +++ b/server/test/dashboard-debug-log-controls.test.js @@ -0,0 +1,161 @@ +'use strict'; + +/* + * Freeze / Copy / Clear on the live debug panel, and the gap between the control row and the info + * grid. + * + * Freeze is the one with a real design decision in it. A log you froze to read something is the + * exact moment the lines that EXPLAIN it are still arriving, so freezing holds the view still and + * keeps buffering underneath — it does not pause the stream. Dropping them would throw away the + * part the operator was about to want, and the panel would have lied about being a live log. + */ +const { test } = require('node:test'); +const assert = require('node:assert/strict'); +const fs = require('fs'); +const path = require('path'); + +const ROOT = path.join(__dirname, '..', '..'); +const read = (p) => fs.readFileSync(path.join(ROOT, p), 'utf8'); +const DETAIL = read('frontend/js/views/device-detail.js'); +const EN = read('frontend/js/i18n/en.js'); + +// ------------------------------------------------------------------ layout + +test('the control row is separated from the info grid', () => { + // They rendered flush against each other: the buttons sat directly on top of the STATUS card + // with no gap, so the destructive ones read as part of the status panel. + const row = DETAIL.slice(DETAIL.indexOf('