Kirill Sizov created IGNITE-21766:
--------------------------------------
Summary: AssertionError is thrown from jraft
Key: IGNITE-21766
URL: https://issues.apache.org/jira/browse/IGNITE-21766
Project: Ignite
Issue Type: Bug
Reporter: Kirill Sizov
One of the test runs failed with java.lang.AssertionError: null.
Seems like there is a race in jraft.
One threads tries to take a node while another one concurrently removes it.
{noformat}
[2024-03-13T04:56:03,164][INFO ][%itcwst_cews_2%Raft-Group-Client-11][Loza]
Stop raft group=8_part_0
[2024-03-13T04:56:03,165][INFO ][%itcwst_cews_2%Raft-Group-Client-11][NodeImpl]
Node <8_part_0/itcwst_cews_2> shutdown, currTerm=1 state=STATE_LEADER.
[2024-03-13T04:56:03,165][INFO
][%itcwst_cews_2%JRaft-FSMCaller-Disruptor_stripe_7-0][StateMachineAdapter]
onLeaderStop: status=Status[ESHUTDOWN<1007>: Raft node is going to quit.].
[2024-03-13T04:56:03,165][INFO
][%itcwst_cews_2%Raft-Group-Client-11][Replicator] Replicator Replicator
[state=Replicate, statInfo=<running=IDLE, firstLogIndex=7, lastLogIncluded=0,
lastLogIndex=7, lastTermIncluded=0>, peerId=itcwst_cews_1, type=Follower] is
going to quit
[2024-03-13T04:56:03,166][INFO
][%itcwst_cews_0%JRaft-Request-Processor-15][NodeImpl] Node
<8_part_0/itcwst_cews_0> received TimeoutNowRequest from itcwst_cews_2, term=1
and starts voting.
[2024-03-13T04:56:03,166][INFO
][%itcwst_cews_0%JRaft-Request-Processor-15][NodeImpl] Node
<8_part_0/itcwst_cews_0> start vote and grant vote self, term=1.
[2024-03-13T04:56:03,166][INFO
][%itcwst_cews_0%JRaft-FSMCaller-Disruptor_stripe_1-0][StateMachineAdapter]
onStopFollowing: LeaderChangeContext [leaderId=itcwst_cews_2, term=1,
status=Status[ERAFTTIMEDOUT<10001>: A follower's leader_id is reset to NULL as
it begins to request_vote.]].
[2024-03-13T04:56:03,166][INFO
][%itcwst_cews_2%Raft-Group-Client-11][LocalRaftMetaStorage] Save raft meta,
path=build/work/ItThinClientWorkerShutdownTest/colocatedExecutionWorkerShutdown_34532261536989015/itcwst_cews_2/8_part_0_itcwst_cews_2_0/meta,
term=1, votedFor=itcwst_cews_2, cost time=1 ms
[2024-03-13T04:56:03,166][INFO
][%itcwst_cews_2%Raft-Group-Client-11][FSMCallerImpl] Shutting down FSMCaller...
[2024-03-13T04:56:03,166][INFO
][%itcwst_cews_2%JRaft-Response-Processor-6][Replicator] Replicator Replicator
[state=Replicate, statInfo=<running=IDLE, firstLogIndex=7, lastLogIncluded=0,
lastLogIndex=7, lastTermIncluded=0>, peerId=itcwst_cews_0, type=Follower] is
going to quit
[2024-03-13T04:56:03,170][INFO
][%itcwst_cews_0%JRaft-Request-Processor-15][LocalRaftMetaStorage] Save raft
meta,
path=build/work/ItThinClientWorkerShutdownTest/colocatedExecutionWorkerShutdown_34532261536989015/itcwst_cews_0/8_part_0_itcwst_cews_0_0/meta,
term=2, votedFor=itcwst_cews_0, cost time=3 ms
[2024-03-13T04:56:03,170][INFO
][%itcwst_cews_1%JRaft-Request-Processor-4][NodeImpl] Node
<8_part_0/itcwst_cews_1> received RequestVoteRequest from itcwst_cews_0,
term=2, currTerm=1.
[2024-03-13T04:56:03,170][INFO
][%itcwst_cews_1%JRaft-FSMCaller-Disruptor_stripe_0-0][StateMachineAdapter]
onStopFollowing: LeaderChangeContext [leaderId=itcwst_cews_2, term=1,
status=Status[EHIGHERTERMRESPONSE<10008>: Raft node receives higher term
RequestVoteRequest.]].
[2024-03-13T04:56:03,171][INFO
][%itcwst_cews_1%JRaft-Request-Processor-4][LocalRaftMetaStorage] Save raft
meta,
path=build/work/ItThinClientWorkerShutdownTest/colocatedExecutionWorkerShutdown_34532261536989015/itcwst_cews_1/8_part_0_itcwst_cews_1_0/meta,
term=2, votedFor=, cost time=1 ms
[2024-03-13T04:56:03,172][INFO
][%itcwst_cews_1%JRaft-Request-Processor-4][LocalRaftMetaStorage] Save raft
meta,
path=build/work/ItThinClientWorkerShutdownTest/colocatedExecutionWorkerShutdown_34532261536989015/itcwst_cews_1/8_part_0_itcwst_cews_1_0/meta,
term=2, votedFor=itcwst_cews_0, cost time=0 ms
[2024-03-13T04:56:03,173][INFO
][%itcwst_cews_0%JRaft-Response-Processor-9][NodeImpl] Node
<8_part_0/itcwst_cews_0> become leader of group, term=2,
conf=itcwst_cews_2,itcwst_cews_1,itcwst_cews_0, oldConf=.
[2024-03-13T04:56:03,173][INFO
][%itcwst_cews_0%JRaft-Response-Processor-9][Replicator] Replicator=Replicator
[state=Created, statInfo=<running=null, firstLogIndex=0, lastLogIncluded=0,
lastLogIndex=0, lastTermIncluded=0>, peerId=itcwst_cews_2,
type=Follower]@itcwst_cews_2 is started
[2024-03-13T04:56:03,173][INFO
][%itcwst_cews_0%JRaft-Response-Processor-9][Replicator] Replicator=Replicator
[state=Created, statInfo=<running=null, firstLogIndex=0, lastLogIncluded=0,
lastLogIndex=0, lastTermIncluded=0>, peerId=itcwst_cews_1,
type=Follower]@itcwst_cews_1 is started
[2024-03-13T04:56:03,174][INFO
][%itcwst_cews_2%Raft-Group-Client-11][RaftGroupService] Stop the
RaftGroupService successfully.
[2024-03-13T04:56:03,175][INFO
][%itcwst_cews_1%JRaft-FSMCaller-Disruptor_stripe_0-0][StateMachineAdapter]
onStartFollowing: LeaderChangeContext [leaderId=itcwst_cews_0, term=2,
status=Status[ENEWLEADER<10011>: Follower receives message from new leader with
the same term.]].
[2024-03-13T04:56:01,427][WARN
][%itcwst_cews_2%JRaft-Response-Processor-3][NodeImpl] Node
<8_part_0/itcwst_cews_2> received invalid PreVoteResponse from itcwst_cews_0,
state not in STATE_FOLLOWER but STATE_CANDIDATE.
[2024-03-13T04:56:01,431][WARN
][%itcwst_cews_2%JRaft-Response-Processor-5][NodeImpl] Node
<8_part_0/itcwst_cews_2> received invalid RequestVoteResponse from
itcwst_cews_1, state not in STATE_CANDIDATE but STATE_LEADER.
[2024-03-13T04:56:01,455][WARN
][%itcwst_cews_1%metastorage-watch-executor-3][WatchProcessor] Watch event
processing has been too long [duration=1619, keys=[catalog.update.3,
catalog.version]]
[2024-03-13T04:56:01,456][WARN
][%itcwst_cews_0%metastorage-watch-executor-0][WatchProcessor] Watch event
processing has been too long [duration=1615, keys=[catalog.update.3,
catalog.version]]
[2024-03-13T04:56:01,457][WARN
][%itcwst_cews_2%metastorage-watch-executor-3][WatchProcessor] Watch event
processing has been too long [duration=1617, keys=[catalog.update.3,
catalog.version]]
[2024-03-13T04:56:02,979][WARN
][%itcwst_cews_2%partition-operations-1][TrackableNetworkMessageHandler]
Message handling has been too long [duration=12ms, message=[class
org.apache.ignite.internal.tx.message.TxCleanupMessageImpl]]
[2024-03-13T04:56:03,165][WARN
][%itcwst_cews_2%JRaft-Common-Executor-2][Replicator] Replicator Replicator
[state=Replicate, statInfo=<running=IDLE, firstLogIndex=7, lastLogIncluded=0,
lastLogIndex=7, lastTermIncluded=0>, peerId=itcwst_cews_0, type=Follower] stops
sending entries.
[2024-03-13T04:56:03,170][WARN
][%itcwst_cews_2%JRaft-Request-Processor-1][NodeImpl] Node
<8_part_0/itcwst_cews_2> is not in active state, currTerm=1.
[2024-03-13T04:56:03,171][WARN
][%itcwst_cews_0%JRaft-Response-Processor-8][NodeImpl] Node
<8_part_0/itcwst_cews_0> RequestVote to itcwst_cews_2 error:
Status[EINVAL<1015>: Node <8_part_0/itcwst_cews_2> is not in active state,
state STATE_SHUTTING.].
[2024-03-13T04:56:03,176][ERROR][%itcwst_cews_2%MessagingService-inbound-0-0][DefaultMessagingService]
onMessage() failed while processing InvokeRequestImpl [correlationId=268,
message=AppendEntriesRequestImpl [committedIndex=6,
data=org.apache.ignite.raft.jraft.util.ByteString@1, entriesList=null,
groupId=8_part_0, peerId=itcwst_cews_2, prevLogIndex=7, prevLogTerm=1,
serverId=itcwst_cews_0, term=2, timestampLong=112086598495305728]] from
ClusterNodeImpl [id=ac6fb201-b427-4497-a494-9d5a3d8060eb, name=itcwst_cews_0,
address=10.233.123.18:3344, nodeMetadata=null]
java.lang.AssertionError: null
at
org.apache.ignite.raft.jraft.rpc.impl.core.AppendEntriesRequestProcessor.getOrCreatePeerRequestContext(AppendEntriesRequestProcessor.java:348)
~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.raft.jraft.rpc.impl.core.AppendEntriesRequestProcessor$PeerExecutorSelector.select(AppendEntriesRequestProcessor.java:72)
~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.raft.jraft.rpc.impl.IgniteRpcServer$RpcMessageHandler.onReceived(IgniteRpcServer.java:169)
~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.internal.network.TrackableNetworkMessageHandler.onReceived(TrackableNetworkMessageHandler.java:49)
~[ignite-network-api-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.internal.network.DefaultMessagingService.handleStartingWithFirstHandler(DefaultMessagingService.java:494)
~[ignite-network-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.internal.network.DefaultMessagingService.lambda$handleMessageFromNetwork$5(DefaultMessagingService.java:401)
~[ignite-network-3.0.0-SNAPSHOT.jar:?]
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[?:?]
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[?:?]
at java.base/java.lang.Thread.run(Thread.java:834) [?:?]
[2024-03-13T04:56:03,190][WARN
][%itcwst_cews_2%MessagingService-inbound-0-0][DefaultMessagingService]
Uncaught exception [thread=IgniteThread
[name=%itcwst_cews_2%MessagingService-inbound-0-0]]
java.lang.AssertionError: null
at
org.apache.ignite.raft.jraft.rpc.impl.core.AppendEntriesRequestProcessor.getOrCreatePeerRequestContext(AppendEntriesRequestProcessor.java:348)
~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.raft.jraft.rpc.impl.core.AppendEntriesRequestProcessor$PeerExecutorSelector.select(AppendEntriesRequestProcessor.java:72)
~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.raft.jraft.rpc.impl.IgniteRpcServer$RpcMessageHandler.onReceived(IgniteRpcServer.java:169)
~[ignite-raft-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.internal.network.TrackableNetworkMessageHandler.onReceived(TrackableNetworkMessageHandler.java:49)
~[ignite-network-api-3.0.0-SNAPSHOT.jar:?]
{noformat}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
