Nextcue/source/tick_test.js

// Drives the real pollPlayer() + estimator against a simulated Resi that
// publishes `position` on a coarse cadence, already slightly stale.

var console = {
  log: function () { print(Array.prototype.join.call(arguments, ' ')) },
  error: function () { print('ERR ' + Array.prototype.join.call(arguments, ' ')) },
  warn: function () { print('WARN ' + Array.prototype.join.call(arguments, ' ')) },
  info: function () { print(Array.prototype.join.call(arguments, ' ')) },
  debug: function () {},
};

var failures = [];
function check(c, m) { if (!c) { failures.push(m); print('  FAIL ' + m) } }
function eq(g, w, m) { check(g === w, m + ' (got ' + g + ', want ' + w + ')') }
function near(g, w, tol, m) {
  check(Math.abs(g - w) <= tol, m + ' (got ' + Math.round(g) + ', want ' + Math.round(w) + ' +/-' + tol + ')');
}

function StubInstanceBase() {}
StubInstanceBase.prototype.updateStatus = function () {}
StubInstanceBase.prototype.log = function () {}
StubInstanceBase.prototype.setVariableValues = function () {}
var stubs = {
  '@companion-module/base': {
    InstanceBase: StubInstanceBase,
    InstanceStatus: { Ok: 'ok', Connecting: 'c', ConnectionFailure: 'f', BadConfig: 'b' },
    runEntrypoint: function () {}, combineRgb: function () { return 0 }, Regex: {},
  },
  './config.js': { GetConfigFields: function () { return [] } },
  './variables.js': { UpdateVariableDefinitions: function () {} },
  './upgrades.js': { UpgradeScripts: [] },
  './actions.js': { UpdateActions: function () {} },
  './feedbacks.js': { UpdateFeedbacks: function () {} },
  './presets.js': { UpdatePresets: function () {} },
};

// ---- the simulated world -------------------------------------------------
var fakeNow = 1700000000000;
Date.now = function () { return fakeNow };

// cadence / lag / jitter can be overridden: jsc tick_test.js -- 10000 3000 4000
var ARGS = (typeof arguments !== 'undefined' ? arguments : []).map(Number);
var DIAG = true;
var RESI_CADENCE = ARGS[0] || 5000;   // how often Resi refreshes `position`
var RESI_LAG = ARGS.length > 1 ? ARGS[1] : 500;  // how stale it already is when it appears
var RESI_JITTER = ARGS[2] || 0;       // how irregular the cadence is
var NET_JITTER = ARGS[3] || 0;        // how variable the request/response round trip is
var START_INTO = ARGS[4] || 0;        // how far into Resi's cycle the module starts polling
var seed = 12345;
function rnd() { seed = (seed * 1103515245 + 12345) & 0x7fffffff; return seed / 0x7fffffff }
var nextCadence = RESI_CADENCE;
var playing = true;
var trueMedia = 8 * 60000 + 48000;      // where the decoder REALLY is
var published = trueMedia - RESI_LAG;   // what the API currently returns
var lastPublish = fakeNow - START_INTO;
var extraPlayerFields = {};
var TOL = RESI_LAG + 1200 + RESI_JITTER;

function pad(n, w) { return String(n).padStart(w, '0') }
function fmt(ms) {
  var t = Math.max(0, Math.floor(ms));
  return pad(Math.floor(t / 3600000), 2) + ':' + pad(Math.floor((t % 3600000) / 60000), 2) + ':' +
         pad(Math.floor((t % 60000) / 1000), 2) + '.' + pad(t % 1000, 3);
}

function advanceWorld(ms) {
  for (var i = 0; i < ms; i += 100) {
    fakeNow += 100;
    if (playing) trueMedia += 100;
    if (fakeNow - lastPublish >= nextCadence) {
      lastPublish = fakeNow;
      published = trueMedia - RESI_LAG;
      nextCadence = RESI_CADENCE + Math.round((rnd() - 0.5) * 2 * RESI_JITTER);
      if (nextCadence < 500) nextCadence = 500;
    }
  }
}

var fetch = function () {
  // the body is whatever Resi had at the moment the request left
  var one = { playerHardwareId: 'DEC1', userName: 'Lobby', position: fmt(published), eventId: 'EV1' };
  for (var k in extraPlayerFields) one[k] = extraPlayerFields[k];
  // ...and the round trip takes a while, during which the world moves on
  if (NET_JITTER) advanceWorld(100 + Math.round(rnd() * NET_JITTER));
  return Promise.resolve({ ok: true, json: function () { return Promise.resolve([one]) } });
};

var tickFn = null, tickMs = null;
var setInterval = function (fn, ms) { tickFn = fn; tickMs = ms; return {} };
var clearInterval = function () {};

var src = readFile(typeof TARGET !== 'undefined' ? TARGET : 'build/pkg/resi-studio-cues/dist/main.js');
var mod = { exports: {} };
(new Function('module', 'exports', 'require', 'setInterval', 'clearInterval', 'console', 'fetch', src))(
  mod, mod.exports,
  function (id) { if (!stubs[id]) throw new Error('unstubbed require: ' + id); return stubs[id] },
  setInterval, clearInterval, console, fetch);

var inst = Object.create(mod.exports.ModuleInstance.prototype);
var vars = {};
inst.setVariableValues = function (o) { for (var k in o) vars[k] = o[k] };
inst.log = function () {};
inst.config = {};
inst.selectedVenueUuid = 'V1';
inst.selectedPlayerHardwareId = 'DEC1';
inst.cookieHeader = 'stub';
inst.currentEventId = 'EV1';
inst.playerPollInFlight = false;
inst.ensureAuthenticated = function () { return Promise.resolve() };
inst.buildAuthHeaders = function () { return {} };
inst.refreshCuesIfDue = function () { return Promise.resolve() };
inst.cues = [
  { uuid: 'a', name: 'Welcome', positionMs: 5 * 60000 },
  { uuid: 'b', name: 'Campus Host', positionMs: 12 * 60000 + 30000 },
  { uuid: 'c', name: 'Message', positionMs: 41 * 60000 },
  { uuid: 'd', name: 'Closing', positionMs: 45 * 60000 },
];

// true once Resi has actually REPORTED a position near `target`
function reported_near(target) {
  return Number.isFinite(inst.__lastSampleMediaMs) && Math.abs(inst.__lastSampleMediaMs - target) < 8000;
}

// one second of real operation: advance the world, poll, redraw
// any PAUSED while the decoder is really playing is a false pause: it freezes the countdown
var falsePauses = 0;
async function second() {
  advanceWorld(1000); await inst.pollPlayer(); tickFn();
  if (playing && vars.playback_state === 'PAUSED') falsePauses++;
}
async function seconds(n) { for (var i = 0; i < n; i++) await second() }

function timestampChecks() {
  var now = Date.now();
  eq(inst.detectSampleTime({ lastUpdated: new Date(now - 2000).toISOString() }), now - 2000,
     'uses an ISO "lastUpdated" as the sample time');
  eq(inst.detectSampleTime({ reportedAt: now - 1500 }), now - 1500,
     'uses an epoch-ms "reportedAt" as the sample time');
  eq(inst.detectSampleTime({ startTime: new Date(now - 120000).toISOString() }), undefined,
     'ignores a timestamp too old to be this reading');
  eq(inst.detectSampleTime({ userName: 'Lobby', position: '00:01:02.000' }), undefined,
     'ignores fields that are not timestamps');
}

(async function () {
  inst.startSmoothTick();
  eq(tickMs, 1000, 'display ticks every second');

  // ---- accuracy while playing -----------------------------------------
  await seconds(40);
  var err = trueMedia - inst.__lastEstMs;
  check(err <= TOL + NET_JITTER * 0.35, 'estimate is not lagging (behind truth by ' + Math.round(err) + 'ms)');
  check(err >= -300, 'estimate does not run ahead of the real playhead (' + Math.round(err) + 'ms)');

  // the point of the whole exercise: compare against the raw value over a
  // full publish cycle, not at one lucky instant
  var maxEstErr = 0, maxRawErr = 0;
  for (var w = 0; w < 30; w++) {
    await second();
    maxEstErr = Math.max(maxEstErr, trueMedia - inst.__lastEstMs);
    maxRawErr = Math.max(maxRawErr, trueMedia - published);
  }
  if (RESI_CADENCE >= 2000)
  check(maxRawErr >= RESI_CADENCE * 0.4,
        'sanity: the raw Resi value goes badly stale within a cycle (' + Math.round(maxRawErr) + 'ms)');
  check(maxEstErr <= TOL + NET_JITTER * 0.35,
        'the estimate stays close all cycle (worst ' + Math.round(maxEstErr) + 'ms vs raw ' + Math.round(maxRawErr) + 'ms)');

  // ---- ticks every second, never backwards ------------------------------
  var prev = inst.__lastEstMs, stalls = 0, backwards = 0;
  for (var i = 0; i < 60; i++) {
    await second();
    if (inst.__lastEstMs === prev) stalls++;
    if (inst.__lastEstMs < prev) backwards++;
    prev = inst.__lastEstMs;
  }
  eq(stalls, 0, 'no stalled seconds across a minute of playback');
  eq(backwards, 0, 'the playhead never goes backwards');
  eq(vars.playback_state, 'PLAYING', 'reported as playing');
  check(trueMedia - inst.__lastEstMs <= TOL + NET_JITTER * 0.35, 'still accurate after a minute');

  // ---- long run: the offset window is finite, so the best sample eventually
  //      ages out of it; that must not drag the displayed playhead backwards
  var prev2 = inst.__lastEstMs, back2 = 0, worstBack = 0;
  for (var L = 0; L < 200; L++) {
    await second();
    if (inst.__lastEstMs < prev2) {
      back2++; worstBack = Math.max(worstBack, prev2 - inst.__lastEstMs);
      if (typeof DIAG !== 'undefined')
        print('  backward step ' + Math.round(prev2 - inst.__lastEstMs) + 'ms at L=' + L +
              '  state=' + vars.playback_state + '  offsets=' + (inst.__offsets || []).length +
              '  sinceNew=' + (Date.now() - inst.__lastNewSampleAt) + '  base=' + inst.__baseOffset);
    }
    prev2 = inst.__lastEstMs;
  }
  eq(back2, 0, 'no backward steps over 200s (worst was ' + Math.round(worstBack) + 'ms)');
  eq(falsePauses, 0, 'never reported PAUSED while playing, startup included');

  // ---- a fired cue / forward seek --------------------------------------
  inst.lastCueRefreshMs = 999999;
  trueMedia = 40 * 60000 + 50000;            // decoder jumps; Resi says nothing yet
  var jumpAt = fakeNow, sawIt = false;
  for (var q = 0; q < 60 && !sawIt; q++) { await second(); sawIt = reported_near(trueMedia) }
  check(sawIt, 'the jump is picked up at all');
  var detectMs = fakeNow - jumpAt;
  if (typeof DIAG !== 'undefined') print('  jump detected after ' + detectMs + 'ms');
  check(detectMs <= RESI_CADENCE + RESI_JITTER + 2000,
        'jump detected within one publish cycle (' + detectMs + 'ms)');
  eq(inst.lastCueRefreshMs, 0, 'a jump forces the cue list to refresh immediately');
  near(inst.__lastEstMs, trueMedia, TOL + RESI_CADENCE / 2, 'estimate resyncs to the new playhead at once');
  if (typeof DIAG !== 'undefined') print('  post-seek error: ' + Math.round(trueMedia - inst.__lastEstMs) + 'ms');
  check(trueMedia - inst.__lastEstMs >= -400,
        'estimate does not overshoot after a seek (' + Math.round(trueMedia - inst.__lastEstMs) + 'ms)');
  eq(vars.next_cue_name, 'Message', 'next cue is correct straight after the jump');

  await seconds(15);
  eq(vars.next_cue_name, 'Closing', 'rolled over after passing Message');
  eq(vars.prev_cue_name, 'Message', 'passed cue became prev');

  // ---- a backwards seek -------------------------------------------------
  trueMedia = 6 * 60000;
  for (var r = 0; r < 60 && !reported_near(trueMedia); r++) await second();
  near(inst.__lastEstMs, trueMedia, TOL + RESI_CADENCE / 2, 'follows a backwards seek');
  eq(vars.next_cue_name, 'Campus Host', 'cue targets recompute after seeking back');

  // ---- pause ------------------------------------------------------------
  playing = false;
  // how long the module can legitimately take to call it a pause, given this feed
  var pauseWait = Math.ceil((Math.max(15000, Math.min(45000, (RESI_CADENCE + RESI_JITTER) * 2.5 + 6000))
                             + RESI_CADENCE + RESI_JITTER + 6000) / 1000);
  await seconds(pauseWait);
  eq(vars.playback_state, 'PAUSED', 'detects a real pause');
  var held = inst.__lastEstMs;
  await seconds(20);
  eq(inst.__lastEstMs, held, 'paused playhead holds instead of running on');

  // ---- resume -----------------------------------------------------------
  playing = true;
  await seconds(25);
  eq(vars.playback_state, 'PLAYING', 'recovers after resume');
  near(inst.__lastEstMs, trueMedia, TOL + 1500, 'estimate re-locks after resume');

  // ---- operator-driven resync (beats waiting for Resi to republish) ----
  var beforeEst = inst.__lastEstMs;
  eq(inst.resyncToCue('No Such Cue'), false, 'resync to an unknown cue is refused');
  eq(inst.__lastEstMs, beforeEst, 'a refused resync leaves the playhead alone');

  inst.lastCueRefreshMs = 999999;
  eq(inst.resyncToCue('Campus Host'), true, 'resync to a named cue succeeds');
  eq(inst.__lastEstMs, 12 * 60000 + 30000, 'playhead snaps to that cue immediately');
  eq(vars.next_cue_name, 'Message', 'next cue updates in the same instant');
  eq(inst.lastCueRefreshMs, 0, 'resync also forces a cue-list refresh');

  eq(inst.resyncToNextCue(), true, 'resync to the next cue succeeds');
  eq(inst.__lastEstMs, 41 * 60000, 'playhead snaps to the following cue');

  // a real sample after a resync must still be taken seriously
  trueMedia = 30 * 60000; published = trueMedia - RESI_LAG; lastPublish = fakeNow;
  await seconds(2);
  for (var z = 0; z < 60 && !reported_near(trueMedia); z++) await second();
  near(inst.__lastEstMs, trueMedia, TOL + RESI_CADENCE / 2, 'a real reading overrides a resync');

  timestampChecks();

  var b = failures.length;
  eq(vars.next_cue_name, 'Not A Real Cue', 'deliberate failure');
  if (failures.length !== b + 1) { print('HARNESS BROKEN'); throw new Error('harness') }
  failures.pop();

  if (failures.length) { print('\n' + failures.length + ' FAILED'); throw new Error('tests failed') }
  print('\nall estimator tests passed  [cadence ' + RESI_CADENCE + 'ms, lag ' + RESI_LAG + 'ms, jitter +/-' + RESI_JITTER + 'ms]');
})();