From 4305e189ace8c1f1c6429327394fe8c4b374903d Mon Sep 17 00:00:00 2001 From: "Mars.P" Date: Sun, 20 Sep 2026 08:22:28 +0800 Subject: [PATCH] Run every heartbeat on the clock its caller passed MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The loop's TimeProvider was optional and defaulted to TimeProvider.System, so both executor call sites kept the wall clock without saying so: the seam existed and production ignored it. A test could therefore only pin the loop by racing real milliseconds, and A_failing_ping_is_reported_but_does_not_ kill_the_loop asserted that at least two 20ms ticks fitted inside a real 200ms window. On a loaded runner one did, reddening runs whose diffs touched nothing near this loop. Making the parameter required turns "which clock" into a question the compiler asks at every call site, and both executor heartbeats now hand it the DI-registered TimeProvider they already hold for the checkpoint cadence — the system provider's Delay IS the Task.Delay this used before, so the cadence is unchanged. With the fake clock deciding time, the test asserts exactly one ping per elapsed interval instead of "at least two", which was the property meant all along. A fake clock proves the loop honours whatever interval it is handed and says nothing about which one production hands it, so the real cadence is pinned as a number where it is derived. --- .../Services/Agents/AgentRunExecutor.cs | 6 +- .../Services/Agents/HeartbeatLoop.cs | 17 +++-- ...RealModelAnswerReviewDelegationE2ETests.cs | 2 +- .../Workflows/AgentRunLivenessTests.cs | 12 ++++ .../Workflows/HeartbeatLoopTests.cs | 62 ++++++++++++++----- 5 files changed, 74 insertions(+), 25 deletions(-) diff --git a/backend/src/CodeSpace.Core/Services/Agents/AgentRunExecutor.cs b/backend/src/CodeSpace.Core/Services/Agents/AgentRunExecutor.cs index 4642d811e..b5c50ce85 100644 --- a/backend/src/CodeSpace.Core/Services/Agents/AgentRunExecutor.cs +++ b/backend/src/CodeSpace.Core/Services/Agents/AgentRunExecutor.cs @@ -270,7 +270,8 @@ public async Task ExecuteAsync(Guid agentRunId, CancellationToken cancellationTo ct => RenewObservationAndCredentialAsync(heartbeatRuns, owner, observerCts, ct), AgentRunLiveness.HeartbeatInterval, ex => _logger.LogWarning(ex, "Heartbeat ping failed for agent run {RunId}; lost ownership stops observation, transient failures retry", agentRunId), - heartbeatCts.Token); + heartbeatCts.Token, + _clock); // Holds the run's resolved secret(s) once the credential is resolved (below), so the catch-all can scrub // them from a failure message too. None until then — a pre-resolve failure has no secret to leak. @@ -803,7 +804,8 @@ public async Task ReattachAsync(AgentRunReattachReservation reservation, Cancell ct => RenewObservationAndCredentialAsync(heartbeatRuns, owner, observerCts, ct), AgentRunLiveness.HeartbeatInterval, ex => _logger.LogWarning(ex, "Heartbeat ping failed for re-attached agent run {RunId}; lost ownership stops observation, transient failures retry", agentRunId), - heartbeatCts.Token); + heartbeatCts.Token, + _clock); var expectedEpoch = owner.Epoch; diff --git a/backend/src/CodeSpace.Core/Services/Agents/HeartbeatLoop.cs b/backend/src/CodeSpace.Core/Services/Agents/HeartbeatLoop.cs index 4bfb64882..dc61e8271 100644 --- a/backend/src/CodeSpace.Core/Services/Agents/HeartbeatLoop.cs +++ b/backend/src/CodeSpace.Core/Services/Agents/HeartbeatLoop.cs @@ -17,18 +17,23 @@ public static class HeartbeatLoop /// The first ping is deferred by one interval because the claim already stamped an initial heartbeat. /// /// exists so the cadence can be driven deterministically in a test instead - /// of raced against the wall clock. It is OPTIONAL and defaults to , so every - /// existing call site compiles unchanged and production behaviour is byte-identical — the system provider's - /// Delay IS the Task.Delay this used before. rather than a bespoke clock - /// interface: it is the BCL's own seam, so the next thing that needs one does not invent a second vocabulary. + /// of raced against the wall clock. Production passes the DI-registered , whose + /// Delay IS the Task.Delay this used before, so production behaviour is byte-identical. + /// rather than a bespoke clock interface: it is the BCL's own seam, so the next thing + /// that needs one does not invent a second vocabulary. + /// + /// REQUIRED, not optional-defaulting-to-System. While it defaulted, BOTH executor call sites silently kept + /// the wall clock: the seam existed and nothing used it, so a test could only pin the loop by racing real + /// milliseconds. A required parameter makes "which clock does this run on" a decision the compiler asks at every + /// call site instead of one a default answers invisibly. /// - public static async Task RunAsync(Func ping, TimeSpan interval, Action onPingError, CancellationToken cancellationToken, TimeProvider? timeProvider = null) + public static async Task RunAsync(Func ping, TimeSpan interval, Action onPingError, CancellationToken cancellationToken, TimeProvider timeProvider) { try { while (!cancellationToken.IsCancellationRequested) { - await Task.Delay(interval, timeProvider ?? TimeProvider.System, cancellationToken).ConfigureAwait(false); + await Task.Delay(interval, timeProvider, cancellationToken).ConfigureAwait(false); try { diff --git a/backend/tests/CodeSpace.E2ETests/Workflows/RealModelAnswerReviewDelegationE2ETests.cs b/backend/tests/CodeSpace.E2ETests/Workflows/RealModelAnswerReviewDelegationE2ETests.cs index 594e58063..dbe8ef5c7 100644 --- a/backend/tests/CodeSpace.E2ETests/Workflows/RealModelAnswerReviewDelegationE2ETests.cs +++ b/backend/tests/CodeSpace.E2ETests/Workflows/RealModelAnswerReviewDelegationE2ETests.cs @@ -109,7 +109,7 @@ internal static bool MeetsCase(CriticVerdict verdict, bool flawed, string auditT { using var scope = _fixture.BeginScope(); await scope.Resolve().HeartbeatAsync(owner, cancellationToken); - }, TimeSpan.FromSeconds(5), error => { Interlocked.CompareExchange(ref heartbeatFailure, error, null); deadline.Cancel(); }, heartbeatCancellation.Token); + }, TimeSpan.FromSeconds(5), error => { Interlocked.CompareExchange(ref heartbeatFailure, error, null); deadline.Cancel(); }, heartbeatCancellation.Token, TimeProvider.System); try { diff --git a/backend/tests/CodeSpace.UnitTests/Workflows/AgentRunLivenessTests.cs b/backend/tests/CodeSpace.UnitTests/Workflows/AgentRunLivenessTests.cs index 3572f6403..986b8f71d 100644 --- a/backend/tests/CodeSpace.UnitTests/Workflows/AgentRunLivenessTests.cs +++ b/backend/tests/CodeSpace.UnitTests/Workflows/AgentRunLivenessTests.cs @@ -58,6 +58,18 @@ public void HeartbeatInterval_is_floored_for_a_tiny_window() AgentRunLiveness.HeartbeatInterval.ShouldBe(TimeSpan.FromSeconds(5)); } + [Fact] + public void HeartbeatInterval_defaults_to_one_hundred_seconds() + { + // The cadence a live agent run actually pings at — and the ONLY place it is pinned as a number, now that + // HeartbeatLoopTests drives a fake clock. A fake clock proves the loop honours whatever interval it is + // handed; it says nothing about which interval production hands it. Changing either half of the + // derivation (the 5-minute default window, or the /3) silently re-cadences every run, and reds here. + Environment.SetEnvironmentVariable(AgentRunLiveness.WindowEnvVar, null); + + AgentRunLiveness.HeartbeatInterval.ShouldBe(TimeSpan.FromSeconds(100)); + } + [Fact] public void HeartbeatInterval_stays_below_the_window_at_the_default() { diff --git a/backend/tests/CodeSpace.UnitTests/Workflows/HeartbeatLoopTests.cs b/backend/tests/CodeSpace.UnitTests/Workflows/HeartbeatLoopTests.cs index bba90af15..c13c95374 100644 --- a/backend/tests/CodeSpace.UnitTests/Workflows/HeartbeatLoopTests.cs +++ b/backend/tests/CodeSpace.UnitTests/Workflows/HeartbeatLoopTests.cs @@ -9,11 +9,13 @@ namespace CodeSpace.UnitTests.Workflows; /// cadence, a failed ping is reported but doesn't kill the loop, and it returns cleanly on cancellation /// (never surfacing OperationCanceledException). /// -/// The cadence is driven by a , not by the wall clock. The first of these tests -/// asserted on how many real 20ms ticks fitted inside a real 200ms window, and reddened at random on a loaded -/// runner — observed on PR #1297, a diff that touched neither this loop nor anything near it. A test that reds at +/// Every cadence here is driven by a , not by the wall clock. Both counting +/// tests below once asserted on how many real 20ms ticks fitted inside a real 200ms window, and each reddened at +/// random on a loaded runner — the ping test on PR #1297, the failing-ping test on #2001 (pings should be +/// >= 2 but was 1), both diffs that touched neither this loop nor anything near it. A test that reds at /// random is worse than a missing one: it teaches every reader to re-run red instead of reading it, which is how a -/// real regression gets waved through. Advancing a fake clock makes the SAME property exact instead of probable. +/// real regression gets waved through. Advancing a fake clock makes the SAME property exact instead of probable — +/// and turns "at least 2 pings" into "exactly one per elapsed interval", which is the property that was meant. /// [Trait("Category", "Unit")] public class HeartbeatLoopTests @@ -51,8 +53,8 @@ public async Task Pings_once_per_interval_until_cancelled() } /// - /// Advances the fake clock until the loop pings, rather than advancing once and assuming it was - /// listening. + /// Advances the fake clock until the loop signals , rather than advancing once and + /// assuming it was listening. /// /// The loop arms its next timer inside Task.Delay AFTER the previous ping returns, so a /// single Advance can land in the window before that registration and be missed entirely — the @@ -60,11 +62,11 @@ public async Task Pings_once_per_interval_until_cancelled() /// kept losing. Nudging in fractions of an interval cannot fire a timer early, and the count /// assertion at the call site is what still proves one ping per interval. /// - private static async Task AdvanceUntilPingedAsync(FakeTimeProvider time, SemaphoreSlim pinged, TimeSpan interval, int ordinal) + private static async Task AdvanceUntilPingedAsync(FakeTimeProvider time, SemaphoreSlim ticked, TimeSpan interval, int ordinal) { for (var nudge = 0; nudge < 200; nudge++) { - if (await pinged.WaitAsync(TimeSpan.FromMilliseconds(10))) return; + if (await ticked.WaitAsync(TimeSpan.FromMilliseconds(10))) return; time.Advance(interval / 10); } @@ -75,26 +77,38 @@ private static async Task AdvanceUntilPingedAsync(FakeTimeProvider time, Semapho [Fact] public async Task A_failing_ping_is_reported_but_does_not_kill_the_loop() { + var time = new FakeTimeProvider(); + var interval = TimeSpan.FromSeconds(30); + var reported = new SemaphoreSlim(0); var pings = 0; var errors = 0; using var cts = new CancellationTokenSource(); + // The semaphore is released from onPingError, not from the ping: by the time it signals, BOTH counters + // for that tick have settled, so the assertions below read a consistent pair rather than a half-applied one. var loop = HeartbeatLoop.RunAsync( _ => { Interlocked.Increment(ref pings); throw new InvalidOperationException("transient db blip"); }, - TimeSpan.FromMilliseconds(20), - _ => Interlocked.Increment(ref errors), - cts.Token); + interval, + _ => { Interlocked.Increment(ref errors); reported.Release(); }, + cts.Token, + time); - cts.CancelAfter(TimeSpan.FromMilliseconds(200)); - await loop; + for (var i = 1; i <= 3; i++) + { + await AdvanceUntilPingedAsync(time, reported, interval, i); + + Volatile.Read(ref pings).ShouldBe(i, "a throwing ping must not stop, skip, or double the cadence"); + Volatile.Read(ref errors).ShouldBe(i, "every failed ping is reported exactly once — none aborted the loop"); + } - pings.ShouldBeGreaterThanOrEqualTo(2); - errors.ShouldBe(pings); // every failed ping was reported; none aborted the loop + cts.Cancel(); + await loop; // a loop whose every ping threw still returns cleanly on cancel, never surfacing the failure } [Fact] public async Task Returns_without_pinging_when_already_cancelled() { + var time = new FakeTimeProvider(); var count = 0; using var cts = new CancellationTokenSource(); cts.Cancel(); @@ -103,8 +117,24 @@ await HeartbeatLoop.RunAsync( _ => { Interlocked.Increment(ref count); return Task.CompletedTask; }, TimeSpan.FromSeconds(30), _ => { }, - cts.Token); + cts.Token, + time); count.ShouldBe(0); // first ping is deferred one interval; cancelled before it } + + /// + /// The clock is a REQUIRED parameter, so no call site can fall back to the wall clock by saying nothing. + /// + /// It was optional-defaulting-to-System first, and both executor call sites took that default — the seam + /// existed and production ignored it, which is exactly how a "we made it testable" claim goes stale. A default + /// here is re-addable in one character and would red nothing else, so this pins the absence of one. + /// + [Fact] + public void The_clock_cannot_be_omitted_by_a_call_site() + { + var clock = typeof(HeartbeatLoop).GetMethod(nameof(HeartbeatLoop.RunAsync))!.GetParameters().Single(p => p.ParameterType == typeof(TimeProvider)); + + clock.HasDefaultValue.ShouldBeFalse("an optional clock is how both production heartbeats silently stayed on the wall clock"); + } }