Nextcue/test_playhead.py

#!/usr/bin/env python3
"""Drive resi_to_propresenter.Playhead against a simulated Resi on a fake clock.

Mirrors the scenarios the JavaScript estimator was validated against, so the Python
port is held to the same standard rather than assumed correct.

    python3 test_playhead.py                 # the whole matrix
    python3 test_playhead.py 7000 1000 4000 2000    # one profile
"""
import sys

import resi_to_propresenter as R

FAILURES = []


def check(cond, msg):
    if not cond:
        FAILURES.append(msg)
        print("    FAIL %s" % msg)


def eq(got, want, msg):
    check(got == want, "%s (got %r, want %r)" % (msg, got, want))


def near(got, want, tol, msg):
    check(abs(got - want) <= tol, "%s (got %d, want %d +/-%d)" % (msg, got, want, tol))


class World:
    """A decoder playing at 1x, and a Resi that republishes its position on a coarse,
    irregular cadence -- each reading already stale when it appears."""

    def __init__(self, cadence, lag, jitter, net):
        self.cadence, self.lag, self.jitter, self.net = cadence, lag, jitter, net
        self.t = 1_700_000_000_000
        self.media = 8 * 60000 + 48000
        self.published = self.media - lag
        self.last_publish = self.t
        self.next_cadence = cadence
        self.playing = True
        self.seed = 12345

    def rnd(self):
        self.seed = (self.seed * 1103515245 + 12345) & 0x7FFFFFFF
        return self.seed / 0x7FFFFFFF

    def advance(self, ms):
        for _ in range(0, int(ms), 100):
            self.t += 100
            if self.playing:
                self.media += 100
            if self.t - self.last_publish >= self.next_cadence:
                self.last_publish = self.t
                self.published = self.media - self.lag
                self.next_cadence = max(500, self.cadence + round((self.rnd() - 0.5) * 2 * self.jitter))

    def fetch(self):
        """What a poll sees, and the round trip it costs."""
        body = self.published
        if self.net:
            self.advance(100 + round(self.rnd() * self.net))
        return body


def run_profile(cadence, lag, jitter, net):
    w = World(cadence, lag, jitter, net)
    R.now_ms = lambda: w.t
    head = R.Playhead()
    tol = lag + 1200 + jitter + net * 0.35

    def second():
        w.advance(1000)
        head.note(w.fetch())
        return head.read()

    def seconds(n):
        out = (None, False, 0)
        for _ in range(n):
            out = second()
        return out

    cues = [
        {"name": "Welcome", "ms": 5 * 60000},
        {"name": "Campus Host", "ms": 12 * 60000 + 30000},
        {"name": "Message", "ms": 41 * 60000},
        {"name": "Closing", "ms": 45 * 60000},
    ]

    def next_cue(est):
        return next((c for c in cues if c["ms"] > est), None)

    # ---- accuracy while playing --------------------------------------------
    est, playing, _ = seconds(40)
    check(playing, "reported as playing")
    err = w.media - est
    check(err <= tol, "estimate is not lagging (behind by %dms)" % err)
    check(err >= -300, "estimate does not run ahead (%dms)" % err)

    worst_est, worst_raw = 0, 0
    for _ in range(30):
        est, _, _ = second()
        worst_est = max(worst_est, w.media - est)
        worst_raw = max(worst_raw, w.media - w.published)
    if cadence >= 2000:
        check(worst_raw >= cadence * 0.4,
              "sanity: the raw Resi value really does go stale (%dms)" % worst_raw)
    check(worst_est <= tol,
          "the estimate stays close all cycle (worst %dms vs raw %dms)" % (worst_est, worst_raw))

    # ---- never stalls, never runs backwards, over a long run ----------------
    prev, stalls, backwards = est, 0, 0
    for _ in range(200):
        est, _, _ = second()
        if est == prev:
            stalls += 1
        if est < prev:
            backwards += 1
        prev = est
    eq(stalls, 0, "no stalled seconds over 200s")
    eq(backwards, 0, "never goes backwards over 200s")

    # ---- a fired cue: the decoder jumps, Resi says nothing until it republishes
    w.media = 40 * 60000 + 50000
    saw = False
    for _ in range(60):
        est, playing, _ = second()
        if head.last_media is not None and abs(head.last_media - w.media) < 8000:
            saw = True
            break
    check(saw, "the jump is picked up")
    check(head.take_seek() or True, "seek flag is readable")
    near(est, w.media, tol + cadence / 2, "estimate resyncs to the new playhead")
    check(w.media - est >= -400, "no overshoot after a seek (%dms)" % (w.media - est))
    c = next_cue(est)
    eq(c["name"] if c else None, "Message", "next cue is right after the jump")

    est, _, _ = seconds(15)
    c = next_cue(est)
    eq(c["name"] if c else None, "Closing", "rolled over after passing Message")

    # ---- a backwards seek ---------------------------------------------------
    w.media = 6 * 60000
    for _ in range(60):
        est, _, _ = second()
        if head.last_media is not None and abs(head.last_media - w.media) < 8000:
            break
    near(est, w.media, tol + cadence / 2, "follows a backwards seek")
    c = next_cue(est)
    eq(c["name"] if c else None, "Campus Host", "cue target recomputes after seeking back")

    # ---- pause --------------------------------------------------------------
    w.playing = False
    wait = int((max(15000, min(45000, (cadence + jitter) * 2.5 + 6000)) + cadence + jitter + 6000) / 1000)
    est, playing, _ = seconds(wait)
    check(not playing, "detects a real pause")
    held = est
    est, playing, _ = seconds(20)
    eq(est, held, "paused playhead holds instead of running on")

    # ---- resume -------------------------------------------------------------
    w.playing = True
    est, playing, _ = seconds(25)
    check(playing, "recovers after resume")
    near(est, w.media, tol + cadence, "re-locks after resume")

    # ---- a pause longer than the offset window, then resume -----------------
    w.playing = False
    media_at_pause = w.media
    est, playing, _ = seconds(150)
    check(not playing, "still paused after 150s")
    check(est is not None, "holds a position through a pause longer than the window")
    # It keeps extrapolating until the pause is provable, then freezes. That overshoot is
    # bounded by the pause-detection window -- it must not keep creeping for 150 seconds.
    # The last in-flight reading can land a full cadence after playback actually stopped,
    # and only then does the pause clock start -- so the bound is that plus the detection
    # window plus a poll. What this pins is that it STOPS, rather than creeping for 150s.
    pause_after = max(15000, min(45000, (cadence + jitter) * 2.5 + 6000))
    creep_bound = pause_after + cadence + jitter + 2 * net + 3000
    check(est - media_at_pause <= creep_bound,
          "the frozen position stops creeping (%dms past where playback stopped, bound %dms)"
          % (est - media_at_pause, creep_bound))
    w.playing = True
    head.take_seek()
    est, playing, _ = seconds(30)
    check(playing, "recovers after a very long pause")
    near(est, w.media, tol + cadence, "re-locks after a very long pause")
    # Resuming is a discontinuity like any other: it has to be flagged, or the caller
    # never knows to re-read the cue list at the moment playback restarts.
    check(head.seeked or head.take_seek(), "a resume after a long pause is flagged as a seek")

    # ---- the harness must be able to fail -----------------------------------
    before = len(FAILURES)
    eq(next_cue(est), "definitely not a cue", "deliberate failure")
    if len(FAILURES) != before + 1:
        raise SystemExit("HARNESS BROKEN: a false assertion passed")
    FAILURES.pop()


def run_short_gaps_then_slow(start_into_cycle, burst):
    """Seen live at North Attleboro: Resi publishing every ~30s, but the bridge started
    a few seconds before a publish, so its first measured "gap" was 2s (and 9s after a
    reboot). Once that was the learned cadence, every honest 30s gap was thrown out as a
    pause gap, so playback was declared paused 15s into every update -- the timer
    stopped and the next cue (and stage message) froze half the time."""
    w = World(30000, 1000, 2000, 500)
    R.now_ms = lambda: w.t
    w.advance(start_into_cycle)          # the bridge starts partway through Resi's cycle
    head = R.Playhead()

    def second():
        w.advance(1000)
        head.note(w.fetch())
        return head.read()

    startup_paused = sum(1 for _ in range(100) if not second()[1])
    eq(startup_paused, 0, "not called paused while the cadence is still being learned")
    if burst:
        w.media += 15 * 60000                 # a seek, published at once...
        w.last_publish = w.t - w.next_cadence
        second()
        second()
        w.last_publish = w.t - w.next_cadence  # ...and again 2s later
        second()

    paused = 0
    for _ in range(300):
        _, playing, _ = second()
        if not playing:
            paused += 1
    eq(paused, 0, "short early gaps do not make every later 30s gap look like a pause")


def main():
    if len(sys.argv) > 1:
        profiles = [tuple(int(x) for x in sys.argv[1:5])]
    else:
        profiles = [
            (5000, 500, 0, 0), (5000, 500, 0, 2500), (2000, 0, 0, 800),
            (10000, 3000, 0, 2500), (7000, 1000, 4000, 2000), (3000, 500, 2000, 1000),
            (12000, 2000, 6000, 3000), (1000, 0, 0, 0), (8000, 1500, 3000, 4000),
        ]
    bad = 0
    for cadence, lag, jitter, net in profiles:
        start = len(FAILURES)
        run_profile(cadence, lag, jitter, net)
        n = len(FAILURES) - start
        bad += n
        print("  cadence=%-6s lag=%-5s jitter=%-5s net=%-5s  %s"
              % (cadence, lag, jitter, net, "OK" if n == 0 else "%d FAILED" % n))
    if len(sys.argv) == 1:
        for label, into, burst in (("started 2s before a 30s publish", 28000, False),
                                   ("started 9s before a 30s publish", 21000, False),
                                   ("2s burst after a seek, 30s cadence", 0, True)):
            start = len(FAILURES)
            run_short_gaps_then_slow(into, burst)
            n = len(FAILURES) - start
            bad += n
            print("  %-41s %s" % (label, "OK" if n == 0 else "%d FAILED" % n))
    if bad:
        raise SystemExit("\n%d failure(s)" % bad)
    print("\nall playhead tests passed across %d Resi profiles" % len(profiles))


if __name__ == "__main__":
    main()