diff --git a/Darling/Darling.Tests/DarlingCloudIdentityProbeTests.cs b/Darling/Darling.Tests/DarlingCloudIdentityProbeTests.cs index 213feaa418..8abe39f009 100644 --- a/Darling/Darling.Tests/DarlingCloudIdentityProbeTests.cs +++ b/Darling/Darling.Tests/DarlingCloudIdentityProbeTests.cs @@ -95,6 +95,73 @@ public async Task ProbeAsync_Ec2TokenFails_FallsBackToAzureSuccess_ReturnsAzureP /// cannot delay either one, so time past this bar is a wait inside the probe, not the machine. private const long NoPoolStepLimitMs = 1000; + /// A dedicated thread (never a pool thread) that ticks every 10 ms and records each tick that came + /// late (#5600). A stop-the-world GC pause or a descheduled process delays every thread at once, so a stall + /// the watcher saw inside a window is machine time, not probe time, and the budget test below grants that + /// window the stall as extra allowance. A probe that really waits (an untokened delay, say) leaves the + /// watcher ticking on time, so the wait gets no allowance and still fails. + private sealed class StallWatcher : IDisposable + { + private const int TickMs = 10; + private const long MinStallMs = 25; + private readonly Stopwatch _clock; + private readonly object _gate = new(); + private readonly List<(long Start, long End)> _stalls = []; + private readonly Thread _thread; + private volatile bool _stop; + + public StallWatcher(Stopwatch clock) + { + _clock = clock; + _thread = new Thread(Run) { IsBackground = true, Name = "probe-test-stall-watcher" }; + _thread.Start(); + } + + private void Run() + { + var last = _clock.ElapsedMilliseconds; + while (!_stop) + { + Thread.Sleep(TickMs); + var now = _clock.ElapsedMilliseconds; + if (now - last - TickMs >= MinStallMs) + { + lock (_gate) + { + _stalls.Add((last, now)); + } + } + + last = now; + } + } + + /// The milliseconds of [from, to] that fall inside a stall the watcher saw. + public long StallMsWithin(long from, long to) + { + long total = 0; + lock (_gate) + { + foreach (var (start, end) in _stalls) + { + var overlap = Math.Min(end, to) - Math.Max(start, from); + if (overlap > 0) + { + total += overlap; + } + } + } + + return total; + } + + public void Dispose() + { + _stop = true; + _thread.Join(); + } + } + [Fact] public async Task ProbeAsync_NeitherCloudResponds_ReturnsNone_WithinItsOwnBudget() { @@ -147,11 +214,34 @@ wait on the handler until CI's job timeout. */ throw new InvalidOperationException("unreachable"); }); + /* #5600: this failed again in the whole-suite guards job (about 28,000 tests in one process) at 1083 ms + after the request ended, with the probe unchanged. Two things in the old measure belonged to the + machine, not the probe: + - returnedAt was read in THIS method after `await ... .WaitAsync(...)`, so it included the hop + from the probe task's completion back to this test (WaitAsync's own completion, then the awaiter's + continuation). The probe's task completion is stamped instead by a synchronous continuation on the + probe task itself, which runs on whichever thread completes the probe, with no hop; + - a stop-the-world pause or a descheduled process delays the cancel-to-return step by itself. The + StallWatcher (a dedicated thread) records those, and the window gets that much extra allowance. + A probe that waits after the cancel is still caught: its task completes late with the watcher ticking + on time, so the stamp is past the bar with no stall to excuse it. */ + using var watcher = new StallWatcher(clock); + var returnedAtMs = new long[] { -1 }; + clock.Start(); CloudIdentity identity; + long returnedAt; try { - identity = await DarlingCloudIdentityProbe.ProbeAsync(handler, CancellationToken.None).WaitAsync(HangGuard); + var probe = DarlingCloudIdentityProbe.ProbeAsync(handler, CancellationToken.None); + var stamp = probe.ContinueWith( + _ => Interlocked.CompareExchange(ref returnedAtMs[0], clock.ElapsedMilliseconds, -1), + CancellationToken.None, + TaskContinuationOptions.ExecuteSynchronously, + TaskScheduler.Default); + identity = await probe.WaitAsync(HangGuard); + await stamp.WaitAsync(HangGuard); + returnedAt = Interlocked.Read(ref returnedAtMs[0]); } catch (TimeoutException) { @@ -159,21 +249,23 @@ wait on the handler until CI's job timeout. */ throw; } - var returnedAt = clock.ElapsedMilliseconds; + var resumedAt = clock.ElapsedMilliseconds; Assert.Equal(CloudIdentity.None, identity); var startedAt = Interlocked.Read(ref handlerStartedAtMs[0]); var endedAt = Interlocked.Read(ref handlerEndedAtMs[0]); + var startStallMs = watcher.StallMsWithin(0, Math.Max(startedAt, 0)); + var returnStallMs = watcher.StallMsWithin(Math.Max(endedAt, 0), returnedAt); Assert.True( - startedAt >= 0 && startedAt <= NoPoolStepLimitMs, - $"the handler's first request started at {startedAt} ms (-1 means it never started), not within {NoPoolStepLimitMs} ms of the call: the probe waited before sending it, and nothing bounds that wait"); + startedAt >= 0 && startedAt - startStallMs <= NoPoolStepLimitMs, + $"the handler's first request started at {startedAt} ms (-1 means it never started; {startStallMs} ms of that was a machine stall), not within {NoPoolStepLimitMs} ms of the call: the probe waited before sending it, and nothing bounds that wait"); Assert.True(endedAt >= 0, "ProbeAsync returned while the handler's request was still pending: the budget must cancel the request, not abandon it"); Assert.True( endedAt >= DarlingCloudIdentityProbe.ProbeBudget.TotalMilliseconds / 2, $"the handler's request ended after {endedAt} ms, well before the {DarlingCloudIdentityProbe.ProbeBudget.TotalMilliseconds:0} ms budget: something other than the probe's budget ended it"); Assert.True( - returnedAt - endedAt <= NoPoolStepLimitMs, - $"ProbeAsync returned {returnedAt - endedAt} ms after the handler's request ended (at {endedAt} ms), not within {NoPoolStepLimitMs} ms: the probe waited after the budget cancelled the request, and nothing bounds that wait"); + returnedAt - endedAt - returnStallMs <= NoPoolStepLimitMs, + $"ProbeAsync returned {returnedAt - endedAt} ms after the handler's request ended (at {endedAt} ms; {returnStallMs} ms of that was a machine stall; this test resumed at {resumedAt} ms), not within {NoPoolStepLimitMs} ms: the probe waited after the budget cancelled the request, and nothing bounds that wait"); } /// The number the timing test above no longer measures against a clock (#4741): the 200 ms total