Repository navigation
TestKit: WithinAsync no longer swallows the block's failure when the deadline wins - #8516
Conversation
WithinAsync races the block against Task.Delay(max + 200ms). When the delay won that race the block's Task was never observed: a faulted block lost its exception and the test carried on as if the block had succeeded. The elapsed time check could not catch it either, because the default epsilon (max(0.15 * max, 50ms)) covers the 200ms of slack for any max above ~1.4s. When the delay wins, the block is now observed: - Completed - awaited, so a faulted or cancelled block rethrows with its original stack trace, and a block that finished as the deadline fired still yields its result. - Still running - reported as a failure that names the elapsed time and the maximum allowed duration, instead of returning as if the block had passed. The success path, the min path, the epsilon defaults and every timeout constant are untouched. Only the discarded outcome becomes visible. Tests cover both halves of the race, the unchanged success path, and the exception that a block throws before the deadline. The synchronous Within overloads never had the defect - the action runs inline inside the delegate invocation, so it throws before any race exists - and a test pins that.
|
Classic Linux MNTR triage (build 131110) — two failures, and they split exactly along the line this PR's description predicted: 1. That is this PR's new failure message. A 60-second 2. Both are triage items for follow-up work, not regressions of this change — the first one is precisely the class of masked failure this PR exists to surface. |
|
Final tally for the honest-matrix run (build 131110), all four MNTR lanes settled:
One spec accounts for every unmasking: A restructure of that phase (umbrella removed, waits re-bounded by cadence arithmetic, barrier moved out of the budget scope) is being prepared as a second commit on this PR so the honest primitive and the one spec it exposes land together, keeping the lanes green. |
…ndezvous
The `reestablish connection to receptionist after server restart` phase failed on
three nodes across two transports in the first CI run under the honest
`WithinAsync` (build 131110): classic `second`, artery `client` and `third`, all
with "Block was still running after 00:01:00.2, exceeding the maximum allowed
duration of 00:01:00". The old primitive returned `default` and marched on, so
the phase had been fake-passing.
Three defects, all now fixed:
1. The restarted server bound the wrong port under Artery. The phase pinned the
replacement system with `akka.remote.dot-netty.tcp.port` only, which is inert
when the suite runs on Artery, so the fresh system took a random
`canonical.port`: node `third` came back on 43295 after dying on 34091 and the
client spent the rest of the phase re-sending GetContacts to an address
nothing was listening on. Use `StartNewSystemAsync`, which pins host:port on
both transports.
2. `EnterBarrier("reconnection-verified")` could never rendezvous.
`TestConductor.Shutdown` terminates the target's whole `Sys`, and the
conductor client lives in `Sys`, so the restarted node had no conductor left:
it never logged `entering barriers reconnection-verified` at all. On the
client the conductor had already dropped that role, so the same barrier passed
in 1ms (18:23:24.218 -> .219) without synchronizing anything - while the
server sat in a barrier ask it could not complete. `StartNewSystemAsync`
attaches a fresh conductor, so the barrier is now a real rendezvous, and it is
what keeps the restarted system alive until the client has proven reconnection.
3. Neither `EventFilter` carried a budget, so both fell back to
`RemainingOrDefault` - the umbrella's remaining time. Filter and umbrella then
expired together and "Block was still running" won the race, hiding which log
line never arrived. Both filters now take bounds derived from the client's own
cadences: 10s for "Lost contact" (heartbeat-interval 1s + acceptable-heartbeat-
pause 3s + one tick + the conductor round trip) and 20s for "Connected to"
(retry-gate-closed-for 5s + 3 x establishing-get-contacts-interval 3s).
The 60s umbrella is gone. Barriers must not run inside a Within, whose
`RemainingOr(barrier-timeout)` starves the rendezvous exactly when the phase has
run long; the trailing `after-N` barriers in the other phases move outside their
umbrellas for the same reason, and the startup phase - five barriers around one
convergence poll - drops its umbrella entirely in favour of an explicit
`AwaitCount` budget.
Also converts the phase's one remaining synchronous `ExpectMsg` to `ExpectMsgAsync`.
| // Just throw if the calling code cancels the cancellation token | ||
| cancellationToken.ThrowIfCancellationRequested(); | ||
|
|
||
| // The deadline won the race. Observe the block instead of discarding its outcome. |
|
|
||
| var elapsed = Now - start; | ||
|
|
||
| if (blockStillRunning) |
… its own 3 s window instead of the Within's remaining time A zero-count EventFilter.ExpectAsync(0, action) with no explicit timeout, run inside a WithinAsync(max) block, captures the Within's remaining time as its own quiet window, runs the action, then waits out that whole window to prove nothing was logged. The block therefore ends at start + T_action + max by construction, while WithinAsync abandons a still-running block at max + 200ms and fails the fact (since #8516). On a cold CI agent the action's async part (cluster self-join in BugFix3724Spec) doesn't leave enough margin. Pekko's filter always uses akka.test.filter-leeway (3s, dilated) for its quiet window, never the remaining Within time. Pass that window explicitly via the ExpectAsync(count, timeout, action) overload in both specs so the block runs in roughly T_action + 3s instead of racing the outer deadline.
… its own 3 s window instead of the Within's remaining time A zero-count EventFilter.ExpectAsync(0, action) with no explicit timeout, run inside a WithinAsync(max) block, captures the Within's remaining time as its own quiet window, runs the action, then waits out that whole window to prove nothing was logged. The block therefore ends at start + T_action + max by construction, while WithinAsync abandons a still-running block at max + 200ms and fails the fact (since #8516). On a cold CI agent the action's async part (cluster self-join in BugFix3724Spec) doesn't leave enough margin. Pekko's filter always uses akka.test.filter-leeway (3s, dilated) for its quiet window, never the remaining Within time. Pass that window explicitly via the ExpectAsync(count, timeout, action) overload in both specs so the block runs in roughly T_action + 3s instead of racing the outer deadline.
… its own 3 s window instead of the Within's remaining time (#8566) A zero-count EventFilter.ExpectAsync(0, action) with no explicit timeout, run inside a WithinAsync(max) block, captures the Within's remaining time as its own quiet window, runs the action, then waits out that whole window to prove nothing was logged. The block therefore ends at start + T_action + max by construction, while WithinAsync abandons a still-running block at max + 200ms and fails the fact (since #8516). On a cold CI agent the action's async part (cluster self-join in BugFix3724Spec) doesn't leave enough margin. Pekko's filter always uses akka.test.filter-leeway (3s, dilated) for its quiet window, never the remaining Within time. Pass that window explicitly via the ExpectAsync(count, timeout, action) overload in both specs so the block runs in roughly T_action + 3s instead of racing the outer deadline.
…deadline wins (#8516) (#8529) * Fix #8483: WithinAsync no longer swallows the block's failure WithinAsync races the block against Task.Delay(max + 200ms). When the delay won that race the block's Task was never observed: a faulted block lost its exception and the test carried on as if the block had succeeded. The elapsed time check could not catch it either, because the default epsilon (max(0.15 * max, 50ms)) covers the 200ms of slack for any max above ~1.4s. When the delay wins, the block is now observed: - Completed - awaited, so a faulted or cancelled block rethrows with its original stack trace, and a block that finished as the deadline fired still yields its result. - Still running - reported as a failure that names the elapsed time and the maximum allowed duration, instead of returning as if the block had passed. The success path, the min path, the epsilon defaults and every timeout constant are untouched. Only the discarded outcome becomes visible. Tests cover both halves of the race, the unchanged success path, and the exception that a block throws before the deadline. The synchronous Within overloads never had the defect - the action runs inline inside the delegate invocation, so it throws before any race exists - and a test pins that. * De-flake ClusterClientSpec server-restart phase: real rebind, real rendezvous The `reestablish connection to receptionist after server restart` phase failed on three nodes across two transports in the first CI run under the honest `WithinAsync` (build 131110): classic `second`, artery `client` and `third`, all with "Block was still running after 00:01:00.2, exceeding the maximum allowed duration of 00:01:00". The old primitive returned `default` and marched on, so the phase had been fake-passing. Three defects, all now fixed: 1. The restarted server bound the wrong port under Artery. The phase pinned the replacement system with `akka.remote.dot-netty.tcp.port` only, which is inert when the suite runs on Artery, so the fresh system took a random `canonical.port`: node `third` came back on 43295 after dying on 34091 and the client spent the rest of the phase re-sending GetContacts to an address nothing was listening on. Use `StartNewSystemAsync`, which pins host:port on both transports. 2. `EnterBarrier("reconnection-verified")` could never rendezvous. `TestConductor.Shutdown` terminates the target's whole `Sys`, and the conductor client lives in `Sys`, so the restarted node had no conductor left: it never logged `entering barriers reconnection-verified` at all. On the client the conductor had already dropped that role, so the same barrier passed in 1ms (18:23:24.218 -> .219) without synchronizing anything - while the server sat in a barrier ask it could not complete. `StartNewSystemAsync` attaches a fresh conductor, so the barrier is now a real rendezvous, and it is what keeps the restarted system alive until the client has proven reconnection. 3. Neither `EventFilter` carried a budget, so both fell back to `RemainingOrDefault` - the umbrella's remaining time. Filter and umbrella then expired together and "Block was still running" won the race, hiding which log line never arrived. Both filters now take bounds derived from the client's own cadences: 10s for "Lost contact" (heartbeat-interval 1s + acceptable-heartbeat- pause 3s + one tick + the conductor round trip) and 20s for "Connected to" (retry-gate-closed-for 5s + 3 x establishing-get-contacts-interval 3s). The 60s umbrella is gone. Barriers must not run inside a Within, whose `RemainingOr(barrier-timeout)` starves the rendezvous exactly when the phase has run long; the trailing `after-N` barriers in the other phases move outside their umbrellas for the same reason, and the startup phase - five barriers around one convergence poll - drops its umbrella entirely in favour of an explicit `AwaitCount` budget. Also converts the phase's one remaining synchronous `ExpectMsg` to `ExpectMsgAsync`. Backport note (v1.5) Both defects were confirmed present on v1.5 before the pick. `TestKitBase_Within.cs` was byte-identical to the commit's parent on dev, so the swallow is the same code. The `ClusterClientSpec` restart phase carried the same hand-rolled `ActorSystem.Create`, the same `reconnection-verified` barrier after `TestConductor.ShutdownAsync`, the same 60s umbrella and the same budget-less `EventFilter`s. Scoping of the dev-only claims above: the CI build number and the per-node port and timestamp evidence come from dev's run and were not re-observed here. v1.5 has no Artery, so restart-phase defect 1 (the replacement system taking a random `canonical.port` because only `akka.remote.dot-netty.tcp.port` was pinned) cannot occur on this branch - the classic lane is the only transport and that key is live. `StartNewSystemAsync` is still the correct call on v1.5: it pins host and port for dot-netty and, more importantly here, attaches a fresh conductor, which is what defect 2 needs. Defects 2 and 3 are transport-independent and apply in full. (cherry picked from commit 94c1949)
… its own 3 s window instead of the Within's remaining time (#8566) A zero-count EventFilter.ExpectAsync(0, action) with no explicit timeout, run inside a WithinAsync(max) block, captures the Within's remaining time as its own quiet window, runs the action, then waits out that whole window to prove nothing was logged. The block therefore ends at start + T_action + max by construction, while WithinAsync abandons a still-running block at max + 200ms and fails the fact (since #8516). On a cold CI agent the action's async part (cluster self-join in BugFix3724Spec) doesn't leave enough margin. Pekko's filter always uses akka.test.filter-leeway (3s, dilated) for its quiet window, never the remaining Within time. Pass that window explicitly via the ExpectAsync(count, timeout, action) overload in both specs so the block runs in roughly T_action + 3s instead of racing the outer deadline. (cherry picked from commit 3432d6f)
Fixes #8483.
Commit 1:
WithinAsyncno longer swallows failuresWithinAsyncraces the block againstTask.Delay(max + 200ms). When the delay won, the old code never looked at the block again. A block that failed after the deadline lost its exception and the test passed.Now, when the delay wins:
awaitit. A failure rethrows with its original stack.max.23 added lines. No timeout constant, epsilon, or dilation changed. The sync
Within(Action)overloads were never affected (they throw inline) — a test now pins that. Two of the five new tests fail on unfixed code, proving the swallow.Commit 2: the one spec the fix exposed
The first CI run of commit 1 failed exactly one spec suite-wide, on all four MNTR lanes:
ClusterClientSpec's server-restart phase. It was not flaky — it was broken, and had been fake-passing:reconnection-verifiedbarrier could never synchronize.TestConductor.ShutdownAsynckills the node's conductor client, so the restarted system never re-attached and the barrier was a no-op.WithinAsynchid all of it. The real reconnect cost is ~7 seconds.Fix:
StartNewSystemAsync()(pins the port on both transports and re-attaches the conductor, so the barrier is real), explicit derived bounds on theEventFilters, umbrella deleted, trailing barriers moved out ofWithinAsyncscopes. Phase runtime dropped from 92s to 33s. Fail-first reproduced instantly on both transports; fixed spec soaked 18/18.Evidence
Akka.API.Tests: no approval delta.Triage details for the first CI run (the unmasking) are in the PR comments.