[ https://issues.apache.org/jira/browse/IGNITE-16478?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17488932#comment-17488932 ]
Mirza Aliev edited comment on IGNITE-16478 at 2/8/22, 3:12 PM: --------------------------------------------------------------- We analysed debug logs from TC in and came up with possible ways of investigation: * Why we got {{ETIMEDOUT<1010>: RPC exception:null}}. Probably it entails further majority death {{[ERAFTTIMEDOUT<10001>: Majority of the group dies: 1/2]}} and stepping down of the leader. * In log we could see that we have several {{can't apply, status=Status[EPERM<1008>: Is not leader.]}} messages, which means that some task weren't applied to leaders log. Need to figure out what task weren't applied and check if we lost them completely. * In logs we can see {{called hasNext = false, cur = null}} which was logged after {{internalBatchCounter = 0 clo.command().getCounter() = 1}}, hasNext = false is not expected as far as new leader was supposed to return true for our scan command. That means that we've got {{isValid}} equal false for internal iterator {{RocksIterator}} of RocksDB. (see {{org.apache.ignite.internal.rocksdb.RocksIteratorAdapter#hasNext}}) {noformat} [14:34:42]W: 2022-02-07 14:34:42:780 +0300 [INFO][main][ItMixedQueriesTest] >>> Starting test: ItMixedQueriesTest#testOrderingByColumnOutsideSelectList, displayName: repetition 113 of 1000, workDir: /opt/buildagent/work/b8d4df1365f1f1e5/modules/runner/target/work/ItMixedQueriesTest/static_1644233560390 [14:34:43]W: 2022-02-07 14:34:43:076 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-AppendEntries-Processor-0][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3345 received AppendEntriesResponse from 172.17.0.6:3344 prevLogIndex=1010 prevLogTerm=1 count=1 fail, sleep, status=Status[ETIMEDOUT<1010>: RPC exception:null] [14:34:43]W: 2022-02-07 14:34:43:076 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-AppendEntries-Processor-0][Replicator] Blocking 172.17.0.6:3344 for 120 ms [14:34:43]W: 2022-02-07 14:34:43:077 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-AppendEntries-Processor-0][Replicator] Replicator Replicator [state=Probe, statInfo=<running=APPENDING_ENTRIES, firstLogIndex=1011, lastLogIncluded=0, lastLogIndex=1010, lastTermIncluded=0>, peerId=172.17.0.6:3344, type=Follower] is processing RPC responses, after processed, continue to send entries: false [14:34:43]W: 2022-02-07 14:34:43:077 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-AppendEntries-Processor-0][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3345 received HeartbeatResponse from 172.17.0.6:3344 prevLogIndex=1010 prevLogTerm=1 [14:34:43]W: 2022-02-07 14:34:43:092 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-AppendEntries-Processor-0][Replicator] Replicator Replicator [state=Probe, statInfo=<running=BLOCKING, firstLogIndex=1011, lastLogIncluded=0, lastLogIndex=1010, lastTermIncluded=0>, peerId=172.17.0.6:3344, type=Follower] ignored old version response 78, current version is 79, request is org.apache.ignite.raft.jraft.rpc.AppendEntriesRequestImpl@82dd5f83 [14:34:43]W: , and response is null [14:34:43]W: , status is Status[ETIMEDOUT<1010>: RPC exception:null]. [14:34:43]W: 2022-02-07 14:34:43:197 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-Common-Executor-13][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> send HeartbeatRequest to 172.17.0.6:3344 term 1 lastCommittedIndex 1010 [14:34:43]W: 2022-02-07 14:34:43:198 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-Common-Executor-8][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> send HeartbeatRequest to 172.17.0.6:3344 term 1 lastCommittedIndex 1010 [14:34:43]W: 2022-02-07 14:34:43:621 +0300 [WARNING][%ItMixedQueriesTest_null_1%JRaft-StepDownTimer-11][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> steps down when alive nodes don't satisfy quorum, term=1, deadNodes=172.17.0.6:3344, conf=172.17.0.6:3344,172.17.0.6:3345. [14:34:43]W: 2022-02-07 14:34:43:621 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-StepDownTimer-11][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> stepDown, term=1, newTerm=1, wakeupCandidate=false. [14:34:43]W: 2022-02-07 14:34:43:622 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-FSMCaller-Disruptor-_stripe_2-0][StateMachineAdapter] onLeaderStop: status=Status[ERAFTTIMEDOUT<10001>: Majority of the group dies: 1/2]. [14:34:43]W: 2022-02-07 14:34:43:622 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-StepDownTimer-11][Replicator] Replicator Replicator [state=Probe, statInfo=<running=APPENDING_ENTRIES, firstLogIndex=1011, lastLogIncluded=0, lastLogIndex=1010, lastTermIncluded=0>, peerId=172.17.0.6:3344, type=Follower] is going to quit [14:34:43]W: 2022-02-07 14:34:43:681 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:43]W: 2022-02-07 14:34:43:884 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:43]W: 2022-02-07 14:34:43:981 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:086 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:183 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:288 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:384 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:489 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:585 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:691 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:787 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:891 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:987 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:45]W: 2022-02-07 14:34:45:093 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:45]W: 2022-02-07 14:34:45:188 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:45]W: 2022-02-07 14:34:45:294 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:45]W: 2022-02-07 14:34:45:353 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-ElectionTimer-9][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> term 1 start preVote. [14:34:45]W: 2022-02-07 14:34:45:353 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-FSMCaller-Disruptor-_stripe_2-0][StateMachineAdapter] onStopFollowing: LeaderChangeContext [leaderId=172.17.0.6:3345, term=1, status=Status[ERAFTTIMEDOUT<10001>: Lost connection from leader 172.17.0.6:3345.]]. [14:34:45]W: 2022-02-07 14:34:45:354 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-82][PingRequestProcessor] Pinged from=172.17.0.6:3344 [14:34:45]W: 2022-02-07 14:34:45:361 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-83][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> received PreVoteRequest from 172.17.0.6:3344, term=2, currTerm=1, granted=true, requestLastLogId=LogId [index=1011, term=1], lastLogId=LogId [index=1011, term=1]. [14:34:45]W: 2022-02-07 14:34:45:362 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-1][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> received PreVoteResponse from 172.17.0.6:3345, term=1, granted=true. [14:34:45]W: 2022-02-07 14:34:45:362 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-1][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> start vote and grant vote self, term=1. [14:34:45]W: 2022-02-07 14:34:45:362 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-1][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> stop election timer, term=1. [14:34:45]W: 2022-02-07 14:34:45:362 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-1][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> start vote timer, term=2 . [14:34:45]W: 2022-02-07 14:34:45:363 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-84][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> received RequestVoteRequest from 172.17.0.6:3344, term=2, currTerm=1. [14:34:45]W: 2022-02-07 14:34:45:363 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-84][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> stepDown, term=1, newTerm=2, wakeupCandidate=false. [14:34:45]W: 2022-02-07 14:34:45:365 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-1][LocalRaftMetaStorage] Save raft meta, path=target/work/ItMixedQueriesTest/static_1644233560390/ItMixedQueriesTest_null_0/3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0_172.17.0.6_3344/meta, term=2, votedFor=172.17.0.6:3344, cost time=2 ms [14:34:45]W: 2022-02-07 14:34:45:365 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-84][LocalRaftMetaStorage] Save raft meta, path=target/work/ItMixedQueriesTest/static_1644233560390/ItMixedQueriesTest_null_1/3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0_172.17.0.6_3345/meta, term=2, votedFor=0.0.0.0:0, cost time=2 ms [14:34:45]W: 2022-02-07 14:34:45:365 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-84][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> stepDown, term=2, newTerm=2, wakeupCandidate=false. [14:34:45]W: 2022-02-07 14:34:45:375 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-84][LocalRaftMetaStorage] Save raft meta, path=target/work/ItMixedQueriesTest/static_1644233560390/ItMixedQueriesTest_null_1/3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0_172.17.0.6_3345/meta, term=2, votedFor=172.17.0.6:3344, cost time=9 ms [14:34:45]W: 2022-02-07 14:34:45:376 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-2][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> become leader of group, term=2, conf=172.17.0.6:3344,172.17.0.6:3345, oldConf=. [14:34:45]W: 2022-02-07 14:34:45:376 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-2][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> add a replicator, term=2, peer=172.17.0.6:3345. [14:34:45]W: 2022-02-07 14:34:45:376 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-2][Replicator] Replicator=Replicator [state=null, statInfo=<running=null, firstLogIndex=0, lastLogIncluded=0, lastLogIndex=0, lastTermIncluded=0>, peerId=172.17.0.6:3345, type=Follower]@172.17.0.6:3345 is started [14:34:45]W: 2022-02-07 14:34:45:376 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-2][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send HeartbeatRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1010 [14:34:45]W: 2022-02-07 14:34:45:379 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-AppendEntries-Processor-1][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> stepDown, term=2, newTerm=2, wakeupCandidate=false. [14:34:45]W: 2022-02-07 14:34:45:380 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-FSMCaller-Disruptor-_stripe_2-0][StateMachineAdapter] onStartFollowing: LeaderChangeContext [leaderId=172.17.0.6:3344, term=2, status=Status[ENEWLEADER<10011>: Follower receives message from new leader with the same term.]]. [14:34:45]W: 2022-02-07 14:34:45:380 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3344 received AppendEntriesResponse from 172.17.0.6:3345 prevLogIndex=1011 prevLogTerm=1 count=0, success [14:34:45]W: 2022-02-07 14:34:45:380 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicator Replicator [state=Probe, statInfo=<running=APPENDING_ENTRIES, firstLogIndex=1012, lastLogIncluded=0, lastLogIndex=1011, lastTermIncluded=0>, peerId=172.17.0.6:3345, type=Follower] is processing RPC responses, after processed, continue to send entries: true [14:34:45]W: 2022-02-07 14:34:45:381 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send AppendEntriesRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1010 prevLogIndex 1011 prevLogTerm 1 logIndex 1012 count 1 [14:34:45]W: 2022-02-07 14:34:45:381 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:389 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:45]W: 2022-02-07 14:34:45:394 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3344 received AppendEntriesResponse from 172.17.0.6:3345 prevLogIndex=1011 prevLogTerm=1 count=1, success [14:34:45]W: 2022-02-07 14:34:45:394 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][BallotBox] Committed log fromIndex=1012, toIndex=1012. [14:34:45]W: 2022-02-07 14:34:45:394 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicated logs in [1012, 1012] to peer 172.17.0.6:3345 [14:34:45]W: 2022-02-07 14:34:45:394 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicator Replicator [state=Replicate, statInfo=<running=IDLE, firstLogIndex=1012, lastLogIncluded=0, lastLogIndex=1012, lastTermIncluded=0>, peerId=172.17.0.6:3345, type=Follower] is processing RPC responses, after processed, continue to send entries: true [14:34:45]W: 2022-02-07 14:34:45:394 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:394 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-FSMCaller-Disruptor-_stripe_2-0][StateMachineAdapter] onLeaderStart: term=2. [14:34:45]W: 2022-02-07 14:34:45:496 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-6][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send AppendEntriesRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1012 prevLogIndex 1012 prevLogTerm 2 logIndex 1013 count 1 [14:34:45]W: 2022-02-07 14:34:45:496 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-6][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:497 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-7][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send HeartbeatRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1012 [14:34:45]W: 2022-02-07 14:34:45:497 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3344 received HeartbeatResponse from 172.17.0.6:3345 prevLogIndex=1012 prevLogTerm=2 [14:34:45]W: 2022-02-07 14:34:45:505 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3344 received AppendEntriesResponse from 172.17.0.6:3345 prevLogIndex=1012 prevLogTerm=2 count=1, success [14:34:45]W: 2022-02-07 14:34:45:505 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][BallotBox] Committed log fromIndex=1013, toIndex=1013. [14:34:45]W: 2022-02-07 14:34:45:505 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicated logs in [1013, 1013] to peer 172.17.0.6:3345 [14:34:45]W: 2022-02-07 14:34:45:505 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicator Replicator [state=Replicate, statInfo=<running=IDLE, firstLogIndex=1013, lastLogIncluded=0, lastLogIndex=1013, lastTermIncluded=0>, peerId=172.17.0.6:3345, type=Follower] is processing RPC responses, after processed, continue to send entries: true [14:34:45]W: 2022-02-07 14:34:45:505 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:507 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-8][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send AppendEntriesRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1013 prevLogIndex 1013 prevLogTerm 2 logIndex 1014 count 1 [14:34:45]W: 2022-02-07 14:34:45:507 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-8][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3344 received AppendEntriesResponse from 172.17.0.6:3345 prevLogIndex=1013 prevLogTerm=2 count=1, success [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][BallotBox] Committed log fromIndex=1014, toIndex=1014. [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicated logs in [1014, 1014] to peer 172.17.0.6:3345 [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicator Replicator [state=Replicate, statInfo=<running=IDLE, firstLogIndex=1014, lastLogIncluded=0, lastLogIndex=1014, lastTermIncluded=0>, peerId=172.17.0.6:3345, type=Follower] is processing RPC responses, after processed, continue to send entries: true [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-FSMCaller-Disruptor-_stripe_2-0][PartitionListener] internalBatchCounter = 0 clo.command().getCounter() = 1 [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-FSMCaller-Disruptor-_stripe_2-0][VersionedRowStore] called hasNext = false, cur = null [14:34:45]W: 2022-02-07 14:34:45:515 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-9][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send AppendEntriesRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1014 prevLogIndex 1014 prevLogTerm 2 logIndex 1015 count 1 [14:34:45]W: 2022-02-07 14:34:45:515 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-9][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:618 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-10][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send HeartbeatRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1014 [14:34:45]W: 2022-02-07 14:34:45:816 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-FSMCaller-Disruptor-_stripe_2-0][PartitionListener] internalBatchCounter = 0 clo.command().getCounter() = 1 [14:34:45]W: 2022-02-07 14:34:45:817 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-11][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send AppendEntriesRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1014 prevLogIndex 1015 prevLogTerm 2 logIndex 1016 count 1 [14:34:45]W: 2022-02-07 14:34:45:817 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-FSMCaller-Disruptor-_stripe_2-0][VersionedRowStore] called hasNext = true, cur = 1064766965 [14:34:45]W: 2022-02-07 14:34:45:817 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-FSMCaller-Disruptor-_stripe_2-0][VersionedRowStore] called next, cur = 1064766965 [14:34:45]W: 2022-02-07 14:34:45:817 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-11][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:819 +0300 [INFO][main][ItMixedQueriesTest] >>> Stopping test: ItMixedQueriesTest#testOrderingByColumnOutsideSelectList, displayName: repetition 113 of 1000, cost: 3039ms. {noformat} was (Author: maliev): We analysed debug logs from TC in and came up with possible ways of investigation: * Why we got {{ETIMEDOUT<1010>: RPC exception:null}}. Probably it entail further majority death {{[ERAFTTIMEDOUT<10001>: Majority of the group dies: 1/2]}} and stepping down of the leader. * In log we could see that we have several {{can't apply, status=Status[EPERM<1008>: Is not leader.]}} messages, which means that some task weren't applied to leaders log. Need to figure out what task weren't applied and check if we lost them completely. * In logs we can see {{called hasNext = false, cur = null}} which was logged after {{internalBatchCounter = 0 clo.command().getCounter() = 1}}, hasNext = false is not expected as far as new leader was supposed to return true for our scan command. That means that we've got {{isValid}} equal false for internal iterator {{RocksIterator}} of RocksDB. (see {{org.apache.ignite.internal.rocksdb.RocksIteratorAdapter#hasNext}}) {noformat} [14:34:42]W: 2022-02-07 14:34:42:780 +0300 [INFO][main][ItMixedQueriesTest] >>> Starting test: ItMixedQueriesTest#testOrderingByColumnOutsideSelectList, displayName: repetition 113 of 1000, workDir: /opt/buildagent/work/b8d4df1365f1f1e5/modules/runner/target/work/ItMixedQueriesTest/static_1644233560390 [14:34:43]W: 2022-02-07 14:34:43:076 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-AppendEntries-Processor-0][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3345 received AppendEntriesResponse from 172.17.0.6:3344 prevLogIndex=1010 prevLogTerm=1 count=1 fail, sleep, status=Status[ETIMEDOUT<1010>: RPC exception:null] [14:34:43]W: 2022-02-07 14:34:43:076 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-AppendEntries-Processor-0][Replicator] Blocking 172.17.0.6:3344 for 120 ms [14:34:43]W: 2022-02-07 14:34:43:077 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-AppendEntries-Processor-0][Replicator] Replicator Replicator [state=Probe, statInfo=<running=APPENDING_ENTRIES, firstLogIndex=1011, lastLogIncluded=0, lastLogIndex=1010, lastTermIncluded=0>, peerId=172.17.0.6:3344, type=Follower] is processing RPC responses, after processed, continue to send entries: false [14:34:43]W: 2022-02-07 14:34:43:077 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-AppendEntries-Processor-0][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3345 received HeartbeatResponse from 172.17.0.6:3344 prevLogIndex=1010 prevLogTerm=1 [14:34:43]W: 2022-02-07 14:34:43:092 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-AppendEntries-Processor-0][Replicator] Replicator Replicator [state=Probe, statInfo=<running=BLOCKING, firstLogIndex=1011, lastLogIncluded=0, lastLogIndex=1010, lastTermIncluded=0>, peerId=172.17.0.6:3344, type=Follower] ignored old version response 78, current version is 79, request is org.apache.ignite.raft.jraft.rpc.AppendEntriesRequestImpl@82dd5f83 [14:34:43]W: , and response is null [14:34:43]W: , status is Status[ETIMEDOUT<1010>: RPC exception:null]. [14:34:43]W: 2022-02-07 14:34:43:197 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-Common-Executor-13][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> send HeartbeatRequest to 172.17.0.6:3344 term 1 lastCommittedIndex 1010 [14:34:43]W: 2022-02-07 14:34:43:198 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-Common-Executor-8][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> send HeartbeatRequest to 172.17.0.6:3344 term 1 lastCommittedIndex 1010 [14:34:43]W: 2022-02-07 14:34:43:621 +0300 [WARNING][%ItMixedQueriesTest_null_1%JRaft-StepDownTimer-11][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> steps down when alive nodes don't satisfy quorum, term=1, deadNodes=172.17.0.6:3344, conf=172.17.0.6:3344,172.17.0.6:3345. [14:34:43]W: 2022-02-07 14:34:43:621 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-StepDownTimer-11][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> stepDown, term=1, newTerm=1, wakeupCandidate=false. [14:34:43]W: 2022-02-07 14:34:43:622 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-FSMCaller-Disruptor-_stripe_2-0][StateMachineAdapter] onLeaderStop: status=Status[ERAFTTIMEDOUT<10001>: Majority of the group dies: 1/2]. [14:34:43]W: 2022-02-07 14:34:43:622 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-StepDownTimer-11][Replicator] Replicator Replicator [state=Probe, statInfo=<running=APPENDING_ENTRIES, firstLogIndex=1011, lastLogIncluded=0, lastLogIndex=1010, lastTermIncluded=0>, peerId=172.17.0.6:3344, type=Follower] is going to quit [14:34:43]W: 2022-02-07 14:34:43:681 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:43]W: 2022-02-07 14:34:43:884 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:43]W: 2022-02-07 14:34:43:981 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:086 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:183 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:288 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:384 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:489 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:585 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:691 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:787 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:891 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:44]W: 2022-02-07 14:34:44:987 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:45]W: 2022-02-07 14:34:45:093 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:45]W: 2022-02-07 14:34:45:188 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:45]W: 2022-02-07 14:34:45:294 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:45]W: 2022-02-07 14:34:45:353 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-ElectionTimer-9][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> term 1 start preVote. [14:34:45]W: 2022-02-07 14:34:45:353 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-FSMCaller-Disruptor-_stripe_2-0][StateMachineAdapter] onStopFollowing: LeaderChangeContext [leaderId=172.17.0.6:3345, term=1, status=Status[ERAFTTIMEDOUT<10001>: Lost connection from leader 172.17.0.6:3345.]]. [14:34:45]W: 2022-02-07 14:34:45:354 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-82][PingRequestProcessor] Pinged from=172.17.0.6:3344 [14:34:45]W: 2022-02-07 14:34:45:361 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-83][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> received PreVoteRequest from 172.17.0.6:3344, term=2, currTerm=1, granted=true, requestLastLogId=LogId [index=1011, term=1], lastLogId=LogId [index=1011, term=1]. [14:34:45]W: 2022-02-07 14:34:45:362 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-1][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> received PreVoteResponse from 172.17.0.6:3345, term=1, granted=true. [14:34:45]W: 2022-02-07 14:34:45:362 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-1][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> start vote and grant vote self, term=1. [14:34:45]W: 2022-02-07 14:34:45:362 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-1][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> stop election timer, term=1. [14:34:45]W: 2022-02-07 14:34:45:362 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-1][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> start vote timer, term=2 . [14:34:45]W: 2022-02-07 14:34:45:363 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-84][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> received RequestVoteRequest from 172.17.0.6:3344, term=2, currTerm=1. [14:34:45]W: 2022-02-07 14:34:45:363 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-84][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> stepDown, term=1, newTerm=2, wakeupCandidate=false. [14:34:45]W: 2022-02-07 14:34:45:365 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-1][LocalRaftMetaStorage] Save raft meta, path=target/work/ItMixedQueriesTest/static_1644233560390/ItMixedQueriesTest_null_0/3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0_172.17.0.6_3344/meta, term=2, votedFor=172.17.0.6:3344, cost time=2 ms [14:34:45]W: 2022-02-07 14:34:45:365 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-84][LocalRaftMetaStorage] Save raft meta, path=target/work/ItMixedQueriesTest/static_1644233560390/ItMixedQueriesTest_null_1/3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0_172.17.0.6_3345/meta, term=2, votedFor=0.0.0.0:0, cost time=2 ms [14:34:45]W: 2022-02-07 14:34:45:365 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-84][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> stepDown, term=2, newTerm=2, wakeupCandidate=false. [14:34:45]W: 2022-02-07 14:34:45:375 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-Request-Processor-84][LocalRaftMetaStorage] Save raft meta, path=target/work/ItMixedQueriesTest/static_1644233560390/ItMixedQueriesTest_null_1/3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0_172.17.0.6_3345/meta, term=2, votedFor=172.17.0.6:3344, cost time=9 ms [14:34:45]W: 2022-02-07 14:34:45:376 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-2][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> become leader of group, term=2, conf=172.17.0.6:3344,172.17.0.6:3345, oldConf=. [14:34:45]W: 2022-02-07 14:34:45:376 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-2][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> add a replicator, term=2, peer=172.17.0.6:3345. [14:34:45]W: 2022-02-07 14:34:45:376 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-2][Replicator] Replicator=Replicator [state=null, statInfo=<running=null, firstLogIndex=0, lastLogIncluded=0, lastLogIndex=0, lastTermIncluded=0>, peerId=172.17.0.6:3345, type=Follower]@172.17.0.6:3345 is started [14:34:45]W: 2022-02-07 14:34:45:376 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Response-Processor-2][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send HeartbeatRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1010 [14:34:45]W: 2022-02-07 14:34:45:379 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-AppendEntries-Processor-1][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> stepDown, term=2, newTerm=2, wakeupCandidate=false. [14:34:45]W: 2022-02-07 14:34:45:380 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-FSMCaller-Disruptor-_stripe_2-0][StateMachineAdapter] onStartFollowing: LeaderChangeContext [leaderId=172.17.0.6:3344, term=2, status=Status[ENEWLEADER<10011>: Follower receives message from new leader with the same term.]]. [14:34:45]W: 2022-02-07 14:34:45:380 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3344 received AppendEntriesResponse from 172.17.0.6:3345 prevLogIndex=1011 prevLogTerm=1 count=0, success [14:34:45]W: 2022-02-07 14:34:45:380 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicator Replicator [state=Probe, statInfo=<running=APPENDING_ENTRIES, firstLogIndex=1012, lastLogIncluded=0, lastLogIndex=1011, lastTermIncluded=0>, peerId=172.17.0.6:3345, type=Follower] is processing RPC responses, after processed, continue to send entries: true [14:34:45]W: 2022-02-07 14:34:45:381 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send AppendEntriesRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1010 prevLogIndex 1011 prevLogTerm 1 logIndex 1012 count 1 [14:34:45]W: 2022-02-07 14:34:45:381 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:389 +0300 [DEBUG][%ItMixedQueriesTest_null_1%JRaft-NodeImpl-Disruptor-_stripe_2-0][NodeImpl] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3345> can't apply, status=Status[EPERM<1008>: Is not leader.]. [14:34:45]W: 2022-02-07 14:34:45:394 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3344 received AppendEntriesResponse from 172.17.0.6:3345 prevLogIndex=1011 prevLogTerm=1 count=1, success [14:34:45]W: 2022-02-07 14:34:45:394 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][BallotBox] Committed log fromIndex=1012, toIndex=1012. [14:34:45]W: 2022-02-07 14:34:45:394 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicated logs in [1012, 1012] to peer 172.17.0.6:3345 [14:34:45]W: 2022-02-07 14:34:45:394 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicator Replicator [state=Replicate, statInfo=<running=IDLE, firstLogIndex=1012, lastLogIncluded=0, lastLogIndex=1012, lastTermIncluded=0>, peerId=172.17.0.6:3345, type=Follower] is processing RPC responses, after processed, continue to send entries: true [14:34:45]W: 2022-02-07 14:34:45:394 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:394 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-FSMCaller-Disruptor-_stripe_2-0][StateMachineAdapter] onLeaderStart: term=2. [14:34:45]W: 2022-02-07 14:34:45:496 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-6][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send AppendEntriesRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1012 prevLogIndex 1012 prevLogTerm 2 logIndex 1013 count 1 [14:34:45]W: 2022-02-07 14:34:45:496 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-6][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:497 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-7][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send HeartbeatRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1012 [14:34:45]W: 2022-02-07 14:34:45:497 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3344 received HeartbeatResponse from 172.17.0.6:3345 prevLogIndex=1012 prevLogTerm=2 [14:34:45]W: 2022-02-07 14:34:45:505 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3344 received AppendEntriesResponse from 172.17.0.6:3345 prevLogIndex=1012 prevLogTerm=2 count=1, success [14:34:45]W: 2022-02-07 14:34:45:505 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][BallotBox] Committed log fromIndex=1013, toIndex=1013. [14:34:45]W: 2022-02-07 14:34:45:505 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicated logs in [1013, 1013] to peer 172.17.0.6:3345 [14:34:45]W: 2022-02-07 14:34:45:505 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicator Replicator [state=Replicate, statInfo=<running=IDLE, firstLogIndex=1013, lastLogIncluded=0, lastLogIndex=1013, lastTermIncluded=0>, peerId=172.17.0.6:3345, type=Follower] is processing RPC responses, after processed, continue to send entries: true [14:34:45]W: 2022-02-07 14:34:45:505 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:507 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-8][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send AppendEntriesRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1013 prevLogIndex 1013 prevLogTerm 2 logIndex 1014 count 1 [14:34:45]W: 2022-02-07 14:34:45:507 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-8][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node 3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0:172.17.0.6:3344 received AppendEntriesResponse from 172.17.0.6:3345 prevLogIndex=1013 prevLogTerm=2 count=1, success [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][BallotBox] Committed log fromIndex=1014, toIndex=1014. [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicated logs in [1014, 1014] to peer 172.17.0.6:3345 [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Replicator Replicator [state=Replicate, statInfo=<running=IDLE, firstLogIndex=1014, lastLogIncluded=0, lastLogIndex=1014, lastTermIncluded=0>, peerId=172.17.0.6:3345, type=Follower] is processing RPC responses, after processed, continue to send entries: true [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-AppendEntries-Processor-1][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-FSMCaller-Disruptor-_stripe_2-0][PartitionListener] internalBatchCounter = 0 clo.command().getCounter() = 1 [14:34:45]W: 2022-02-07 14:34:45:513 +0300 [INFO][%ItMixedQueriesTest_null_0%JRaft-FSMCaller-Disruptor-_stripe_2-0][VersionedRowStore] called hasNext = false, cur = null [14:34:45]W: 2022-02-07 14:34:45:515 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-9][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send AppendEntriesRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1014 prevLogIndex 1014 prevLogTerm 2 logIndex 1015 count 1 [14:34:45]W: 2022-02-07 14:34:45:515 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-9][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:618 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-10][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send HeartbeatRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1014 [14:34:45]W: 2022-02-07 14:34:45:816 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-FSMCaller-Disruptor-_stripe_2-0][PartitionListener] internalBatchCounter = 0 clo.command().getCounter() = 1 [14:34:45]W: 2022-02-07 14:34:45:817 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-11][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> send AppendEntriesRequest to 172.17.0.6:3345 term 2 lastCommittedIndex 1014 prevLogIndex 1015 prevLogTerm 2 logIndex 1016 count 1 [14:34:45]W: 2022-02-07 14:34:45:817 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-FSMCaller-Disruptor-_stripe_2-0][VersionedRowStore] called hasNext = true, cur = 1064766965 [14:34:45]W: 2022-02-07 14:34:45:817 +0300 [INFO][%ItMixedQueriesTest_null_1%JRaft-FSMCaller-Disruptor-_stripe_2-0][VersionedRowStore] called next, cur = 1064766965 [14:34:45]W: 2022-02-07 14:34:45:817 +0300 [DEBUG][%ItMixedQueriesTest_null_0%JRaft-Common-Executor-11][Replicator] Node <3-74778f80-6cef-40db-82ae-5636e926a8ad_part_0/172.17.0.6:3344> waits more entries [14:34:45]W: 2022-02-07 14:34:45:819 +0300 [INFO][main][ItMixedQueriesTest] >>> Stopping test: ItMixedQueriesTest#testOrderingByColumnOutsideSelectList, displayName: repetition 113 of 1000, cost: 3039ms. {noformat} > RocksDB returns unexpected cursor.hasNext equals false after leader is changed > ------------------------------------------------------------------------------ > > Key: IGNITE-16478 > URL: https://issues.apache.org/jira/browse/IGNITE-16478 > Project: Ignite > Issue Type: Bug > Reporter: Mirza Aliev > Priority: Major > Labels: ignite-3 > > After investigation of https://issues.apache.org/jira/browse/IGNITE-16406 we > found a bug in {{PartitionListener#handleScanRetrieveBatchCommand}} when > leader is changed. In some case, {{cursorDesc.cursor().hasNext()}} returns > false, hence select operation return empty response, but should response > several rows. > Investigation showed that cursor that is returned from > {{RocksDbPartitionStorage#scan}} > is inconsistent after leader changing because its hasNext returns unexpected > false. > Further investigation is needed. -- This message was sent by Atlassian Jira (v8.20.1#820001)