diff --git a/bin/api/player_log.dart b/bin/api/player_log.dart new file mode 100644 index 0000000..3a17c2b --- /dev/null +++ b/bin/api/player_log.dart @@ -0,0 +1,70 @@ +import 'dart:convert'; + +import 'package:shelf/shelf.dart'; + +/// Journal des incidents de lecture remontés par le lecteur web. +/// +/// POURQUOI : les freezes (image et son figés puis reprise) se produisent +/// chez l'utilisateur, dans son navigateur ; le serveur n'en voit rien. Le +/// lecteur envoie ici chaque coupure, erreur, recréation et saut, et le +/// serveur les écrit dans `docker logs` (`[Player] …`) : on sait alors si un +/// freeze vient d'un buffer à sec, d'une erreur du démuxeur ou d'une +/// relance du flux. +/// +/// Entrée non fiable : seuls des champs connus, courts et typés passent. + +const _events = { + 'start', 'first_frame', 'stall', 'seek', 'mpegts_error', 'recreate', + 'fallback_hls', 'hls_error', 'profile', 'error_shown', 'heartbeat', +}; + +const _numericFields = { + 't', 'ms', 'buffer', 'pos', 'from', 'to', 'stalls', 'stallMs', 'seeks', + 'errors', 'rate', +}; + +const _textFields = {'session', 'ch', 'mode', 'profile', 'detail'}; + +/// Ligne de journal pour l'événement [raw], ou null s'il est invalide. +String? formatPlayerEvent(Object? raw) { + if (raw is! Map) return null; + final event = raw['event']; + if (event is! String || !_events.contains(event)) return null; + + final parts = [event]; + for (final key in _textFields) { + final value = raw[key]; + if (value is String && value.isNotEmpty) { + // Ni espace, ni retour ligne, ni URL : jamais d'injection de faux + // journaux, jamais d'identifiants recopiés depuis une URL d'erreur. + final safe = value + .replaceAll(RegExp(r'https?://\S+'), '') + .replaceAll(RegExp(r'[^\w.\-:/<>]'), '_'); + parts.add('$key=${safe.length > 60 ? safe.substring(0, 60) : safe}'); + } + } + for (final key in _numericFields) { + final value = raw[key]; + if (value is num && value.isFinite) { + parts.add('$key=${value is int ? value : value.toStringAsFixed(1)}'); + } + } + return '[Player] ${parts.join(' ')}'; +} + +Future handlePlayerLog(Request request) async { + final body = await request.readAsString(); + if (body.length > 4096) return Response(413); + Object? decoded; + try { + decoded = jsonDecode(body); + } catch (_) { + return Response.badRequest(); + } + final events = decoded is List ? decoded.take(20) : [decoded]; + for (final event in events) { + final line = formatPlayerEvent(event); + if (line != null) print(line); + } + return Response(204); +} diff --git a/bin/server.dart b/bin/server.dart index c34bc45..79b1e10 100644 --- a/bin/server.dart +++ b/bin/server.dart @@ -29,6 +29,7 @@ import 'services/cleanup_service.dart'; import 'services/recording_scheduler.dart'; import 'utils/asset_versioning.dart'; import 'api/upstream_probe.dart'; +import 'api/player_log.dart'; void main(List args) async { // Parse command line arguments @@ -221,6 +222,14 @@ void main(List args) async { .addMiddleware(authMiddleware(db)) .addHandler(logoApi.handle), ) + // Incidents de lecture remontés par le lecteur web (freezes, erreurs), + // écrits dans les logs pour le diagnostic. + ..post( + '/api/player-log', + const Pipeline() + .addMiddleware(authMiddleware(db)) + .addHandler(handlePlayerLog), + ) // EPG - guide TV (auth required) ..mount( '/api/epg', diff --git a/bin/test/player_log_test.dart b/bin/test/player_log_test.dart new file mode 100644 index 0000000..a047fb2 --- /dev/null +++ b/bin/test/player_log_test.dart @@ -0,0 +1,47 @@ +import 'package:test/test.dart'; +import '../api/player_log.dart'; + +void main() { + group('formatPlayerEvent', () { + test('écrit une coupure avec sa durée et le buffer', () { + expect( + formatPlayerEvent({ + 'event': 'stall', + 'session': 'ab12', + 'ch': '554034', + 'ms': 5230, + 'buffer': 0.04, + }), + '[Player] stall session=ab12 ch=554034 ms=5230 buffer=0.0', + ); + }); + + test('refuse un événement inconnu ou un payload invalide', () { + expect(formatPlayerEvent({'event': 'rm -rf'}), isNull); + expect(formatPlayerEvent('stall'), isNull); + expect(formatPlayerEvent(null), isNull); + }); + + test('pas d\'injection de lignes ni d\'URL (identifiants Xtream)', () { + final line = formatPlayerEvent({ + 'event': 'mpegts_error', + 'detail': 'NetworkError http://panel/live/user/pass/1.ts\n[Player] faux', + })!; + expect(line, isNot(contains('\n'))); + expect(line, isNot(contains('user/pass'))); + expect(line, contains('')); + }); + + test('ignore les champs inattendus et les nombres non finis', () { + final line = formatPlayerEvent({ + 'event': 'seek', + 'from': 10, + 'to': double.infinity, + 'cookie': 'secret', + })!; + expect(line, contains('from=10')); + expect(line, isNot(contains('to='))); + expect(line, isNot(contains('secret'))); + }); + }); +} diff --git a/test/web/xf_player_core_test.mjs b/test/web/xf_player_core_test.mjs index c499fed..8791026 100644 --- a/test/web/xf_player_core_test.mjs +++ b/test/web/xf_player_core_test.mjs @@ -101,6 +101,54 @@ test('live : le retard est résorbé en douceur (liveSync) plutôt que par sauts assert.ok(c.liveSyncMaxLatency <= c.liveBufferLatencyMaxLatency); }); +test('télémétrie : une coupure (waiting → playing) est remontée avec sa durée', async () => { + const sent = []; + const listeners = {}; + const video = { + addEventListener(type, fn) { (listeners[type] ||= []).push(fn); }, + removeEventListener() {}, + canPlayType: () => '', + play: () => Promise.resolve(), + buffered: { length: 0 }, + seekable: { length: 0 }, + currentTime: 12, + playbackRate: 1, + }; + const fire = (type) => (listeners[type] || []).forEach((fn) => fn()); + const window = { + addEventListener() {}, removeEventListener() {}, + console: { log() {} }, + location: { origin: 'https://xf.test', href: 'https://xf.test/', search: '' }, + parent: { postMessage() {} }, + localStorage: { getItem: () => 'tok' }, + }; + let now = 1000; + const context = vm.createContext({ + window, + location: window.location, + document: { addEventListener() {}, removeEventListener() {} }, + URLSearchParams, + setInterval: () => 0, + clearInterval() {}, + setTimeout, + Date: { now: () => now }, + fetch: (url, opts) => { sent.push({ url, body: JSON.parse(opts.body) }); return Promise.resolve(); }, + }); + vm.runInContext(source, context); + const player = new window.XFPlayer({ video, url: '/api/live/554034/turbo.ts', type: 'live' }); + player._wireVideoEvents(); + + fire('playing'); // premier affichage + now += 1000; fire('waiting'); + now += 4200; fire('playing'); // reprise 4,2 s plus tard + + const stall = sent.map((s) => s.body).find((b) => b.event === 'stall'); + assert.ok(stall, 'aucun événement stall envoyé'); + assert.equal(stall.ms, 4200); + assert.equal(stall.ch, '554034'); + assert.equal(sent[0].url, '/api/player-log'); +}); + test('live : le buffer déjà lu est purgé (sinon QuotaExceeded en séance longue)', () => { const c = liveMpegtsConfig(); assert.equal(c.autoCleanupSourceBuffer, true); diff --git a/web/xf-player-core.js b/web/xf-player-core.js index 744e1c9..44f79cf 100644 --- a/web/xf-player-core.js +++ b/web/xf-player-core.js @@ -190,8 +190,75 @@ // ça, une relance après échec laisserait l'ancienne instance réagir aux // commandes du parent et republier des positions périmées. this._listeners = []; + + // Télémétrie des incidents (voir _report) : chaque freeze vécu par + // l'utilisateur finit dans les logs du serveur, avec sa cause. + this._t0 = Date.now(); + this._session = Math.random().toString(36).slice(2, 8); + var idMatch = /\/api\/(?:live|vod|recordings\/stream)\/([^/?#.]+)/.exec(this.url || ''); + this._channel = idMatch ? idMatch[1] : ''; + this._stallSince = null; + this._stats = { stalls: 0, stallMs: 0, seeks: 0, errors: 0 }; + this._lastPos = 0; + var self = this; + var userOnError = this.onError; + this.onError = function (msg) { + self._report('error_shown', { detail: String(msg) }); + userOnError(msg); + }; } + // ---------------- Télémétrie ---------------- + + /** Secondes d'avance dans le buffer à la position courante. */ + XFPlayer.prototype._bufferAhead = function () { + var v = this.video; + try { + for (var i = 0; i < v.buffered.length; i++) { + if (v.buffered.start(i) <= v.currentTime + 0.5 && + v.buffered.end(i) >= v.currentTime) { + return v.buffered.end(i) - v.currentTime; + } + } + } catch (e) {} + return 0; + }; + + /** + * Remonte un incident au serveur (`POST /api/player-log`, écrit dans les + * logs `[Player] …`). Jamais bloquant : erreurs ignorées, aucun envoi + * sans session. + */ + XFPlayer.prototype._report = function (event, data) { + try { + var token = null; + try { token = global.localStorage.getItem('auth_token'); } catch (e) {} + if (!token || typeof fetch !== 'function') return; + var payload = { + event: event, + session: this._session, + ch: this._channel, + t: (Date.now() - this._t0) / 1000, + mode: this.hls ? 'hls' : (this.mpegts ? 'ts' : 'direct'), + profile: this.profile.name, + buffer: this._bufferAhead(), + pos: this.video.currentTime || 0 + }; + for (var k in data) { + if (Object.prototype.hasOwnProperty.call(data, k)) payload[k] = data[k]; + } + fetch('/api/player-log', { + method: 'POST', + keepalive: true, + headers: { + 'Content-Type': 'application/json', + 'Authorization': 'Bearer ' + token + }, + body: JSON.stringify(payload) + }).catch(function () {}); + } catch (e) {} + }; + /** addEventListener + mémorisation pour un retrait propre. */ XFPlayer.prototype._on = function (target, type, handler, options) { target.addEventListener(type, handler, options); @@ -224,6 +291,7 @@ var isLive = this.type === 'live'; this.onLoading('Ouverture du flux'); + this._report('start', {}); // Safari / iOS : HLS natif = le chemin le plus rapide, aucune lib à charger. if (isHls && this._canPlayNativeHls()) { @@ -345,6 +413,8 @@ hls.on(Hls.Events.ERROR, function (e, d) { if (!d.fatal) return; self.log('Erreur HLS fatale : ' + d.details); + self._stats.errors++; + self._report('hls_error', { detail: d.type + '/' + d.details }); if (d.type === Hls.ErrorTypes.NETWORK_ERROR) { // Playlist jamais obtenue (transcodeur en échec → 502, serveur trop // chargé → délai dépassé), après les relances internes de hls.js. @@ -462,6 +532,7 @@ self._audioFallbackDone = true; self.log('Aucune piste audio démuxée (codec non supporté) — bascule HLS'); + self._report('fallback_hls', { detail: 'no_audio' }); self.onLoading('Piste audio incompatible — réencodage'); try { @@ -479,6 +550,8 @@ player.on(mpegts.Events.ERROR, function (type, detail) { self.log('Erreur MPEG-TS : ' + type + ' / ' + detail); if (self._destroyed) return; + self._stats.errors++; + self._report('mpegts_error', { detail: type + '/' + detail }); // Chaque recréation relance un FFmpeg côté serveur : sur un serveur // déjà saturé, recréer sans fin toutes les 1,2 s ne faisait @@ -503,6 +576,7 @@ return; } self.log('Erreurs MPEG-TS répétées — bascule HLS'); + self._report('fallback_hls', { detail: 'repeated_mpegts_errors' }); self.onLoading('Ouverture du flux'); self.url = hlsUrl; if (self._canPlayNativeHls()) self._playDirect(hlsUrl); @@ -519,6 +593,7 @@ player.detachMediaElement(); player.destroy(); } catch (e) {} + self._report('recreate', {}); self._createMpegts(self._mpegtsIsLive); }, 1200); }); @@ -585,6 +660,7 @@ var next = PROFILES[ORDER[idx + 1]]; this.profile = next; this.log('Escalade buffer → ' + next.name + ' (' + reason + ')'); + this._report('profile', { detail: reason }); this.onProfileChange(next.name, reason); // HLS : les fenêtres de buffer sont modifiables à chaud, pas besoin de @@ -628,6 +704,19 @@ }); this._on(v, 'playing', function () { + if (!self._started) { + self._report('first_frame', { ms: Date.now() - self._t0 }); + } + if (self._stallSince !== null) { + var stallMs = Date.now() - self._stallSince; + self._stallSince = null; + // < 250 ms : imperceptible, ne pas noyer les logs. + if (stallMs >= 250) { + self._stats.stalls++; + self._stats.stallMs += stallMs; + self._report('stall', { ms: stallMs }); + } + } self._started = true; self.onReady(); self.send({ type: 'playback_status', status: 'playing' }); @@ -637,9 +726,36 @@ self.send({ type: 'playback_status', status: 'paused' }); }); - this._on(v, 'waiting', function () { self._noteStall(); }); + this._on(v, 'waiting', function () { + if (self._started && self._stallSince === null) { + self._stallSince = Date.now(); + } + self._noteStall(); + }); this._on(v, 'stalled', function () { self._noteStall(); }); + // Sauts (rattrapage du direct, recherche) : d'où, vers où. + this._on(v, 'timeupdate', function () { + if (!v.seeking) self._lastPos = v.currentTime; + }); + this._on(v, 'seeking', function () { + if (!self._started) return; + self._stats.seeks++; + self._report('seek', { from: self._lastPos, to: v.currentTime }); + }); + + // Bilan toutes les 60 s : nombre et durée cumulée des coupures. + this._beatTimer = setInterval(function () { + if (!self._started) return; + self._report('heartbeat', { + stalls: self._stats.stalls, + stallMs: self._stats.stallMs, + seeks: self._stats.seeks, + errors: self._stats.errors, + rate: v.playbackRate + }); + }, 60000); + this._on(v, 'ended', function () { self.send({ type: 'playback_ended', @@ -806,6 +922,7 @@ XFPlayer.prototype.destroy = function () { this._destroyed = true; clearInterval(this._posTimer); + clearInterval(this._beatTimer); this._listeners.forEach(function (l) { try { l.target.removeEventListener(l.type, l.handler); } catch (e) {} });