[
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:13 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 tasks 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 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}
> 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)
