Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Follower keep rejecting MsgAppend from leader #428

Closed
whfuyn opened this issue Apr 14, 2021 · 10 comments · Fixed by cita-cloud/consensus_raft#18
Closed

Follower keep rejecting MsgAppend from leader #428

whfuyn opened this issue Apr 14, 2021 · 10 comments · Fixed by cita-cloud/consensus_raft#18
Labels
Question A question to be answered.

Comments

@whfuyn
Copy link

whfuyn commented Apr 14, 2021

Hi, I encounter a problem that a follower(the old leader) keep rejecting MsgAppend from the new leader.

There are three peers, peer_1, peer_2, peer_3.

  1. peer_2 is the leader at term 15 in the begining.
  2. Some network issue happened.
  3. peer_3 become candidate, requests votes from peer_1 and peer_2.
  4. peer_1 votes for peer_3, peer_3 become leader at term 16.
  5. During the election process, peer_2 as the raft: Avoid scanning raft log in become_leader #15 leader, appended an entry (index 3827, term 15).
  6. peer_2 receives msg of higher term, becomes follower at term 16.
  7. peer_3 tries to append entry (index 3827, term 16) to peer_2.
  8. peer_2 found conflict at index 3827 (conflicting term 16, existing term 15).
  9. peer_3 tries to append entry (index 3828, term 16) to peer_2, but peer_2 reject it because term mismatch at index 3827 (conflicting term 16, existing term 15).
  10. peer_3 keeps appending these two entries to peer_2:
    • (log_term: 15 index: 3826 entries {term: 16 index: 3827}), which is ignored for lower than committed.
    • (log_term: 16 index: 3827 entries {term: 16 index: 3828}), which is rejected for mismatched term.
  11. peer_2 get stuck, but the consensus is still going within peer_1 and peer_3

It looks like the old entry (index 3827 term 15) in peer_2 isn't overwritten by new leader's MsgAppend.

This issue happened several times after updating raft-rs in master branch from six months ago to latest.

I've updated my ready handling and storage implementation according to the latest five_mem_node example and recent commits,
and no peers were restarted during the whole time.

The raft-rs I used is the latest master branch with rev a5423b241ed641ca0941c816153a9dfc0fdbfad9.

I'm not sure if it's a problem of my implementation or not. Can someone help me with it?

@whfuyn
Copy link
Author

whfuyn commented Apr 14, 2021

peer_1's log

Apr 08 20:15:10.004 DEBG Sending from 1 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:10.605 DEBG Sending from 1 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:11.553 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2 index: 3826 commit: 3825, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:11.679 DEBG persisted index 3826, raft_id: 1, tag: peer_1
Apr 08 20:15:11.680 DEBG Sending from 1 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:11.680 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2 index: 3826 commit: 3826, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:11.680 INFO commiting proposal, entry: 0000000000000edbe8a28b3f32b5d8ecdbb9241b6c773a14b1ab631b38abcf8ce57c5147eeda68040000000000000000000000000000000000000000000000000000000000000000, tag: peer_1
Apr 08 20:15:19.058 INFO received a message with higher term from 3, msg type: MsgRequestVote, message_term: 16, term: 15, from: 3, raft_id: 1, tag: peer_1
Apr 08 20:15:19.080 DEBG reset election timeout 45 -> 55 at 39, election_elapsed: 39, timeout: 55, prev_timeout: 45, raft_id: 1, tag: peer_1
Apr 08 20:15:19.080 INFO became follower at term 16, term: 16, raft_id: 1, tag: peer_1
Apr 08 20:15:19.080 INFO [logterm: 15, index: 3826, vote: 0] cast vote for 3 [logterm: 15, index: 3826] at term 16, msg type: MsgRequestVote, term: 16, msg_index: 3826, msg_term: 15, from: 3, vote: 0, log_index: 3826, log_term: 15, raft_id: 1, tag: peer_1
Apr 08 20:15:19.081 DEBG Sending from 1 to 3, msg: msg_type: MsgRequestVoteResponse to: 3 term: 16, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.251 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.260 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.261 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.261 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.262 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.262 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.262 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.262 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.263 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.263 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.264 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.265 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.399 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.400 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.400 DEBG Sending from 1 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.400 DEBG Sending from 1 to 3, msg: msg_type: MsgAppendResponse to: 3 index: 3827 commit: 3826, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.509 DEBG persisted index 3827, raft_id: 1, tag: peer_1
Apr 08 20:15:19.522 DEBG Sending from 1 to 3, msg: msg_type: MsgAppendResponse to: 3 index: 3827 commit: 3827, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.841 DEBG Sending from 1 to 3, msg: msg_type: MsgAppendResponse to: 3 index: 3828 commit: 3827, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.917 DEBG persisted index 3828, raft_id: 1, tag: peer_1
Apr 08 20:15:19.917 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3827, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.930 DEBG Sending from 1 to 3, msg: msg_type: MsgAppendResponse to: 3 index: 3828 commit: 3827, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.932 DEBG Sending from 1 to 3, msg: msg_type: MsgAppendResponse to: 3 index: 3828 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:19.932 INFO commiting proposal, entry: 0000000000000edc0b2759ec3147f3167049f1b3e76df4179dcffed782a212816acad49e43980a0a0000000000000000000000000000000000000000000000000000000000000000, tag: peer_1
Apr 08 20:15:20.411 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:21.015 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:21.611 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:22.213 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:22.811 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:23.412 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:24.012 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:24.612 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:25.211 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:26.292 DEBG Sending from 1 to 3, msg: msg_type: MsgAppendResponse to: 3 index: 3829 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:26.402 DEBG persisted index 3829, raft_id: 1, tag: peer_1
Apr 08 20:15:26.402 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:26.411 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3828, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:26.413 DEBG Sending from 1 to 3, msg: msg_type: MsgAppendResponse to: 3 index: 3829 commit: 3829, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:26.436 INFO commiting proposal, entry: 0000000000000edd162291d906bc84e9c2af8613ddaeb76e5b98010869a8e6ab1067e92dbbd090280000000000000000000000000000000000000000000000000000000000000000, tag: peer_1
Apr 08 20:15:27.416 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3829, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:27.614 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3829, to: 3, from: 1, raft_id: 1, tag: peer_1
Apr 08 20:15:28.214 DEBG Sending from 1 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3829, to: 3, from: 1, raft_id: 1, tag: peer_1

@whfuyn
Copy link
Author

whfuyn commented Apr 14, 2021

peer_2's log

Apr 08 20:15:11.137 DEBG Sending from 2 to 1, msg: msg_type: MsgAppend to: 1 log_term: 15 index: 3825 entries {term: 15 index: 3826 data: "\000\000\000\000\000\000\016\333\350\242\213?2\265\330\354\333\271$\033lw:\024\261\253c\0338\253\317\214\345|QG\356\332h\004\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3825, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:11.138 DEBG Sending from 2 to 3, msg: msg_type: MsgAppend to: 3 log_term: 15 index: 3825 entries {term: 15 index: 3826 data: "\000\000\000\000\000\000\016\333\350\242\213?2\265\330\354\333\271$\033lw:\024\261\253c\0338\253\317\214\345|QG\356\332h\004\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3825, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:11.362 DEBG persisted index 3826, raft_id: 2, tag: peer_2
Apr 08 20:15:11.363 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3825, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:11.363 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3825, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:11.364 DEBG committing index 3826, index: 3826, raft_id: 2, tag: peer_2
Apr 08 20:15:11.364 DEBG Sending from 2 to 1, msg: msg_type: MsgAppend to: 1 log_term: 15 index: 3826 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:11.364 DEBG Sending from 2 to 3, msg: msg_type: MsgAppend to: 3 log_term: 15 index: 3826 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:11.364 INFO commiting proposal, entry: 0000000000000edbe8a28b3f32b5d8ecdbb9241b6c773a14b1ab631b38abcf8ce57c5147eeda68040000000000000000000000000000000000000000000000000000000000000000, tag: peer_2
Apr 08 20:15:18.980 DEBG Sending from 2 to 1, msg: msg_type: MsgAppend to: 1 log_term: 15 index: 3826 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.031 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.031 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.031 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.032 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.032 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.032 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.032 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.033 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.033 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.033 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.034 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.034 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.034 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.034 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.035 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.035 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.035 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.035 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.036 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.036 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.036 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.036 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.037 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.037 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.037 DEBG Sending from 2 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.037 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeat to: 3 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.054 INFO [logterm: 15, index: 3826, vote: 2] ignored vote from 3 [logterm: 15, index: 3826]: lease is not expired, msg type: MsgRequestVote, remaining ticks: 21, term: 15, msg_index: 3826, msg_term: 15, from: 3, vote: 2, log_index: 3826, log_term: 15, raft_id: 2, tag: peer_2
Apr 08 20:15:19.167 INFO propose, hash: 0000000000000edc7a6a604f76ad20c80276d6cf006dfc81ab511612afb20e55d38318c033058edc0000000000000000000000000000000000000000000000000000000000000000, tag: peer_2
Apr 08 20:15:19.168 DEBG Sending from 2 to 1, msg: msg_type: MsgAppend to: 1 log_term: 15 index: 3826 entries {term: 15 index: 3827 data: "\000\000\000\000\000\000\016\334zj`Ov\255 \310\002v\326\317\000m\374\201\253Q\026\022\257\262\016U\323\203\030\3003\005\216\334\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3826, to: 1, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.168 DEBG Sending from 2 to 3, msg: msg_type: MsgAppend to: 3 log_term: 15 index: 3826 entries {term: 15 index: 3827 data: "\000\000\000\000\000\000\016\334zj`Ov\255 \310\002v\326\317\000m\374\201\253Q\026\022\257\262\016U\323\203\030\3003\005\216\334\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.249 DEBG persisted index 3827, raft_id: 2, tag: peer_2
Apr 08 20:15:19.255 INFO received a message with higher term from 1, msg type: MsgAppendResponse, message_term: 16, term: 15, from: 1, raft_id: 2, tag: peer_2
Apr 08 20:15:19.256 DEBG reset election timeout 53 -> 47 at 10, election_elapsed: 10, timeout: 47, prev_timeout: 53, raft_id: 2, tag: peer_2
Apr 08 20:15:19.256 INFO became follower at term 16, term: 16, raft_id: 2, tag: peer_2
Apr 08 20:15:19.353 INFO found conflict at index 3827, conflicting term: 16, existing term: 15, index: 3827, raft_id: 2, tag: peer_2
Apr 08 20:15:19.353 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 index: 3827 commit: 3826, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.545 DEBG rejected msgApp [logterm: 16, index: 3827] from 3, logterm: Ok(15), index: 3827, from: 3, msg_index: 3827, msg_log_term: 16, raft_id: 2, tag: peer_2
Apr 08 20:15:19.546 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 log_term: 15 index: 3827 commit: 3826 reject: true reject_hint: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.821 DEBG rejected msgApp [logterm: 16, index: 3827] from 3, logterm: Ok(15), index: 3827, from: 3, msg_index: 3827, msg_log_term: 16, raft_id: 2, tag: peer_2
Apr 08 20:15:19.821 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 log_term: 15 index: 3827 commit: 3826 reject: true reject_hint: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.859 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.932 DEBG rejected msgApp [logterm: 16, index: 3828] from 3, logterm: Ok(0), index: 3828, from: 3, msg_index: 3828, msg_log_term: 16, raft_id: 2, tag:peer_2
Apr 08 20:15:19.932 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 log_term: 15 index: 3828 commit: 3827 reject: true reject_hint: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.935 DEBG rejected msgApp [logterm: 16, index: 3828] from 3, logterm: Ok(0), index: 3828, from: 3, msg_index: 3828, msg_log_term: 16, raft_id: 2, tag:peer_2
Apr 08 20:15:19.935 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 log_term: 15 index: 3828 commit: 3827 reject: true reject_hint: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.957 DEBG rejected msgApp [logterm: 16, index: 3827] from 3, logterm: Ok(15), index: 3827, from: 3, msg_index: 3827, msg_log_term: 16, raft_id: 2, tag: peer_2
Apr 08 20:15:19.957 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 log_term: 15 index: 3827 commit: 3827 reject: true reject_hint: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:19.997 DEBG got message with lower index than committed., raft_id: 2, tag: peer_2
Apr 08 20:15:19.997 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 index: 3827 commit: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:20.414 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:20.426 DEBG rejected msgApp [logterm: 16, index: 3827] from 3, logterm: Ok(15), index: 3827, from: 3, msg_index: 3827, msg_log_term: 16, raft_id: 2, tag: peer_2
Apr 08 20:15:20.476 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 log_term: 15 index: 3827 commit: 3827 reject: true reject_hint: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:20.476 DEBG got message with lower index than committed., raft_id: 2, tag: peer_2
Apr 08 20:15:20.477 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 index: 3827 commit: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:21.017 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:21.031 DEBG rejected msgApp [logterm: 16, index: 3827] from 3, logterm: Ok(15), index: 3827, from: 3, msg_index: 3827, msg_log_term: 16, raft_id: 2, tag: peer_2
Apr 08 20:15:21.031 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 log_term: 15 index: 3827 commit: 3827 reject: true reject_hint: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:21.043 DEBG got message with lower index than committed., raft_id: 2, tag: peer_2
Apr 08 20:15:21.043 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 index: 3827 commit: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:21.612 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:21.626 DEBG rejected msgApp [logterm: 16, index: 3827] from 3, logterm: Ok(15), index: 3827, from: 3, msg_index: 3827, msg_log_term: 16, raft_id: 2, tag: peer_2
Apr 08 20:15:21.626 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 log_term: 15 index: 3827 commit: 3827 reject: true reject_hint: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:21.634 DEBG got message with lower index than committed., raft_id: 2, tag: peer_2
Apr 08 20:15:21.635 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 index: 3827 commit: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:22.217 DEBG Sending from 2 to 3, msg: msg_type: MsgHeartbeatResponse to: 3 commit: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:22.243 DEBG rejected msgApp [logterm: 16, index: 3827] from 3, logterm: Ok(15), index: 3827, from: 3, msg_index: 3827, msg_log_term: 16, raft_id: 2, tag: peer_2
Apr 08 20:15:22.243 DEBG Sending from 2 to 3, msg: msg_type: MsgAppendResponse to: 3 log_term: 15 index: 3827 commit: 3827 reject: true reject_hint: 3827, to: 3, from: 2, raft_id: 2, tag: peer_2
Apr 08 20:15:22.243 DEBG got message with lower index than committed., raft_id: 2, tag: peer_2

@whfuyn
Copy link
Author

whfuyn commented Apr 14, 2021

peer_3's log


Apr 08 20:15:01.607 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3824, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:02.208 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3824, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:02.806 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3824, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:03.409 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3824, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:03.840 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2 index: 3825 commit: 3824, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:03.842 DEBG persisted index 3825, raft_id: 3, tag: peer_3
Apr 08 20:15:03.995 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2 index: 3825 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:03.996 INFO commiting proposal, entry: 0000000000000eda203dbee1b43e5631ca21fa893b5056abf71ba82aafee9d8ad707fb1e8ea0a5030000000000000000000000000000000000000000000000000000000000000000, tag: peer_3
Apr 08 20:15:05.338 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:05.342 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:05.343 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:05.808 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:06.409 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:07.008 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:07.607 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:08.208 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:08.807 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:09.407 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:10.007 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:10.608 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:11.248 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2 index: 3826 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:11.251 DEBG persisted index 3826, raft_id: 3, tag: peer_3
Apr 08 20:15:11.370 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeatResponse to: 2 commit: 3825, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:11.375 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2 index: 3826 commit: 3826, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:11.377 INFO commiting proposal, entry: 0000000000000edbe8a28b3f32b5d8ecdbb9241b6c773a14b1ab631b38abcf8ce57c5147eeda68040000000000000000000000000000000000000000000000000000000000000000, tag: peer_3
Apr 08 20:15:17.609 INFO starting a new election, term: 15, raft_id: 3, tag: peer_3
Apr 08 20:15:17.609 DEBG reset election timeout 32 -> 39 at 0, election_elapsed: 0, timeout: 39, prev_timeout: 32, raft_id: 3, tag: peer_3
Apr 08 20:15:17.609 INFO became candidate at term 16, term: 16, raft_id: 3, tag: peer_3
Apr 08 20:15:17.609 DEBG Sending from 3 to 1, msg: msg_type: MsgRequestVote to: 1 term: 16 log_term: 15 index: 3826 commit: 3826 commit_term: 15, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:17.609 DEBG Sending from 3 to 2, msg: msg_type: MsgRequestVote to: 2 term: 16 log_term: 15 index: 3826 commit: 3826 commit_term: 15, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:17.609 INFO broadcasting vote request, to: [1, 2], log_index: 3826, log_term: 15, term: 16, type: MsgRequestVote, raft_id: 3, tag: peer_3
Apr 08 20:15:19.260 INFO received votes response, term: 16, type: MsgRequestVoteResponse, approvals: 2, rejections: 0, from: 1, vote: true, raft_id: 3, tag: peer_3
Apr 08 20:15:19.261 DEBG reset election timeout 39 -> 52 at 8, election_elapsed: 8, timeout: 52, prev_timeout: 39, raft_id: 3, tag: peer_3
Apr 08 20:15:19.261 INFO became leader at term 16, term: 16, raft_id: 3, tag: peer_3
Apr 08 20:15:19.261 DEBG Sending from 3 to 1, msg: msg_type: MsgAppend to: 1 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3826, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.261 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3826, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.264 DEBG persisted index 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:19.264 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.264 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.270 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.271 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.271 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.271 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.272 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.272 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.272 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.273 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.273 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.273 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.274 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.274 DEBG Sending from 3 to 2, msg: msg_type: MsgAppendResponse to: 2, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.515 DEBG committing index 3827, index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:19.515 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.518 DEBG Sending from 3 to 1, msg: msg_type: MsgAppend to: 1 log_term: 16 index: 3827 commit: 3827, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.550 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:19.807 INFO propose, hash: 0000000000000edc0b2759ec3147f3167049f1b3e76df4179dcffed782a212816acad49e43980a0a0000000000000000000000000000000000000000000000000000000000000000, tag: peer_3
Apr 08 20:15:19.807 DEBG Sending from 3 to 1, msg: msg_type: MsgAppend to: 1 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3827, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.808 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.810 DEBG persisted index 3828, raft_id: 3, tag: peer_3
Apr 08 20:15:19.810 DEBG Sending from 3 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3827, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.810 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeat to: 2 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.826 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:19.924 DEBG Sending from 3 to 1, msg: msg_type: MsgAppend to: 1 log_term: 16 index: 3828 commit: 3827, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.925 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3828 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.925 DEBG committing index 3828, index: 3828, raft_id: 3, tag: peer_3
Apr 08 20:15:19.925 DEBG Sending from 3 to 1, msg: msg_type: MsgAppend to: 1 log_term: 16 index: 3828 commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.925 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3828 commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.926 INFO commiting proposal, entry: 0000000000000edc0b2759ec3147f3167049f1b3e76df4179dcffed782a212816acad49e43980a0a0000000000000000000000000000000000000000000000000000000000000000, tag: peer_3
Apr 08 20:15:19.946 DEBG received msgAppend rejection, index: 3828, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:19.946 DEBG decreased progress of 2, progress: Progress { matched: 3827, next_idx: 3828, state: Replicate, paused: false, pending_snapshot: 0, pending_request_snapshot: 0, recent_active: true, ins: Inflights { start: 0, count: 1, buffer: [3828, 3624, 3625, 3626, 3627, 3622, 3420, 3421, 3422, 3423, 3424, 3425, 3412, 3413, 3226, 3129, 3130, 3131, 3132, 3133, 3134, 3135, 3136, 3137, 3138, 3139, 3140, 3141, 3142, 3143, 3144, 3145, 3146, 3147, 3148, 3149, 3150, 3151, 3152, 3153, 3154,3155, 3156, 3157, 3158, 3159, 3160, 3161, 3162, 3163, 3164, 3165, 3166, 3167, 3168, 3169, 3170, 3171, 3172, 3173, 3174, 3175, 3176, 3177, 3178, 3179, 3180, 3181, 3182, 3183, 3184, 3185, 3186, 3187, 3188, 3189, 3190, 3191, 3192, 3193, 3194, 3195, 3196, 3197, 3198, 3199, 2944, 2945, 2946, 2947, 2948, 2949, 2950, 2951, 2952, 2953, 2954, 2955, 2956, 2957, 2958, 2959, 2960, 2961, 2962, 2963, 2964, 2965, 2966, 2967, 2968, 2969, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978, 2979, 2980, 2981,2982, 2983, 2984, 2985, 2986, 2987, 2988, 2989, 2990, 2991, 2992, 2993, 2994, 2995, 2996, 2997, 2998, 2999, 3000, 3001, 3002, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3014, 3015, 3016, 3017, 3018, 3019, 3020, 3021, 3022, 3023, 3024, 3025, 3026, 3027, 3028, 3029, 3030, 3031, 3032, 3033, 3034, 3035, 3036, 3037, 3038, 3039, 3040, 3041, 3042, 3043, 3044, 3045, 3046, 3047, 3048, 3049, 3050, 3051, 3052, 3053, 3054, 3055, 3056, 3057, 3058, 3059, 3060, 3061, 3062, 3063, 3064,3065, 3066, 3067, 3068, 3069, 3070, 3071, 3072, 3073, 3074, 3075, 3076, 3077, 3078, 3079, 3080, 3081, 3082, 3083, 3084, 3085, 3086, 3087, 3088, 3089, 3090, 3091, 3092, 3093, 3094, 3095, 3096, 3097, 3098, 3099, 3100, 3101, 3102, 3103, 3104, 3105, 3106, 3107, 3108, 3109, 3110, 3111, 3112, 3113] }, commit_group_id: 0, committed_index: 3827 }, raft_id: 3, tag: peer_3
Apr 08 20:15:19.946 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:19.952 DEBG received msgAppend rejection, index: 3828, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:19.992 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:19.992 DEBG decreased progress of 2, progress: Progress { matched: 3827, next_idx: 3827, state: Probe, paused: false, pending_snapshot: 0, pending_request_snapshot: 0, recent_active: true, ins: Inflights { start: 0, count: 0, buffer: [3828, 3624, 3625, 3626, 3627, 3622, 3420, 3421, 3422, 3423, 3424, 3425, 3412, 3413,3226, 3129, 3130, 3131, 3132, 3133, 3134, 3135, 3136, 3137, 3138, 3139, 3140, 3141, 3142, 3143, 3144, 3145, 3146, 3147, 3148, 3149, 3150, 3151, 3152, 3153, 3154, 3155, 3156, 3157, 3158, 3159, 3160, 3161, 3162, 3163, 3164, 3165, 3166, 3167, 3168, 3169, 3170, 3171, 3172, 3173, 3174, 3175, 3176, 3177, 3178, 3179, 3180, 3181, 3182, 3183, 3184, 3185, 3186, 3187, 3188, 3189, 3190, 3191, 3192, 3193, 3194, 3195, 3196, 3197, 3198, 3199, 2944, 2945, 2946, 2947, 2948, 2949, 2950, 2951, 2952, 2953, 2954,2955, 2956, 2957, 2958, 2959, 2960, 2961, 2962, 2963, 2964, 2965, 2966, 2967, 2968, 2969, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978, 2979, 2980, 2981, 2982, 2983, 2984, 2985, 2986, 2987, 2988, 2989, 2990, 2991, 2992, 2993, 2994, 2995, 2996, 2997, 2998, 2999, 3000, 3001, 3002, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3014, 3015, 3016, 3017, 3018, 3019, 3020, 3021, 3022, 3023, 3024, 3025, 3026, 3027, 3028, 3029, 3030, 3031, 3032, 3033, 3034, 3035, 3036, 3037,3038, 3039, 3040, 3041, 3042, 3043, 3044, 3045, 3046, 3047, 3048, 3049, 3050, 3051, 3052, 3053, 3054, 3055, 3056, 3057, 3058, 3059, 3060, 3061, 3062, 3063, 3064, 3065, 3066, 3067, 3068, 3069, 3070, 3071, 3072, 3073, 3074, 3075, 3076, 3077, 3078, 3079, 3080, 3081, 3082, 3083, 3084, 3085, 3086, 3087, 3088, 3089, 3090, 3091, 3092, 3093, 3094, 3095, 3096, 3097, 3098, 3099, 3100, 3101, 3102, 3103, 3104, 3105, 3106, 3107, 3108, 3109, 3110, 3111, 3112, 3113] }, commit_group_id: 0, committed_index: 3827 }, raft_id: 3, tag: peer_3
Apr 08 20:15:19.993 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:20.407 DEBG Sending from 3 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:20.407 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeat to: 2 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:20.418 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:20.432 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:20.432 DEBG decreased progress of 2, progress: Progress { matched: 3827, next_idx: 3827, state: Probe, paused: false, pending_snapshot: 0, pending_request_snapshot: 0, recent_active: true, ins: Inflights { start: 0, count: 0, buffer: [3828, 3624, 3625, 3626, 3627, 3622, 3420, 3421, 3422, 3423, 3424, 3425, 3412, 3413,3226, 3129, 3130, 3131, 3132, 3133, 3134, 3135, 3136, 3137, 3138, 3139, 3140, 3141, 3142, 3143, 3144, 3145, 3146, 3147, 3148, 3149, 3150, 3151, 3152, 3153, 3154, 3155, 3156, 3157, 3158, 3159, 3160, 3161, 3162, 3163, 3164, 3165, 3166, 3167, 3168, 3169, 3170, 3171, 3172, 3173, 3174, 3175, 3176, 3177, 3178, 3179, 3180, 3181, 3182, 3183, 3184, 3185, 3186, 3187, 3188, 3189, 3190, 3191, 3192, 3193, 3194, 3195, 3196, 3197, 3198, 3199, 2944, 2945, 2946, 2947, 2948, 2949, 2950, 2951, 2952, 2953, 2954,2955, 2956, 2957, 2958, 2959, 2960, 2961, 2962, 2963, 2964, 2965, 2966, 2967, 2968, 2969, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978, 2979, 2980, 2981, 2982, 2983, 2984, 2985, 2986, 2987, 2988, 2989, 2990, 2991, 2992, 2993, 2994, 2995, 2996, 2997, 2998, 2999, 3000, 3001, 3002, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3014, 3015, 3016, 3017, 3018, 3019, 3020, 3021, 3022, 3023, 3024, 3025, 3026, 3027, 3028, 3029, 3030, 3031, 3032, 3033, 3034, 3035, 3036, 3037,3038, 3039, 3040, 3041, 3042, 3043, 3044, 3045, 3046, 3047, 3048, 3049, 3050, 3051, 3052, 3053, 3054, 3055, 3056, 3057, 3058, 3059, 3060, 3061, 3062, 3063, 3064, 3065, 3066, 3067, 3068, 3069, 3070, 3071, 3072, 3073, 3074, 3075, 3076, 3077, 3078, 3079, 3080, 3081, 3082, 3083, 3084, 3085, 3086, 3087, 3088, 3089, 3090, 3091, 3092, 3093, 3094, 3095, 3096, 3097, 3098, 3099, 3100, 3101, 3102, 3103, 3104, 3105, 3106, 3107, 3108, 3109, 3110, 3111, 3112, 3113] }, commit_group_id: 0, committed_index: 3827 }, raft_id: 3, tag: peer_3
Apr 08 20:15:20.432 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:21.009 DEBG Sending from 3 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:21.010 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeat to: 2 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:21.022 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:21.035 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:21.035 DEBG decreased progress of 2, progress: Progress { matched: 3827, next_idx: 3827, state: Probe, paused: false, pending_snapshot: 0, pending_request_snapshot: 0, recent_active: true, ins: Inflights { start: 0, count: 0, buffer: [3828, 3624, 3625, 3626, 3627, 3622, 3420, 3421, 3422, 3423, 3424, 3425, 3412, 3413,3226, 3129, 3130, 3131, 3132, 3133, 3134, 3135, 3136, 3137, 3138, 3139, 3140, 3141, 3142, 3143, 3144, 3145, 3146, 3147, 3148, 3149, 3150, 3151, 3152, 3153, 3154, 3155, 3156, 3157, 3158, 3159, 3160, 3161, 3162, 3163, 3164, 3165, 3166, 3167, 3168, 3169, 3170, 3171, 3172, 3173, 3174, 3175, 3176, 3177, 3178, 3179, 3180, 3181, 3182, 3183, 3184, 3185, 3186, 3187, 3188, 3189, 3190, 3191, 3192, 3193, 3194, 3195, 3196, 3197, 3198, 3199, 2944, 2945, 2946, 2947, 2948, 2949, 2950, 2951, 2952, 2953, 2954,2955, 2956, 2957, 2958, 2959, 2960, 2961, 2962, 2963, 2964, 2965, 2966, 2967, 2968, 2969, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978, 2979, 2980, 2981, 2982, 2983, 2984, 2985, 2986, 2987, 2988, 2989, 2990, 2991, 2992, 2993, 2994, 2995, 2996, 2997, 2998, 2999, 3000, 3001, 3002, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3014, 3015, 3016, 3017, 3018, 3019, 3020, 3021, 3022, 3023, 3024, 3025, 3026, 3027, 3028, 3029, 3030, 3031, 3032, 3033, 3034, 3035, 3036, 3037,3038, 3039, 3040, 3041, 3042, 3043, 3044, 3045, 3046, 3047, 3048, 3049, 3050, 3051, 3052, 3053, 3054, 3055, 3056, 3057, 3058, 3059, 3060, 3061, 3062, 3063, 3064, 3065, 3066, 3067, 3068, 3069, 3070, 3071, 3072, 3073, 3074, 3075, 3076, 3077, 3078, 3079, 3080, 3081, 3082, 3083, 3084, 3085, 3086, 3087, 3088, 3089, 3090, 3091, 3092, 3093, 3094, 3095, 3096, 3097, 3098, 3099, 3100, 3101, 3102, 3103, 3104, 3105, 3106, 3107, 3108, 3109, 3110, 3111, 3112, 3113] }, commit_group_id: 0, committed_index: 3827 }, raft_id: 3, tag: peer_3
Apr 08 20:15:21.036 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:21.607 DEBG Sending from 3 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:21.607 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeat to: 2 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:21.616 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:21.631 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:21.631 DEBG decreased progress of 2, progress: Progress { matched: 3827, next_idx: 3827, state: Probe, paused: false, pending_snapshot: 0, pending_request_snapshot: 0, recent_active: true, ins: Inflights { start: 0, count: 0, buffer: [3828, 3624, 3625, 3626, 3627, 3622, 3420, 3421, 3422, 3423, 3424, 3425, 3412, 3413,3226, 3129, 3130, 3131, 3132, 3133, 3134, 3135, 3136, 3137, 3138, 3139, 3140, 3141, 3142, 3143, 3144, 3145, 3146, 3147, 3148, 3149, 3150, 3151, 3152, 3153, 3154, 3155, 3156, 3157, 3158, 3159, 3160, 3161, 3162, 3163, 3164, 3165, 3166, 3167, 3168, 3169, 3170, 3171, 3172, 3173, 3174, 3175, 3176, 3177, 3178, 3179, 3180, 3181, 3182, 3183, 3184, 3185, 3186, 3187, 3188, 3189, 3190, 3191, 3192, 3193, 3194, 3195, 3196, 3197, 3198, 3199, 2944, 2945, 2946, 2947, 2948, 2949, 2950, 2951, 2952, 2953, 2954,2955, 2956, 2957, 2958, 2959, 2960, 2961, 2962, 2963, 2964, 2965, 2966, 2967, 2968, 2969, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978, 2979, 2980, 2981, 2982, 2983, 2984, 2985, 2986, 2987, 2988, 2989, 2990, 2991, 2992, 2993, 2994, 2995, 2996, 2997, 2998, 2999, 3000, 3001, 3002, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3014, 3015, 3016, 3017, 3018, 3019, 3020, 3021, 3022, 3023, 3024, 3025, 3026, 3027, 3028, 3029, 3030, 3031, 3032, 3033, 3034, 3035, 3036, 3037,3038, 3039, 3040, 3041, 3042, 3043, 3044, 3045, 3046, 3047, 3048, 3049, 3050, 3051, 3052, 3053, 3054, 3055, 3056, 3057, 3058, 3059, 3060, 3061, 3062, 3063, 3064, 3065, 3066, 3067, 3068, 3069, 3070, 3071, 3072, 3073, 3074, 3075, 3076, 3077, 3078, 3079, 3080, 3081, 3082, 3083, 3084, 3085, 3086, 3087, 3088, 3089, 3090, 3091, 3092, 3093, 3094, 3095, 3096, 3097, 3098, 3099, 3100, 3101, 3102, 3103, 3104, 3105, 3106, 3107, 3108, 3109, 3110, 3111, 3112, 3113] }, commit_group_id: 0, committed_index: 3827 }, raft_id: 3, tag: peer_3
Apr 08 20:15:21.631 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:22.207 DEBG Sending from 3 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:22.209 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeat to: 2 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:22.222 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:22.236 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:22.237 DEBG decreased progress of 2, progress: Progress { matched: 3827, next_idx: 3827, state: Probe, paused: false, pending_snapshot: 0, pending_request_snapshot: 0, recent_active: true, ins: Inflights { start: 0, count: 0, buffer: [3828, 3624, 3625, 3626, 3627, 3622, 3420, 3421, 3422, 3423, 3424, 3425, 3412, 3413,3226, 3129, 3130, 3131, 3132, 3133, 3134, 3135, 3136, 3137, 3138, 3139, 3140, 3141, 3142, 3143, 3144, 3145, 3146, 3147, 3148, 3149, 3150, 3151, 3152, 3153, 3154, 3155, 3156, 3157, 3158, 3159, 3160, 3161, 3162, 3163, 3164, 3165, 3166, 3167, 3168, 3169, 3170, 3171, 3172, 3173, 3174, 3175, 3176, 3177, 3178, 3179, 3180, 3181, 3182, 3183, 3184, 3185, 3186, 3187, 3188, 3189, 3190, 3191, 3192, 3193, 3194, 3195, 3196, 3197, 3198, 3199, 2944, 2945, 2946, 2947, 2948, 2949, 2950, 2951, 2952, 2953, 2954,2955, 2956, 2957, 2958, 2959, 2960, 2961, 2962, 2963, 2964, 2965, 2966, 2967, 2968, 2969, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978, 2979, 2980, 2981, 2982, 2983, 2984, 2985, 2986, 2987, 2988, 2989, 2990, 2991, 2992, 2993, 2994, 2995, 2996, 2997, 2998, 2999, 3000, 3001, 3002, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3014, 3015, 3016, 3017, 3018, 3019, 3020, 3021, 3022, 3023, 3024, 3025, 3026, 3027, 3028, 3029, 3030, 3031, 3032, 3033, 3034, 3035, 3036, 3037,3038, 3039, 3040, 3041, 3042, 3043, 3044, 3045, 3046, 3047, 3048, 3049, 3050, 3051, 3052, 3053, 3054, 3055, 3056, 3057, 3058, 3059, 3060, 3061, 3062, 3063, 3064, 3065, 3066, 3067, 3068, 3069, 3070, 3071, 3072, 3073, 3074, 3075, 3076, 3077, 3078, 3079, 3080, 3081, 3082, 3083, 3084, 3085, 3086, 3087, 3088, 3089, 3090, 3091, 3092, 3093, 3094, 3095, 3096, 3097, 3098, 3099, 3100, 3101, 3102, 3103, 3104, 3105, 3106, 3107, 3108, 3109, 3110, 3111, 3112, 3113] }, commit_group_id: 0, committed_index: 3827 }, raft_id: 3, tag: peer_3
Apr 08 20:15:22.237 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:22.807 DEBG Sending from 3 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:22.807 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeat to: 2 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:22.818 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:22.830 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:22.831 DEBG decreased progress of 2, progress: Progress { matched: 3827, next_idx: 3827, state: Probe, paused: false, pending_snapshot: 0, pending_request_snapshot: 0, recent_active: true, ins: Inflights { start: 0, count: 0, buffer: [3828, 3624, 3625, 3626, 3627, 3622, 3420, 3421, 3422, 3423, 3424, 3425, 3412, 3413,3226, 3129, 3130, 3131, 3132, 3133, 3134, 3135, 3136, 3137, 3138, 3139, 3140, 3141, 3142, 3143, 3144, 3145, 3146, 3147, 3148, 3149, 3150, 3151, 3152, 3153, 3154, 3155, 3156, 3157, 3158, 3159, 3160, 3161, 3162, 3163, 3164, 3165, 3166, 3167, 3168, 3169, 3170, 3171, 3172, 3173, 3174, 3175, 3176, 3177, 3178, 3179, 3180, 3181, 3182, 3183, 3184, 3185, 3186, 3187, 3188, 3189, 3190, 3191, 3192, 3193, 3194, 3195, 3196, 3197, 3198, 3199, 2944, 2945, 2946, 2947, 2948, 2949, 2950, 2951, 2952, 2953, 2954,2955, 2956, 2957, 2958, 2959, 2960, 2961, 2962, 2963, 2964, 2965, 2966, 2967, 2968, 2969, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978, 2979, 2980, 2981, 2982, 2983, 2984, 2985, 2986, 2987, 2988, 2989, 2990, 2991, 2992, 2993, 2994, 2995, 2996, 2997, 2998, 2999, 3000, 3001, 3002, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3014, 3015, 3016, 3017, 3018, 3019, 3020, 3021, 3022, 3023, 3024, 3025, 3026, 3027, 3028, 3029, 3030, 3031, 3032, 3033, 3034, 3035, 3036, 3037,3038, 3039, 3040, 3041, 3042, 3043, 3044, 3045, 3046, 3047, 3048, 3049, 3050, 3051, 3052, 3053, 3054, 3055, 3056, 3057, 3058, 3059, 3060, 3061, 3062, 3063, 3064, 3065, 3066, 3067, 3068, 3069, 3070, 3071, 3072, 3073, 3074, 3075, 3076, 3077, 3078, 3079, 3080, 3081, 3082, 3083, 3084, 3085, 3086, 3087, 3088, 3089, 3090, 3091, 3092, 3093, 3094, 3095, 3096, 3097, 3098, 3099, 3100, 3101, 3102, 3103, 3104, 3105, 3106, 3107, 3108, 3109, 3110, 3111, 3112, 3113] }, commit_group_id: 0, committed_index: 3827 }, raft_id: 3, tag: peer_3
Apr 08 20:15:22.832 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:23.407 DEBG Sending from 3 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:23.407 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeat to: 2 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:23.420 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:23.433 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:23.433 DEBG decreased progress of 2, progress: Progress { matched: 3827, next_idx: 3827, state: Probe, paused: false, pending_snapshot: 0, pending_request_snapshot: 0, recent_active: true, ins: Inflights { start: 0, count: 0, buffer: [3828, 3624, 3625, 3626, 3627, 3622, 3420, 3421, 3422, 3423, 3424, 3425, 3412, 3413,3226, 3129, 3130, 3131, 3132, 3133, 3134, 3135, 3136, 3137, 3138, 3139, 3140, 3141, 3142, 3143, 3144, 3145, 3146, 3147, 3148, 3149, 3150, 3151, 3152, 3153, 3154, 3155, 3156, 3157, 3158, 3159, 3160, 3161, 3162, 3163, 3164, 3165, 3166, 3167, 3168, 3169, 3170, 3171, 3172, 3173, 3174, 3175, 3176, 3177, 3178, 3179, 3180, 3181, 3182, 3183, 3184, 3185, 3186, 3187, 3188, 3189, 3190, 3191, 3192, 3193, 3194, 3195, 3196, 3197, 3198, 3199, 2944, 2945, 2946, 2947, 2948, 2949, 2950, 2951, 2952, 2953, 2954,2955, 2956, 2957, 2958, 2959, 2960, 2961, 2962, 2963, 2964, 2965, 2966, 2967, 2968, 2969, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978, 2979, 2980, 2981, 2982, 2983, 2984, 2985, 2986, 2987, 2988, 2989, 2990, 2991, 2992, 2993, 2994, 2995, 2996, 2997, 2998, 2999, 3000, 3001, 3002, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3014, 3015, 3016, 3017, 3018, 3019, 3020, 3021, 3022, 3023, 3024, 3025, 3026, 3027, 3028, 3029, 3030, 3031, 3032, 3033, 3034, 3035, 3036, 3037,3038, 3039, 3040, 3041, 3042, 3043, 3044, 3045, 3046, 3047, 3048, 3049, 3050, 3051, 3052, 3053, 3054, 3055, 3056, 3057, 3058, 3059, 3060, 3061, 3062, 3063, 3064, 3065, 3066, 3067, 3068, 3069, 3070, 3071, 3072, 3073, 3074, 3075, 3076, 3077, 3078, 3079, 3080, 3081, 3082, 3083, 3084, 3085, 3086, 3087, 3088, 3089, 3090, 3091, 3092, 3093, 3094, 3095, 3096, 3097, 3098, 3099, 3100, 3101, 3102, 3103, 3104, 3105, 3106, 3107, 3108, 3109, 3110, 3111, 3112, 3113] }, commit_group_id: 0, committed_index: 3827 }, raft_id: 3, tag: peer_3
Apr 08 20:15:23.434 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:24.007 DEBG Sending from 3 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:24.007 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeat to: 2 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:24.020 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:24.034 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:24.034 DEBG decreased progress of 2, progress: Progress { matched: 3827, next_idx: 3827, state: Probe, paused: false, pending_snapshot: 0, pending_request_snapshot: 0, recent_active: true, ins: Inflights { start: 0, count: 0, buffer: [3828, 3624, 3625, 3626, 3627, 3622, 3420, 3421, 3422, 3423, 3424, 3425, 3412, 3413,3226, 3129, 3130, 3131, 3132, 3133, 3134, 3135, 3136, 3137, 3138, 3139, 3140, 3141, 3142, 3143, 3144, 3145, 3146, 3147, 3148, 3149, 3150, 3151, 3152, 3153, 3154, 3155, 3156, 3157, 3158, 3159, 3160, 3161, 3162, 3163, 3164, 3165, 3166, 3167, 3168, 3169, 3170, 3171, 3172, 3173, 3174, 3175, 3176, 3177, 3178, 3179, 3180, 3181, 3182, 3183, 3184, 3185, 3186, 3187, 3188, 3189, 3190, 3191, 3192, 3193, 3194, 3195, 3196, 3197, 3198, 3199, 2944, 2945, 2946, 2947, 2948, 2949, 2950, 2951, 2952, 2953, 2954,2955, 2956, 2957, 2958, 2959, 2960, 2961, 2962, 2963, 2964, 2965, 2966, 2967, 2968, 2969, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978, 2979, 2980, 2981, 2982, 2983, 2984, 2985, 2986, 2987, 2988, 2989, 2990, 2991, 2992, 2993, 2994, 2995, 2996, 2997, 2998, 2999, 3000, 3001, 3002, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3014, 3015, 3016, 3017, 3018, 3019, 3020, 3021, 3022, 3023, 3024, 3025, 3026, 3027, 3028, 3029, 3030, 3031, 3032, 3033, 3034, 3035, 3036, 3037,3038, 3039, 3040, 3041, 3042, 3043, 3044, 3045, 3046, 3047, 3048, 3049, 3050, 3051, 3052, 3053, 3054, 3055, 3056, 3057, 3058, 3059, 3060, 3061, 3062, 3063, 3064, 3065, 3066, 3067, 3068, 3069, 3070, 3071, 3072, 3073, 3074, 3075, 3076, 3077, 3078, 3079, 3080, 3081, 3082, 3083, 3084, 3085, 3086, 3087, 3088, 3089, 3090, 3091, 3092, 3093, 3094, 3095, 3096, 3097, 3098, 3099, 3100, 3101, 3102, 3103, 3104, 3105, 3106, 3107, 3108, 3109, 3110, 3111, 3112, 3113] }, commit_group_id: 0, committed_index: 3827 }, raft_id: 3, tag: peer_3
Apr 08 20:15:24.034 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:24.607 DEBG Sending from 3 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:24.607 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeat to: 2 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:24.618 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:24.630 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:24.630 DEBG decreased progress of 2, progress: Progress { matched: 3827, next_idx: 3827, state: Probe, paused: false, pending_snapshot: 0, pending_request_snapshot: 0, recent_active: true, ins: Inflights { start: 0, count: 0, buffer: [3828, 3624, 3625, 3626, 3627, 3622, 3420, 3421, 3422, 3423, 3424, 3425, 3412, 3413,3226, 3129, 3130, 3131, 3132, 3133, 3134, 3135, 3136, 3137, 3138, 3139, 3140, 3141, 3142, 3143, 3144, 3145, 3146, 3147, 3148, 3149, 3150, 3151, 3152, 3153, 3154, 3155, 3156, 3157, 3158, 3159, 3160, 3161, 3162, 3163, 3164, 3165, 3166, 3167, 3168, 3169, 3170, 3171, 3172, 3173, 3174, 3175, 3176, 3177, 3178, 3179, 3180, 3181, 3182, 3183, 3184, 3185, 3186, 3187, 3188, 3189, 3190, 3191, 3192, 3193, 3194, 3195, 3196, 3197, 3198, 3199, 2944, 2945, 2946, 2947, 2948, 2949, 2950, 2951, 2952, 2953, 2954,2955, 2956, 2957, 2958, 2959, 2960, 2961, 2962, 2963, 2964, 2965, 2966, 2967, 2968, 2969, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978, 2979, 2980, 2981, 2982, 2983, 2984, 2985, 2986, 2987, 2988, 2989, 2990, 2991, 2992, 2993, 2994, 2995, 2996, 2997, 2998, 2999, 3000, 3001, 3002, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3014, 3015, 3016, 3017, 3018, 3019, 3020, 3021, 3022, 3023, 3024, 3025, 3026, 3027, 3028, 3029, 3030, 3031, 3032, 3033, 3034, 3035, 3036, 3037,3038, 3039, 3040, 3041, 3042, 3043, 3044, 3045, 3046, 3047, 3048, 3049, 3050, 3051, 3052, 3053, 3054, 3055, 3056, 3057, 3058, 3059, 3060, 3061, 3062, 3063, 3064, 3065, 3066, 3067, 3068, 3069, 3070, 3071, 3072, 3073, 3074, 3075, 3076, 3077, 3078, 3079, 3080, 3081, 3082, 3083, 3084, 3085, 3086, 3087, 3088, 3089, 3090, 3091, 3092, 3093, 3094, 3095, 3096, 3097, 3098, 3099, 3100, 3101, 3102, 3103, 3104, 3105, 3106, 3107, 3108, 3109, 3110, 3111, 3112, 3113] }, commit_group_id: 0, committed_index: 3827 }, raft_id: 3, tag: peer_3
Apr 08 20:15:24.631 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:25.207 DEBG Sending from 3 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:25.207 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeat to: 2 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:25.219 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:25.254 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:25.255 DEBG decreased progress of 2, progress: Progress { matched: 3827, next_idx: 3827, state: Probe, paused: false, pending_snapshot: 0, pending_request_snapshot: 0, recent_active: true, ins: Inflights { start: 0, count: 0, buffer: [3828, 3624, 3625, 3626, 3627, 3622, 3420, 3421, 3422, 3423, 3424, 3425, 3412, 3413,3226, 3129, 3130, 3131, 3132, 3133, 3134, 3135, 3136, 3137, 3138, 3139, 3140, 3141, 3142, 3143, 3144, 3145, 3146, 3147, 3148, 3149, 3150, 3151, 3152, 3153, 3154, 3155, 3156, 3157, 3158, 3159, 3160, 3161, 3162, 3163, 3164, 3165, 3166, 3167, 3168, 3169, 3170, 3171, 3172, 3173, 3174, 3175, 3176, 3177, 3178, 3179, 3180, 3181, 3182, 3183, 3184, 3185, 3186, 3187, 3188, 3189, 3190, 3191, 3192, 3193, 3194, 3195, 3196, 3197, 3198, 3199, 2944, 2945, 2946, 2947, 2948, 2949, 2950, 2951, 2952, 2953, 2954,2955, 2956, 2957, 2958, 2959, 2960, 2961, 2962, 2963, 2964, 2965, 2966, 2967, 2968, 2969, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978, 2979, 2980, 2981, 2982, 2983, 2984, 2985, 2986, 2987, 2988, 2989, 2990, 2991, 2992, 2993, 2994, 2995, 2996, 2997, 2998, 2999, 3000, 3001, 3002, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3014, 3015, 3016, 3017, 3018, 3019, 3020, 3021, 3022, 3023, 3024, 3025, 3026, 3027, 3028, 3029, 3030, 3031, 3032, 3033, 3034, 3035, 3036, 3037,3038, 3039, 3040, 3041, 3042, 3043, 3044, 3045, 3046, 3047, 3048, 3049, 3050, 3051, 3052, 3053, 3054, 3055, 3056, 3057, 3058, 3059, 3060, 3061, 3062, 3063, 3064, 3065, 3066, 3067, 3068, 3069, 3070, 3071, 3072, 3073, 3074, 3075, 3076, 3077, 3078, 3079, 3080, 3081, 3082, 3083, 3084, 3085, 3086, 3087, 3088, 3089, 3090, 3091, 3092, 3093, 3094, 3095, 3096, 3097, 3098, 3099, 3100, 3101, 3102, 3103, 3104, 3105, 3106, 3107, 3108, 3109, 3110, 3111, 3112, 3113] }, commit_group_id: 0, committed_index: 3827 }, raft_id: 3, tag: peer_3
Apr 08 20:15:25.255 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:25.807 INFO propose, hash: 0000000000000edd162291d906bc84e9c2af8613ddaeb76e5b98010869a8e6ab1067e92dbbd090280000000000000000000000000000000000000000000000000000000000000000, tag: peer_3
Apr 08 20:15:25.808 DEBG Sending from 3 to 1, msg: msg_type: MsgAppend to: 1 log_term: 16 index: 3828 entries {term: 16 index: 3829 data: "\000\000\000\000\000\000\016\335\026\"\221\331\006\274\204\351\302\257\206\023\335\256\267n[\230\001\010i\250\346\253\020g\351-\273\320\220(\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:25.810 DEBG persisted index 3829, raft_id: 3, tag: peer_3
Apr 08 20:15:25.812 DEBG Sending from 3 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:25.812 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeat to: 2 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:25.823 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 16 index: 3827 entries {term: 16 index: 3828 data: "\000\000\000\000\000\000\016\334\013\'Y\3541G\363\026pI\361\263\347m\364\027\235\317\376\327\202\242\022\201j\312\324\236C\230\n\n\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:25.835 DEBG received msgAppend rejection, index: 3827, from: 2, reject_hint_term: 15, reject_hint_index: 3827, raft_id: 3, tag: peer_3
Apr 08 20:15:25.836 DEBG decreased progress of 2, progress: Progress { matched: 3827, next_idx: 3827, state: Probe, paused: false, pending_snapshot: 0, pending_request_snapshot: 0, recent_active: true, ins: Inflights { start: 0, count: 0, buffer: [3828, 3624, 3625, 3626, 3627, 3622, 3420, 3421, 3422, 3423, 3424, 3425, 3412, 3413,3226, 3129, 3130, 3131, 3132, 3133, 3134, 3135, 3136, 3137, 3138, 3139, 3140, 3141, 3142, 3143, 3144, 3145, 3146, 3147, 3148, 3149, 3150, 3151, 3152, 3153, 3154, 3155, 3156, 3157, 3158, 3159, 3160, 3161, 3162, 3163, 3164, 3165, 3166, 3167, 3168, 3169, 3170, 3171, 3172, 3173, 3174, 3175, 3176, 3177, 3178, 3179, 3180, 3181, 3182, 3183, 3184, 3185, 3186, 3187, 3188, 3189, 3190, 3191, 3192, 3193, 3194, 3195, 3196, 3197, 3198, 3199, 2944, 2945, 2946, 2947, 2948, 2949, 2950, 2951, 2952, 2953, 2954,2955, 2956, 2957, 2958, 2959, 2960, 2961, 2962, 2963, 2964, 2965, 2966, 2967, 2968, 2969, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978, 2979, 2980, 2981, 2982, 2983, 2984, 2985, 2986, 2987, 2988, 2989, 2990, 2991, 2992, 2993, 2994, 2995, 2996, 2997, 2998, 2999, 3000, 3001, 3002, 3003, 3004, 3005, 3006, 3007, 3008, 3009, 3010, 3011, 3012, 3013, 3014, 3015, 3016, 3017, 3018, 3019, 3020, 3021, 3022, 3023, 3024, 3025, 3026, 3027, 3028, 3029, 3030, 3031, 3032, 3033, 3034, 3035, 3036, 3037,3038, 3039, 3040, 3041, 3042, 3043, 3044, 3045, 3046, 3047, 3048, 3049, 3050, 3051, 3052, 3053, 3054, 3055, 3056, 3057, 3058, 3059, 3060, 3061, 3062, 3063, 3064, 3065, 3066, 3067, 3068, 3069, 3070, 3071, 3072, 3073, 3074, 3075, 3076, 3077, 3078, 3079, 3080, 3081, 3082, 3083, 3084, 3085, 3086, 3087, 3088, 3089, 3090, 3091, 3092, 3093, 3094, 3095, 3096, 3097, 3098, 3099, 3100, 3101, 3102, 3103, 3104, 3105, 3106, 3107, 3108, 3109, 3110, 3111, 3112, 3113] }, commit_group_id: 0, committed_index: 3827 }, raft_id: 3, tag: peer_3
Apr 08 20:15:25.836 DEBG Sending from 3 to 2, msg: msg_type: MsgAppend to: 2 log_term: 15 index: 3826 entries {term: 16 index: 3827} commit: 3828, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:26.407 DEBG Sending from 3 to 1, msg: msg_type: MsgHeartbeat to: 1 commit: 3828, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:26.407 DEBG Sending from 3 to 2, msg: msg_type: MsgHeartbeat to: 2 commit: 3827, to: 2, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:26.408 DEBG committing index 3829, index: 3829, raft_id: 3, tag: peer_3
Apr 08 20:15:26.408 DEBG Sending from 3 to 1, msg: msg_type: MsgAppend to: 1 log_term: 16 index: 3829 commit: 3829, to: 1, from: 3, raft_id: 3, tag: peer_3
Apr 08 20:15:26.409 INFO commiting proposal, entry: 0000000000000edd162291d906bc84e9c2af8613ddaeb76e5b98010869a8e6ab1067e92dbbd090280000000000000000000000000000000000000000000000000000000000000000, tag: peer_3

@BusyJay
Copy link
Member

BusyJay commented Apr 14, 2021

Can it be reproduced reliably? I guess it's caused by not overwriting conflict entries correctly.

/cc @gengliqi I believe persisted will not be updated correctly in this case due to term check failure.

raft-rs/src/raft_log.rs

Lines 521 to 523 in a5423b2

if index > self.persisted
&& index < first_update_index
&& self.store.term(index).map_or(false, |t| t == term)

@BusyJay BusyJay added the Question A question to be answered. label Apr 14, 2021
@BusyJay
Copy link
Member

BusyJay commented Apr 14, 2021

It will be helpful if you share the storage implementations and how ready is processed.

@whfuyn
Copy link
Author

whfuyn commented Apr 14, 2021

I don't know how to reproduce it reliably. But when the network load is heavy and messages are delayed for a long time, this problem may occur. It's not a rare case.

ready handling:

https://github.com/cita-cloud/consensus_raft/blob/2d9286ddd80cb0cd8e98739830dca6346fae9b09/src/peer.rs#L428-L498

It's the same as five_mem_node example.

storage implementation:

https://github.com/cita-cloud/consensus_raft/blob/2d9286ddd80cb0cd8e98739830dca6346fae9b09/src/storage.rs#L47-L269

It's a very poor implementation, and basically the same as MemStorage's implementation but stores states into files.

It has the problem that states are not stored atomically. Since no peers restarted, I think it's not the case.

@BusyJay
Copy link
Member

BusyJay commented Apr 14, 2021

Following is wrong if ready's entries are conflict with the vector. The vector should truncated and then append.

https://github.com/cita-cloud/consensus_raft/blob/2d9286ddd80cb0cd8e98739830dca6346fae9b09/src/storage.rs#L122-L128

One of the example can be found here:

raft-rs/src/storage.rs

Lines 296 to 298 in a5423b2

let diff = ents[0].index - self.first_index();
self.entries.drain(diff as usize..);
self.entries.extend_from_slice(&ents);

@whfuyn
Copy link
Author

whfuyn commented Apr 14, 2021

Oh, thanks! I'll fix that to see if this problem solved.

By the way, what's the recommend version of raft-rs to use for now? Should I use the same version as the raftstore in tikv?

@BusyJay
Copy link
Member

BusyJay commented Apr 14, 2021

TiKV uses a version that is almost the same as master. Latest master fixes bugs for general cases that don't affect TiKV, so TiKV don't update it yet. There is no known bugs for latest master, and I wish we can release a new version when documentations are polished.

@gengliqi
Copy link
Member

Can it be reproduced reliably? I guess it's caused by not overwriting conflict entries correctly.

/cc @gengliqi I believe persisted will not be updated correctly in this case due to term check failure.

raft-rs/src/raft_log.rs

Lines 521 to 523 in a5423b2

if index > self.persisted
&& index < first_update_index
&& self.store.term(index).map_or(false, |t| t == term)

If the term check failed, generally it means the log of this index is stale and there should be a log with a different term of this index.
However, in this case, the reason is quite different which is this log is not persisted on disk so the check failure is an accident in my opinion. (In the previous logic, this code may work well until some peers restart)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Question A question to be answered.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants