FAILED: ClusterLeaderActionsClusteredTests.test_singleLeader #945
Description
Maybe just flaky, but happened on updating NIO so maybe timings changed and the test was too sensitive to them?
https://ci.swiftserver.group/job/swift-distributed-actors-nightly-prb/357/consoleFull
18:22:46 Test Case 'ClusterLeaderActionsClusteredTests.test_singleLeader' started at 2022-06-05 09:22:46.980
18:22:52 [pprint][9:22:46.9840] [/code/Sources/DistributedActors/Cluster/ClusterShell.swift:271][thread:140641564575488]: Started ClusterShell
18:22:52 <EXPR>:0: error: ClusterLeaderActionsClusteredTests.test_singleLeader : threw error "
18:22:52 switch try p.expectMessage() {
18:22:52 ^~~~~~~~~~~~~~
18:22:52 error: Did not receive message of type [Event] within [5s], error: noMessagesInQueue"
18:22:52 ------------------------------------- ClusterSystem(first, sact://[email protected]:7111) ------------------------------------------------
18:22:52 Captured log [first][2022-06-05 9:22:46.9850] [ClusterSystem.swift:894] [warning] Assign identity
18:22:52 // metadata:
18:22:52 // "actor/id": /system/receptionist
18:22:52 // "actor/id/uniqueNode": sact://[email protected]:7111
18:22:52 // "actor/type": OpLogDistributedReceptionist
18:22:52 Captured log [first][2022-06-05 9:22:46.9850] [ClusterShell.swift:409][/system/cluster] [info] Binding to: [sact://[email protected]:7111]
18:22:52 Captured log [first][2022-06-05 9:22:46.9850] [ClusterSystem.swift:907] [trace] Actor ready
18:22:52 // metadata:
18:22:52 // "actor/id": /system/receptionist
18:22:52 // "actor/type": OpLogDistributedReceptionist
18:22:52 Captured log [first][2022-06-05 9:22:46.9860] [Leadership.swift:114][/system/cluster/leadership] [trace] Configured with LowestReachableMember(minimumNumberOfMembersToDecide: 1, loseLeadershipIfBelowMinNrOfMembers: false)
18:22:52 Captured log [first][2022-06-05 9:22:46.9860] [ClusterSystem.swift:894] [warning] Assign identity
18:22:52 // metadata:
18:22:52 // "actor/id": /system/downingStrategy
18:22:52 // "actor/id/uniqueNode": sact://[email protected]:7111
18:22:52 // "actor/type": DowningStrategyShell
18:22:52 Captured log [first][2022-06-05 9:22:46.9860] [ClusterSystem.swift:907] [trace] Actor ready
18:22:52 // metadata:
18:22:52 // "actor/id": /system/downingStrategy
18:22:52 // "actor/type": DowningStrategyShell
18:22:52 Captured log [first][2022-06-05 9:22:46.9860] [ClusterEventStream.swift:44][/system/clusterEvents] [trace] Successfully subscribed [_ActorRef<Cluster.Event>(/system/cluster/leadership)], offering membership snapshot
18:22:52 Captured log [first][2022-06-05 9:22:46.9860] [Leadership.swift:299][/system/cluster/leadership] [debug] Selected new leader: [nil -> Member(sact://[email protected]:7111, status: joining, reachability: reachable)]
18:22:52 // metadata:
18:22:52 // "leadership/election": DistributedActors.Leadership.LowestReachableMember
18:22:52 // "membership": Membership(count: 1, leader: Member(sact://[email protected]:7111, status: joining, reachability: reachable), members: [Member(sact://first:[email protected]:7111, status: joining, reachability: reachable)])
18:22:52 Captured log [first][2022-06-05 9:22:46.9860] [ClusterEventStream.swift:80][/system/clusterEvents] [trace] Successfully added async subscriber [ObjectIdentifier(0x00007fea2004f840)]
18:22:52 Captured log [first][2022-06-05 9:22:46.9860] [ClusterSystem.swift:391] [info] ClusterSystem [first] initialized, listening on: sact://[email protected]:7111
18:22:52 Captured log [first][2022-06-05 9:22:46.9860] [ClusterSystem.swift:393] [info] Setting in effect: .autoLeaderElection: lowestReachable(minNumberOfMembers: 1)
18:22:52 Captured log [first][2022-06-05 9:22:46.9860] [ClusterSystem.swift:394] [info] Setting in effect: .downingStrategy: timeout(DistributedActors.TimeoutBasedDowningStrategySettings(downUnreachableMembersAfter: TimeAmount(1s, nanoseconds: 1000000000)))
18:22:52 Captured log [first][2022-06-05 9:22:46.9860] [ClusterSystem.swift:395] [info] Setting in effect: .onDownAction: gracefulShutdown(delay: TimeAmount(3s, nanoseconds: 3000000000))
18:22:52 Captured log [first][2022-06-05 9:22:46.9860] [_OperationLogClusterReceptionistBehavior.swift:101][/system/receptionist-ref] [debug] Initialized receptionist
18:22:52 Captured log [first][2022-06-05 9:22:46.9860] [ClusterEventStream.swift:80][/system/clusterEvents] [trace] Successfully added async subscriber [ObjectIdentifier(0x000055f4a0f8dff0)]
18:22:52 Captured log [first][2022-06-05 9:22:46.9870] [ClusterShell.swift:420][/system/cluster] [info] Bound to [IPv4]127.0.0.1/127.0.0.1:7111
18:22:52 Captured log [first][2022-06-05 9:22:46.9870] [ClusterEventStream.swift:44][/system/clusterEvents] [trace] Successfully subscribed [_ActorRef<Cluster.Event>(/system/nodeDeathWatcher/$sub-DistributedActors.Cluster.Event-y)], offering membership snapshot
18:22:52 Captured log [first][2022-06-05 9:22:46.9870] [ClusterEventStream.swift:44][/system/clusterEvents] [trace] Successfully subscribed [_ActorRef<Cluster.Event>(/system/receptionist-ref/$sub-DistributedActors.Cluster.Event-y)], offering membership snapshot
18:22:52 Captured log [first][2022-06-05 9:22:46.9870] [ClusterShellState.swift:428][/system
18:22:52 /cluster] [debug] Leader change: LeadershipChange(oldLeader: nil, newLeader: Optional(Member(sact://first:[email protected]:7111, status: joining, reachability: reachable)), file: "/code/Sources/DistributedActors/Cluster/Cluster+Membership.swift", line: 355)
18:22:52 // metadata:
18:22:52 // "membership/count": 1
18:22:52 Captured log [first][2022-06-05 9:22:46.9870] [ClusterShellState.swift:465][/system/cluster] [trace] Membership updated on [sact://[email protected]:7111] by leadershipChange(DistributedActors.Cluster.LeadershipChange(oldLeader: nil, newLeader: Optional(Member(sact://first:[email protected]:7111, status: joining, reachability: reachable)), file: "/code/Sources/DistributedActors/Cluster/Cluster+Membership.swift", line: 355)): leader: Member(sact://[email protected]:7111, status: joining, reachability: reachable)
18:22:52 sact://first:[email protected]:7111 status [joining]
18:22:52 Captured log [first][2022-06-05 9:22:46.9870] [Gossiper+Shell.swift:149][/system/cluster/gossip] [trace] Update (locally) gossip payload [membership]
18:22:52 // metadata:
18:22:52 // "gossip/identifier": membership
18:22:52 // "gossip/payload": MembershipGossip(
18:22:52 // owner: sact://first:[email protected]:7111,
18:22:52 // seen: Cluster.Gossip.SeenTable(
18:22:52 // sact://[email protected]:7111 observed versions:
18:22:52 // uniqueNode:sact://[email protected]:7111 @ 1
18:22:52 // ),
18:22:52 // membership: Membership(
18:22:52 // _members: [
18:22:52 // sact://[email protected]:7111: Member(sact://[email protected]:7111, status: joining, reachability: reachable),
18:22:52 // ],
18:22:52 // _leaderNode: nil,
18:22:52 // ),
18:22:52 // )
18:22:52 Captured log [first][2022-06-05 9:22:46.9870] [ClusterEventStream.swift:65][/system/clusterEvents] [trace] Published event membershipChange(sact://[email protected]:7111 :: [unknown] -> [joining]) to 3 subscribers and 2 async subscribers
18:22:52 // metadata:
18:22:52 // "eventStream/asyncSubscribers":
18:22:52 // ObjectIdentifier(0x000055f4a0f8dff0)
18:22:52 // ObjectIdentifier(0x00007fea2004f840)
18:22:52 // "eventStream/event": DistributedActors.Cluster.Event.membershipChange(sact://[email protected]:7111 :: [unknown] -> [joining])
18:22:52 // "eventStream/subscribers":
18:22:52 // /system/nodeDeathWatcher/$sub-DistributedActors.Cluster.Event-y
18:22:52 // /system/receptionist-ref/$sub-DistributedActors.Cluster.Event-y
18:22:52 // /system/cluster/leadership
18:22:52 Captured log [first][2022-06-05 9:22:46.9870] [Leadership.swift:299][/system/cluster/leadership] [debug] Selected new leader: [nil -> Member(sact://[email protected]:7111, status: joining, reachability: reachable)]
18:22:52 // metadata:
18:22:52 // "leadership/election": DistributedActors.Leadership.LowestReachableMember
18:22:52 // "membership": Membership(count: 1, leader: Member(sact://[email protected]:7111, status: joining, reachability: reachable), members: [Member(sact://first:[email protected]:7111, status: joining, reachability: reachable)])
18:22:52 Captured log [first][2022-06-05 9:22:46.9870] [ClusterEventStream.swift:44][/system/clusterEvents] [trace] Successfully subscribed [_ActorRef<Cluster.Event>(/system/cluster/gossip/$sub-DistributedActors.Cluster.Event-y)], offering membership snapshot
18:22:52 Captured log [first][2022-06-05 9:22:46.9870] [Gossiper+Shell.swift:149][/system/cluster/gossip] [trace] Update (locally) gossip payload [membership]
18:22:52 // metadata:
18:22:52 // "gossip/identifier": membership
18:22:52 // "gossip/payload": MembershipGossip(
18:22:52 // owner: sact://first:[email protected]:7111,
18:22:52 // seen: Cluster.Gossip.SeenTable(
18:22:52 // sact://[email protected]:7111 observed versions:
18:22:52 // uniqueNode:sact://[email protected]:7111 @ 2
18:22:52 // ),
18:22:52 // membership: Membership(
18:22:52 // _members: [
18:22:52 // sact://[email protected]:7111: Member(sact://[email protected]:7111, status: joining, reachability: reachable),
18:22:52 // ],
18:22:52 // _leaderNode: sact://first:[email protected]:7111,
18:22:52 // ),
18:22:52 // )
18:22:52 Captured log [first][2022-06-05 9:22:46.9870] [ClusterShell+LeaderActions.swift:77][/system/cluster] [trace] Performing leader actions: [DistributedActors.ClusterShellState.LeaderAction.moveMember(sact://[email protected]:7111 :: [join
18:22:52 ing] -> [ up])]
18:22:52 // metadata:
18:22:52 // "gossip/converged": true
18:22:52 // "gossip/current": MembershipGossip(owner: sact://first:[email protected]:7111, seen: Cluster.MembershipGossip.SeenTable([sact://first:[email protected]:7111: [uniqueNode:sact://[email protected]:7111: 3]]), membership: Membership(count: 1, leader: Member(sact://[email protected]:7111, status: joining, reachability: reachable), members: [Member(sact://first:[email protected]:7111, status: joining, reachability: reachable)]))
18:22:52 // "leader/actions": [DistributedActors.ClusterShellState.LeaderAction.moveMember(sact://[email protected]:7111 :: [joining] -> [ up])]
18:22:52 // "tag": leader-action
18:22:52 Captured log [first][2022-06-05 9:22:46.9870] [ClusterShell+LeaderActions.swift:127][/system/cluster] [debug] Leader moved member: sact://[email protected]:7111 :: [joining] -> [ up]
18:22:52 // metadata:
18:22:52 // "tag": leader-action
18:22:52 Captured log [first][2022-06-05 9:22:46.9880] [ClusterShell+LeaderActions.swift:104][/system/cluster] [trace] Membership state after leader actions: Membership(count: 1, leader: Member(sact://[email protected]:7111, status: up, reachability: reachable), members: [Member(sact://first:[email protected]:7111, status: up, reachability: reachable, upNumber: 1)])
18:22:52 // metadata:
18:22:52 // "gossip/before": MembershipGossip(owner: sact://first:[email protected]:7111, seen: Cluster.MembershipGossip.SeenTable([sact://first:[email protected]:7111: [uniqueNode:sact://[email protected]:7111: 3]]), membership: Membership(count: 1, leader: Member(sact://[email protected]:7111, status: joining, reachability: reachable), members: [Member(sact://first:[email protected]:7111, status: joining, reachability: reachable)]))
18:22:52 // "gossip/current": MembershipGossip(owner: sact://first:[email protected]:7111, seen: Cluster.MembershipGossip.SeenTable([sact://first:[email protected]:7111: [uniqueNode:sact://[email protected]:7111: 4]]), membership: Membership(count: 1, leader: Member(sact://[email protected]:7111, status: up, reachability: reachable), members: [Member(sact://first:[email protected]:7111, status: up, reachability: reachable, upNumber: 1)]))
18:22:52 // "tag": leader-action
18:22:52 Captured log [first][2022-06-05 9:22:46.9880] [ClusterEventStream.swift:65][/system/clusterEvents] [trace] Published event leadershipChange(DistributedActors.Cluster.LeadershipChange(oldLeader: nil, newLeader: Optional(Member(sact://first:[email protected]:7111, status: joining, reachability: reachable)), file: "/code/Sources/DistributedActors/Cluster/Cluster+Membership.swift", line: 355)) to 4 subscribers and 2 async subscribers
18:22:52 // metadata:
18:22:52 // "eventStream/asyncSubscribers":
18:22:52 // ObjectIdentifier(0x000055f4a0f8dff0)
18:22:52 // ObjectIdentifier(0x00007fea2004f840)
18:22:52 // "eventStream/event": DistributedActors.Cluster.Event.leadershipChange(DistributedActors.Cluster.LeadershipChange(oldLeader: nil, newLeader: Optional(Member(sact://first:[email protected]:7111, status: joining, reachability: reachable)), file: "/code/Sources/DistributedActors/Cluster/Cluster+Membership.swift", line: 355))
18:22:52 // "eventStream/subscribers":
18:22:52 // /system/cluster/leadership
18:22:52 // /system/cluster/gossip/$sub-DistributedActors.Cluster.Event-y
18:22:52 // /system/receptionist-ref/$sub-DistributedActors.Cluster.Event-y
18:22:52 // /system/nodeDeathWatcher/$sub-DistributedActors.Cluster.Event-y
18:22:52 Captured log [first][2022-06-05 9:22:46.9880] [Gossiper+Shell.swift:149][/system/cluster/gossip] [trace] Update (locally) gossip payload [membership]
18:22:52 // metadata:
18:22:52 // "gossip/identifier": membership
18:22:52 // "gossip/payload": MembershipGossip(
18:22:52 // owner: sact://first:[email protected]:7111,
18:22:54 // seen: Cluster.Gossip.SeenTable(
18:22:54 // sact://[email protected]:7111 observed versions:
18:22:54 // uniqueNode:sact://[email protected]:7111 @ 3
18:22:54 // ),
18:22:54 // membership: Membership(
18:22:54 // _members: [
18:22:54 // sact://[email protected]:7111: Member(sact://[email protected]:7111, status: joining, reachability: reachable),
18:22:54 /
18:22:54 / ],
18:22:54 // _leaderNode: sact://first:[email protected]:7111,
18:22:54 // ),
18:22:54 // )
18:22:54 Captured log [first][2022-06-05 9:22:46.9880] [Gossiper+Shell.swift:149][/system/cluster/gossip] [trace] Update (locally) gossip payload [membership]
18:22:54 // metadata:
18:22:54 // "gossip/identifier": membership
18:22:54 // "gossip/payload": MembershipGossip(
18:22:54 // owner: sact://first:[email protected]:7111,
18:22:54 // seen: Cluster.Gossip.SeenTable(
18:22:54 // sact://[email protected]:7111 observed versions:
18:22:54 // uniqueNode:sact://[email protected]:7111 @ 4
18:22:54 // ),
18:22:54 // membership: Membership(
18:22:54 // _members: [
18:22:54 // sact://[email protected]:7111: Member(sact://[email protected]:7111, status: up, reachability: reachable),
18:22:54 // ],
18:22:54 // _leaderNode: sact://first:[email protected]:7111,
18:22:54 // ),
18:22:54 // )
18:22:54 Captured log [first][2022-06-05 9:22:46.9880] [ClusterEventStream.swift:65][/system/clusterEvents] [trace] Published event membershipChange(sact://[email protected]:7111 :: [joining] -> [ up]) to 4 subscribers and 2 async subscribers
18:22:54 // metadata:
18:22:54 // "eventStream/asyncSubscribers":
18:22:54 // ObjectIdentifier(0x000055f4a0f8dff0)
18:22:54 // ObjectIdentifier(0x00007fea2004f840)
18:22:54 // "eventStream/event": DistributedActors.Cluster.Event.membershipChange(sact://[email protected]:7111 :: [joining] -> [ up])
18:22:54 // "eventStream/subscribers":
18:22:54 // /system/cluster/leadership
18:22:54 // /system/cluster/gossip/$sub-DistributedActors.Cluster.Event-y
18:22:54 // /system/receptionist-ref/$sub-DistributedActors.Cluster.Event-y
18:22:54 // /system/nodeDeathWatcher/$sub-DistributedActors.Cluster.Event-y
18:22:54 Captured log [first][2022-06-05 9:22:46.9880] [Gossiper+Shell.swift:149][/system/cluster/gossip] [trace] Update (locally) gossip payload [membership]
18:22:54 // metadata:
18:22:54 // "gossip/identifier": membership
18:22:54 // "gossip/payload": MembershipGossip(
18:22:54 // owner: sact://first:[email protected]:7111,
18:22:54 // seen: Cluster.Gossip.SeenTable(
18:22:54 // sact://[email protected]:7111 observed versions:
18:22:54 // uniqueNode:sact://[email protected]:7111 @ 4
18:22:54 // ),
18:22:54 // membership: Membership(
18:22:54 // _members: [
18:22:54 // sact://[email protected]:7111: Member(sact://[email protected]:7111, status: up, reachability: reachable),
18:22:54 // ],
18:22:54 // _leaderNode: sact://first:[email protected]:7111,
18:22:54 // ),
18:22:54 // )
18:22:54 Captured log [first][2022-06-05 9:22:46.9890] [ClusterEventStream.swift:44][/system/clusterEvents] [trace] Successfully subscribed [_ActorRef<Cluster.Event>(/user/selfishSingleLeader)], offering membership snapshot
18:22:54 ========================================================================================================================