debug: round 2 -- deferred trace plus a quiet duplicate

Round 1's in-poll fprintf made Windows pass, so poll() is back to its
pristine form and the numbers are recorded into locals and printed after
the fact. The quiet copy runs the same sequence with no observation at
all, to tell codegen apart from data. TEMPORARY.

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

core/src/session_types.cpp

@@ -14,10 +14,6 @@ You may obtain a copy of the License at
 // TEMPORARY DEBUG -- remove before merge.
 #include <cstdio>
 #include <ratio>
-namespace { long long dbg_ns(std::chrono::steady_clock::time_point tp) {
-    return (long long)std::chrono::duration_cast<std::chrono::nanoseconds>(tp.time_since_epoch()).count();
-} }
-
 
 namespace stplugin {
 
@@ -223,23 +219,6 @@ void StallWatchdog::onFrameDelivered(std::chrono::steady_clock::time_point now)
 
 bool StallWatchdog::poll(std::chrono::steady_clock::time_point now)
 {
-    // TEMPORARY DEBUG -- remove before merge.
-    std::fprintf(stderr,
-                 "WDPOLL now_ns=%lld base_ns=%lld next_ns=%lld elapsed_ms=%lld "
-                 "backoff_ms=%lld timeout_ms=%lld max_ms=%lld attempts=%d "
-                 "expecting=%d have_base=%d c_elapsed_lt_timeout=%d c_now_lt_next=%d "
-                 "tick_num=%lld tick_den=%lld sizeof_rep=%d\n",
-                 dbg_ns(now), dbg_ns(baseline_), dbg_ns(next_attempt_allowed_),
-                 (long long)std::chrono::duration_cast<std::chrono::milliseconds>(now - baseline_).count(),
-                 (long long)backoff_.count(), (long long)timeout_.count(),
-                 (long long)max_backoff_.count(), attempts_,
-                 expecting_ ? 1 : 0, have_baseline_ ? 1 : 0,
-                 (now - baseline_ < timeout_) ? 1 : 0,
-                 (now < next_attempt_allowed_) ? 1 : 0,
-                 (long long)std::chrono::steady_clock::period::num,
-                 (long long)std::chrono::steady_clock::period::den,
-                 (int)sizeof(std::chrono::steady_clock::rep));
-
     if (!expecting_ || !have_baseline_)
         return false;
     if (now - baseline_ < timeout_)
@@ -274,10 +253,6 @@ bool StallWatchdog::poll(std::chrono::steady_clock::time_point now)
     // doubling also means the product is computed only when it cannot
     // exceed max_backoff_, so no intermediate can overflow.
     backoff_ = (wait > max_backoff_ / 2) ? max_backoff_ : wait * 2;
-    // TEMPORARY DEBUG -- remove before merge.
-    std::fprintf(stderr, "WDFIRE attempts=%d wait_ms=%lld new_next_ns=%lld new_backoff_ms=%lld\n",
-                 attempts_, (long long)wait.count(), dbg_ns(next_attempt_allowed_),
-                 (long long)backoff_.count());
     return true;
 }
 

core/tests/test_session.cpp

@@ -27,6 +27,7 @@ You may obtain a copy of the License at
 
 #include <atomic>
 #include <cstdio>
+#include <cstdio>
 #include <chrono>
 #include <string>
 #include <thread>
@@ -370,6 +371,119 @@ void testStallWatchdogBacksOffRatherThanLooping()
     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 byte-for-byte quiet copy of the
+// loop from testStallWatchdogBacksOffRatherThanLooping: no accessor calls,
+// no printing inside the loop. Results are collected into an int array and
+// reported afterwards, so if the loud trace above passes while this one
+// fails, the observation is the cure and the fault is codegen, not data.
+void testStallWatchdogQuiet()
+{
+    int early[6] = {0};
+    int fire[6] = {0};
+
+    const auto t0 = std::chrono::steady_clock::now();
+    StallWatchdog w(std::chrono::milliseconds(2000), std::chrono::milliseconds(30000));
+    w.setExpectingFrames(true, t0);
+
+    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);
+    const int attempts_before_loop = w.attemptsThisStall();
+
+    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;
+    }
+
+    std::fprintf(stderr, "WDQUIET attempts_before_loop=%d\n", attempts_before_loop);
+    for (int i = 0; i < 6; ++i)
+        std::fprintf(stderr, "WDQUIET i=%d early=%d(want 0) fire=%d(want 1)\n", i, early[i], fire[i]);
+    for (int i = 0; i < 6; ++i) {
+        ST_ASSERT(early[i] == 0);
+        ST_ASSERT(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),
@@ -528,6 +642,8 @@ int main()
     testStallWatchdogFiresAfterThreshold();
     testStallWatchdogDoesNotFireWhenNotExpectingFrames();
     testStallWatchdogBacksOffRatherThanLooping();
+    testStallWatchdogTrace();
+    testStallWatchdogQuiet();
     testStallWatchdogNeverWaitsLongerThanTheCeiling();
 
     LiveKitSession::globalInitialize();