diff options
| -rw-r--r-- | packages/meshbay-client/src/cast-relay.js | 53 | ||||
| -rw-r--r-- | packages/meshbay-hub/tests/test_cast_subtitles.py | 55 |
2 files changed, 75 insertions, 33 deletions
diff --git a/packages/meshbay-client/src/cast-relay.js b/packages/meshbay-client/src/cast-relay.js index 71c07a4..58eb9ac 100644 --- a/packages/meshbay-client/src/cast-relay.js +++ b/packages/meshbay-client/src/cast-relay.js @@ -19,7 +19,7 @@ * · Bind to the LAN interface, never 0.0.0.0 * · Fixed port range (19550-19553), opened only during active cast * · Unguessable token in the URL (32 hex chars) - * · CORS is granted on the subtitle path only, and still behind the token + * · CORS is granted on both served paths, and both stay behind the token * · Cache-Control: no-store on every response * · Server destroyed when playback stops — zero residual surface */ @@ -29,6 +29,25 @@ const crypto = require('node:crypto'); const http = require('node:http'); const os = require('node:os'); +const util = require('node:util'); + +/** + * Progress logging, off unless asked for: + * + * NODE_DEBUG=cast-relay npm start + * + * Most of what this class has to say repeats without bound — a line every + * fiftieth fragment for the length of a film, one per dropped fragment + * whenever a client falls behind — and it lands in the terminal the app was + * started from. Node's own `debuglog` is used rather than a flag of our own: + * it costs nothing when disabled, since the message is never even formatted. + * + * Nothing that stops a cast is hidden behind it. Every hard failure here + * throws — no free port, no such file — and the renderer already reports the + * rejection. The one fault that neither throws nor reaches anybody else is a + * loss of fMP4 framing, and that one stays on `console.warn`. + */ +const debug = util.debuglog('cast-relay'); const RING_CAP = 64; const BACKPRESSURE_HIGH = 8 * 1024 * 1024; @@ -71,7 +90,7 @@ class BoxAccumulator { if (!this._synced) { const idx = this._findMoof(); if (idx === -1) return fragments; - console.log(`[cast-relay] box sync: found first moof at byte offset ${idx}, discarded ${idx} bytes`); + debug(`[cast-relay] box sync: found first moof at byte offset ${idx}, discarded ${idx} bytes`); this._buf = this._buf.subarray(idx); this._synced = true; } @@ -81,7 +100,11 @@ class BoxAccumulator { const type = this._buf.readUInt32BE(4); if (size < 8) { - console.log(`[cast-relay] box sync lost: invalid size ${size}, rescanning`); + // Not `debug`: the byte stream stopped being framed fMP4. It recovers + // by rescanning, so nothing throws and nobody else ever hears about + // it — this line is the only trace that the picture on the television + // is missing a piece. + console.warn(`[cast-relay] box sync lost: invalid size ${size}, rescanning`); this._synced = false; const idx = this._findMoof(); if (idx === -1) return fragments; @@ -182,7 +205,7 @@ class CastRelay { if (!sub || !sub.vtt) { this._subtitle = null; this._subtitleVersion++; - console.log('[cast-relay] subtitle cleared'); + debug('[cast-relay] subtitle cleared'); return null; } this._subtitle = { @@ -191,7 +214,7 @@ class CastRelay { label: sub.label || '', }; this._subtitleVersion++; - console.log(`[cast-relay] subtitle set: ${this._subtitle.vtt.length} bytes` + debug(`[cast-relay] subtitle set: ${this._subtitle.vtt.length} bytes` + `, lang "${this._subtitle.language}", v${this._subtitleVersion}`); return this.subtitle; } @@ -232,14 +255,14 @@ class CastRelay { bound = true; } catch (err) { if (err.code !== 'EADDRINUSE') throw err; - console.log(`[cast-relay] port ${port} busy, trying next`); + debug(`[cast-relay] port ${port} busy, trying next`); } } if (!bound) throw new Error('All cast relay ports are in use'); this._server = server; - console.log(`[cast-relay] started on ${this.url}`); - console.log(`[cast-relay] init segment: ${this._initSegment ? this._initSegment.length + ' bytes' : 'none'}`); + debug(`[cast-relay] started on ${this.url}`); + debug(`[cast-relay] init segment: ${this._initSegment ? this._initSegment.length + ' bytes' : 'none'}`); return { url: this.url, port: this._port, @@ -257,7 +280,7 @@ class CastRelay { for (const frag of fragments) { this._fragCount++; if (this._fragCount <= 3 || this._fragCount % 50 === 0) { - console.log(`[cast-relay] fragment #${this._fragCount}: ${frag.length} bytes (from ${this._chunkCount} chunks), ${this._clients.size} client(s)`); + debug(`[cast-relay] fragment #${this._fragCount}: ${frag.length} bytes (from ${this._chunkCount} chunks), ${this._clients.size} client(s)`); } if (this._ring.length >= RING_CAP) { @@ -267,7 +290,7 @@ class CastRelay { for (const res of this._clients) { if (res.writableLength > BACKPRESSURE_HIGH) { - console.log(`[cast-relay] backpressure: dropping fragment for slow client`); + debug(`[cast-relay] backpressure: dropping fragment for slow client`); continue; } res.write(frag); @@ -277,14 +300,14 @@ class CastRelay { } finish() { - console.log('[cast-relay] finishing stream'); + debug('[cast-relay] finishing stream'); for (const res of this._clients) { try { res.end(); } catch { /* already closed */ } } } async stop() { - console.log(`[cast-relay] stopping — ${this._chunkCount} chunks, ${this._fragCount} fragments, ${(this._bytesSent / 1048576).toFixed(1)} MB sent`); + debug(`[cast-relay] stopping — ${this._chunkCount} chunks, ${this._fragCount} fragments, ${(this._bytesSent / 1048576).toFixed(1)} MB sent`); for (const res of this._clients) { try { res.end(); } catch { /* already closed */ } } @@ -372,12 +395,12 @@ class CastRelay { sent += frag.length; } - console.log(`[cast-relay] client connected from ${req.socket.remoteAddress} — sent init + ${this._ring.length} fragments (${(sent / 1024).toFixed(0)} KB)`); + debug(`[cast-relay] client connected from ${req.socket.remoteAddress} — sent init + ${this._ring.length} fragments (${(sent / 1024).toFixed(0)} KB)`); this._clients.add(res); req.on('close', () => { this._clients.delete(res); - console.log(`[cast-relay] client disconnected, ${this._clients.size} remaining`); + debug(`[cast-relay] client disconnected, ${this._clients.size} remaining`); }); } @@ -394,7 +417,7 @@ class CastRelay { 'Cache-Control': 'no-store', }); res.end(this._subtitle.vtt); - console.log(`[cast-relay] subtitle served: ${this._subtitle.vtt.length} bytes`); + debug(`[cast-relay] subtitle served: ${this._subtitle.vtt.length} bytes`); } } diff --git a/packages/meshbay-hub/tests/test_cast_subtitles.py b/packages/meshbay-hub/tests/test_cast_subtitles.py index 3fe627d..fdf7fcc 100644 --- a/packages/meshbay-hub/tests/test_cast_subtitles.py +++ b/packages/meshbay-hub/tests/test_cast_subtitles.py @@ -393,28 +393,47 @@ def test_a_stream_without_subtitles_declares_none(loaded): assert loaded["without"]["options"]["activeTrackIds"] == [] -@chromecast_only -def test_progress_logging_is_off_unless_asked_for(): +# Anything that reaches the terminal whatever the user asked for. `warn` and +# `info` are named alongside `log` because a future line using either would be +# exactly as loud, and a guard that names only `log` would not see it. +LOUD = ("console.log(", "console.warn(", "console.info(") + +# The one line per module that is deliberately audible, and why. Each names a +# fault that nothing else in the system reports: a cast that goes quiet, or a +# television showing a picture with a hole in it. Both are the kind of thing +# somebody has to be told about without knowing in advance to ask. +DELIBERATELY_AUDIBLE = { + "cast-chromecast.js": "console.error(`[cast-chromecast] client error", + "cast-relay.js": "console.warn(`[cast-relay] box sync lost", +} + + +@pytest.mark.parametrize("path", [CHROMECAST, RELAY], ids=lambda p: p.name) +def test_progress_logging_is_off_unless_asked_for(path): """ - The receiver reports its state on a timer, so `player status: PLAYING` - repeats for as long as a film runs. Left on `console.log` it fills the - terminal the app was started from and buries everything else in it. + Casting talks constantly and says almost nothing. The receiver reports its + state on a timer, so `player status: PLAYING` repeats for as long as a film + runs; the relay logs every fiftieth fragment, and one line per dropped + fragment whenever a client falls behind. All of it lands in the terminal the + app was started from, and buries whatever was worth reading there. - Read rather than run because the noisy line only fires with a device on the - network. What is checked is the property that matters: nothing in this - module reaches the terminal unconditionally except a failure. `console.warn` - and `console.info` are named too — a future line using either would be just - as loud, and this guard would not otherwise see it. + Read rather than run because the noisy lines need a device on the network to + fire at all. What is asserted is the property that survives that: the only + thing either module says unbidden is the failure it alone can report. """ - src = CHROMECAST.read_text(encoding="utf-8") + if not path.exists(): + pytest.skip("desktop client sources not present") + src = path.read_text(encoding="utf-8") + audible = DELIBERATELY_AUDIBLE[path.name] + unconditional = [ line.strip() for line in src.splitlines() - if ("console.log(" in line or "console.warn(" in line - or "console.info(" in line) - and not line.lstrip().startswith(("*", "//"))] + if any(token in line for token in LOUD) + and not line.lstrip().startswith(("*", "//")) + and audible not in line] assert unconditional == [], ( "these reach the terminal whatever the user asked for; route them " - f"through `debug` or `console.error`: {unconditional}") - # And the failure path is still audible, or a cast that dies takes its own - # explanation with it. - assert "console.error(`[cast-chromecast] client error" in src + f"through `debug`: {unconditional}") + + assert audible in src, ( + f"{path.name} no longer reports the one fault nothing else does") |