handle_append_entries_resp() declined append

[kishorekrd]

I am using release 2.0. I am seeing this issue, Leader is showing " handle_append_entries_resp() declined append" message. Follower is continuously getting duplicate append entry.

I see an old fix #227 for this , but its already there in Release 2.0.

Here is the log

` Leader, Node 2:

I230808 00:14:19.775986 17437 [nuraft_w_0] src/asio_service.cxx:830 handle_accept() receive a incoming rpc connection I230808 00:14:19.776027 17438 [nuraft_w_0] src/asio_service.cxx:259 prepare_handshake() session 6 got connection from 10.92.2.5:51146 (as a server) I230808 00:14:19.776248 17439 [nuraft_w_0] src/handle_vote.cxx:398 handle_prevote_req() [PRE-VOTE REQ] my role leader, from peer 0, log term: req 6 / mine 7 I230808 00:14:19.776248 17439 [nuraft_w_0] src/handle_vote.cxx:398 handle_prevote_req() +last idx: req 4368 / mine 4559, term: req 6 / mine 7 I230808 00:14:19.776248 17439 [nuraft_w_0] src/handle_vote.cxx:398 handle_prevote_req() +HB alive I230808 00:14:19.776275 17440 [nuraft_w_0] src/handle_vote.cxx:429 handle_prevote_req() pre-vote decision: X (deny) I230808 00:14:22.037955 17443 [nuraft_w_0] src/handle_vote.cxx:398 handle_prevote_req() [PRE-VOTE REQ] my role leader, from peer 0, log term: req 6 / mine 7 I230808 00:14:22.037955 17443 [nuraft_w_0] src/handle_vote.cxx:398 handle_prevote_req() +last idx: req 4368 / mine 4559, term: req 6 / mine 7 I230808 00:14:22.037955 17443 [nuraft_w_0] src/handle_vote.cxx:398 handle_prevote_req() +HB alive I230808 00:14:22.037991 17444 [nuraft_w_0] src/handle_vote.cxx:429 handle_prevote_req() pre-vote decision: X (deny) I230808 00:14:23.746224 17447 [nuraft_w_0] src/asio_service.cxx:1309 connected() 0x7f2f2e807710 connected to 10.92.8.47:5593 (as a client) W230808 00:14:23.763125 17448 [nuraft_w_0] src/handle_append_entries.cxx:948 handle_append_entries_resp() declined append: peer 0, prev next log idx 4560, resp next 4369, new next log idx 4369 W230808 00:14:23.763541 17449 [nuraft_w_0] src/handle_append_entries.cxx:242 request_append_entries() recovered from long pause to peer 0, 38 warnings, 1045 ms, 1 times W230808 00:14:23.778410 17450 [nuraft_w_0] src/raft_server.cxx:817 handle_peer_resp() recovered from RPC failure from peer 0, 23 errors

I230808 00:14:23.778502 17451 [nuraft_w_0] server.cc:539 raft_callback() Marking peer live. myId 2 leaderId 2 peerId 0 I230808 00:14:23.778516 17452 [nuraft_w_0] server.cc:192 system_config_online_node() Set Node 0 to online

W230808 00:14:24.067998 17453 [nuraft_w_0] src/handle_append_entries.cxx:296 request_append_entries() skipped sending msg to 0 too long time, last msg sent 55 ms ago W230808 00:14:24.118162 17454 [nuraft_w_0] src/handle_append_entries.cxx:296 request_append_entries() skipped sending msg to 0 too long time, last msg sent 106 ms ago W230808 00:14:24.168330 17455 [nuraft_w_0] src/handle_append_entries.cxx:296 request_append_entries() skipped sending msg to 0 too long time, last msg sent 156 ms ago W230808 00:14:24.208674 17456 [nuraft_w_0] src/raft_server.cxx:780 handle_peer_resp() peer (0) response error: failed to read response to peer 0, 10.92.8.47:5593, error 2, End of file E230808 00:14:24.208962 17457 [nuraft_w_0] src/asio_service.cxx:326 operator()() session 6 failed to read rpc header from socket 10.92.2.5:51146 due to error 2, End of file, ref count 1 W230808 00:14:24.218967 17458 [nuraft_w_0] src/raft_server.cxx:780 handle_peer_resp() peer (0) response error: failed to connect to peer 0, 10.92.8.47:5593, error 111, Connection refused W230808 00:14:24.319220 17460 [nuraft_w_0] src/raft_server.cxx:780 handle_peer_resp() peer (0) response error: failed to connect to peer 0, 10.92.8.47:5593, error 111, Connection refused W230808 00:14:24.469375 17461 [nuraft_w_0] src/raft_server.cxx:780 handle_peer_resp() peer (0) response error: failed to connect to peer 0, 10.92.8.47:5593, error 111, Connection refused W230808 00:14:24.669604 17462 [nuraft_w_0] src/raft_server.cxx:780 handle_peer_resp() peer (0) response error: failed to connect to peer 0, 10.92.8.47:5593, error 111, Connection refused W230808 00:14:24.919792 17463 [nuraft_w_0] src/raft_server.cxx:780 handle_peer_resp() peer (0) response error: failed to connect to peer 0, 10.92.8.47:5593, error 111, Connection refused W230808 00:14:25.219977 17464 [nuraft_w_0] src/raft_server.cxx:780 handle_peer_resp() peer (0) response error: failed to connect to peer 0, 10.92.8.47:5593, error 111, Connection refused

Follower, Node 0:

W230808 00:14:22.026652 309 [nuraft_w_0] src/handle_timeout.cxx:286 handle_election_timeout() Election timeout, initiate leader election I230808 00:14:22.026755 310 [nuraft_w_0] src/handle_priority.cxx:213 decay_target_priority() [PRIORITY] decay, target 1 -> 1, mine 1 I230808 00:14:22.026793 311 [nuraft_w_0] src/handle_timeout.cxx:299 handle_election_timeout() [ELECTION TIMEOUT] current role: candidate, log last term 6, state term 6, target p 1, my p 1, hb dead, pre-vote NOT done I230808 00:14:22.026821 312 [nuraft_w_0] src/handle_vote.cxx:134 request_prevote() [PRE-VOTE INIT] my id 0, my role candidate, term 6, log idx 4368, log term 6, priority (target 1 / mine 1) I230808 00:14:22.027331 313 [nuraft_w_0] src/handle_vote.cxx:465 handle_prevote_resp() [PRE-VOTE RESP] peer 2 (X), term 6, resp term 6, my role candidate, dead 1, live 1, abandoned 0, num voting members 3, quorum 2 I230808 00:14:22.027382 314 [nuraft_w_0] src/handle_vote.cxx:465 handle_prevote_resp() [PRE-VOTE RESP] peer 1 (X), term 6, resp term 6, my role candidate, dead 1, live 2, abandoned 0, num voting members 3, quorum 2 W230808 00:14:22.027398 315 [nuraft_w_0] src/handle_vote.cxx:497 handle_prevote_resp() [PRE-VOTE] rejected by quorum, count 2 I230808 00:14:23.735481 324 [nuraft_w_0] src/asio_service.cxx:830 handle_accept() receive a incoming rpc connection I230808 00:14:23.735537 325 [nuraft_w_0] src/asio_service.cxx:259 prepare_handshake() session 1 got connection from 10.92.0.29:57608 (as a server) I230808 00:14:23.751864 327 [nuraft_w_0] src/raft_server.cxx:1295 become_follower() [BECOME FOLLOWER] term 7

raft_callback() raft_callback Node id 0 BecomeFollower

W230808 00:14:23.751945 329 [nuraft_w_0] src/handle_append_entries.cxx:570 handle_append_entries() [LOG XX] req log idx: 4559, req log term: 7, my last log idx: 4368, my log (4559) term: 0 W230808 00:14:23.751987 330 [nuraft_w_0] src/handle_append_entries.cxx:582 handle_append_entries() deny, req term 7, my term 7, req log idx 4559, my log idx 4368 W230808 00:14:23.754062 331 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754125 332 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754170 333 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754213 334 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754257 335 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754303 336 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754347 337 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754391 338 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754435 339 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754489 340 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754535 341 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754579 342 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754628 343 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1 W230808 00:14:23.754673 344 [nuraft_w_0] log_store.cc:176 append() Got duplicate raft log entry, start_idx_ 1 idx 4369 logs_->size() 4369 term 6 type 1

Continued forever ...

`

[greensky00]

W230808 00:14:23.751987 330 [nuraft_w_0] src/handle_append_entries.cxx:582 handle_append_entries() deny, req term 7, my term 7, req log idx 4559, my log idx 4368

This log means your log store reported that your last log index is 4368, so leader sent 4369. But your log store complained 4369 is duplicate. You may need to investigate whether your next_slot() returns the correct log index.