Lecture TV : traverser les silences du panneau sans figer

Télémétrie d'un freeze en prod : le panneau s'est tu ~15-20 s sur une connexion restée ouverte (aucune reconnexion FFmpeg dans les logs). Le lecteur n'avait gardé que 11-16 s d'avance — il « consommait » à x1,1 celle que le panneau envoie au démarrage pour revenir à 12 s — puis, après la coupure de 6,3 s, il repartait avec 1 s de stock et recoupait aussitôt (1,7 s puis 2,0 s). - réserve visée 25 s (liveSync 25/35, saut au-delà de 45 s) : ~25 s de retard sur le direct en échange de la traversée de ces silences - après une coupure, attente de 4 s de réserve avant de relire (comme mpv cache-pause), 15 s au plus ; une pause utilisateur l'annule ; le lecteur lite affiche « Reconstitution de la réserve » au lieu du bouton lecture Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Diagnostic : le lecteur remonte ses freezes dans les logs du serveur
2026-10-11 17:30:00 +02:00 · 2026-10-11 00:04:25 +02:00 · 2026-10-10 23:38:17 +02:00
6 changed files with 415 additions and 7 deletions
@@ -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 = <String>[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+'), '<url>')
+          .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<Response> 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);
+}
@@ -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<String> args) async {
  // Parse command line arguments
@@ -221,6 +222,14 @@ void main(List<String> 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',
@@ -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('<url>'));
+    });
+
+    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')));
+    });
+  });
+}
@@ -101,6 +101,113 @@ 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');
+});
+
+// Freeze mesuré en prod (télémétrie) : le panneau s'est tu ~15-20 s sur une
+// connexion restée ouverte, alors que le lecteur n'avait gardé que 11-16 s.
+const PROVIDER_OUTAGE_S = 18;
+
+test('live : la réserve visée couvre un silence du panneau de ~18 s', () => {
+  const c = liveMpegtsConfig();
+  // liveSync ramène le retard vers la cible : c'est la réserve en régime
+  // établi. Elle doit dépasser le silence mesuré.
+  assert.ok(c.liveSyncTargetLatency > PROVIDER_OUTAGE_S,
+    `cible ${c.liveSyncTargetLatency}s < silence mesuré ${PROVIDER_OUTAGE_S}s`);
+  assert.ok(c.liveBufferLatencyMinRemain > PROVIDER_OUTAGE_S);
+});
+
+test('reprise après coupure : attendre une vraie réserve avant de relire', () => {
+  const calls = [];
+  const listeners = {};
+  let ahead = 0;
+  const video = {
+    addEventListener(type, fn) { (listeners[type] ||= []).push(fn); },
+    removeEventListener() {},
+    canPlayType: () => '',
+    play: () => { calls.push('play'); return Promise.resolve(); },
+    pause: () => { calls.push('pause'); },
+    get buffered() { return { length: 1, start: () => 0, end: () => 100 + ahead }; },
+    seekable: { length: 0 },
+    currentTime: 100,
+    playbackRate: 1,
+    seeking: false,
+  };
+  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() {} },
+  };
+  const context = vm.createContext({
+    window, location: window.location,
+    document: { addEventListener() {}, removeEventListener() {} },
+    URLSearchParams, setInterval: () => 0, clearInterval() {}, setTimeout, Date,
+  });
+  vm.runInContext(source, context);
+  const player = new window.XFPlayer({ video, url: '/api/live/1/turbo.ts', type: 'live' });
+  player.mpegts = {}; // flux MPEG-TS en cours
+  player._wireVideoEvents();
+
+  fire('playing');
+  fire('waiting');            // le panneau se tait
+  assert.deepEqual(calls.slice(-1), ['pause'], 'le lecteur doit se mettre en attente');
+
+  ahead = 1;                  // 1 s arrive : trop peu, ne pas repartir
+  player._checkHold();
+  assert.ok(!calls.slice(1).includes('play'), 'reparti avec 1 s : recoupera aussitôt');
+
+  ahead = 5;                  // vraie réserve reconstituée
+  player._checkHold();
+  assert.equal(calls.at(-1), 'play');
+});
+
 test('live : le buffer déjà lu est purgé (sinon QuotaExceeded en séance longue)', () => {
  const c = liveMpegtsConfig();
  assert.equal(c.autoCleanupSourceBuffer, true);
@@ -141,6 +141,12 @@

            // Contrat historique du lite : mise en pause manuelle → overlay lecture.
            video.addEventListener('pause', function () {
+                // Pause technique : le lecteur attend que la réserve se
+                // reconstitue après une coupure, il repartira seul.
+                if (player && player._holding) {
+                    showLoading('Reconstitution de la réserve');
+                    return;
+                }
                if (video.currentTime === 0 || video.paused) {
                    loading.style.display = 'none';
                    playOverlay.style.display = 'flex';
@@ -58,6 +58,14 @@
  // Erreurs MPEG-TS tolérées sur 60 s avant de basculer sur HLS.
  var MPEGTS_MAX_ERRORS = 3;

+  // Après une coupure en direct, réserve à reconstituer avant de relire.
+  // Repartir dès la première seconde reçue transformait un silence du
+  // panneau en cascade de micro-coupures (6,3 s puis 1,7 s puis 2,0 s,
+  // mesuré) ; comme mpv (cache-pause), on attend une vraie réserve.
+  var REBUFFER_SECONDS = 4;
+  // Au-delà, on relance quand même avec ce qu'on a.
+  var REBUFFER_MAX_WAIT_MS = 15000;
+
  // ------------------------------------------------------------------
  // Chargement paresseux des libs (aucune requête inutile)
  // ------------------------------------------------------------------
@@ -190,8 +198,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 +299,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 +421,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.
@@ -427,14 +505,21 @@
        // coupure toutes les 3-4 s et contenu sauté (12 sauts et 14 coupures
        // en 30 s sur une chaîne FHD). La marge de 12 s couvre deux silences ;
        // le saut ne sert plus qu'à borner un retard réellement accumulé.
+        //
+        // 25 s et non plus 12 : la télémétrie a mesuré un silence du panneau
+        // de ~15-20 s sur une connexion restée ouverte, alors que le lecteur
+        // n'avait gardé que 11-16 s — il venait de « consommer » à x1,1
+        // l'avance que le panneau envoie au démarrage. On la garde : ~25 s
+        // de retard sur le direct, en échange d'une lecture qui traverse ces
+        // silences sans figer.
        liveBufferLatencyChasing: isLive,
-        liveBufferLatencyMaxLatency: 30,
-        liveBufferLatencyMinRemain: 12,
-        // Au-delà de 20 s de retard, accélérer légèrement (x1,1) jusqu'à
-        // revenir à 12 s : rattrapage invisible, sans saut ni coupure.
+        liveBufferLatencyMaxLatency: 45,
+        liveBufferLatencyMinRemain: 25,
+        // Au-delà de 35 s de retard, accélérer légèrement (x1,1) jusqu'à
+        // revenir à 25 s : rattrapage invisible, sans saut ni coupure.
        liveSync: isLive,
-        liveSyncMaxLatency: 20,
-        liveSyncTargetLatency: 12,
+        liveSyncMaxLatency: 35,
+        liveSyncTargetLatency: 25,
        liveSyncPlaybackRate: 1.1,
        // Purge du buffer déjà lu : sans elle, une longue séance finit par
        // saturer le SourceBuffer (QuotaExceededError → erreur MPEG-TS).
@@ -462,6 +547,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 +565,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 +591,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 +608,7 @@
          player.detachMediaElement();
          player.destroy();
        } catch (e) {}
+        self._report('recreate', {});
        self._createMpegts(self._mpegtsIsLive);
      }, 1200);
    });
@@ -585,6 +675,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
@@ -602,6 +693,32 @@
    // recréation du lecteur (déclenchée par le handler d'erreur).
  };

+  /**
+   * Direct MPEG-TS à sec : se mettre en pause jusqu'à [REBUFFER_SECONDS] de
+   * réserve (voir la constante). HLS gère déjà sa propre reprise.
+   */
+  XFPlayer.prototype._holdUntilBuffered = function () {
+    if (this._holding || !this.mpegts || this.type !== 'live') return;
+    var self = this;
+    this._holding = true;
+    this._holdSince = Date.now();
+    try { this.video.pause(); } catch (e) {}
+    this._holdTimer = setInterval(function () { self._checkHold(); }, 250);
+  };
+
+  /** Relance la lecture dès que la réserve est reconstituée. */
+  XFPlayer.prototype._checkHold = function () {
+    if (!this._holding) return;
+    if (this._destroyed) { clearInterval(this._holdTimer); return; }
+    var waited = Date.now() - this._holdSince;
+    if (this._bufferAhead() < REBUFFER_SECONDS && waited < REBUFFER_MAX_WAIT_MS) {
+      return;
+    }
+    clearInterval(this._holdTimer);
+    this._holding = false;
+    this._attemptPlay();
+  };
+
  XFPlayer.prototype._noteStall = function () {
    if (!this._started) return; // les attentes d'amorçage ne comptent pas
    var now = Date.now();
@@ -628,18 +745,62 @@
    });

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

    this._on(v, 'pause', function () {
+      // Pause posée par l'attente de réserve : pas une pause utilisateur,
+      // l'interface ne doit pas basculer sur « lecture ».
+      if (self._holding) return;
      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();
+      if (self._started) self._holdUntilBuffered();
+    });
    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',
@@ -781,6 +942,12 @@
          self._attemptPlay();
          break;
        case 'pause':
+          // Pause voulue par l'utilisateur : l'attente de réserve ne doit
+          // pas relancer la lecture derrière son dos.
+          if (self._holding) {
+            clearInterval(self._holdTimer);
+            self._holding = false;
+          }
          v.pause();
          break;
        case 'seek':
@@ -806,6 +973,8 @@
  XFPlayer.prototype.destroy = function () {
    this._destroyed = true;
    clearInterval(this._posTimer);
+    clearInterval(this._beatTimer);
+    clearInterval(this._holdTimer);
    this._listeners.forEach(function (l) {
      try { l.target.removeEventListener(l.type, l.handler); } catch (e) {}
    });