FAILED: test_singletonByClusterLeadership_withLeaderChange

[ktoso]

!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
14010:Test Case 'ActorSingletonPluginClusteredTests.test_singletonByClusterLeadership_withLeaderChange' failed (14.538 seconds)
Test Case 'ActorSingletonPluginClusteredTests.test_singletonByClusterLeadership_withLeaderChange' started at 2020-02-05 07:44:28.673
/code/Tests/ActorSingletonPluginTests/ActorSingletonPluginClusteredTests.swift:135: error: ActorSingletonPluginClusteredTests.test_singletonByClusterLeadership_withLeaderChange : failed -
        try shouldNotThrow {
            ^~~~~~~~~~~~~~~
error: Unexpected throw captured
            try replyProbe3.expectMessage("Hello-4 Charlie-3!")
                            ^~~~~~~~~~~~~~
error: Did not receive expected [Hello-4 Charlie-3!]:String within [3s], error: noMessagesInQueue
<EXPR>:0: error: ActorSingletonPluginClusteredTests.test_singletonByClusterLeadership_withLeaderChange : threw error "unexpectedErrorWasThrown"
------------------------------------- ActorSystem(first, sact://first@localhost:7111) ------------------------------------------------

ActorSingletonPluginClusteredTests.test_singletonByClusterLeadership_withLeaderChange.txt

[ktoso]

The singleton tests hurting quite a bit under the new receptionist -- expecting them to be too timing sensitive (and also #492 )

ActorSingletonPluginClusteredTests.test_singletonByClusterLeadership_withLeaderChange.error.txt

[ktoso]

The association hardening helped those, as well. Taking a closer look.

[ktoso]

Note to self, this was hitting a nasty unexpected a node extending a handshake then getting an accept but not expecting it.

Captured log [third][2020-04-29 0:2:30.3910] [ClusterShell.swift:177][third] [trace] Closed connection with sact://first@127.0.0.1:7111: success(DistributedActors.Association.Tombstone(remoteNode: sact://first:2996756348@127.0.0.1:7111, removalDeadline: 157477929714974))
Captured log [third][2020-04-29 0:2:30.4920] [ClusterShell.swift:669][/system/cluster] [trace] beginHandshake INITIATED Handshake state: [DistributedActors.HandshakeStateMachine.State.initiated(DistributedActors.HandshakeStateMachine.InitiatedState(backoff: DistributedActors.ExponentialBackoffStrategy(initialInterval: TimeAmount(100ms, nanoseconds: 100000000), multiplier: 1.5, capInterval: TimeAmount(∞ (infinite), nanoseconds: 9223372036854775807), randomFactor: 0.25, currentBaseInterval: TimeAmount(100ms, nanoseconds: 100000000)), settings: DistributedActors.ClusterSettings(enabled: true, node: sact://third@127.0.0.1:9333, nid: 3870929634, bindTimeout: TimeAmount(3s, nanoseconds: 3000000000), unbindTimeout: TimeAmount(3s, nanoseconds: 3000000000), connectTimeout: TimeAmount(500ms, nanoseconds: 500000000), associationHandshakeBackoff: DistributedActors.ExponentialBackoffStrategy(initialInterval: TimeAmount(100ms, nanoseconds: 100000000), multiplier: 1.5, capInterval: TimeAmount(∞ (infinite), nanoseconds: 9223372036854775807), randomFactor: 0.25, currentBaseInterval: TimeAmount(100ms, nanoseconds: 100000000)), associationTombstoneTTL: TimeAmount(1d, nanoseconds: 86400000000000), _protocolVersion: Version(0.0.1, reserved:0), membershipGossipInterval: TimeAmount(500ms, nanoseconds: 500000000), autoLeaderElection: DistributedActors.ClusterSettings.LeadershipSelectionSettings.lowestReachable(minNumberOfMembers: 3), tls: nil, tlsPassphraseCallback: nil, eventLoopGroup: Optional(MultiThreadedEventLoopGroup { threadPattern = NIO-ELT-2-#* }), receptionist: DistributedActors.ClusterReceptionist.Settings(implementation: DistributedActors.ClusterReceptionist.Settings.ClusterReceptionistImplementationSettings.opLogSync, traceLogLevel: nil, ackPullReplicationIntervalSlow: TimeAmount(1s 200ms, nanoseconds: 1200000000), syncBatchSize: 50), allocator: NIO.ByteBufferAllocator(malloc: (Function), realloc: (Function), free: (Function), memcpy: (Function)), downingStrategy: DistributedActors.DowningStrategySettings.timeout(DistributedActors.TimeoutBasedDowningStrategySettings(downUnreachableMembersAfter: TimeAmount(1s, nanoseconds: 1000000000))), onDownAction: DistributedActors.OnDownActionStrategySettings.gracefulShutdown(delay: TimeAmount(3s, nanoseconds: 3000000000)), swim: DistributedActors.SWIMSettings(disabled: false, gossip: DistributedActors.SWIMGossipSettings(maxNumberOfMessages: 20, maxGossipCountPerMessage: 6), indirectProbeCount: 3, probeInterval: TimeAmount(100ms, nanoseconds: 100000000), pingTimeout: TimeAmount(50ms, nanoseconds: 50000000), lifeguard: DistributedActors.SWIMLifeguardSettings(maxLocalHealthMultiplier: 1, suspicionTimeoutMax: TimeAmount(1s, nanoseconds: 1000000000), suspicionTimeoutMin: TimeAmount(500ms, nanoseconds: 500000000), maxIndependentSuspicions: 4, timeSourceNanos: (Function)), name: nil, traceLogLevel: nil), logMembershipChanges: Optional(Logging.Logger.Level.debug), traceLogLevel: nil), remoteNode: sact://fourth@127.0.0.1:7444, localNode: sact://third:3870929634@127.0.0.1:9333, whenCompleted: Optional(NIO.EventLoopPromise<DistributedActors.Wire.HandshakeResponse>(futureResult: NIO.EventLoopFuture<DistributedActors.Wire.HandshakeResponse>)), channel: nil))]
Captured log [third][2020-04-29 0:2:30.4920] [ClusterShell.swift:687][/system/cluster] [info] Extending handshake offer to sact://fourth@127.0.0.1:7444)
Captured log [third][2020-04-29 0:2:30.4940] [TransportPipelines.swift:78][/system/transport.client] [trace] Offering handshake [DistributedActors.ProtoHandshakeOffer:
version {
  patch: 1
}
from {
  node {
    protocol: "sact"
    system: "third"
    hostname: "127.0.0.1"
    port: 9333
  }
  nid: 3870929634
}
to {
  protocol: "sact"
  system: "fourth"
  hostname: "127.0.0.1"
  port: 7444
}
]
Captured log [third][2020-04-29 0:2:30.4940] [ClusterShell.swift:708][/system/cluster] [info] EXTENDING HANDSHAKE [DistributedActors.HandshakeStateMachine.State.initiated(DistributedActors.HandshakeStateMachine.InitiatedState(backoff: DistributedActors.ExponentialBackoffStrategy(initialInterval: TimeAmount(100ms, nanoseconds: 100000000), multiplier: 1.5, capInterval: TimeAmount(∞ (infinite), nanoseconds: 9223372036854775807), randomFactor: 0.25, currentBaseInterval: TimeAmount(100ms, nanoseconds: 100000000)), settings: DistributedActors.ClusterSettings(enabled: true, node: sact://third@127.0.0.1:9333, nid: 3870929634, bindTimeout: TimeAmount(3s, nanoseconds: 3000000000), unbindTimeout: TimeAmount(3s, nanoseconds: 3000000000), connectTimeout: TimeAmount(500ms, nanoseconds: 500000000), associationHandshakeBackoff: DistributedActors.ExponentialBackoffStrategy(initialInterval: TimeAmount(100ms, nanoseconds: 100000000), multiplier: 1.5, capInterval: TimeAmount(∞ (infinite), nanoseconds: 9223372036854775807), randomFactor: 0.25, currentBaseInterval: TimeAmount(100ms, nanoseconds: 100000000)), associationTombstoneTTL: TimeAmount(1d, nanoseconds: 86400000000000), _protocolVersion: Version(0.0.1, reserved:0), membershipGossipInterval: TimeAmount(500ms, nanoseconds: 500000000), autoLeaderElection: DistributedActors.ClusterSettings.LeadershipSelectionSettings.lowestReachable(minNumberOfMembers: 3), tls: nil, tlsPassphraseCallback: nil, eventLoopGroup: Optional(MultiThreadedEventLoopGroup { threadPattern = NIO-ELT-2-#* }), receptionist: DistributedActors.ClusterReceptionist.Settings(implementation: DistributedActors.ClusterReceptionist.Settings.ClusterReceptionistImplementationSettings.opLogSync, traceLogLevel: nil, ackPullReplicationIntervalSlow: TimeAmount(1s 200ms, nanoseconds: 1200000000), syncBatchSize: 50), allocator: NIO.ByteBufferAllocator(malloc: (Function), realloc: (Function), free: (Function), memcpy: (Function)), downingStrategy: DistributedActors.DowningStrategySettings.timeout(DistributedActors.TimeoutBasedDowningStrategySettings(downUnreachableMembersAfter: TimeAmount(1s, nanoseconds: 1000000000))), onDownAction: DistributedActors.OnDownActionStrategySettings.gracefulShutdown(delay: TimeAmount(3s, nanoseconds: 3000000000)), swim: DistributedActors.SWIMSettings(disabled: false, gossip: DistributedActors.SWIMGossipSettings(maxNumberOfMessages: 20, maxGossipCountPerMessage: 6), indirectProbeCount: 3, probeInterval: TimeAmount(100ms, nanoseconds: 100000000), pingTimeout: TimeAmount(50ms, nanoseconds: 50000000), lifeguard: DistributedActors.SWIMLifeguardSettings(maxLocalHealthMultiplier: 1, suspicionTimeoutMax: TimeAmount(1s, nanoseconds: 1000000000), suspicionTimeoutMin: TimeAmount(500ms, nanoseconds: 500000000), maxIndependentSuspicions: 4, timeSourceNanos: (Function)), name: nil, traceLogLevel: nil), logMembershipChanges: Optional(Logging.Logger.Level.debug), traceLogLevel: nil), remoteNode: sact://fourth@127.0.0.1:7444, localNode: sact://third:3870929634@127.0.0.1:9333, whenCompleted: Optional(NIO.EventLoopPromise<DistributedActors.Wire.HandshakeResponse>(futureResult: NIO.EventLoopFuture<DistributedActors.Wire.HandshakeResponse>)), channel: Optional(SocketChannel { BaseSocket { fd=5 }, active = true, localAddress = Optional([IPv4]127.0.0.1/127.0.0.1:52123), remoteAddress = Optional([IPv4]127.0.0.1/127.0.0.1:7444) })))])
Captured log [third][2020-04-29 0:2:30.4970] [TransportPipelines.swift:59][/system/transport.client] [debug] Received handshake accept from: [sact://fourth@127.0.0.1:7444]
Captured log [third][2020-04-29 0:2:30.4970] [ClusterShell.swift:926][/system/cluster] [error] Handshake error while connecting [sact://fourth@127.0.0.1:7444]: [truncated]SwiftProtobuf.BinaryDecodingError
Captured log [third][2020-04-29 0:2:30.4970] [ClusterShell.swift:855][/system/cluster] [info] IN PROCESS HANDSHAKES: []
Captured log [third][2020-04-29 0:2:30.4970] [ClusterShell.swift:856][/system/cluster] [info] IN PROCESS HANDSHAKES WITH sact://fourth@127.0.0.1:7444: [NIL]
Captured log [third][2020-04-29 0:2:30.4970] [ClusterShell.swift:862][/system/cluster] [error] Unexpected handshake accept received: [HandshakeAccept(version: Version(0.0.1, reserved:0), from: sact://fourth:3162759719@127.0.0.1:7444, origin: sact://third:3870929634@127.0.0.1:9333)]. No handshake was in progress with sact://fourth@127.0.0.1:7444
Captured log [third][2020-04-29 0:2:30.7070] [ClusterShell.swift:623][/system/cluster] [debug] Attempted associating with already associated node: [sact://fourth@127.0.0.1:7444], existing association: [AssociatedState(associating(queue: DistributedActors.MPSCLinkedQueue<DistributedActors.TransportEnvelope>), selfNode: sact://third@127.0.0.1:9333, remoteNode: sact://fourth@127.0.0.1:7444)]
Captured log [third][2020-04-29 0:2:30.7080] [ClusterShell.swift:669][/system/cluster] [trace] beginHandshake INITIATED Handshake state: [DistributedActors.HandshakeStateMachine.State.initiated(DistributedActors.HandshakeStateMachine.InitiatedState(backoff: DistributedActors.ExponentialBackoffStrategy(initialInterval: TimeAmount(100ms, nanoseconds: 100000000), multiplier: 1.5, capInterval: TimeAmount(∞ (infinite), nanoseconds: 9223372036854775807), randomFactor: 0.25, currentBaseInterval: TimeAmount(100ms, nanoseconds: 100000000)), settings: DistributedActors.ClusterSettings(enabled: true, node: sact://third@127.0.0.1:9333, nid: 3870929634, bindTimeout: TimeAmount(3s, nanoseconds: 3000000000), unbindTimeout: TimeAmount(3s, nanoseconds: 3000000000), connectTimeout: TimeAmount(500ms, nanoseconds: 500000000), associationHandshakeBackoff: DistributedActors.ExponentialBackoffStrategy(initialInterval: TimeAmount(100ms, nanoseconds: 100000000), multiplier: 1.5, capInterval: TimeAmount(∞ (infinite), nanoseconds: 9223372036854775807), randomFactor: 0.25, currentBaseInterval: TimeAmount(100ms, nanoseconds: 100000000)), associationTombstoneTTL: TimeAmount(1d, nanoseconds: 86400000000000), _protocolVersion: Version(0.0.1, reserved:0), membershipGossipInterval: TimeAmount(500ms, nanoseconds: 500000000), autoLeaderElection: DistributedActors.ClusterSettings.LeadershipSelectionSettings.lowestReachable(minNumberOfMembers: 3), tls: nil, tlsPassphraseCallback: nil, eventLoopGroup: Optional(MultiThreadedEventLoopGroup { threadPattern = NIO-ELT-2-#* }), receptionist: DistributedActors.ClusterReceptionist.Settings(implementation: DistributedActors.ClusterReceptionist.Settings.ClusterReceptionistImplementationSettings.opLogSync, traceLogLevel: nil, ackPullReplicationIntervalSlow: TimeAmount(1s 200ms, nanoseconds: 1200000000), syncBatchSize: 50), allocator: NIO.ByteBufferAllocator(malloc: (Function), realloc: (Function), free: (Function), memcpy: (Function)), downingStrategy: DistributedActors.DowningStrategySettings.timeout(DistributedActors.TimeoutBasedDowningStrategySettings(downUnreachableMembersAfter: TimeAmount(1s, nanoseconds: 1000000000))), onDownAction: DistributedActors.OnDownActionStrategySettings.gracefulShutdown(delay: TimeAmount(3s, nanoseconds: 3000000000)), swim: DistributedActors.SWIMSettings(disabled: false, gossip: DistributedActors.SWIMGossipSettings(maxNumberOfMessages: 20, maxGossipCountPerMessage: 6), indirectProbeCount: 3, probeInterval: TimeAmount(100ms, nanoseconds: 100000000), pingTimeout: TimeAmount(50ms, nanoseconds: 50000000), lifeguard: DistributedActors.SWIMLifeguardSettings(maxLocalHealthMultiplier: 1, suspicionTimeoutMax: TimeAmount(1s, nanoseconds: 1000000000), suspicionTimeoutMin: TimeAmount(500ms, nanoseconds: 500000000), maxIndependentSuspicions: 4, timeSourceNanos: (Function)), name: nil, traceLogLevel: nil), logMembershipChanges: Optional(Logging.Logger.Level.debug), traceLogLevel: nil), remoteNode: sact://fourth@127.0.0.1:7444, localNode: sact://third:3870929634@127.0.0.1:9333, whenCompleted: Optional(NIO.EventLoopPromise<DistributedActors.Wire.HandshakeResponse>(futureResult: NIO.EventLoopFuture<DistributedActors.Wire.HandshakeResponse>)), channel: nil))]
Captured log [third][2020-04-29 0:2:30.7080] [ClusterShell.swift:683][/system/cluster] [info] No need to extend handshake offer, node [sact://fourth@127.0.0.1:7444] is already associated.
Captured log [third][2020-04-29 0:2:31.4550] [ClusterShell.swift:532][/system/cluster] [trace] Local membership version is [.concurrent] to incoming gossip; Merge resulted in 2 changes.

This manifests a bug in the #577 reimpl