test(session): derive watchdog instants from t0, not an accumulated local
Build / macOS (macos-latest) (push) Successful in 53s
Build / Linux (ubuntu-24.04) (push) Successful in 1m7s
Release / macOS (macos-latest) (push) Successful in 57s
Release / Linux (ubuntu-24.04) (push) Successful in 1m14s
Build / Windows (windows-latest) (push) Successful in 4m6s
Release / Windows (windows-latest) (push) Successful in 3m55s
Release / Create Gitea Release (push) Successful in 20s
Build / macOS (macos-latest) (push) Successful in 53s
Build / Linux (ubuntu-24.04) (push) Successful in 1m7s
Release / macOS (macos-latest) (push) Successful in 57s
Release / Linux (ubuntu-24.04) (push) Successful in 1m14s
Build / Windows (windows-latest) (push) Successful in 4m6s
Release / Windows (windows-latest) (push) Successful in 3m55s
Release / Create Gitea Release (push) Successful in 20s
Windows CI failed on the stall-recovery watchdog for three attempts. The first two diagnoses both blamed the backoff arithmetic; the second produced a byte-identical failure, which was the clue that neither had found the cause. Instrumenting the test on the Windows runner settled it with numbers. Capturing the time point on the callee side of a noinline wrapper showed the six `w.poll(now)` calls in the capped-backoff loop received: Windows 32000, 32000, 32000, 32000, 32000, 32000 (ms after t0) Linux/macOS 62000, 92000, 122000, 152000, 182000, 212000 while a checksum of the caller's own arguments in the same loop summed to 822000 -- exactly the correct series. The caller's value was right; the value that crossed the call boundary was not. MSVC 19.44 x64 Release hoists the argument of the second poll() out of the fixed-stride loop `poll(now + 29999ms); now += 30000ms; poll(now);`, so every iteration passed the pre-loop `now`. StallWatchdog is correct on all three platforms and is not changed here. Production never had this exposure: watchdogLoop() calls poll() with a fresh steady_clock::now() per tick, never a loop-carried local advanced by a constant. Both watchdog tests now derive every instant absolutely as `t0 + milliseconds(at_ms)` from an integer cursor -- the shape verified to compile correctly on that runner. No assertion is weakened: every gap is still checked one millisecond either side of its boundary. Also corrects the comment in session_types.cpp that blamed a Windows release build for mis-capping the ceiling. It never did. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
@@ -234,10 +234,18 @@ bool StallWatchdog::poll(std::chrono::steady_clock::time_point now)
|
||||
// between two recovery attempts, so it is enforced on the gap itself;
|
||||
// that way the promise holds for whatever backoff_ happens to contain,
|
||||
// rather than depending on every earlier growth step having clamped
|
||||
// correctly. A capped release build on Windows got that one step wrong
|
||||
// (the ceiling engaged one attempt late, so a single 32s gap slipped
|
||||
// past the 30s ceiling), which is exactly the kind of drift this
|
||||
// clamp-at-use makes unrepresentable.
|
||||
// correctly.
|
||||
//
|
||||
// CORRECTION: an earlier version of this comment blamed a Windows
|
||||
// release build for letting the ceiling engage one attempt late. That
|
||||
// was wrong, and it is worth recording why rather than quietly
|
||||
// deleting it. Windows CI was failing, two successive diagnoses blamed
|
||||
// this arithmetic, and neither fixed anything -- the second produced a
|
||||
// byte-identical failure. Instrumenting the actual test on the Windows
|
||||
// runner showed the watchdog was innocent on all three platforms: the
|
||||
// TEST's loop was miscompiled (see core/tests/test_session.cpp). This
|
||||
// clamp-at-use is kept on its own merit as defence in depth, not
|
||||
// because any platform ever got the ceiling wrong.
|
||||
const std::chrono::milliseconds wait = backoff_ < max_backoff_ ? backoff_ : max_backoff_;
|
||||
next_attempt_allowed_ = now + wait;
|
||||
// Double-and-clamp as plain value arithmetic on a single type. This was
|
||||
|
||||
+64
-26
@@ -278,45 +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);
|
||||
|
||||
// Milliseconds since t0. A plain integer cursor, advanced explicitly.
|
||||
long long at_ms = 2000;
|
||||
|
||||
// First attempt at the threshold.
|
||||
auto now = t0 + std::chrono::milliseconds(2000);
|
||||
ST_ASSERT(w.poll(now));
|
||||
ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
|
||||
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(now + std::chrono::milliseconds(1999)));
|
||||
ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 250)));
|
||||
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);
|
||||
ST_ASSERT(w.poll(now));
|
||||
at_ms += 2000;
|
||||
ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
|
||||
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)));
|
||||
now += std::chrono::milliseconds(4000);
|
||||
ST_ASSERT(w.poll(now));
|
||||
ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 3999)));
|
||||
at_ms += 4000;
|
||||
ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
|
||||
ST_ASSERT_EQ(w.attemptsThisStall(), 3);
|
||||
|
||||
// ... and again to 8000ms, and again to 16000ms.
|
||||
ST_ASSERT(!w.poll(now + std::chrono::milliseconds(7999)));
|
||||
now += std::chrono::milliseconds(8000);
|
||||
ST_ASSERT(w.poll(now));
|
||||
ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 7999)));
|
||||
at_ms += 8000;
|
||||
ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
|
||||
ST_ASSERT_EQ(w.attemptsThisStall(), 4);
|
||||
|
||||
ST_ASSERT(!w.poll(now + std::chrono::milliseconds(15999)));
|
||||
now += std::chrono::milliseconds(16000);
|
||||
ST_ASSERT(w.poll(now));
|
||||
ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 15999)));
|
||||
at_ms += 16000;
|
||||
ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
|
||||
ST_ASSERT_EQ(w.attemptsThisStall(), 5);
|
||||
|
||||
// The backoff is capped: doubling 16000ms would be 32000ms, but it
|
||||
@@ -324,18 +360,18 @@ 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) {
|
||||
ST_ASSERT(!w.poll(now + std::chrono::milliseconds(29999)));
|
||||
now += std::chrono::milliseconds(30000);
|
||||
ST_ASSERT(w.poll(now));
|
||||
ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 29999)));
|
||||
at_ms += 30000;
|
||||
ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
|
||||
}
|
||||
|
||||
// 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(now + std::chrono::milliseconds(2000)));
|
||||
ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + 1999)));
|
||||
ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms + 2000)));
|
||||
ST_ASSERT_EQ(w.attemptsThisStall(), 1);
|
||||
}
|
||||
|
||||
@@ -352,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);
|
||||
ST_ASSERT(w.poll(now));
|
||||
// Absolute instants off t0, for the reason spelled out above
|
||||
// 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
|
||||
@@ -361,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)));
|
||||
now += std::chrono::milliseconds(gap);
|
||||
ST_ASSERT(w.poll(now));
|
||||
ST_ASSERT(!w.poll(t0 + std::chrono::milliseconds(at_ms + gap - 1)));
|
||||
at_ms += gap;
|
||||
ST_ASSERT(w.poll(t0 + std::chrono::milliseconds(at_ms)));
|
||||
ST_ASSERT_EQ(w.attemptsThisStall(), ++attempt);
|
||||
}
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user