Repository navigation
De-flake ClusterSingletonRestartSpec: accept the hand-over retry's repeated HandOverInProgress - #8600
Merged
Aaronontheweb merged 1 commit intoSep 22, 2026
Conversation
…cond HandOverInProgress akkadotnet#8590 wrapped both hand-overs in an `EventFilter.ExpectOneAsync` on the "Hand-over in progress at" INFO line so a lost hand-over confirmation is named where it breaks instead of surfacing as an unrelated timeout later. That is the right signal, but `ExpectOne` asserts an exact count, and the count is not fixed. In build 131691 (Linux unit lane) the spec failed with the opposite complaint to the one akkadotnet#8590 was written for: Received 1 message too many. Expected 1 message but received 2 that matched filter [Info when Message starts with "Hand-over in progress at"] Two lines is correct behavior. On entering BecomingOldest the new oldest arms HandOverRetryTimer at `hand-over-retry-interval` (default 1s, see ClusterSingletonManager.OnTransition). If the first HandOverInProgress has not been processed by the time that timer fires, the HandOverRetry case re-sends HandOverToMe, and the previous oldest answers every repeat with another HandOverInProgress for as long as it is still in HandingOver - the handler is literally commented `// retry`. The new oldest logs the line once per HandOverInProgress and only then cancels the timer. So on an agent where the round trip exceeds one second, two or more lines is the designed path, not a fault. Replaced both call sites with an `AwaitHandOverConfirmationAsync` helper that keeps akkadotnet#8590's signal but expects at least one rather than exactly one: it subscribes a probe to the new oldest's EventStream for `Info` before the hand-over runs, so a confirmation arriving mid-flight is buffered rather than missed, then fishes for the line afterwards. `FishForMessageAsync` returns on the first match and ignores anything else, which is precisely "at least one", and it carries a hint naming the system that never logged the confirmation. The TestKit has no at-least-N EventFilter form and its `MatchedEventHandler` counter is protected, so a plain EventStream subscription is the public-API way to say this. No timeout, window or config value was widened, and the assertion was not removed. Verification: - Build clean with -warnaserror. - Spec 30x on this branch: 30/30 passed, ~6-7s each. - Negative check: temporarily changed the fished prefix to "Hand-over in progress at NOWHERE"; the fact failed with "Timeout (00:00:10) during fishForMessage, hint: [ClusterSingletonRestartSpec-1] never logged the hand-over confirmation from the previous oldest" - so the assertion still discriminates a lost hand-over. Restored and reran. - Could not reproduce the doubled message on this machine: even with `hand-over-retry-interval` forced to 1ms and the worker pool capped at 2, the local round trip still beats the timer and exactly one line is logged per hand-over ("Retry [n], sending HandOverToMe" never appears). The duplicate is reasoned from the code path above, which the CI log matches.
Aaronontheweb
enabled auto-merge (squash)
September 22, 2026 19:02
4 tasks done
Aaronontheweb
added a commit
that referenced
this pull request
Sep 23, 2026
… fixed deadlines (#8609) * De-flake DispatcherModelSpec: await dispatcher conditions instead of blocking on fixed deadlines Three tests in `Akka.Tests.Actor.Dispatch.DispatcherModelSpec` failed together on the Windows unit-test lane of #8601 (ADO build 131736) within ~20s of each other, while Linux passed: A_dispatcher_must_process_messages_in_parallel "Failed to count down within 3000 milliseconds. Should process other actors in parallel" A_dispatcher_must_dynamically_handle_its_own_lifecycle "System.Exception : Await failed" A_dispatcher_must_continue_to_process_messages_when_exception_is_thrown "Assert.True() Failure", on one of the Assert.True(fN.Wait(...)) lines #8601 is not implicated. It touches Settings.cs, the ActorSystemImpl scheduler site, AkkaFeatures.cs, TypeExtensions.cs, an AOT canary app and src/xunitSettings.props -- none of them on a dispatcher or test-scheduling path, and it does not touch this file (the PR merge commit's copy of ActorModelSpec.cs is byte-identical to dev's). Its xunitSettings.props change re-anchors the xunit.runner.json copy from $(SolutionDir) to $(MSBuildThisFileDirectory); build-system/azure-pipeline.template.yaml compiles with `dotnet build -c Release` from the repo root -- a solution build, so $(SolutionDir) is set -- and then runs the tests with --no-build, so the file was already reaching bin/ on dev. Confirmed locally: a project-path build leaves no xunit.runner.json in bin, a -p:SolutionDir=... build puts it there. Root cause: all three are the same failure mode. `my-test-dispatcher` runs on `executor = default-executor`, i.e. the shared .NET ThreadPool (MessageDispatcherConfigurator.ConfigureExecutor -> ThreadPoolExecutorServiceFactory -> FullThreadPoolExecutorServiceImpl -> ThreadPool.UnsafeQueueUserWorkItem). Under xUnit v3 with collection parallelism off there is no sync context, so the test body itself runs on a ThreadPool worker -- the same pool, whose floor is 2 on a 2-vCPU hosted agent. Every wait in this harness blocked that worker: * AssertCountdown called CountdownEvent.Wait(ms). In A_dispatcher_must_process_messages_in_parallel, once aStart has passed the test thread is parked in bParallel.Wait while actor `a` is parked in the Meet handler's WaitFor.Wait() -- that is the whole pool floor. b.Tell was enqueued from the test thread with preferLocal: true, so b's mailbox run sits in the blocked thread's local queue and needs a third worker to steal it. CountdownEvent.Wait blocks inside ManualResetEventSlim, which does NOT trip the pool's blocking compensation, so the only source of a third thread is the starvation heuristic (~1 per 500ms, and slower still when the CPU is saturated). * Await(until, condition), shared by AssertDispatcher and AssertRef, was a SpinWait hot loop. It pinned its own thread AND burned a core, which on 2 vCPUs competes with the very workers it waits for and pushes the injection heuristic toward its slow rate. AssertDispatcher's deadline was ShutdownTimeout*5 (5s); AssertRef ran seven successive Awaits against one shared 1s budget, so the counter that settled last got only the leftovers. * A_dispatcher_must_continue_to_process_messages_when_exception_is_thrown used the synchronous EventFilter...Expect, which blocks through Nito's WaitAndUnwrapException, plus four Assert.True(fN.Wait(GetTimeoutOrDefault(null))) -- a raw, NON-dilated 3s. And the cascade: A_dispatcher_must_process_messages_in_parallel signalled aStop only AFTER the assertion that failed. With the latch never released, actor `a` stayed in the unbounded meet.WaitFor.Wait() for good, the ActorSystem could not terminate (TestKit's 5s Shutdown cap and then force-shutdown, matching the 5s dispose in the log), and that ThreadPool worker was gone for the rest of the test host's life. That is why the other two failed seconds later: they are victims, not independent flakes. Fix, in the style of #8299. No timeout was widened, nothing was skipped, and no warning was suppressed: * try/finally around the latch-gated sections of A_dispatcher_must_process_messages_in_parallel and A_dispatcher_must_process_messages_one_at_a_time, so a failed assertion always releases the gate. * Meet now carries a MaxWait, so its handler's wait is bounded (dilated 10s) and no failing test can pin a worker for the life of the process. * AssertCountdown/AssertNoCountdown became AssertCountdownAsync/AssertNoCountdownAsync, which poll latch.IsSet through AwaitConditionNoThrowAsync -- Task.Delay between checks, so the thread goes back to the pool. Assertion messages are unchanged. * Await's SpinWait loop is gone. AssertDispatcherAsync and AssertRefAsync use AwaitAssertAsync, which polls with Task.Delay and dilates its own timeout. Same nominal bounds as before: ShutdownTimeout*5 and 1s. AssertRefAsync checks all seven counters in one polling assertion instead of draining a shared budget serially. * A_dispatcher_must_dynamically_handle_its_own_lifecycle awaits a.WatchAsync() before asserting the dispatcher's stop count. Sys.Stop is fire-and-forget and only the Terminate mailbox run needs a pool worker; the dispatcher's idle shutdown then fires on the HashedWheelTimer's own thread. Waiting for termination first keeps "the actor never stopped" distinguishable from "the dispatcher never shut down". * A_dispatcher_must_continue_to_process_messages_when_exception_is_thrown awaits ExpectAsync(2, async () => ...) and reads each ask with (await fN.WaitAsync(RemainingOrDefault)) -- the dilated single-expect default -- instead of Task.Wait. * All 8 tests in ActorModelSpec/DispatcherModelSpec are async Task now, and the last two sync TestKit calls (AwaitCondition in A_dispatcher_must_not_double_deregister and in AwaitStarted) are awaited. * Dropped the AwaitLatch/Wait/WaitAck messages and their handlers. Nothing has constructed them since #8299 replaced Wait(1000) with Meet, and they held the last unbounded Wait() and the last Thread.Sleep calls in the harness -- the remaining route back to this bug. akka.test.timefactor is 1.0 on CI, so "dilated" is a no-op today. The point of routing every wait through Dilated/AwaitAssertAsync is that the knob becomes effective for the Windows lane if we ever need to stretch it. Test-only change. No production code under src/core/Akka/Dispatch/ was modified; the dispatcher's behavior is correct. * ClusterSingletonRestartSpec: name both sources of a repeated HandOverInProgress in the hand-over remark The <remarks> added by #8600 on AwaitHandOverConfirmationAsync explains the "at least one, not exactly one" expectation solely through HandOverRetryTimer. That is not the path CI actually hit, and attributing it to the timer invites someone to tighten the expectation back to an exact count once the timer looks harmless. Build 131691's log has ZERO "Retry [n], sending HandOverToMe" lines, and the two "Hand-over in progress at" lines on the new oldest carry the same millisecond on the same thread. What happened is a timer-less cross-fire: * the new oldest sends its first HandOverToMe on OldestChanged (ClusterSingletonManager.cs:916); * independently the previous oldest sends TakeOverFromMe (:801), re-sent once a second from WasOldest (:1237-1244); * the new oldest, still in BecomingOldest, answers that TakeOverFromMe with a SECOND HandOverToMe (:1061); * the previous oldest, now in HandingOver, answers every HandOverToMe it sees with HandOverInProgress (:1304-1308). So the new oldest logs the line once per HandOverToMe it sent, with no timer involved, whenever the remote TakeOverFromMe round trip beats the local PoisonPill/Terminated one. The HandOverRetryTimer is a real second path (armed at :1420, re-sends at :1080-1083, drawing another HandOverInProgress from the same :1308 case), but the first confirmation cancels it (:983) -- which is exactly why it leaves no trace in a log that already has the line. Both paths are designed behavior and both produce N >= 1 lines, so "at least one" remains the only correct expectation. The remark now names both. Comment-only change; no test logic touched.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Changes
De-flakes
ClusterSingletonRestartSpec.Restarting_cluster_node_with_same_hostname_and_port_must_handover_to_next_oldest, which failed on the #8599 CI run with:Root cause: the spec asserted an exact count on a message that legitimately repeats. #8590 added
ExpectOneAsyncon the "Hand-over in progress at" log line so a lostHandOverInProgressfails with a clear message instead of a timeout. But inClusterSingletonManager,BecomingOldestarmsHandOverRetryTimerathand-over-retry-interval(default 1s) and re-sendsHandOverToMeon each tick; the previous oldest inHandingOveranswers every repeat (// retry→Sender.Tell(HandOverInProgress.Instance)), and the new oldest logs the line once per message received before cancelling the timer. On a loaded 2-vCPU agent the first round trip can exceed 1s, so two log lines is the designed path.Fix: keep #8590's signal, drop the exact count. A
TestProbesubscribed to the new oldest'sEventStreambefore the hand-over runs, thenFishForMessageAsyncon the same prefix: returns on the first match and ignores later repeats, so "at least one" by construction. No timeout or interval was widened; the assertion is not removed.ExpectOne/Expect(count)are all exact and the TestKit's matched-event handler isprotected, so anEventStreamsubscription is the public-API way to say "at least one".Verification: 30/30 local runs green; all 22
Singletonspecs pass; negative check (fishing for a prefix that never appears) fails with the intended "never logged the hand-over confirmation" hint. The duplicate could not be reproduced locally even athand-over-retry-interval = 1ms(local round trip always beats the timer); the mechanism is read fromClusterSingletonManager.csand matches the CI output.Checklist