diff --git a/src/Testing/CoreTests/Runtime/Agents/ejection_hysteresis_tests.cs b/src/Testing/CoreTests/Runtime/Agents/ejection_hysteresis_tests.cs index 7aa351529..f75a5d277 100644 --- a/src/Testing/CoreTests/Runtime/Agents/ejection_hysteresis_tests.cs +++ b/src/Testing/CoreTests/Runtime/Agents/ejection_hysteresis_tests.cs @@ -146,4 +146,50 @@ public async Task the_leadership_lock_holder_may_eject_a_stale_leader() await assertPeerDeleted(1); } + + /// + /// GH-3698. The observer writes one DormantNodeEjected record per node it is handed, and it used to be + /// handed the whole stale list — including every node the checks above deliberately spare. A node that + /// blipped stale for a single tick and recovered was therefore recorded as ejected while still + /// heartbeating, which is exactly the contradiction reported against the production cluster: an + /// "ejected" record sitting next to a fresh health_check. + /// + [Fact] + public async Task records_no_ejection_for_a_peer_still_inside_the_hysteresis_window() + { + snapshotIs(Self(), Peer(stale: true)); + + await tickAsync(); // observed stale, but below the ejection threshold + + await _persistence.DidNotReceive().DeleteAsync(_peerId, Arg.Any()); + await _runtime.Observer.DidNotReceive().StaleNodes(Arg.Any>()); + } + + [Fact] + public async Task records_no_ejection_for_a_stale_leader_a_follower_may_not_delete() + { + _options.Durability.StaleNodeEjectionThreshold = 1; + _persistence.HasLeadershipLock().Returns(false); + + snapshotIs(Self(), Peer(stale: true, isLeader: true)); + + await tickAsync(); + + await _persistence.DidNotReceive().DeleteAsync(_peerId, Arg.Any()); + await _runtime.Observer.DidNotReceive().StaleNodes(Arg.Any>()); + } + + [Fact] + public async Task records_an_ejection_for_the_peer_it_actually_deleted() + { + _options.Durability.StaleNodeEjectionThreshold = 1; + + snapshotIs(Self(), Peer(stale: true)); + + await tickAsync(); + + await assertPeerDeleted(1); + await _runtime.Observer.Received(1) + .StaleNodes(Arg.Is>(x => x.Count == 1 && x[0].NodeId == _peerId)); + } } diff --git a/src/Testing/CoreTests/Runtime/Agents/node_reregisters_after_ejection.cs b/src/Testing/CoreTests/Runtime/Agents/node_reregisters_after_ejection.cs index f8c3daeab..4a896c100 100644 --- a/src/Testing/CoreTests/Runtime/Agents/node_reregisters_after_ejection.cs +++ b/src/Testing/CoreTests/Runtime/Agents/node_reregisters_after_ejection.cs @@ -156,4 +156,23 @@ public Task StopAsync(CancellationToken cancellationToken) return Task.CompletedTask; } } + + /// + /// GH-3698. NodeRecord.For reads Options.Durability.AssignedNodeNumber, and the Balanced + /// start path called the observer one line BEFORE adopting the number PersistAsync handed back — + /// so every NodeStarted row in a Balanced cluster carried the per-process default, + /// Guid.NewGuid().ToString().GetDeterministicHashCode(): a random value unrelated to the node it + /// describes. The Solo path already had the two in the right order. + /// + [Fact] + public async Task the_node_started_record_sees_the_assigned_node_number() + { + int? numberWhenObserved = null; + _runtime.Observer.When(x => x.NodeStarted()) + .Do(_ => numberWhenObserved = _options.Durability.AssignedNodeNumber); + + await startedControllerAsync(); + + numberWhenObserved.ShouldBe(AssignedNumber); + } } diff --git a/src/Wolverine/Runtime/Agents/NodeAgentController.HeartBeat.cs b/src/Wolverine/Runtime/Agents/NodeAgentController.HeartBeat.cs index 63b6102c4..93acad2af 100644 --- a/src/Wolverine/Runtime/Agents/NodeAgentController.HeartBeat.cs +++ b/src/Wolverine/Runtime/Agents/NodeAgentController.HeartBeat.cs @@ -302,7 +302,8 @@ await _persistence.AddAssignmentAsync(_runtime.Options.UniqueNodeId, LeaderUri, IsLeader = true; - _logger.LogInformation("Node {NodeNumber} successfully assumed leadership", _runtime.Options.UniqueNodeId); + _logger.LogInformation("Node {NodeNumber} ({NodeId}) successfully assumed leadership", + _runtime.Options.Durability.AssignedNodeNumber, _runtime.Options.UniqueNodeId); await _observer.AssumedLeadership(); @@ -335,6 +336,13 @@ private async Task ejectStaleNodes(IReadOnlyList staleNodes) // blip from destroying a live leader's row, ownership, and assignments. var holdsLeadership = _persistence.HasLeadershipLock(); + // GH-3698: only the nodes actually deleted below get a DormantNodeEjected record. Reporting the whole + // stale list wrote one for every node the checks here deliberately SPARE -- this node itself, a + // leader a follower may not evict, and above all a node inside the GH-3604 hysteresis window. So a + // node that blipped stale for one tick and recovered was recorded as ejected while still heartbeating, + // which is exactly the contradiction reported: an "ejected" record alongside a fresh health_check. + var ejected = new List(); + // As per GH-1116, don't delete yourself! foreach (var staleNode in staleNodes.Where(x => x.AssignedNodeNumber != _runtime.DurabilitySettings.AssignedNodeNumber)) { @@ -355,11 +363,12 @@ private async Task ejectStaleNodes(IReadOnlyList staleNodes) await _persistence.DeleteAsync(staleNode.NodeId, staleNode.AssignedNodeNumber); _staleObservations.Remove(staleNode.NodeId); + ejected.Add(staleNode); } - if (staleNodes.Any()) + if (ejected.Count != 0) { - await _observer.StaleNodes(staleNodes); + await _observer.StaleNodes(ejected); } } diff --git a/src/Wolverine/Runtime/Agents/NodeAgentController.StartLocalProcessing.cs b/src/Wolverine/Runtime/Agents/NodeAgentController.StartLocalProcessing.cs index 103cda76c..500bd738f 100644 --- a/src/Wolverine/Runtime/Agents/NodeAgentController.StartLocalProcessing.cs +++ b/src/Wolverine/Runtime/Agents/NodeAgentController.StartLocalProcessing.cs @@ -17,11 +17,16 @@ public async Task StartLocalAgentProcessingAsync(WolverineOptions _capabilities = current.Capabilities.ToArray(); current.AssignedNodeNumber = await _persistence.PersistAsync(current, _cancellation.Token); - - await _observer.NodeStarted(); + // GH-3698: adopt the assigned number BEFORE the observer writes the NodeStarted record. NodeRecord.For + // reads it straight off Options.Durability, which until this line still holds the per-process default + // -- Guid.NewGuid().ToString().GetDeterministicHashCode() -- so every NodeStarted row in a Balanced + // cluster carried a random node_number unrelated to the node it describes. The Solo path in + // StartLocally.cs already sets it first. _runtime.Options.Durability.AssignedNodeNumber = current.AssignedNodeNumber; + await _observer.NodeStarted(); + _logger.LogInformation("Starting agents for Node {NodeId} with assigned node id {Id} and Control Uri {ControlUri}", options.UniqueNodeId, current.AssignedNodeNumber,current.ControlUri);