diff --git a/brightsign/autorun.brs b/brightsign/autorun.brs index 8b45384..a335896 100644 --- a/brightsign/autorun.brs +++ b/brightsign/autorun.brs @@ -460,7 +460,7 @@ End Function ' card holds nothing but autorun.zip and the OS processes it. Once autorun.brs exists at the ' storage root the OS no longer auto-processes the archive — so from then on the host has to do it ' itself, or self-update would work exactly once. -Sub ApplyPendingPackage(root As String) +Sub ApplyPendingPackage(root As String, buf As Object) dir$ = root + "/" zipPath$ = root + "/autorun.zip" donePath$ = root + "/autorun.zip.done" @@ -470,11 +470,11 @@ Sub ApplyPendingPackage(root As String) if not FileExists(dir$ + "autorun.zip") then return if FileExists(dir$ + "autorun.zip.done") then return ' already unpacked; again is the boot loop - print "[st-update] unpacking pending package" + LogTo(buf, "update", "unpacking pending package") package = CreateObject("roBrightPackage", zipPath$) if package = invalid then - print "[st-update] ERROR: archive unreadable — parking it as .bad" + LogTo(buf, "update", "ERROR: archive unreadable — parking it as .bad") MoveFile(zipPath$, badPath$) return end if @@ -492,7 +492,7 @@ Sub ApplyPendingPackage(root As String) ' Unpack() returns Void, so success is proven by looking for what should now exist rather than ' by testing a return value that was never there. if not FileExists(stage$ + "/autorun.brs") then - print "[st-update] ERROR: extract produced no autorun.brs — parking it as .bad" + LogTo(buf, "update", "ERROR: extract produced no autorun.brs — parking it as .bad") MoveFile(zipPath$, badPath$) return end if @@ -507,15 +507,15 @@ Sub ApplyPendingPackage(root As String) if MoveFile(stage$ + "/" + name, root + "/" + name) then moved% = moved% + 1 end if end for - print "[st-update] installed "; moved%; " file(s)" + LogTo(buf, "update", "installed " + Stri(moved%).Trim() + " file(s)") if not MoveFile(zipPath$, donePath$) then ' Refusing to reboot without the marker: we would extract and reboot forever. - print "[st-update] ERROR: could not mark done — not rebooting" + LogTo(buf, "update", "ERROR: could not mark done — not rebooting") return end if - print "[st-update] package applied — rebooting into it" + LogTo(buf, "update", "package applied — rebooting into it") sleep(2000) RebootSystem() End Sub @@ -646,10 +646,112 @@ Function VerifyPackage(path As String, expected As String, expectedSize As Integ return LCase(digest.ToHexString()) = LCase(expected) End Function +'=== host diagnostics ======================================================================= +' +' Everything the host knows that the PAGE cannot ask for, routed into the same channels the other +' players already use: the dashboard log stream, the device-event feed, and the heartbeat telemetry. +' +' This exists because of a specific, expensive afternoon. A single bad string literal stopped this +' script compiling, and the only evidence anywhere was a line on a serial console — the server saw a +' player that simply never appeared, and the display showed nothing. Every other player reports its +' own failures; this one printed them to a cable. A panel on a wall has no cable. +' +' The pre-widget phase is the part that matters most and is the part that is hardest to reach: the +' storage probe, a pending package being applied, the video mode being set, all happen before there +' is a page to talk to. Those lines accumulate in a buffer and are flushed the moment the widget +' exists, so the boot story arrives even though it happened before anyone could listen. + +' Append a diagnostic to the pre-widget buffer AND put it on the console. The buffer is an roArray +' created in Main and passed down; BrightScript has no global store (no GetGlobalAA here), and +' threading it explicitly beats the alternative of losing the boot entirely. +Sub LogTo(buf As Object, tag As String, message As String) + print "[st-"; tag; "] "; message + if buf <> invalid then + if buf.Count() < 200 then ' a boot that logs 200 lines has a worse problem + buf.Push({ tag: tag, message: message }) + end if + end if +End Sub + +' Send one diagnostic to the page, which forwards it to the server as a device:log line. +Sub HostLog(widget As Object, tag As String, message As String) + print "[st-"; tag; "] "; message + if widget = invalid then return + widget.PostJSMessage({ type: "host-log", tag: tag, level: "i", message: message }) +End Sub + +' Hand the buffered boot diagnostics to the page in one go, oldest first. +Sub FlushLog(widget As Object, buf As Object) + if widget = invalid or buf = invalid then return + for each line in buf + widget.PostJSMessage({ type: "host-log", tag: line.tag, level: "i", message: line.message }) + end for + buf.Clear() +End Sub + +' A device EVENT rather than a log line: these land in the incident feed the dashboard shows against +' a display, so they are reserved for things an operator would want explained — a reboot, a network +' change, the player falling over. +Sub HostEvent(widget As Object, event As String, reason As String, detail As String) + print "[st-event] "; event; " "; reason; " "; detail + if widget = invalid then return + widget.PostJSMessage({ type: "host-event", event: event, reason: reason, detail: detail }) +End Sub + +' The facts only the host can see. The page has no API for any of this: @brightsign/storage exposes +' format and eject, not volumes; there is no JavaScript route to the uptime, the wired IP, the video +' mode actually in force, or which volume the player booted from. +Sub SendHostTelemetry(widget As Object, cfg As Object) + if widget = invalid then return + + t = { type: "host-telemetry" } + + ' Seconds since boot. A display that reports a small uptime every time it is polled is + ' rebooting in a loop, which is otherwise indistinguishable from a healthy one. + up = UpTime(0) + if up <> invalid then t.uptime_seconds = Int(up) + + di = CreateObject("roDeviceInfo") + if di <> invalid then + t.model = di.GetModel() + t.os_version = di.GetVersion() + end if + + ' The wired address. Empty string when nothing is configured, per the documented contract. + nc = CreateObject("roNetworkConfiguration", 0) + if nc <> invalid then + cur = nc.GetCurrentConfig() + if cur <> invalid and cur.ip4_address <> invalid and cur.ip4_address <> "" then + t.local_ip = cur.ip4_address + end if + end if + + vm = CreateObject("roVideoMode") + if vm <> invalid then t.video_mode = vm.GetMode() + + ' Which volume is actually in use, and how much of it is left. The page's + ' navigator.storage.estimate() reports the widget's CACHE QUOTA, not the disk — a panel can + ' report gigabytes free while the volume holding them is full. + st = StorageProbe() + if st.present then + t.storage_volume = st.volume + t.storage_free_mb = st.free_mb + t.storage_total_mb = st.total_mb + end if + t.boot_volume = StorageRoot() + t.package_version = PackageVersion() + + widget.PostJSMessage(t) +End Sub + '=== main =================================================================================== Sub Main() + ' Diagnostics from before there is a page to send them to. Flushed the moment the widget exists. + boot = CreateObject("roArray", 32, true) + cfg = LoadConfig() + LogTo(boot, "boot", "host " + PackageVersion() + " from " + StorageRoot() + " -> " + cfg.server_url) ' Crash dumps land here if the widget ever falls over — cheap, and the only forensic trail ' available on a panel nobody can reach. @@ -661,7 +763,7 @@ Sub Main() ' A package staged by a previous run lands here, before anything is on screen. Doing it after ' the widget started would mean rebooting out of a playing playlist, and the panel would blink ' mid-content for a reason nobody watching could explain. - ApplyPendingPackage(StorageRoot()) + ApplyPendingPackage(StorageRoot(), boot) port = CreateObject("roMessagePort") @@ -681,6 +783,11 @@ Sub Main() widget = MakeWidget(PlayerUrl(cfg, 1), rect, port, cfg) widget.Show() + ' The boot story, delivered late but delivered. Everything above here happened with no page to + ' talk to, which is exactly the window in which the interesting failures live. + FlushLog(widget, boot) + SendHostTelemetry(widget, cfg) + widget2 = invalid if dual then screen2 = 2 @@ -706,7 +813,14 @@ Sub Main() ' exception, decoder stall) without the OS ever reporting an error. st-bridge.js posts a ' heartbeat every 30s; three missed beats and we rebuild the widget. This is the difference ' between a panel that recovers on its own and one that needs a site visit. - WATCHDOG_MS = 120000 + ' Seconds first, milliseconds derived: the diagnostic message needs an INTEGER to format, and + ' dividing at the call site would hand Stri a float. + WATCHDOG_S = 120 + WATCHDOG_MS = WATCHDOG_S * 1000 + + lastHostTel = CreateObject("roTimespan") + lastHostTel.Mark() + HOST_TEL_MS = 60000 while true msg = wait(5000, port) @@ -726,7 +840,12 @@ Sub Main() ' The key is `uri` on a load-error; `url` belongs to download-request. Printing ' the wrong one meant the single diagnostic that names the failing resource always ' printed "invalid". - print "[st] load-error ("; retries; "): "; data.uri + ' data.uri is already a String per the event contract, so no conversion is wanted: + ' Str() is for numbers and would abort the event loop. Guarded because a missing key + ' yields invalid, and assigning invalid to a $-typed name is a runtime error. + uri$ = "" + if data.uri <> invalid then uri$ = data.uri + HostEvent(widget, "app_error", "load-error", "attempt " + Stri(retries).Trim() + ": " + uri$) sleep(ChooseBackoff(retries)) if retries >= 3 then ' The server URL rides along so the fallback page can name it on screen and @@ -804,11 +923,21 @@ Sub Main() ' watchdog if lastBeat.TotalMilliseconds() > WATCHDOG_MS then - print "[st] watchdog: no heartbeat in "; WATCHDOG_MS; "ms — rebuilding widget" + ' Reported as a crash, because that is what it is from the floor: the page stopped + ' answering and the host restarted it. Previously this healed the panel in silence, so a + ' display rebuilding itself every two minutes looked identical to one that was fine. + HostEvent(widget, "crash", "watchdog", "no heartbeat for " + Stri(WATCHDOG_S).Trim() + "s — rebuilt the widget") widget = RebuildWidget(widget, PlayerUrl(cfg, 1), rect, port, cfg) lastBeat.Mark() end if + ' Host facts, on the same cadence as the package check is cheap but far too slow to be + ' useful; every telemetry tick would be too chatty. A minute is what the dashboard shows. + if lastHostTel.TotalMilliseconds() > HOST_TEL_MS then + lastHostTel.Mark() + SendHostTelemetry(widget, cfg) + end if + ' Periodic package check. Marked BEFORE the call, not after: a check that blocks on a slow ' server would otherwise be retried immediately on the next tick and hammer it. if cfg.self_update and lastPkgCheck.TotalMilliseconds() > PKG_CHECK_MS then diff --git a/brightsign/st-bridge.js b/brightsign/st-bridge.js index c2940ea..67421b2 100644 --- a/brightsign/st-bridge.js +++ b/brightsign/st-bridge.js @@ -230,6 +230,30 @@ // its own telemetry object, and a null here would overwrite a value another player family had // legitimately supplied. Absent means "nothing to say", which is not the same as "zero". var telemetry = {}; + + /* + * Facts pushed by the host, merged into the same cache the heartbeat reads. + * + * Registered at load, directly on the listener list rather than behind the readiness gate: the + * host starts sending these the moment the widget exists, and anything attached later would miss + * the boot report — the one that says which volume the player came up from and whether a package + * applied. + * + * The host's numbers WIN over the page's where they overlap. navigator.storage.estimate() + * describes the widget's cache quota, not the disk: a panel can report gigabytes free while the + * volume holding them is full, and only the host can tell the difference. + */ + listeners.push(function (msg) { + if (msg && msg.type === 'host-telemetry') { + var keys = ['uptime_seconds', 'local_ip', 'model', 'os_version', 'video_mode', + 'storage_volume', 'storage_free_mb', 'storage_total_mb', + 'boot_volume', 'package_version']; + for (var i = 0; i < keys.length; i++) { + var v = msg[keys[i]]; + if (v !== undefined && v !== null && v !== '') telemetry[keys[i]] = v; + } + } + }); var TELEMETRY_REFRESH_MS = 60000; var deviceInfo = null; @@ -625,6 +649,42 @@ onHostMessage: function (fn) { if (typeof fn === 'function') listeners.push(fn); }, + /* + * Host diagnostics, routed into the channels the player already speaks. + * + * The host sees things the page has no API for — the uptime, the wired IP, the video mode + * actually in force, which volume it booted from, whether a staged package applied — and until + * now it printed all of it to a serial console. On a panel on a wall that is the same as not + * reporting it. A bad string literal once stopped this script compiling and the only evidence + * anywhere was on a cable; the server just saw a player that never appeared. + * + * These are deliberately thin: the bridge does not decide what a log line or an incident MEANS, + * it just carries them to the player, which sends them the same way it sends its own. + */ + onHostLog: function (fn) { + if (typeof fn !== 'function') return; + listeners.push(function (msg) { + if (!msg || msg.type !== 'host-log') return; + fn({ + tag: String(msg.tag || 'host').slice(0, 64), + level: String(msg.level || 'i').slice(0, 8), + message: String(msg.message || '').slice(0, 2000) + }); + }); + }, + + onHostEvent: function (fn) { + if (typeof fn !== 'function') return; + listeners.push(function (msg) { + if (!msg || msg.type !== 'host-event' || !msg.event) return; + fn({ + event: String(msg.event), + reason: String(msg.reason || '').slice(0, 64), + detail: String(msg.detail || '').slice(0, 500) + }); + }); + }, + /* * Telemetry, read synchronously from a cache. * diff --git a/server/player/index.html b/server/player/index.html index bbf016c..0268e14 100644 --- a/server/player/index.html +++ b/server/player/index.html @@ -503,6 +503,35 @@ let swRegistrationFailed = false; // feat/offline-cause-log: typed incident feed (device:event) — server inserts a device_events row. // Best-effort + auth-guarded (the reconnected socket is authenticated by the time we emit). + /* + * BrightSign host diagnostics, forwarded as if the page had produced them. + * + * The host sees what the page cannot — the uptime, the wired IP, which volume it booted from, + * whether a staged package applied — and everything it knew used to go to a serial console. + * On a panel on a wall that is the same as knowing nothing: a script that failed to compile + * looked, from here, exactly like a player that never started. + * + * Wired once, guarded, and a no-op on every other platform: the hooks only exist on the + * BrightSign bridge, so a browser skips this entirely. + */ + function wireHostDiagnostics() { + try { + if (!BS || typeof BS.onHostLog !== 'function') return; + BS.onHostLog((line) => { + try { + if (socket?.connected && config.deviceId) { + socket.emit('device:log', { + device_id: config.deviceId, + tag: line.tag, level: line.level, message: line.message + }); + } + console.log(`[host/${line.tag}] ${line.message}`); + } catch (e) { /* diagnostics must never break playback */ } + }); + BS.onHostEvent((ev) => emitDeviceEvent(ev.event, ev.reason, ev.detail)); + } catch (e) { /* a bridge that throws here must not stop the player starting */ } + } + function emitDeviceEvent(type, reason, detail) { try { if (!socket?.connected || !config.deviceId) return; @@ -1380,6 +1409,9 @@ startWatchdog(); // v4: arm-gated half-open watchdog (no-op until a heartbeat-ack arms it) startPlaylistRefresh(); startVersionCheck(); + // After the socket is up, because these forward to the SERVER — wiring them earlier would + // drop the host's boot report on the floor rather than delivering it late. + wireHostDiagnostics(); }); socket.on('device:paired', (data) => { diff --git a/server/test/brightscript-api-surface.test.js b/server/test/brightscript-api-surface.test.js index 598ffd0..2b4e6da 100644 --- a/server/test/brightscript-api-surface.test.js +++ b/server/test/brightscript-api-surface.test.js @@ -213,3 +213,15 @@ test('file existence is tested with roReadFile, not MatchFiles', () => { `${f}: FileExists must use roReadFile — MatchFiles does not answer reliably for a volume root`); } }); + +test('Str() is never applied to something that is already a string', () => { + // Str(value As Float). Handing it a string is a type error that aborts wherever it runs — and the + // place this was reached from is the event loop, i.e. it would take the player down while + // reporting a diagnostic. Message keys documented as String need no conversion at all. + for (const f of FILES) { + for (const m of code(f).matchAll(/\bStr\((\w+(?:\.\w+)*)\)/g)) { + assert.ok(/%$|^\d/.test(m[1]) || /count|len|size|retries|attempts/i.test(m[1]), + `${f}: Str(${m[1]}) — Str is for numbers; a String needs no conversion`); + } + } +}); diff --git a/server/test/brightsign-host-diagnostics.test.js b/server/test/brightsign-host-diagnostics.test.js new file mode 100644 index 0000000..3a27dd8 --- /dev/null +++ b/server/test/brightsign-host-diagnostics.test.js @@ -0,0 +1,116 @@ +'use strict'; + +// A BrightSign knows things the page cannot ask for — the uptime, the wired IP, the video mode +// actually in force, which volume it booted from, whether a staged package applied — and all of it +// used to go to a serial console. On a panel on a wall that is the same as reporting nothing. +// +// The cost was concrete: a single bad string literal stopped the host script compiling, and the only +// evidence anywhere in the world was one line on a cable. From the server the display looked +// identical to one that had simply never started. Every other player reports its own failures. +// +// This pins the three-hop contract — host posts, bridge forwards, player emits — because no part of +// it can be executed here. The host half is BrightScript (no interpreter), the bridge half needs a +// widget, and a broken link in the chain is silent by construction: diagnostics that do not arrive +// look exactly like diagnostics that were never generated. + +const { test } = require('node:test'); +const assert = require('node:assert/strict'); +const fs = require('node:fs'); +const path = require('node:path'); + +const ROOT = path.join(__dirname, '..', '..'); +const host = fs.readFileSync(path.join(ROOT, 'brightsign', 'autorun.brs'), 'utf8'); +const bridge = fs.readFileSync(path.join(ROOT, 'brightsign', 'st-bridge.js'), 'utf8'); +const player = fs.readFileSync(path.join(ROOT, 'server', 'player', 'index.html'), 'utf8'); +const code = host.split('\n').filter((l) => !/^\s*'/.test(l)).join('\n'); + +test('the host reports its boot story, which happens before there is a page to hear it', () => { + // The interesting failures all live in this window: the storage probe, a pending package being + // applied, the video mode being set. A design that could only report after the widget existed + // would miss every one of them. + assert.match(code, /Sub LogTo\(buf As Object/, 'a buffer the pre-widget phase can log into'); + assert.match(code, /Sub FlushLog\(widget As Object, buf As Object\)/, 'and a flush once there is a page'); + assert.match(code, /boot = CreateObject\("roArray"/, 'Main must create the buffer'); + assert.match(code, /FlushLog\(widget, boot\)/, 'and flush it once the widget exists'); + // The update path is the one that replaces the boot script — its diagnostics are the ones you + // most want when a player does not come back. + assert.match(code, /Sub ApplyPendingPackage\(root As String, buf As Object\)/); + assert.match(code, /LogTo\(buf, "update"/); +}); + +test('the host reports facts the page has no API for', () => { + const fn = code.slice(code.indexOf('Sub SendHostTelemetry')); + for (const [needle, why] of [ + ['UpTime(', 'a display that always reports a small uptime is reboot-looping'], + ['roNetworkConfiguration', 'the wired IP — there is no JavaScript route to it'], + ['GetVersion', 'the OS build, which decides which APIs exist at all'], + ['StorageProbe()', 'the real volume, not the widget cache quota'], + ['StorageRoot()', 'which volume it booted from'], + ['PackageVersion()', 'what it is actually running'], + ]) { + assert.ok(fn.slice(0, 2000).includes(needle), `host telemetry must include ${needle}: ${why}`); + } +}); + +test('a widget rebuild is reported as an incident, not just a console line', () => { + // The watchdog healing a wedged page is the single most important thing a BrightSign does + // unattended. Doing it silently made a panel rebuilding itself every two minutes look identical + // to one that was healthy. + assert.match(code, /HostEvent\(widget, "crash", "watchdog"/); + assert.match(code, /HostEvent\(widget, "app_error", "load-error"/); +}); + +test('the event types the host emits are ones the server actually accepts', () => { + // The server drops unknown event types silently, so an invented one would be exactly as + // invisible as the console.warn this replaces. + const allowed = fs.readFileSync(path.join(ROOT, 'server', 'lib', 'incident-classify.js'), 'utf8'); + for (const m of code.matchAll(/HostEvent\([^,]+,\s*"([a-z_]+)"/g)) { + assert.ok(allowed.includes(`'${m[1]}'`), `the server does not accept event type "${m[1]}"`); + } +}); + +test('the bridge carries logs and events without interpreting them', () => { + assert.match(bridge, /onHostLog: function/); + assert.match(bridge, /onHostEvent: function/); + // Bounded before they reach the wire: the server truncates too, but a host bug should not be + // able to push a megabyte through the socket every second. + assert.match(bridge, /msg\.message \|\| ''\)\.slice\(0, 2000\)/); + assert.match(bridge, /msg\.detail \|\| ''\)\.slice\(0, 500\)/); +}); + +test('host telemetry merges into the snapshot the heartbeat already sends', () => { + // Not a new channel — the heartbeat has carried BS.telemetrySnapshot() for releases. The host + // simply fills in the fields only it can see. + assert.match(bridge, /msg\.type === 'host-telemetry'/); + assert.match(bridge, /telemetry\[keys\[i\]\] = v/); + assert.match(player, /BS\.telemetrySnapshot\(\) : \{\}/); +}); + +test('the host telemetry listener is registered at load, not behind the readiness gate', () => { + // The host sends its boot report the moment the widget exists. A listener attached after the + // bridge finished its own probe would miss precisely the message that says which volume the + // player came up from and whether a package applied. + const seg = bridge.slice(bridge.indexOf('var telemetry = {}'), bridge.indexOf('var telemetry = {}') + 1400); + assert.match(seg, /listeners\.push\(function \(msg\)/); + assert.ok(!/onReady\(function/.test(seg), 'must not wait on readiness to start listening'); +}); + +test('the player forwards them, and only where the hooks exist', () => { + assert.match(player, /function wireHostDiagnostics\(\)/); + assert.match(player, /typeof BS\.onHostLog !== 'function'\) return;/, 'a browser must skip this entirely'); + assert.match(player, /socket\.emit\('device:log'/); + assert.match(player, /BS\.onHostEvent\(\(ev\) => emitDeviceEvent\(ev\.event, ev\.reason, ev\.detail\)\)/); +}); + +test('forwarding is wired AFTER the socket, or the boot report is dropped rather than delayed', () => { + const connect = player.slice(player.indexOf('startVersionCheck();'), player.indexOf('startVersionCheck();') + 400); + assert.match(connect, /wireHostDiagnostics\(\)/); +}); + +test('diagnostics can never take the player down', () => { + // The whole point is a display that keeps playing while telling you it is unhappy. A reporting + // path that throws would invert that. + const fn = player.slice(player.indexOf('function wireHostDiagnostics'), player.indexOf('function emitDeviceEvent')); + assert.equal((fn.match(/try \{/g) || []).length >= 2, true, 'both the wiring and each callback must be guarded'); + assert.match(fn, /catch \(e\) \{ \/\* diagnostics must never break playback/); +});