You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@ignite.apache.org by "Mirza Aliev (Jira)" <ji...@apache.org> on 2024/02/06 15:32:00 UTC
[jira] [Comment Edited] (IGNITE-21457) ItNodeTest#testSetPeer2 is flaky
[ https://issues.apache.org/jira/browse/IGNITE-21457?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17814860#comment-17814860 ]
Mirza Aliev edited comment on IGNITE-21457 at 2/6/24 3:31 PM:
--------------------------------------------------------------
What has been debugged so far:
we can simplify the test scenario: start 3 raft node, restart two of them and wait for the topology on restarted nodes see all three nodes.
We see that sometimes assertion for that is failed after 10 seconds;
{noformat}
assertTrue(waitForTopology(cluster, followerPeer1, 3, 10_000));
{noformat}
Logs show that while we wait for that assertion on the node A, node A do not receive {{[MembershipProtocol]}} events about any node, so topology on that node is not equal to the full topology.
After increasing of the timeout for the assertion from 10 to 60 seconds, we see missing events from{{{}[MembershipProtocol]{}}}
{noformat}
[2024-02-06T15:05:59,401][INFO ][main][ItNodeTest] start follower int_tsp_5003
[2024-02-06T15:05:59,421][INFO ][main][ConnectionManager] Server started [address=/0:0:0:0:0:0:0:0:5003]
[2024-02-06T15:05:59,423][INFO ][main][Cluster] [default:int_tsp_5003:61c47a75b81403f@127.0.0.1:5003][doStart] Starting, config: ClusterConfig[metadata=null, metadataTimeout=1000, metadataCodec=io.scalecube.cluster.metadata.JdkMetadataCodec@4eb9f2af, memberId='061c47a7-5b81-403f-bb1d-c94311653766', memberAlias='int_tsp_5003', externalHost='null', externalPort=null, transportConfig=TransportConfig[port=0, clientSecured=false, connectTimeout=1000, messageCodec=io.scalecube.cluster.transport.api.JdkMessageCodec@4a481728, maxFrameLength=2097152, transportFactory=org.apache.ignite.internal.network.scalecube.ScaleCubeClusterServiceFactory$2$$Lambda$676/0x0000000800458c40@3e252e42, addressMapper=java.util.function.Function$$Lambda$99/0x0000000800122040@77fa9381], failureDetectorConfig=FailureDetectorConfig[pingInterval=500, pingTimeout=200, pingReqMembers=1], gossipConfig=GossipConfig[gossipFanout=3, gossipInterval=10, gossipRepeatMult=2, gossipSegmentationThreshold=1000], membershipConfig=MembershipConfig[seedMembers=[], syncInterval=1000, syncTimeout=3000, suspicionMult=1, namespace='default', removedMembersHistorySize=42]]
[2024-02-06T15:05:59,423][INFO ][main][Cluster] [default:int_tsp_5003:61c47a75b81403f@127.0.0.1:5003][doStart] Started
[2024-02-06T15:05:59,423][INFO ][main][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=061c47a7-5b81-403f-bb1d-c94311653766, name=int_tsp_5003, address=127.0.0.1:5003, nodeMetadata=null]]
[2024-02-06T15:05:59,423][INFO ][main][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5003]]
[2024-02-06T15:05:59,492][INFO ][main][FSMCallerImpl] Starts FSMCaller successfully.
[2024-02-06T15:05:59,492][INFO ][2024-02-06T15:05:59,492][WARN ][main][LocalSnapshotStorage] No data for snapshot reader build/work/ItNodeTest/testSetPeer2_613743809901666/int_tsp_5003/snapshot.
[main][NodeImpl] Init node int_tsp_5003 with empty conf.
[2024-02-06T15:05:59,492][INFO ][main][NodeImpl] Node <unitest/int_tsp_5003> init, term=0, lastLogId=LogId [index=0, term=0], conf=, oldConf=.
[2024-02-06T15:05:59,492][INFO ][main][RaftGroupService] Start the RaftGroupService successfully <unitest/int_tsp_5003>
[2024-02-06T15:05:59,492][INFO ][main][ItNodeTest] start follower int_tsp_5005
[2024-02-06T15:05:59,503][INFO ][main][ConnectionManager] Server started [address=/0:0:0:0:0:0:0:0:5005]
[2024-02-06T15:05:59,504][INFO ][main][Cluster] [default:int_tsp_5005:573fbde03e8445fa@127.0.0.1:5005][doStart] Starting, config: ClusterConfig[metadata=null, metadataTimeout=1000, metadataCodec=io.scalecube.cluster.metadata.JdkMetadataCodec@4eb9f2af, memberId='d73fbde0-3e84-45fa-a27c-4ca5c7bdbe78', memberAlias='int_tsp_5005', externalHost='null', externalPort=null, transportConfig=TransportConfig[port=0, clientSecured=false, connectTimeout=1000, messageCodec=io.scalecube.cluster.transport.api.JdkMessageCodec@4a481728, maxFrameLength=2097152, transportFactory=org.apache.ignite.internal.network.scalecube.ScaleCubeClusterServiceFactory$2$$Lambda$676/0x0000000800458c40@61d812ff, addressMapper=java.util.function.Function$$Lambda$99/0x0000000800122040@77fa9381], failureDetectorConfig=FailureDetectorConfig[pingInterval=500, pingTimeout=200, pingReqMembers=1], gossipConfig=GossipConfig[gossipFanout=3, gossipInterval=10, gossipRepeatMult=2, gossipSegmentationThreshold=1000], membershipConfig=MembershipConfig[seedMembers=[], syncInterval=1000, syncTimeout=3000, suspicionMult=1, namespace='default', removedMembersHistorySize=42]]
[2024-02-06T15:05:59,504][INFO ][main][Cluster] [default:int_tsp_5005:573fbde03e8445fa@127.0.0.1:5005][doStart] Started
[2024-02-06T15:05:59,504][INFO ][main][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=d73fbde0-3e84-45fa-a27c-4ca5c7bdbe78, name=int_tsp_5005, address=127.0.0.1:5005, nodeMetadata=null]]
[2024-02-06T15:05:59,504][INFO ][main][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5005]]
[2024-02-06T15:05:59,573][INFO ][main][FSMCallerImpl] Starts FSMCaller successfully.
[2024-02-06T15:05:59,573][WARN ][main][LocalSnapshotStorage] No data for snapshot reader build/work/ItNodeTest/testSetPeer2_613743809901666/int_tsp_5005/snapshot.
[2024-02-06T15:05:59,573][INFO ][main][NodeImpl] Init node int_tsp_5005 with empty conf.
[2024-02-06T15:05:59,573][INFO ][main][NodeImpl] Node <unitest/int_tsp_5005> init, term=0, lastLogId=LogId [index=0, term=0], conf=, oldConf=.
[2024-02-06T15:05:59,573][INFO ][main][RaftGroupService] Start the RaftGroupService successfully <unitest/int_tsp_5005>
[2024-02-06T15:05:59,593][INFO ][sc-cluster-5005-950][MembershipProtocol] [default:int_tsp_5005:573fbde03e8445fa@127.0.0.1:5005][publishEvent] MembershipEvent[type=ADDED, member=default:int_tsp_5004:6c68eb78ac574dba@127.0.0.1:5004, oldMetadata=null, newMetadata=7e16449-5, timestamp=2024-02-06T11:05:59.593Z]
[2024-02-06T15:05:59,593][INFO ][sc-cluster-5005-950][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=6c68eb78-ac57-4dba-876a-0f46f907ee99, name=int_tsp_5004, address=127.0.0.1:5004, nodeMetadata=null]]
[2024-02-06T15:05:59,593][INFO ][sc-cluster-5005-950][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5005, int_tsp_5004]]
[2024-02-06T15:05:59,593][INFO ][sc-cluster-5004-947][MembershipProtocol] [default:int_tsp_5004:6c68eb78ac574dba@127.0.0.1:5004][publishEvent] MembershipEvent[type=ADDED, member=default:int_tsp_5005:573fbde03e8445fa@127.0.0.1:5005, oldMetadata=null, newMetadata=7e16449-5, timestamp=2024-02-06T11:05:59.593Z]
[2024-02-06T15:05:59,593][INFO ][sc-cluster-5004-947][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=d73fbde0-3e84-45fa-a27c-4ca5c7bdbe78, name=int_tsp_5005, address=127.0.0.1:5005, nodeMetadata=null]]
[2024-02-06T15:05:59,593][INFO ][sc-cluster-5004-947][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5005, int_tsp_5004]]
[2024-02-06T15:06:11,598][INFO ][sc-cluster-5003-949][MembershipProtocol] [default:int_tsp_5003:61c47a75b81403f@127.0.0.1:5003][publishEvent] MembershipEvent[type=ADDED, member=default:int_tsp_5004:6c68eb78ac574dba@127.0.0.1:5004, oldMetadata=null, newMetadata=7e16449-5, timestamp=2024-02-06T11:06:11.598Z]
[2024-02-06T15:06:11,599][INFO ][sc-cluster-5003-949][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=6c68eb78-ac57-4dba-876a-0f46f907ee99, name=int_tsp_5004, address=127.0.0.1:5004, nodeMetadata=null]]
[2024-02-06T15:06:11,599][INFO ][sc-cluster-5003-949][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5004, int_tsp_5003]]
[2024-02-06T15:06:11,599][INFO ][sc-cluster-5003-949][MembershipProtocol] [default:int_tsp_5003:61c47a75b81403f@127.0.0.1:5003][publishEvent] MembershipEvent[type=ADDED, member=default:int_tsp_5005:573fbde03e8445fa@127.0.0.1:5005, oldMetadata=null, newMetadata=7e16449-5, timestamp=2024-02-06T11:06:11.599Z]
[2024-02-06T15:06:11,599][INFO ][sc-cluster-5003-949][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=d73fbde0-3e84-45fa-a27c-4ca5c7bdbe78, name=int_tsp_5005, address=127.0.0.1:5005, nodeMetadata=null]]
[2024-02-06T15:06:11,599][INFO ][sc-cluster-5003-949][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5005, int_tsp_5004, int_tsp_5003]]
[2024-02-06T15:06:11,600][INFO ][sc-cluster-5004-947][MembershipProtocol] [default:int_tsp_5004:6c68eb78ac574dba@127.0.0.1:5004][publishEvent] MembershipEvent[type=ADDED, member=default:int_tsp_5003:61c47a75b81403f@127.0.0.1:5003, oldMetadata=null, newMetadata=7e16449-5, timestamp=2024-02-06T11:06:11.600Z]
[2024-02-06T15:06:11,600][INFO ][sc-cluster-5004-947][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=061c47a7-5b81-403f-bb1d-c94311653766, name=int_tsp_5003, address=127.0.0.1:5003, nodeMetadata=null]]
[2024-02-06T15:06:11,600][INFO ][sc-cluster-5004-947][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5005, int_tsp_5004, int_tsp_5003]]
[2024-02-06T15:06:11,603][INFO ][sc-cluster-5005-950][MembershipProtocol] [default:int_tsp_5005:573fbde03e8445fa@127.0.0.1:5005][publishEvent] MembershipEvent[type=ADDED, member=default:int_tsp_5003:61c47a75b81403f@127.0.0.1:5003, oldMetadata=null, newMetadata=7e16449-5, timestamp=2024-02-06T11:06:11.603Z]
[2024-02-06T15:06:11,603][INFO ][sc-cluster-5005-950][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=061c47a7-5b81-403f-bb1d-c94311653766, name=int_tsp_5003, address=127.0.0.1:5003, nodeMetadata=null]]
[2024-02-06T15:06:11,603][INFO ][sc-cluster-5005-950][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5005, int_tsp_5004, int_tsp_5003]]
{noformat}
and finally we see
{noformat}
Topology snapshot [nodes=[int_tsp_5005, int_tsp_5004, int_tsp_5003]]
{noformat}
on the node A.
From that log and some other failed runs we can see that this awaiting of the {{[MembershipProtocol]}} messages on the node A last approx. 10-12 seconds.
The root cause may be connected with the incorrect scalecube timeouts, need to investigate further. We have checked scalecube's suspicion timeout, seems that this is not our case, because {{suspicionTimeout}} was equal to 1 second
was (Author: maliev):
What has been debugged so far:
we can simplify the test scenario: start 3 raft node, restart two of them and wait for the topology on restarted nodes see all three nodes.
We see that sometimes assertion for that is failed after 10 seconds;
{noformat}
assertTrue(waitForTopology(cluster, followerPeer1, 3, 10_000));
{noformat}
Logs show that while we wait for that assertion on the node A, node A do not receive {{[MembershipProtocol]}} events about any node, so topology on that node is not equal to the full topology.
After increasing of the timeout for the assertion from 10 to 60 seconds, we see that missing events from{{{}[MembershipProtocol]{}}}
{noformat}
[2024-02-06T15:05:59,401][INFO ][main][ItNodeTest] start follower int_tsp_5003
[2024-02-06T15:05:59,421][INFO ][main][ConnectionManager] Server started [address=/0:0:0:0:0:0:0:0:5003]
[2024-02-06T15:05:59,423][INFO ][main][Cluster] [default:int_tsp_5003:61c47a75b81403f@127.0.0.1:5003][doStart] Starting, config: ClusterConfig[metadata=null, metadataTimeout=1000, metadataCodec=io.scalecube.cluster.metadata.JdkMetadataCodec@4eb9f2af, memberId='061c47a7-5b81-403f-bb1d-c94311653766', memberAlias='int_tsp_5003', externalHost='null', externalPort=null, transportConfig=TransportConfig[port=0, clientSecured=false, connectTimeout=1000, messageCodec=io.scalecube.cluster.transport.api.JdkMessageCodec@4a481728, maxFrameLength=2097152, transportFactory=org.apache.ignite.internal.network.scalecube.ScaleCubeClusterServiceFactory$2$$Lambda$676/0x0000000800458c40@3e252e42, addressMapper=java.util.function.Function$$Lambda$99/0x0000000800122040@77fa9381], failureDetectorConfig=FailureDetectorConfig[pingInterval=500, pingTimeout=200, pingReqMembers=1], gossipConfig=GossipConfig[gossipFanout=3, gossipInterval=10, gossipRepeatMult=2, gossipSegmentationThreshold=1000], membershipConfig=MembershipConfig[seedMembers=[], syncInterval=1000, syncTimeout=3000, suspicionMult=1, namespace='default', removedMembersHistorySize=42]]
[2024-02-06T15:05:59,423][INFO ][main][Cluster] [default:int_tsp_5003:61c47a75b81403f@127.0.0.1:5003][doStart] Started
[2024-02-06T15:05:59,423][INFO ][main][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=061c47a7-5b81-403f-bb1d-c94311653766, name=int_tsp_5003, address=127.0.0.1:5003, nodeMetadata=null]]
[2024-02-06T15:05:59,423][INFO ][main][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5003]]
[2024-02-06T15:05:59,492][INFO ][main][FSMCallerImpl] Starts FSMCaller successfully.
[2024-02-06T15:05:59,492][INFO ][2024-02-06T15:05:59,492][WARN ][main][LocalSnapshotStorage] No data for snapshot reader build/work/ItNodeTest/testSetPeer2_613743809901666/int_tsp_5003/snapshot.
[main][NodeImpl] Init node int_tsp_5003 with empty conf.
[2024-02-06T15:05:59,492][INFO ][main][NodeImpl] Node <unitest/int_tsp_5003> init, term=0, lastLogId=LogId [index=0, term=0], conf=, oldConf=.
[2024-02-06T15:05:59,492][INFO ][main][RaftGroupService] Start the RaftGroupService successfully <unitest/int_tsp_5003>
[2024-02-06T15:05:59,492][INFO ][main][ItNodeTest] start follower int_tsp_5005
[2024-02-06T15:05:59,503][INFO ][main][ConnectionManager] Server started [address=/0:0:0:0:0:0:0:0:5005]
[2024-02-06T15:05:59,504][INFO ][main][Cluster] [default:int_tsp_5005:573fbde03e8445fa@127.0.0.1:5005][doStart] Starting, config: ClusterConfig[metadata=null, metadataTimeout=1000, metadataCodec=io.scalecube.cluster.metadata.JdkMetadataCodec@4eb9f2af, memberId='d73fbde0-3e84-45fa-a27c-4ca5c7bdbe78', memberAlias='int_tsp_5005', externalHost='null', externalPort=null, transportConfig=TransportConfig[port=0, clientSecured=false, connectTimeout=1000, messageCodec=io.scalecube.cluster.transport.api.JdkMessageCodec@4a481728, maxFrameLength=2097152, transportFactory=org.apache.ignite.internal.network.scalecube.ScaleCubeClusterServiceFactory$2$$Lambda$676/0x0000000800458c40@61d812ff, addressMapper=java.util.function.Function$$Lambda$99/0x0000000800122040@77fa9381], failureDetectorConfig=FailureDetectorConfig[pingInterval=500, pingTimeout=200, pingReqMembers=1], gossipConfig=GossipConfig[gossipFanout=3, gossipInterval=10, gossipRepeatMult=2, gossipSegmentationThreshold=1000], membershipConfig=MembershipConfig[seedMembers=[], syncInterval=1000, syncTimeout=3000, suspicionMult=1, namespace='default', removedMembersHistorySize=42]]
[2024-02-06T15:05:59,504][INFO ][main][Cluster] [default:int_tsp_5005:573fbde03e8445fa@127.0.0.1:5005][doStart] Started
[2024-02-06T15:05:59,504][INFO ][main][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=d73fbde0-3e84-45fa-a27c-4ca5c7bdbe78, name=int_tsp_5005, address=127.0.0.1:5005, nodeMetadata=null]]
[2024-02-06T15:05:59,504][INFO ][main][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5005]]
[2024-02-06T15:05:59,573][INFO ][main][FSMCallerImpl] Starts FSMCaller successfully.
[2024-02-06T15:05:59,573][WARN ][main][LocalSnapshotStorage] No data for snapshot reader build/work/ItNodeTest/testSetPeer2_613743809901666/int_tsp_5005/snapshot.
[2024-02-06T15:05:59,573][INFO ][main][NodeImpl] Init node int_tsp_5005 with empty conf.
[2024-02-06T15:05:59,573][INFO ][main][NodeImpl] Node <unitest/int_tsp_5005> init, term=0, lastLogId=LogId [index=0, term=0], conf=, oldConf=.
[2024-02-06T15:05:59,573][INFO ][main][RaftGroupService] Start the RaftGroupService successfully <unitest/int_tsp_5005>
[2024-02-06T15:05:59,593][INFO ][sc-cluster-5005-950][MembershipProtocol] [default:int_tsp_5005:573fbde03e8445fa@127.0.0.1:5005][publishEvent] MembershipEvent[type=ADDED, member=default:int_tsp_5004:6c68eb78ac574dba@127.0.0.1:5004, oldMetadata=null, newMetadata=7e16449-5, timestamp=2024-02-06T11:05:59.593Z]
[2024-02-06T15:05:59,593][INFO ][sc-cluster-5005-950][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=6c68eb78-ac57-4dba-876a-0f46f907ee99, name=int_tsp_5004, address=127.0.0.1:5004, nodeMetadata=null]]
[2024-02-06T15:05:59,593][INFO ][sc-cluster-5005-950][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5005, int_tsp_5004]]
[2024-02-06T15:05:59,593][INFO ][sc-cluster-5004-947][MembershipProtocol] [default:int_tsp_5004:6c68eb78ac574dba@127.0.0.1:5004][publishEvent] MembershipEvent[type=ADDED, member=default:int_tsp_5005:573fbde03e8445fa@127.0.0.1:5005, oldMetadata=null, newMetadata=7e16449-5, timestamp=2024-02-06T11:05:59.593Z]
[2024-02-06T15:05:59,593][INFO ][sc-cluster-5004-947][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=d73fbde0-3e84-45fa-a27c-4ca5c7bdbe78, name=int_tsp_5005, address=127.0.0.1:5005, nodeMetadata=null]]
[2024-02-06T15:05:59,593][INFO ][sc-cluster-5004-947][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5005, int_tsp_5004]]
[2024-02-06T15:06:11,598][INFO ][sc-cluster-5003-949][MembershipProtocol] [default:int_tsp_5003:61c47a75b81403f@127.0.0.1:5003][publishEvent] MembershipEvent[type=ADDED, member=default:int_tsp_5004:6c68eb78ac574dba@127.0.0.1:5004, oldMetadata=null, newMetadata=7e16449-5, timestamp=2024-02-06T11:06:11.598Z]
[2024-02-06T15:06:11,599][INFO ][sc-cluster-5003-949][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=6c68eb78-ac57-4dba-876a-0f46f907ee99, name=int_tsp_5004, address=127.0.0.1:5004, nodeMetadata=null]]
[2024-02-06T15:06:11,599][INFO ][sc-cluster-5003-949][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5004, int_tsp_5003]]
[2024-02-06T15:06:11,599][INFO ][sc-cluster-5003-949][MembershipProtocol] [default:int_tsp_5003:61c47a75b81403f@127.0.0.1:5003][publishEvent] MembershipEvent[type=ADDED, member=default:int_tsp_5005:573fbde03e8445fa@127.0.0.1:5005, oldMetadata=null, newMetadata=7e16449-5, timestamp=2024-02-06T11:06:11.599Z]
[2024-02-06T15:06:11,599][INFO ][sc-cluster-5003-949][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=d73fbde0-3e84-45fa-a27c-4ca5c7bdbe78, name=int_tsp_5005, address=127.0.0.1:5005, nodeMetadata=null]]
[2024-02-06T15:06:11,599][INFO ][sc-cluster-5003-949][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5005, int_tsp_5004, int_tsp_5003]]
[2024-02-06T15:06:11,600][INFO ][sc-cluster-5004-947][MembershipProtocol] [default:int_tsp_5004:6c68eb78ac574dba@127.0.0.1:5004][publishEvent] MembershipEvent[type=ADDED, member=default:int_tsp_5003:61c47a75b81403f@127.0.0.1:5003, oldMetadata=null, newMetadata=7e16449-5, timestamp=2024-02-06T11:06:11.600Z]
[2024-02-06T15:06:11,600][INFO ][sc-cluster-5004-947][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=061c47a7-5b81-403f-bb1d-c94311653766, name=int_tsp_5003, address=127.0.0.1:5003, nodeMetadata=null]]
[2024-02-06T15:06:11,600][INFO ][sc-cluster-5004-947][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5005, int_tsp_5004, int_tsp_5003]]
[2024-02-06T15:06:11,603][INFO ][sc-cluster-5005-950][MembershipProtocol] [default:int_tsp_5005:573fbde03e8445fa@127.0.0.1:5005][publishEvent] MembershipEvent[type=ADDED, member=default:int_tsp_5003:61c47a75b81403f@127.0.0.1:5003, oldMetadata=null, newMetadata=7e16449-5, timestamp=2024-02-06T11:06:11.603Z]
[2024-02-06T15:06:11,603][INFO ][sc-cluster-5005-950][ScaleCubeTopologyService] Node joined [node=ClusterNodeImpl [id=061c47a7-5b81-403f-bb1d-c94311653766, name=int_tsp_5003, address=127.0.0.1:5003, nodeMetadata=null]]
[2024-02-06T15:06:11,603][INFO ][sc-cluster-5005-950][ScaleCubeTopologyService] Topology snapshot [nodes=[int_tsp_5005, int_tsp_5004, int_tsp_5003]]
{noformat}
and finally we see
{noformat}
Topology snapshot [nodes=[int_tsp_5005, int_tsp_5004, int_tsp_5003]]
{noformat}
on the node A.
From that log and some other failed runs we can see that this awaiting of the {{[MembershipProtocol]}} messages on the node A last approx. 10-12 seconds.
The root cause may be connected with the incorrect scalecube timeouts, need to investigate further. We have checked scalecube's suspicion timeout, seems that this is not our case, because {{suspicionTimeout}} was equal to 1 second
> ItNodeTest#testSetPeer2 is flaky
> --------------------------------
>
> Key: IGNITE-21457
> URL: https://issues.apache.org/jira/browse/IGNITE-21457
> Project: Ignite
> Issue Type: Bug
> Reporter: Alexander Lapin
> Priority: Major
> Labels: ignite-3
> Time Spent: 20m
> Remaining Estimate: 0h
>
> {code:java}
> org.opentest4j.AssertionFailedError: expected: <true> but was: <false>
> at app//org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
> at app//org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
> at app//org.junit.jupiter.api.AssertTrue.failNotTrue(AssertTrue.java:63)
> at app//org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:36)
> at app//org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:31)
> at app//org.junit.jupiter.api.Assertions.assertTrue(Assertions.java:180)
> at app//org.apache.ignite.raft.jraft.core.ItNodeTest.testSetPeer2(ItNodeTest.java:1831)
> at java.base@11.0.17/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) {code}
> on
> {code:java}
> assertTrue(waitForTopology(cluster, followerPeer1, 3, 10_000)); {code}
> https://ci.ignite.apache.org/buildConfiguration/ApacheIgnite3xGradle_Test_RunAllTests/7828788?hideTestsFromDependencies=false&hideProblemsFromDependencies=false&expandBuildTestsSection=true&expandCode+Inspection=true&expandBuildProblemsSection=true&expandBuildChangesSection=true&expandBuildDeploymentsSection=false
--
This message was sent by Atlassian Jira
(v8.20.10#820010)