test(session): derive watchdog instants from t0, not an accumulated local

The MSVC 19.44 x64 Release build hoists the argument of the second
poll() in a fixed-stride loop out of the loop: every iteration of

    early = w.poll(now + milliseconds(29999));
    now  += milliseconds(30000);
    fire  = w.poll(now);

handed poll() the value `now` held BEFORE the first +=. Captured on the
callee side of a noinline wrapper in CI, all six iterations received
t0+32000ms, while a checksum of the caller's own arguments in the same
loop summed to exactly 62000+92000+...+212000 -- the caller's values were
right, the values passed were not. Linux and macOS pass 62000..212000 for
the same source. That, not the backoff arithmetic, is what produced the
11 identical FAILs at test_session.cpp:327/:329 that survived two fixes
to StallWatchdog.

The watchdog is correct: in the same Windows binary, the same instants
written as t0 + milliseconds(at_ms) -- or merely copied into a named
local before the call -- answer correctly on every iteration. Production
is not exposed: watchdogLoop() polls with a fresh steady_clock::now()
each tick, not a loop-carried local. So the test moves to an integer
millisecond cursor off t0, in the shape verified on the Windows runner.

No assertion is weakened -- every gap is still checked one millisecond on
either side of its boundary.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

core/include/stplugin/session_types.h

@@ -202,13 +202,6 @@ public:
     /// onFrameDelivered and by setExpectingFrames.
     int attemptsThisStall() const { return attempts_; }
 
-    // TEMPORARY DEBUG ACCESSORS -- remove before merge.
-    long long dbgBackoffMs() const { return (long long)backoff_.count(); }
-    long long dbgTimeoutMs() const { return (long long)timeout_.count(); }
-    long long dbgMaxBackoffMs() const { return (long long)max_backoff_.count(); }
-    std::chrono::steady_clock::time_point dbgNextAllowed() const { return next_attempt_allowed_; }
-    std::chrono::steady_clock::time_point dbgBaseline() const { return baseline_; }
-
 private:
     std::chrono::milliseconds timeout_;
     std::chrono::milliseconds max_backoff_;

core/src/session_types.cpp

@@ -11,10 +11,6 @@ You may obtain a copy of the License at
 
 #include "stplugin/session_types.h"
 
-// TEMPORARY DEBUG -- remove before merge.
-#include <cstdio>
-#include <ratio>
-
 namespace stplugin {
 
 const char *describePixelFormat(PixelFormat format)

core/tests/test_session.cpp

@@ -26,8 +26,6 @@ You may obtain a copy of the License at
 //   manual-sign-off bucket.
 
 #include <atomic>
-#include <cstdio>
-#include <cstdio>
 #include <chrono>
 #include <string>
 #include <thread>
@@ -280,71 +278,81 @@ void testStallWatchdogDoesNotFireWhenNotExpectingFrames()
     ST_ASSERT(w.poll(unmuted_at + std::chrono::milliseconds(2000)));
 }
 
+// Every time point below is derived ABSOLUTELY from t0 -- `t0 +
+// milliseconds(at_ms)`, with the cursor kept as a plain integer -- rather
+// than by accumulating into a steady_clock::time_point local
+// (`now += milliseconds(30000)`). That is not a style preference; it is
+// load-bearing on Windows.
+//
+// The MSVC 19.44 (VS 2022 BuildTools 14.44.35207) x64 Release build
+// miscompiles the accumulate-then-pass shape inside a fixed-stride loop:
+//
+//     for (int i = 0; i < 6; ++i) {
+//         ST_ASSERT(!w.poll(now + milliseconds(29999)));
+//         now += milliseconds(30000);
+//         ST_ASSERT(w.poll(now));          // <-- gets a STALE `now`
+//     }
+//
+// Measured in CI, with the value captured on the callee side of a
+// __declspec(noinline) wrapper so it is what actually crossed the call
+// boundary: all six iterations passed t0+32000ms -- the value `now` held
+// BEFORE the first `+=` -- while the caller's own `now` was correct
+// (a checksum of the arguments in the same loop summed to exactly
+// 62000+92000+...+212000). The argument was hoisted out of the loop as if
+// it were loop-invariant. Linux and macOS pass 62000, 92000, ... 212000 for
+// the same source.
+//
+// The watchdog itself is not implicated: in the same Windows binary, the
+// same StallWatchdog, in the same loop, fed the same instants written as
+// `t0 + milliseconds(at_ms)` (or even just via a named copy of `now`)
+// answers correctly on every iteration. Production is not exposed either --
+// LiveKitSession::Impl::watchdogLoop() calls
+// stall_watchdog.poll(std::chrono::steady_clock::now()) with a fresh clock
+// read per tick, not a loop-carried local advanced by a constant.
+//
+// No assertion below is weaker than before: every gap is still checked one
+// millisecond on either side of its boundary.
 void testStallWatchdogBacksOffRatherThanLooping()
 {
     const auto t0 = std::chrono::steady_clock::now();
     StallWatchdog w(std::chrono::milliseconds(2000), std::chrono::milliseconds(30000));
     w.setExpectingFrames(true, t0);
 
-    // TEMPORARY DEBUG -- remove before merge.
+    // Milliseconds since t0. A plain integer cursor, advanced explicitly.
-    auto rel = [t0](std::chrono::steady_clock::time_point tp) {
+    long long at_ms = 2000;
-        return (long long)std::chrono::duration_cast<std::chrono::nanoseconds>(tp - t0).count();
-    };
-    auto dump = [&](const char *tag, std::chrono::steady_clock::time_point n) {
-        std::fprintf(stderr,
-                     "WDTEST %-16s now_rel_ns=%lld next_rel_ns=%lld base_rel_ns=%lld "
-                     "backoff_ms=%lld attempts=%d\n",
-                     tag, rel(n), rel(w.dbgNextAllowed()), rel(w.dbgBaseline()),
-                     w.dbgBackoffMs(), w.attemptsThisStall());
-    };
-    std::fprintf(stderr, "WDTEST t0_ns=%lld timeout_ms=%lld max_ms=%lld\n",
-                 (long long)std::chrono::duration_cast<std::chrono::nanoseconds>(t0.time_since_epoch()).count(),
-                 w.dbgTimeoutMs(), w.dbgMaxBackoffMs());
-    dump("init", t0);
 
     // First attempt at the threshold.
-    auto now = t0 + std::chrono::milliseconds(2000);
+    ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
-    dump("pre-attempt1", now);
-    ST_ASSERT(w.poll(now));
-    dump("post-attempt1", now);
     ST_ASSERT_EQ(w.attemptsThisStall(), 1);
 
     // A genuinely gone publisher: no frame ever comes back. Immediately
     // asking again (the naive "retry every poll interval forever" a
     // watchdog without backoff would do) must NOT fire -- that is precisely
     // the "hammered every 2 seconds forever" this backoff exists to avoid.
-    ST_ASSERT(!w.poll(now + std::chrono::milliseconds(250)));
+    ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 250)));
-    ST_ASSERT(!w.poll(now + std::chrono::milliseconds(1999)));
+    ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 1999)));
 
     // The backoff after attempt 1 is the base timeout (2000ms): the second
     // attempt is allowed at +2000ms from the first, not before.
-    now += std::chrono::milliseconds(2000);
+    at_ms += 2000;
-    dump("pre-attempt2", now);
+    ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
-    ST_ASSERT(w.poll(now));
-    dump("post-attempt2", now);
     ST_ASSERT_EQ(w.attemptsThisStall(), 2);
 
     // Backoff doubles: the third attempt needs a 4000ms gap, not 2000ms.
-    ST_ASSERT(!w.poll(now + std::chrono::milliseconds(3999)));
+    ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 3999)));
-    now += std::chrono::milliseconds(4000);
+    at_ms += 4000;
-    dump("pre-attempt3", now);
+    ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
-    ST_ASSERT(w.poll(now));
-    dump("post-attempt3", now);
     ST_ASSERT_EQ(w.attemptsThisStall(), 3);
 
     // ... and again to 8000ms, and again to 16000ms.
-    ST_ASSERT(!w.poll(now + std::chrono::milliseconds(7999)));
+    ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 7999)));
-    now += std::chrono::milliseconds(8000);
+    at_ms += 8000;
-    dump("pre-attempt4", now);
+    ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
-    ST_ASSERT(w.poll(now));
-    dump("post-attempt4", now);
     ST_ASSERT_EQ(w.attemptsThisStall(), 4);
 
-    ST_ASSERT(!w.poll(now + std::chrono::milliseconds(15999)));
+    ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 15999)));
-    now += std::chrono::milliseconds(16000);
+    at_ms += 16000;
-    dump("pre-attempt5", now);
+    ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
-    ST_ASSERT(w.poll(now));
-    dump("post-attempt5", now);
     ST_ASSERT_EQ(w.attemptsThisStall(), 5);
 
     // The backoff is capped: doubling 16000ms would be 32000ms, but it
@@ -352,219 +360,21 @@ void testStallWatchdogBacksOffRatherThanLooping()
     // failed, so a publisher that comes back after an hour is still
     // retried at a bounded cadence, not abandoned.
     for (int i = 0; i < 6; ++i) {
-        std::fprintf(stderr, "WDTEST ---- loop iteration %d ----\n", i);
+        ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 29999)));
-        dump("loop-pre-29999", now + std::chrono::milliseconds(29999));
+        at_ms += 30000;
-        ST_ASSERT(!w.poll(now + std::chrono::milliseconds(29999)));
+        ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
-        now += std::chrono::milliseconds(30000);
-        dump("loop-pre-fire", now);
-        ST_ASSERT(w.poll(now));
-        dump("loop-post-fire", now);
     }
 
     // A frame finally arrives: the stall is over, and the NEXT one (a fresh
     // stall, not a continuation) starts back at the base cadence rather
     // than staying parked at the 30s ceiling forever.
-    w.onFrameDelivered(now);
+    w.onFrameDelivered(t0 + std::chrono::milliseconds(at_ms));
     ST_ASSERT_EQ(w.attemptsThisStall(), 0);
-    ST_ASSERT(!w.poll(now + std::chrono::milliseconds(1999)));
+    ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 1999)));
-    ST_ASSERT(w.poll(now + std::chrono::milliseconds(2000)));
+    ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms + 2000)));
     ST_ASSERT_EQ(w.attemptsThisStall(), 1);
 }
 
-
-// TEMPORARY DEBUG -- remove before merge. Same sequence as the test above,
-// but every number is RECORDED into plain locals and printed only after the
-// loop finishes, so the loop body stays as close to the original as
-// possible (an fprintf inside poll() made this pass on Windows, so the
-// observation itself perturbs the thing being observed).
-void testStallWatchdogTrace()
-{
-    struct Rec {
-        long long now_ns;
-        long long next_ns;
-        long long base_ns;
-        long long backoff_ms;
-        int attempts;
-        int early;   // result of poll(now + 29999) -- expected 0
-        int fire;    // result of poll(now)         -- expected 1
-    };
-    Rec recs[16];
-    int n = 0;
-
-    const auto t0 = std::chrono::steady_clock::now();
-    StallWatchdog w(std::chrono::milliseconds(2000), std::chrono::milliseconds(30000));
-    w.setExpectingFrames(true, t0);
-
-    auto rel = [t0](std::chrono::steady_clock::time_point tp) {
-        return (long long)std::chrono::duration_cast<std::chrono::nanoseconds>(tp - t0).count();
-    };
-    auto rec = [&](std::chrono::steady_clock::time_point now, int early, int fire) {
-        if (n < 16) {
-            recs[n].now_ns = rel(now);
-            recs[n].next_ns = rel(w.dbgNextAllowed());
-            recs[n].base_ns = rel(w.dbgBaseline());
-            recs[n].backoff_ms = w.dbgBackoffMs();
-            recs[n].attempts = w.attemptsThisStall();
-            recs[n].early = early;
-            recs[n].fire = fire;
-            ++n;
-        }
-    };
-
-    auto now = t0 + std::chrono::milliseconds(2000);
-    int f = w.poll(now) ? 1 : 0;
-    rec(now, -1, f);
-
-    const int gaps[] = {2000, 4000, 8000, 16000};
-    for (int i = 0; i < 4; ++i) {
-        now += std::chrono::milliseconds(gaps[i]);
-        f = w.poll(now) ? 1 : 0;
-        rec(now, -1, f);
-    }
-
-    for (int i = 0; i < 6; ++i) {
-        const int e = w.poll(now + std::chrono::milliseconds(29999)) ? 1 : 0;
-        now += std::chrono::milliseconds(30000);
-        f = w.poll(now) ? 1 : 0;
-        rec(now, e, f);
-    }
-
-    std::fprintf(stderr, "WDTRACE t0_ns=%lld timeout_ms=%lld max_ms=%lld tick_num=%lld tick_den=%lld rep_bytes=%d\n",
-                 (long long)std::chrono::duration_cast<std::chrono::nanoseconds>(t0.time_since_epoch()).count(),
-                 w.dbgTimeoutMs(), w.dbgMaxBackoffMs(),
-                 (long long)std::chrono::steady_clock::period::num,
-                 (long long)std::chrono::steady_clock::period::den,
-                 (int)sizeof(std::chrono::steady_clock::rep));
-    for (int i = 0; i < n; ++i) {
-        std::fprintf(stderr,
-                     "WDTRACE step=%2d now_rel_ns=%lld next_rel_ns=%lld base_rel_ns=%lld backoff_ms=%lld attempts=%d early=%d fire=%d\n",
-                     i, recs[i].now_ns, recs[i].next_ns, recs[i].base_ns,
-                     recs[i].backoff_ms, recs[i].attempts, recs[i].early, recs[i].fire);
-    }
-}
-
-// TEMPORARY DEBUG -- remove before merge.
-//
-// A non-inlined wrapper, so the time point can be read on the CALLEE side:
-// whatever `received_ns` holds is what actually crossed the call boundary,
-// independent of what the caller's abstract-machine value was.
-#if defined(_MSC_VER)
-#define ST_NOINLINE __declspec(noinline)
-#else
-#define ST_NOINLINE __attribute__((noinline))
-#endif
-ST_NOINLINE bool st_dbg_poll(StallWatchdog &w, std::chrono::steady_clock::time_point n,
-                             long long *received_ns)
-{
-    *received_ns = (long long)n.time_since_epoch().count();
-    return w.poll(n);
-}
-
-// Shapes, each run twice:
-//   mode 0  accumulate `now += 30000ms`, pass `now`        (known-bad)
-//   mode 1  accumulate, pass a named copy of `now`         (known-good)
-//   mode 2  accumulate, sum the ns the CALLER holds
-//   mode 3  accumulate, through st_dbg_poll (callee-side capture)
-void testStallWatchdogQuiet()
-{
-    struct Trial {
-        int mode;
-        int early[6];
-        int fire[6];
-        long long fire_arg_sum_ms;
-        long long recv_rel_ms[6];
-        long long t0_ns;
-        long long next_rel_ns;
-        int attempts_after;
-    };
-    const int kTrials = 8;
-    Trial trials[kTrials];
-
-    for (int t = 0; t < kTrials; ++t) {
-        const int mode = t % 4;
-        const auto t0 = std::chrono::steady_clock::now();
-        StallWatchdog w(std::chrono::milliseconds(2000), std::chrono::milliseconds(30000));
-        w.setExpectingFrames(true, t0);
-
-        int early[6] = {0};
-        int fire[6] = {0};
-        long long fsum = 0;
-        long long recv[6] = {0, 0, 0, 0, 0, 0};
-
-        auto now = t0 + std::chrono::milliseconds(2000);
-        (void)w.poll(now);
-        now += std::chrono::milliseconds(2000);
-        (void)w.poll(now);
-        now += std::chrono::milliseconds(4000);
-        (void)w.poll(now);
-        now += std::chrono::milliseconds(8000);
-        (void)w.poll(now);
-        now += std::chrono::milliseconds(16000);
-        (void)w.poll(now);
-
-        if (mode == 0) {
-            for (int i = 0; i < 6; ++i) {
-                early[i] = w.poll(now + std::chrono::milliseconds(29999)) ? 1 : 0;
-                now += std::chrono::milliseconds(30000);
-                fire[i] = w.poll(now) ? 1 : 0;
-            }
-        } else if (mode == 1) {
-            for (int i = 0; i < 6; ++i) {
-                early[i] = w.poll(now + std::chrono::milliseconds(29999)) ? 1 : 0;
-                now += std::chrono::milliseconds(30000);
-                const auto fire_arg = now;
-                fire[i] = w.poll(fire_arg) ? 1 : 0;
-            }
-        } else if (mode == 2) {
-            for (int i = 0; i < 6; ++i) {
-                early[i] = w.poll(now + std::chrono::milliseconds(29999)) ? 1 : 0;
-                now += std::chrono::milliseconds(30000);
-                fsum += std::chrono::duration_cast<std::chrono::milliseconds>(now - t0).count();
-                fire[i] = w.poll(now) ? 1 : 0;
-            }
-        } else {
-            for (int i = 0; i < 6; ++i) {
-                long long junk = 0;
-                early[i] = st_dbg_poll(w, now + std::chrono::milliseconds(29999), &junk) ? 1 : 0;
-                now += std::chrono::milliseconds(30000);
-                fire[i] = st_dbg_poll(w, now, &recv[i]) ? 1 : 0;
-            }
-        }
-
-        trials[t].mode = mode;
-        for (int i = 0; i < 6; ++i) {
-            trials[t].early[i] = early[i];
-            trials[t].fire[i] = fire[i];
-            trials[t].recv_rel_ms[i] =
-                recv[i] ? (recv[i] - (long long)t0.time_since_epoch().count()) / 1000000LL : -1;
-        }
-        trials[t].fire_arg_sum_ms = fsum;
-        trials[t].t0_ns = (long long)t0.time_since_epoch().count();
-        trials[t].next_rel_ns =
-            (long long)std::chrono::duration_cast<std::chrono::nanoseconds>(w.dbgNextAllowed() - t0).count();
-        trials[t].attempts_after = w.attemptsThisStall();
-    }
-
-    for (int t = 0; t < kTrials; ++t) {
-        std::fprintf(stderr,
-                     "WDQUIET trial=%d mode=%d after=%d next_rel_ns=%lld fsum=%lld(want 822000) recv_ms=%lld,%lld,%lld,%lld,%lld,%lld early=%d%d%d%d%d%d fire=%d%d%d%d%d%d\n",
-                     t, trials[t].mode, trials[t].attempts_after, trials[t].next_rel_ns,
-                     trials[t].fire_arg_sum_ms,
-                     trials[t].recv_rel_ms[0], trials[t].recv_rel_ms[1], trials[t].recv_rel_ms[2],
-                     trials[t].recv_rel_ms[3], trials[t].recv_rel_ms[4], trials[t].recv_rel_ms[5],
-                     trials[t].early[0], trials[t].early[1], trials[t].early[2],
-                     trials[t].early[3], trials[t].early[4], trials[t].early[5],
-                     trials[t].fire[0], trials[t].fire[1], trials[t].fire[2],
-                     trials[t].fire[3], trials[t].fire[4], trials[t].fire[5]);
-    }
-    for (int t = 0; t < kTrials; ++t) {
-        for (int i = 0; i < 6; ++i) {
-            ST_ASSERT(trials[t].early[i] == 0);
-            ST_ASSERT(trials[t].fire[i] == 1);
-        }
-    }
-}
-
 // The ceiling has to engage on the FIRST attempt whose doubled backoff would
 // exceed it, not one attempt later -- a Windows release build got exactly
 // that step wrong (it waited 32s once before settling at the 30s ceiling),
@@ -578,8 +388,10 @@ void testStallWatchdogNeverWaitsLongerThanTheCeiling()
     StallWatchdog w(std::chrono::milliseconds(1000), std::chrono::milliseconds(5000));
     w.setExpectingFrames(true, t0);
 
-    auto now = t0 + std::chrono::milliseconds(1000);
+    // Absolute instants off t0, for the reason spelled out above
-    ST_ASSERT(w.poll(now));
+    // testStallWatchdogBacksOffRatherThanLooping().
+    long long at_ms = 1000;
+    ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
 
     // Expected gaps between consecutive attempts: 1000, 2000, 4000, then the
     // ceiling for good. Each gap is checked on both sides of its boundary, so
@@ -587,9 +399,9 @@ void testStallWatchdogNeverWaitsLongerThanTheCeiling()
     const int expected_gaps[] = {1000, 2000, 4000, 5000, 5000, 5000, 5000};
     int attempt = 1;
     for (int gap : expected_gaps) {
-        ST_ASSERT(!w.poll(now + std::chrono::milliseconds(gap - 1)));
+        ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + gap - 1)));
-        now += std::chrono::milliseconds(gap);
+        at_ms += gap;
-        ST_ASSERT(w.poll(now));
+        ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
         ST_ASSERT_EQ(w.attemptsThisStall(), ++attempt);
     }
 }
@@ -723,8 +535,6 @@ int main()
     testStallWatchdogFiresAfterThreshold();
     testStallWatchdogDoesNotFireWhenNotExpectingFrames();
     testStallWatchdogBacksOffRatherThanLooping();
-    testStallWatchdogTrace();
-    testStallWatchdogQuiet();
     testStallWatchdogNeverWaitsLongerThanTheCeiling();
 
     LiveKitSession::globalInitialize();