screentinker/server/test/player-media-error-multiadvance.test.js

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