Merge pull request #253 from screentinker/feat/web-player-live-debug-log

Live debug log on the web player — and the playlist-skipping bug it found
This commit is contained in:
screentinker 2026-08-07 20:47:05 -05:00 committed by GitHub
commit 04068f7f0a
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
7 changed files with 1082 additions and 31 deletions

View file

@ -549,7 +549,16 @@ export default {
'device.form.notes_label': 'Notes', 'device.form.notes_label': 'Notes',
'device.form.notes_placeholder': 'Location, setup details, etc.', 'device.form.notes_placeholder': 'Location, setup details, etc.',
'device.debug.toggle': 'Debug logging (live)', '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.toggle': 'Self-update (OTA)',
'device.ota.beta': 'Accept pre-release builds', '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.', '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.',

View file

@ -33,6 +33,81 @@ let shellHandler = null;
let diagPollTimer = null; // polls a diag-smoothness widget's reported frame stats while the page is open let diagPollTimer = null; // polls a diag-smoothness widget's reported frame stats while the page is open
let screenshotInterval = null; let screenshotInterval = null;
let remoteActive = false; 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;
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 // 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). // is live, stop it (the server also auto-stops on socket drop, but bfcache keeps the socket alive).
@ -184,14 +259,16 @@ export function render(container, deviceId) {
// checkbox is on). Appended via textContent — no HTML injection. // checkbox is on). Appended via textContent — no HTML injection.
logHandler = (data) => { logHandler = (data) => {
if (data.device_id !== deviceId) return; if (data.device_id !== deviceId) return;
const panel = document.getElementById('debugLogPanel'); // Frozen: HOLD the line rather than drop it. A log you froze to read something is the exact
if (!panel) return; // moment the lines that explain it are still arriving — pausing the stream would throw away
const line = document.createElement('div'); // the part you were about to want.
const time = new Date(data.ts || Date.now()).toLocaleTimeString(); if (debugFrozen) {
line.textContent = `${time} [${data.tag || ''}] ${data.message || ''}`; debugHeld.push(data);
panel.appendChild(line); if (debugHeld.length > DEBUG_PANEL_MAX) debugHeld.shift();
while (panel.childElementCount > 500) panel.removeChild(panel.firstChild); updateDebugTools();
panel.scrollTop = panel.scrollHeight; return;
}
appendDebugLine(data);
}; };
on('device-status', statusHandler); on('device-status', statusHandler);
@ -356,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 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 so a narrow screen reflows rather than clipping, and each button still renders only
where the display can honour it. --> where the display can honour it. -->
<div style="margin-top:20px;display:flex;gap:8px;flex-wrap:wrap"> <div style="margin:20px 0;display:flex;gap:8px;flex-wrap:wrap">
${can('system.reboot') ? ` ${can('system.reboot') ? `
<button class="btn btn-secondary btn-sm" id="rebootBtn"> <button class="btn btn-secondary btn-sm" id="rebootBtn">
<svg width="14" height="14" viewBox="0 0 24 24" fill="none" stroke="currentColor" stroke-width="2"> <svg width="14" height="14" viewBox="0 0 24 24" fill="none" stroke="currentColor" stroke-width="2">
@ -624,6 +701,16 @@ async function loadDevice(deviceId, activeTab = null) {
<input type="checkbox" id="debugLogToggle"> ${t('device.debug.toggle')} <input type="checkbox" id="debugLogToggle"> ${t('device.debug.toggle')}
</label> </label>
<div style="font-size:11px;color:var(--text-muted);margin:4px 0 0 24px">${t('device.debug.hint')}</div> <div style="font-size:11px;color:var(--text-muted);margin:4px 0 0 24px">${t('device.debug.hint')}</div>
<!-- Freeze holds the view still WITHOUT dropping what arrives: a log you are reading
scrolls the interesting line off the top, and pausing the stream instead would lose
exactly the lines that follow the fault. Copy exists because the useful next step is
pasting this into an issue. -->
<div id="debugLogTools" style="display:none;margin-top:8px;gap:6px;align-items:center;flex-wrap:wrap">
<button class="btn btn-secondary btn-sm" id="debugFreezeBtn">${t('device.debug.freeze')}</button>
<button class="btn btn-secondary btn-sm" id="debugCopyBtn">${t('device.debug.copy')}</button>
<button class="btn btn-secondary btn-sm" id="debugClearBtn">${t('device.debug.clear')}</button>
<span id="debugLogStatus" style="font-size:11px;color:var(--text-muted)"></span>
</div>
<div id="debugLogPanel" style="display:none;margin-top:8px;background:#0b0f1a;border:1px solid var(--border);border-radius:6px;padding:8px;height:220px;overflow-y:auto;font-family:monospace;font-size:11px;line-height:1.45;color:#cbd5e1"></div> <div id="debugLogPanel" style="display:none;margin-top:8px;background:#0b0f1a;border:1px solid var(--border);border-radius:6px;padding:8px;height:220px;overflow-y:auto;font-family:monospace;font-size:11px;line-height:1.45;color:#cbd5e1"></div>
</div> </div>
@ -1150,9 +1237,36 @@ function setupActions(device) {
const enabled = e.target.checked; const enabled = e.target.checked;
const panel = document.getElementById('debugLogPanel'); const panel = document.getElementById('debugLogPanel');
if (panel) panel.style.display = enabled ? 'block' : 'none'; 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 }); 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 () => { document.getElementById('saveNotesBtn')?.addEventListener('click', async () => {
try { try {
await api.updateDevice(device.id, { await api.updateDevice(device.id, {
@ -2171,6 +2285,12 @@ export function cleanup() {
if (shellHandler) off('shell-result', shellHandler); // #161 owner-tools listener if (shellHandler) off('shell-result', shellHandler); // #161 owner-tools listener
if (screenshotInterval) clearInterval(screenshotInterval); if (screenshotInterval) clearInterval(screenshotInterval);
if (remoteActive && currentDevice) stopRemote(currentDevice.id); 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;
debugFrozen = false;
debugHeld = [];
remoteActive = false; remoteActive = false;
currentDevice = null; currentDevice = null;
window._sendKey = null; window._sendKey = null;

View file

@ -24,6 +24,12 @@
try { return Date.now(); } catch (e) { return new Date().getTime(); } 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) { function pushLog(entry) {
try { try {
entry.t = nowMs(); entry.t = nowMs();
@ -32,8 +38,22 @@
window.__debugLog.splice(0, window.__debugLog.length - MAX_LOG); window.__debugLog.splice(0, window.__debugLog.length - MAX_LOG);
} }
} catch (e) { /* we are the safety net; do not crash */ } } 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_push = pushLog; // shared pusher for debug-overlay.js
window.__debugLog_subscribe = function (fn) {
try { if (typeof fn === 'function') subs.push(fn); } catch (e) {}
};
pushLog({ pushLog({
type: 'init', type: 'init',
@ -515,6 +535,23 @@
// ==================== State ==================== // ==================== State ====================
let socket = null; let socket = null;
let config = getConfig(); let config = getConfig();
/*
* Does a <video> on this platform actually yield pixels to a canvas? Cached: it is a property
* of the platform, not of the clip. Consumed by videoCompositingAvailable() ~2900 lines below.
*
* DECLARED HERE, AND IT MUST STAY HERE. It used to live next to its function, and that BRICKED
* a player: boot restores the cached playlist and renders item 0 from a call site far above
* that point, so when item 0 was a video carrying a transition, `isVideoBufferable` read this
* binding before its `let` had executed. That is a TemporalDeadZone *throw*, not a `null` —
* the player died during boot, every boot, and because the offending playlist came from the
* LOCAL cache it never stayed up long enough to receive a corrected one. A permanent brick,
* recoverable only by clearing the device's storage.
*
* Reproduced on a BrightSign XT245 on 2026-08-07: "Cannot access '_videoCompositingOk' before
* initialization @ player:3730". Any web-based player could hit it — it is not BrightSign-specific.
*/
let _videoCompositingOk = null;
// feat/offline-cause-log: connectivity-report state — track in-session disconnects so the next // feat/offline-cause-log: connectivity-report state — track in-session disconnects so the next
// reconnect can report WHY it was gone (local link lost vs server/upstream unreachable). A browser // reconnect can report WHY it was gone (local link lost vs server/upstream unreachable). A browser
// can't see SSID/RSSI, so we send only offline_ms + link_lost + cold_start:false. // can't see SSID/RSSI, so we send only offline_ms + link_lost + cold_start:false.
@ -542,7 +579,12 @@
if (!BS || typeof BS.onHostLog !== 'function') return; if (!BS || typeof BS.onHostLog !== 'function') return;
BS.onHostLog((line) => { BS.onHostLog((line) => {
try { 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', { socket.emit('device:log', {
device_id: config.deviceId, device_id: config.deviceId,
tag: line.tag, level: line.level, message: line.message tag: line.tag, level: line.level, message: line.message
@ -555,6 +597,171 @@
} catch (e) { /* a bridge that throws here must not stop the player starting */ } } 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 <head> 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) { function emitDeviceEvent(type, reason, detail) {
try { try {
if (!socket?.connected || !config.deviceId) return; if (!socket?.connected || !config.deviceId) return;
@ -664,6 +871,51 @@
// playback muted). // playback muted).
let userHasInteracted = false; let userHasInteracted = false;
let advanceTimer = null; 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 // 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 // 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 // blanks the screen. WIDGET_SWAP_TIMEOUT_MS reveals anyway if 'load' never fires (a
@ -1705,6 +1957,10 @@
if (v === null) console.warn('[volume] set_volume with no usable level/value:', JSON.stringify(data)); if (v === null) console.warn('[volume] set_volume with no usable level/value:', JSON.stringify(data));
else setMediaVolume(v); 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; // #129: real-time mute. Apply immediately if the toggled item is the one playing now;
@ -3081,7 +3337,7 @@
// schedule-awareness / Fix A preserved). // schedule-awareness / Fix A preserved).
function reevaluateHeldWidget() { function reevaluateHeldWidget() {
if (nextActiveIndex(currentIndex) === currentIndex) { if (nextActiveIndex(currentIndex) === currentIndex) {
advanceTimer = setTimeout(reevaluateHeldWidget, WIDGET_SOLO_REFRESH_MS); scheduleAdvance(reevaluateHeldWidget, WIDGET_SOLO_REFRESH_MS);
return; return;
} }
nextItem(); nextItem();
@ -3141,7 +3397,7 @@
const c = document.getElementById('playerContainer'); const c = document.getElementById('playerContainer');
c.style.display = 'block'; c.style.display = 'block';
c.appendChild(img); c.appendChild(img);
advanceTimer = setTimeout(nextItem, (item.duration_sec || 10) * 1000); scheduleAdvance(nextItem, (item.duration_sec || 10) * 1000);
preloadNextImage(); preloadNextImage();
} }
// ---- GL transition (feat/transition-engine). Every failure path hard-cuts — never a blank. ---- // ---- GL transition (feat/transition-engine). Every failure path hard-cuts — never a blank. ----
@ -3163,7 +3419,9 @@
// videoFrameIsCapturable() already asks the right question (a 16x16 ALPHA probe, so a genuine // videoFrameIsCapturable() already asks the right question (a 16x16 ALPHA probe, so a genuine
// fade-to-black still reads as captured) but was only ever wired into the screenshot path. // fade-to-black still reads as captured) but was only ever wired into the screenshot path.
// Cached because the answer is a property of the platform, not of the clip. // Cached because the answer is a property of the platform, not of the clip.
let _videoCompositingOk = null; // (The cache variable itself is declared far above, in State — see the note there. It MUST NOT
// be declared here: boot renders the cached playlist from a call site above this line, and a
// `let` read before its declaration executes is a TemporalDeadZone throw, not a `null`.)
function videoCompositingAvailable(v) { function videoCompositingAvailable(v) {
if (_videoCompositingOk !== null) return _videoCompositingOk; if (_videoCompositingOk !== null) return _videoCompositingOk;
if (!v || v.readyState < 2 || !v.videoWidth) return true; // undecided don't cache a guess if (!v || v.readyState < 2 || !v.videoWidth) return true; // undecided don't cache a guess
@ -3285,7 +3543,7 @@
const dwellMs = (item.duration_sec || 10) * 1000; const dwellMs = (item.duration_sec || 10) * 1000;
const container = document.getElementById('playerContainer'); const container = document.getElementById('playerContainer');
runGlWipe(fromImg, toImg, t, dwellMs, 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 () => { // mount: swap in the image, keep the armed timer
toImg.style.cssText = 'width:100%;height:100%;object-fit:contain'; toImg.style.cssText = 'width:100%;height:100%;object-fit:contain';
container.appendChild(toImg); container.appendChild(toImg);
@ -3315,7 +3573,9 @@
const fail = () => { const fail = () => {
if (done) return; done = true; if (done) return; done = true;
if (watchdog) clearTimeout(watchdog); 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 // 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); watchdog = setTimeout(() => { if (cached) swap(cached); else fail(); }, 3000);
@ -3384,7 +3644,7 @@
video.muted = (!userHasInteracted || !!item.muted); // autoplay policy + per-item mute (#129) video.muted = (!userHasInteracted || !!item.muted); // autoplay policy + per-item mute (#129)
if (!video.muted) video.volume = 1.0; if (!video.muted) video.volume = 1.0;
video.onended = () => { if (!video.loop) nextItem(); }; 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 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 setTimeout(() => { if (video.paused) { video.muted = true; video.play().catch(() => {}); } }, 2000); // last-resort kick
}; };
@ -3422,7 +3682,7 @@
video.addEventListener('error', () => { video.addEventListener('error', () => {
if (done) return; done = true; if (done) return; done = true;
if (watchdog) clearTimeout(watchdog); 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 // Watchdog caps the wait so a cold/slow clip hard-cuts (mount+play) instead of the boundary hanging
// (mirrors renderImageBuffered's watchdog). // (mirrors renderImageBuffered's watchdog).
@ -3439,7 +3699,7 @@
if (advanceTimer) { clearTimeout(advanceTimer); advanceTimer = null; } if (advanceTimer) { clearTimeout(advanceTimer); advanceTimer = null; }
// Defense in depth: a transition widget is normalized out server-side and must never render as // 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. // 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 // 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 // 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 // timer below. Multi-zone widgets go through renderZones; wall+widget keeps the legacy
@ -3456,8 +3716,8 @@
// its duration; the first mount + every genuine transition still go through the // its duration; the first mount + every genuine transition still go through the
// buffered swap. // buffered swap.
const held = nextActiveIndex(currentIndex) === currentIndex; const held = nextActiveIndex(currentIndex) === currentIndex;
if (held) advanceTimer = setTimeout(reevaluateHeldWidget, WIDGET_SOLO_REFRESH_MS); if (held) scheduleAdvance(reevaluateHeldWidget, WIDGET_SOLO_REFRESH_MS);
else advanceTimer = setTimeout(nextItem, (item.duration_sec || 30) * 1000); else scheduleAdvance(nextItem, (item.duration_sec || 30) * 1000);
} }
return; return;
} }
@ -3582,10 +3842,7 @@
// advances the index (and the tick seeks position % duration to stay aligned). // advances the index (and the tick seeks position % duration to stay aligned).
video.loop = (playlist.length === 1) || !!groupSync; video.loop = (playlist.length === 1) || !!groupSync;
video.onended = () => { if (!video.loop && !isFollower) nextItem(); }; video.onended = () => { if (!video.loop && !isFollower) nextItem(); };
video.onerror = (e) => { video.onerror = () => mediaFailureSkip(video, 'video', src, !isFollower);
console.error('Video error:', src, e);
if (!isFollower) advanceTimer = setTimeout(nextItem, 3000);
};
video.onloadeddata = () => { 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); console.log('[wall/audio] video loaded file=' + item.filename + ' role=' + (wallConfig ? (wallConfig.is_leader ? 'leader' : 'follower') : 'solo') + ' muted=' + video.muted + ' volume=' + video.volume);
}; };
@ -3619,13 +3876,10 @@
img.style.cssText = wallConfig img.style.cssText = wallConfig
? 'width:100%;height:100%;object-fit:fill' ? 'width:100%;height:100%;object-fit:fill'
: 'width:100%;height:100%;object-fit:contain'; : 'width:100%;height:100%;object-fit:contain';
img.onerror = () => { img.onerror = () => mediaFailureSkip(img, 'image', src, !isFollower);
console.error('Image error');
if (!isFollower) advanceTimer = setTimeout(nextItem, 3000);
};
mount.appendChild(img); mount.appendChild(img);
// Leader / single screen drives image advance; follower waits for sync // 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) { } else if (item.widget_id) {
const iframe = document.createElement('iframe'); const iframe = document.createElement('iframe');
iframe.src = `${serverUrl}/api/widgets/${item.widget_id}/render?device=${encodeURIComponent(config.deviceId||'')}&rev=${item.widget_rev||0}`; iframe.src = `${serverUrl}/api/widgets/${item.widget_id}/render?device=${encodeURIComponent(config.deviceId||'')}&rev=${item.widget_rev||0}`;
@ -3636,7 +3890,7 @@
iframe.setAttribute('sandbox', 'allow-scripts'); iframe.setAttribute('sandbox', 'allow-scripts');
mount.appendChild(iframe); mount.appendChild(iframe);
if (PREVIEW_MODE && item.widget_type === 'webpage') addWebpageNote(mount); // #104 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);
} }
} }
} }

View file

@ -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('<!-- The actions an operator opens this page to take'), DETAIL.indexOf('rebootBtn'));
assert.match(row, /margin:20px 0/, 'the row needs room BELOW it, not just above');
assert.ok(!/margin-top:20px;display:flex/.test(row), 'margin-top alone leaves the grid flush against the buttons');
});
// ------------------------------------------------------------------ freeze
/* Run the real panel logic against a minimal DOM. */
function harness() {
const rows = [];
const panel = {
children: rows,
get childElementCount() { return rows.length; },
get firstChild() { return rows[0]; },
appendChild: (el) => rows.push(el),
removeChild: (el) => rows.splice(rows.indexOf(el), 1),
scrollTop: 0, scrollHeight: 0, style: {}, textContent: '',
};
const els = { debugLogPanel: panel, debugFreezeBtn: { textContent: '' }, debugLogStatus: { textContent: '' } };
const src = DETAIL.slice(DETAIL.indexOf('const DEBUG_LEVEL_COLOR'), DETAIL.indexOf('async function copyToClipboard'));
const state = { debugFrozen: false, debugHeld: [] };
const api = new Function('document', 't', 'state', `
const DEBUG_PANEL_MAX = 500;
let debugFrozen = state.debugFrozen, debugHeld = state.debugHeld;
${src}
return {
appendDebugLine, setDebugFrozen, updateDebugTools, debugLineText,
push: (d) => { if (debugFrozen) { debugHeld.push(d); if (debugHeld.length > DEBUG_PANEL_MAX) debugHeld.shift(); updateDebugTools(); return; } appendDebugLine(d); },
held: () => debugHeld.length,
};`)(
{ getElementById: (id) => els[id] || null, createElement: () => ({ textContent: '', style: {} }) },
(k, v) => `${k}:${v ? v.n : ''}`,
state,
);
return { ...api, panel, els, text: () => rows.map((r) => r.textContent) };
}
test('freezing HOLDS incoming lines rather than dropping them', () => {
const h = harness();
h.push({ message: 'before', ts: 1 });
h.setDebugFrozen(true);
h.push({ message: 'during-1', ts: 2 });
h.push({ message: 'during-2', ts: 3 });
assert.equal(h.panel.childElementCount, 1, 'the view must not move while frozen');
assert.equal(h.held(), 2, 'but the lines must be kept');
});
test('resuming replays what was missed, in order', () => {
const h = harness();
h.setDebugFrozen(true);
h.push({ message: 'a', ts: 1 });
h.push({ message: 'b', ts: 2 });
h.setDebugFrozen(false);
const shown = h.text().join('|');
assert.match(shown, /a.*b/, 'order must survive the freeze');
assert.equal(h.held(), 0, 'and the buffer must be drained, not replayed twice');
h.push({ message: 'c', ts: 3 });
assert.equal(h.panel.childElementCount, 3, 'live appending resumes');
});
test('a panel left frozen overnight is bounded', () => {
const h = harness();
h.setDebugFrozen(true);
for (let i = 0; i < 640; i++) h.push({ message: 'x' + i, ts: i });
assert.equal(h.held(), 500, 'the held buffer must not grow without limit');
h.setDebugFrozen(false);
assert.equal(h.panel.childElementCount, 500, 'and the panel stays capped too');
});
test('freezing says how many lines are waiting', () => {
// Otherwise a frozen panel is indistinguishable from a device that went quiet, and the operator
// reads silence as a symptom.
const h = harness();
h.setDebugFrozen(true);
h.push({ message: 'x', ts: 1 });
assert.match(h.els.debugLogStatus.textContent, /device\.debug\.held:1/);
assert.match(h.els.debugFreezeBtn.textContent, /device\.debug\.resume/, 'the button must offer the way out');
});
test('overflowing while frozen says so, rather than silently discarding', () => {
const h = harness();
h.setDebugFrozen(true);
for (let i = 0; i < 501; i++) h.push({ message: 'x', ts: i });
assert.match(h.els.debugLogStatus.textContent, /held_max/, 'silent truncation would misrepresent the capture');
});
// ------------------------------------------------------------------ copy
test('copy works on a self-hosted dashboard over plain http', () => {
// navigator.clipboard is ABSENT outside a secure context — every other copy button in this app
// quietly does nothing there, and a debug log is exactly what a self-hoster wants to paste.
const fn = DETAIL.slice(DETAIL.indexOf('async function copyToClipboard'), DETAIL.indexOf('async function copyToClipboard') + 900);
assert.match(fn, /window\.isSecureContext/, 'the modern path must be gated on the context it requires');
assert.match(fn, /execCommand\('copy'\)/, 'and there must be a fallback for when it is not');
assert.match(fn, /removeChild\(ta\)/, 'the scratch textarea must not be left in the DOM');
});
test('copy takes what is on screen, and says how much', () => {
const h = DETAIL.slice(DETAIL.indexOf("document.getElementById('debugCopyBtn')"), DETAIL.indexOf("document.getElementById('debugCopyBtn')") + 1200);
assert.match(h, /panel\.children/, 'the copy must come from the rendered panel');
assert.match(h, /device\.debug\.copied/);
assert.match(h, /device\.debug\.copy_failed/, 'a clipboard that refuses must say so, not fail silently');
assert.match(h, /device\.debug\.copy_empty/);
// A pasted log with no device in it is a log nobody can act on.
assert.match(h, /device\.name/);
assert.match(h, /toISOString/);
});
test('unticking the checkbox cannot leave a hidden frozen panel behind', () => {
const h = DETAIL.slice(DETAIL.indexOf("document.getElementById('debugLogToggle')?.addEventListener"), DETAIL.indexOf("document.getElementById('debugFreezeBtn')?.addEventListener"));
assert.match(h, /debugFrozen = false/, 're-ticking would otherwise resume into a freeze nobody remembers setting');
assert.match(h, /debugLogTools/, 'the toolbar must follow the panel');
});
test('leaving the screen resets the freeze state too', () => {
const fn = DETAIL.slice(DETAIL.indexOf('export function cleanup()'));
assert.match(fn, /debugFrozen = false/);
assert.match(fn, /debugHeld = \[\]/, 'held lines from another device must not leak into the next one');
});
// ------------------------------------------------------------------ strings
test('every new string exists', () => {
for (const k of ['freeze', 'resume', 'copy', 'clear', 'held', 'held_max', 'copied', 'copy_empty', 'copy_failed']) {
assert.ok(EN.includes(`'device.debug.${k}'`), `missing device.debug.${k}`);
}
});
test('the hint describes how it actually turns off now', () => {
// It used to promise "turns off on its own when the device reconnects", which was never what
// happened and is not what happens now either.
const hint = /'device\.debug\.hint': '((?:[^'\\]|\\.)*)'/.exec(EN)[1];
assert.ok(!/reconnects/.test(hint), 'the old claim must be gone');
assert.match(hint, /30 minutes/, 'the device-side auto-off is the part an operator must be able to rely on');
});

View file

@ -0,0 +1,86 @@
'use strict';
/*
* THE BRICK: a `let` read during boot, before its declaration had executed.
*
* Found the hard way on 2026-08-07 a BrightSign XT245 on shipped 1.9.32 went dark and STAYED
* dark across reboots. The exit beacon said:
*
* crashed: Cannot access '_videoCompositingOk' before initialization @ player:3730:12
*
* Boot restores the CACHED playlist and renders item 0 immediately, from a call site ~2300 lines
* above where `_videoCompositingOk` was declared. When that item was a video carrying a transition,
* `isVideoBufferable` read the binding while it was still in the temporal dead zone. A TDZ read is
* a *throw*, not a `null` so the player died during boot.
*
* And because the offending playlist came from the device's OWN localStorage cache, it never
* stayed up long enough to receive a corrected one. Every boot re-read the same poisoned cache and
* died the same way: a permanent brick, recoverable only by clearing device storage. Rebooting the
* player the one remedy an operator has did nothing.
*
* Nothing about this is BrightSign-specific. Any web-based player could hit it.
*
* The fix is placement, so the test is about placement: anything boot can reach must be declared
* before boot runs. A guard rather than a repro, because reproducing it needs a whole page
* lifecycle and a guard is what stops it coming back when someone tidies the declaration back
* down next to its function, which is exactly where it looked like it belonged.
*/
const { test } = require('node:test');
const assert = require('node:assert/strict');
const fs = require('fs');
const path = require('path');
const PLAYER = fs.readFileSync(path.join(__dirname, '..', '..', 'server/player/index.html'), 'utf8');
const lineOf = (needle) => PLAYER.slice(0, PLAYER.indexOf(needle)).split('\n').length;
test('the compositing cache is declared before the Boot section, not beside its function', () => {
const decl = PLAYER.indexOf('let _videoCompositingOk = null;');
const boot = PLAYER.indexOf('==================== Boot ====================');
assert.ok(decl > 0, '_videoCompositingOk declaration not found');
assert.ok(boot > 0, 'Boot section marker not found');
assert.ok(
decl < boot,
`declared at line ${lineOf('let _videoCompositingOk = null;')} but Boot starts at line ` +
`${lineOf('==================== Boot ====================')} — boot renders the cached playlist ` +
'and would read this binding in its temporal dead zone, bricking the player on every boot',
);
});
test('it is declared exactly once — a second `let` would shadow nothing and throw again', () => {
const n = (PLAYER.match(/let _videoCompositingOk\b/g) || []).length;
assert.equal(n, 1, `expected one declaration, found ${n}`);
});
test('every CODE read of it happens after the declaration', () => {
// Comments must not count: this file documents the bug by name, both here and at the old
// declaration site, and those mentions sit above the declaration by design.
const stripped = PLAYER
.replace(/\/\*[\s\S]*?\*\//g, (m) => ' '.repeat(m.length)) // block comments -> spaces, offsets preserved
.replace(/(^|[^:])\/\/[^\n]*/g, (m) => ' '.repeat(m.length)); // line comments (not "://" in URLs)
const decl = stripped.indexOf('let _videoCompositingOk = null;');
assert.ok(decl > 0, 'declaration not found in stripped source');
const early = [];
const re = /_videoCompositingOk/g;
let m;
while ((m = re.exec(stripped))) if (m.index < decl) early.push(m.index);
assert.equal(early.length, 0,
`${early.length} code read(s) precede the declaration — each one is a temporal-dead-zone throw`);
});
test('the boot path really does render a cached item before the old declaration site', () => {
// Documents WHY the ordering matters, so a future reader can see the hazard is structural and
// not a style preference. If this ever stops being true the guard above is merely harmless.
const restore = PLAYER.indexOf('const cachedPlaylist = loadPlaylistCache();');
const consumer = PLAYER.indexOf('&& _videoCompositingOk !== false;');
assert.ok(restore > 0 && consumer > 0);
assert.ok(
restore < consumer,
'boot restores and renders the cached playlist before the consumer appears in source order — ' +
'which is the whole reason the declaration must be hoisted above boot',
);
// And the consumer is reached only for video, which is why an image-first playlist survived it.
const decl = PLAYER.slice(PLAYER.indexOf('const isVideoBufferable'), consumer + 40);
assert.match(decl, /mime_type\.startsWith\('video\/'\)/,
'the short-circuit on video mime is what kept image-first playlists alive');
});

View file

@ -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 <head> 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 <head> error trap for real — it is ES5 and self-contained, so it executes standalone. */
function loadTrap() {
const start = PLAYER.indexOf('<script>');
const src = PLAYER.slice(PLAYER.indexOf('(function () {', start), PLAYER.indexOf('</script>', 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\)/);
});

View file

@ -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');
});