rafttest: reduce waitLeader flakiness

[pav-kv]

There are a few tests requiring a stable leader. For example, TestBasicProgress waits for a leader, submits 100 proposals, and expects that all 100 proposals are committed. In rare cases, a leader is elected, and the test proceeds, but in the meantime another node campaigns and wins a higher-term election. After this, some proposals end up not committed (legitimately), and the test fails.

This commit modifies the waitLeader function with a better heuristic for a stable leader. It now waits until the leader has the highest term in the cluster, which more reliably (although not 100%) guarantees that there is no in-flight campaign that is about to win.

[pav-kv]

Example log of a TestBasicProcess flake (and explanation why it flaked):

=== RUN   TestBasicProgress
23:05:24 INFO: 1 switched to configuration voters=()
23:05:24 INFO: 1 became follower at term 0
23:05:24 INFO: newRaft 1 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
23:05:24 INFO: 1 became follower at term 1
23:05:24 INFO: 1 switched to configuration voters=(1)
23:05:24 INFO: 1 switched to configuration voters=(1 2)
23:05:24 INFO: 1 switched to configuration voters=(1 2 3)
23:05:24 INFO: 1 switched to configuration voters=(1 2 3 4)
23:05:24 INFO: 1 switched to configuration voters=(1 2 3 4 5)
23:05:24 INFO: 2 switched to configuration voters=()
23:05:24 INFO: 2 became follower at term 0
23:05:24 INFO: newRaft 2 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
23:05:24 INFO: 2 became follower at term 1
23:05:24 INFO: 2 switched to configuration voters=(1)
23:05:24 INFO: 2 switched to configuration voters=(1 2)
23:05:24 INFO: 2 switched to configuration voters=(1 2 3)
23:05:24 INFO: 2 switched to configuration voters=(1 2 3 4)
23:05:24 INFO: 2 switched to configuration voters=(1 2 3 4 5)
23:05:24 INFO: 3 switched to configuration voters=()
23:05:24 INFO: 3 became follower at term 0
23:05:24 INFO: newRaft 3 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
23:05:24 INFO: 3 became follower at term 1
23:05:24 INFO: 3 switched to configuration voters=(1)
23:05:24 INFO: 3 switched to configuration voters=(1 2)
23:05:24 INFO: 3 switched to configuration voters=(1 2 3)
23:05:24 INFO: 3 switched to configuration voters=(1 2 3 4)
23:05:24 INFO: 3 switched to configuration voters=(1 2 3 4 5)
23:05:24 INFO: 4 switched to configuration voters=()
23:05:24 INFO: 4 became follower at term 0
23:05:24 INFO: newRaft 4 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
23:05:24 INFO: 4 became follower at term 1
23:05:24 INFO: 4 switched to configuration voters=(1)
23:05:24 INFO: 4 switched to configuration voters=(1 2)
23:05:24 INFO: 4 switched to configuration voters=(1 2 3)
23:05:24 INFO: 4 switched to configuration voters=(1 2 3 4)
23:05:24 INFO: 4 switched to configuration voters=(1 2 3 4 5)
23:05:24 INFO: 5 switched to configuration voters=()
23:05:24 INFO: 5 became follower at term 0
23:05:24 INFO: newRaft 5 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
23:05:24 INFO: 5 became follower at term 1
23:05:24 INFO: 5 switched to configuration voters=(1)
23:05:24 INFO: 5 switched to configuration voters=(1 2)
23:05:24 INFO: 5 switched to configuration voters=(1 2 3)
23:05:24 INFO: 5 switched to configuration voters=(1 2 3 4)
23:05:24 INFO: 5 switched to configuration voters=(1 2 3 4 5)
23:05:24 INFO: 3 is starting a new election at term 1
23:05:24 INFO: 3 became candidate at term 2
23:05:24 INFO: 3 [logterm: 1, index: 5] sent MsgVote request to 1 at term 2
23:05:24 INFO: 3 [logterm: 1, index: 5] sent MsgVote request to 2 at term 2
23:05:24 INFO: 3 [logterm: 1, index: 5] sent MsgVote request to 4 at term 2
23:05:24 INFO: 3 [logterm: 1, index: 5] sent MsgVote request to 5 at term 2
23:05:24 INFO: 3 received MsgVoteResp from 3 at term 2
23:05:24 INFO: 3 has received 1 MsgVoteResp votes and 0 vote rejections
23:05:24 INFO: 4 [term: 1] received a MsgVote message with higher term from 3 [term: 2]
23:05:24 INFO: 4 became follower at term 2
23:05:24 INFO: 4 [logterm: 1, index: 5, vote: 0] cast MsgVote for 3 [logterm: 1, index: 5] at term 2
23:05:24 INFO: 1 [term: 1] received a MsgVote message with higher term from 3 [term: 2]
23:05:24 INFO: 1 became follower at term 2
23:05:24 INFO: 1 [logterm: 1, index: 5, vote: 0] cast MsgVote for 3 [logterm: 1, index: 5] at term 2
23:05:24 INFO: 5 is starting a new election at term 1
23:05:24 INFO: 5 became candidate at term 2
23:05:24 INFO: 5 [logterm: 1, index: 5] sent MsgVote request to 1 at term 2
23:05:24 INFO: 5 [logterm: 1, index: 5] sent MsgVote request to 2 at term 2
23:05:24 INFO: 5 [logterm: 1, index: 5] sent MsgVote request to 3 at term 2
23:05:24 INFO: 5 [logterm: 1, index: 5] sent MsgVote request to 4 at term 2
23:05:24 INFO: 5 received MsgVoteResp from 5 at term 2
23:05:24 INFO: 5 has received 1 MsgVoteResp votes and 0 vote rejections
23:05:24 INFO: 5 [logterm: 1, index: 5, vote: 5] rejected MsgVote from 3 [logterm: 1, index: 5] at term 2
23:05:24 INFO: 3 received MsgVoteResp from 4 at term 2
23:05:24 INFO: 3 has received 2 MsgVoteResp votes and 0 vote rejections
23:05:24 INFO: 3 [logterm: 1, index: 5, vote: 3] rejected MsgVote from 5 [logterm: 1, index: 5] at term 2
23:05:24 INFO: 1 [logterm: 1, index: 5, vote: 3] rejected MsgVote from 5 [logterm: 1, index: 5] at term 2
23:05:24 INFO: 3 received MsgVoteResp from 1 at term 2
23:05:24 INFO: 3 has received 3 MsgVoteResp votes and 0 vote rejections
23:05:24 INFO: 3 became leader at term 2
23:05:24 INFO: raft.node: 3 elected leader 3 at term 2
23:05:24 INFO: 5 received MsgVoteResp rejection from 3 at term 2
23:05:24 INFO: 5 has received 1 MsgVoteResp votes and 1 vote rejections
23:05:24 INFO: 4 [logterm: 1, index: 5, vote: 3] rejected MsgVote from 5 [logterm: 1, index: 5] at term 2
23:05:24 INFO: raft.node: 4 elected leader 3 at term 2
23:05:24 INFO: 5 became follower at term 2
23:05:24 INFO: raft.node: 5 elected leader 3 at term 2
23:05:24 INFO: raft.node: 1 elected leader 3 at term 2
23:05:25 INFO: 2 [term: 1] received a MsgVote message with higher term from 3 [term: 2]
23:05:25 INFO: 2 became follower at term 2
23:05:25 INFO: 2 [logterm: 1, index: 5, vote: 0] cast MsgVote for 3 [logterm: 1, index: 5] at term 2
23:05:25 INFO: 2 [logterm: 1, index: 5, vote: 3] rejected MsgVote from 5 [logterm: 1, index: 5] at term 2
23:05:25 INFO: raft.node: 2 elected leader 3 at term 2
23:05:25 INFO: 2 is starting a new election at term 2
23:05:25 INFO: 2 became candidate at term 3
23:05:25 INFO: 2 [logterm: 2, index: 6] sent MsgVote request to 1 at term 3
23:05:25 INFO: 2 [logterm: 2, index: 6] sent MsgVote request to 3 at term 3
23:05:25 INFO: 2 [logterm: 2, index: 6] sent MsgVote request to 4 at term 3
23:05:25 INFO: 2 [logterm: 2, index: 6] sent MsgVote request to 5 at term 3
23:05:25 INFO: raft.node: 2 lost leader 3 at term 3
23:05:25 INFO: 2 received MsgVoteResp from 2 at term 3
23:05:25 INFO: 2 has received 1 MsgVoteResp votes and 0 vote rejections
23:05:25 INFO: 2 [term: 3] ignored a MsgHeartbeat message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 2] received a MsgVote message with higher term from 2 [term: 3]
23:05:25 INFO: 5 became follower at term 3
23:05:25 INFO: 5 [logterm: 2, index: 6, vote: 0] cast MsgVote for 2 [logterm: 2, index: 6] at term 3
23:05:25 INFO: raft.node: 5 lost leader 3 at term 3
23:05:25 INFO: 2 [term: 3] ignored a MsgHeartbeat message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgHeartbeat message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgHeartbeat message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgHeartbeat message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgVoteResp message with lower term from 2 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgHeartbeat message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 2] received a MsgVote message with higher term from 2 [term: 3]
23:05:25 INFO: 3 became follower at term 3
23:05:25 INFO: 3 [logterm: 2, index: 78, vote: 0] rejected MsgVote from 2 [logterm: 2, index: 6] at term 3
23:05:25 INFO: raft.node: 3 lost leader 3 at term 3
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 2] received a MsgVote message with higher term from 2 [term: 3]
23:05:25 INFO: 4 became follower at term 3
23:05:25 INFO: 4 [logterm: 2, index: 6, vote: 0] cast MsgVote for 2 [logterm: 2, index: 6] at term 3
23:05:25 INFO: raft.node: 4 lost leader 3 at term 3
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored entry appends from a MsgStorageAppendResp message with lower term [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 4 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgHeartbeat message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 4 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 4 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 2] received a MsgVote message with higher term from 2 [term: 3]
23:05:25 INFO: 1 became follower at term 3
23:05:25 INFO: 1 [logterm: 2, index: 7, vote: 0] rejected MsgVote from 2 [logterm: 2, index: 6] at term 3
23:05:25 INFO: raft.node: 1 lost leader 3 at term 3
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 2 received MsgVoteResp from 5 at term 3
23:05:25 INFO: 2 has received 2 MsgVoteResp votes and 0 vote rejections
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 4 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 4 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgHeartbeat message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgHeartbeat message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgHeartbeatResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgHeartbeat message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 4 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 4 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 4 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 received MsgVoteResp from 4 at term 3
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 has received 3 MsgVoteResp votes and 0 vote rejections
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 became leader at term 3
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: raft.node: 2 elected leader 2 at term 3
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 5 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 4 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 2 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgApp message with lower term from 3 [term: 2]
23:05:25 INFO: 1 [term: 3] ignored a MsgHeartbeat message with lower term from 3 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 4 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgHeartbeatResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: 3 [term: 3] ignored a MsgAppResp message with lower term from 1 [term: 2]
23:05:25 INFO: raft.node: 1 elected leader 2 at term 3
23:05:25 INFO: raft.node: 5 elected leader 2 at term 3
23:05:25 INFO: found conflict at index 7 [existing term: 2, conflicting term: 3]
23:05:25 INFO: replace the unstable entries from index 7
23:05:25 INFO: raft.node: 4 elected leader 2 at term 3
23:05:25 INFO: found conflict at index 7 [existing term: 2, conflicting term: 3]
23:05:25 INFO: replace the unstable entries from index 7
23:05:25 INFO: raft.node: 3 elected leader 2 at term 3
    node_test.go:47: commits failed to converge!
23:05:30 raft.1: stop
23:05:30 raft.2: stop
23:05:30 raft.3: stop
23:05:30 raft.4: stop
23:05:30 raft.5: stop
23:05:30 INFO: 1 switched to configuration voters=()
23:05:30 INFO: 1 became follower at term 0
23:05:30 INFO: newRaft 1 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
23:05:30 INFO: 1 became follower at term 1
23:05:30 INFO: 1 switched to configuration voters=(1)
23:05:30 INFO: 1 switched to configuration voters=(1 2)
23:05:30 INFO: 1 switched to configuration voters=(1 2 3)
23:05:30 INFO: 1 switched to configuration voters=(1 2 3 4)
23:05:30 INFO: 1 switched to configuration voters=(1 2 3 4 5)
23:05:30 INFO: 2 switched to configuration voters=()
23:05:30 INFO: 2 became follower at term 0
23:05:30 INFO: newRaft 2 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
23:05:30 INFO: 2 became follower at term 1
23:05:30 INFO: 2 switched to configuration voters=(1)
23:05:30 INFO: 2 switched to configuration voters=(1 2)
23:05:30 INFO: 2 switched to configuration voters=(1 2 3)
23:05:30 INFO: 2 switched to configuration voters=(1 2 3 4)
23:05:30 INFO: 2 switched to configuration voters=(1 2 3 4 5)
23:05:30 INFO: 3 switched to configuration voters=()
23:05:30 INFO: 3 became follower at term 0
23:05:30 INFO: newRaft 3 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
23:05:30 INFO: 3 became follower at term 1
23:05:30 INFO: 3 switched to configuration voters=(1)
23:05:30 INFO: 3 switched to configuration voters=(1 2)
23:05:30 INFO: 3 switched to configuration voters=(1 2 3)
23:05:30 INFO: 3 switched to configuration voters=(1 2 3 4)
23:05:30 INFO: 3 switched to configuration voters=(1 2 3 4 5)
23:05:30 INFO: 4 switched to configuration voters=()
23:05:30 INFO: 4 became follower at term 0
23:05:30 INFO: newRaft 4 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
23:05:30 INFO: 4 became follower at term 1
23:05:30 INFO: 4 switched to configuration voters=(1)
23:05:30 INFO: 4 switched to configuration voters=(1 2)
23:05:30 INFO: 4 switched to configuration voters=(1 2 3)
23:05:30 INFO: 4 switched to configuration voters=(1 2 3 4)
23:05:30 INFO: 4 switched to configuration voters=(1 2 3 4 5)
23:05:30 INFO: 5 switched to configuration voters=()
23:05:30 INFO: 5 became follower at term 0
23:05:30 INFO: newRaft 5 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
23:05:30 INFO: 5 became follower at term 1
23:05:30 INFO: 5 switched to configuration voters=(1)
23:05:30 INFO: 5 switched to configuration voters=(1 2)
23:05:30 INFO: 5 switched to configuration voters=(1 2 3)
23:05:30 INFO: 5 switched to configuration voters=(1 2 3 4)
23:05:30 INFO: 5 switched to configuration voters=(1 2 3 4 5)
--- FAIL: TestBasicProgress (5.25s)

[pav-kv]

One unclear bit in this log, though, is:

23:05:25 INFO: 2 [term: 1] received a MsgVote message with higher term from 3 [term: 2]
23:05:25 INFO: 2 became follower at term 2
23:05:25 INFO: 2 [logterm: 1, index: 5, vote: 0] cast MsgVote for 3 [logterm: 1, index: 5] at term 2
23:05:25 INFO: 2 [logterm: 1, index: 5, vote: 3] rejected MsgVote from 5 [logterm: 1, index: 5] at term 2
23:05:25 INFO: raft.node: 2 elected leader 3 at term 2
23:05:25 INFO: 2 is starting a new election at term 2
23:05:25 INFO: 2 became candidate at term 3
23:05:25 INFO: 2 [logterm: 2, index: 6] sent MsgVote request to 1 at term 3
23:05:25 INFO: 2 [logterm: 2, index: 6] sent MsgVote request to 3 at term 3
23:05:25 INFO: 2 [logterm: 2, index: 6] sent MsgVote request to 4 at term 3
23:05:25 INFO: 2 [logterm: 2, index: 6] sent MsgVote request to 5 at term 3

Specifically, the node 2 has voted for node 3 @ term 2, and immediately went to the candidate state for term 3, even though it had no reason to do so.

[pav-kv]

My immediate guess is that it was just a very bad timing of messages:

• Node 2 decides to campaign. It sends itself a MsgHup.
• But this message ends up behind a MsgVote in the channel.
• So node 2 votes, in response to MsgVote.
• And then immediately campaigns, in response to MsgHup.

OTOH, I don't see any code path in this test that would call this Campaign() method and send MsgHup. All the campaigning in this test happens internally in RawNode, and synchronously. This means that we might be having a different issue here:

• A node is approaching the election timeout.
• Just before the election timeout fired, it received MsgVote and voted. It did not reset the election timeout.
• Right after this, the timeout fires, and the node campaigns.

The second scenario shouldn't be possible though, because we do reset the timeout after voting.

[pav-kv]

So, the last hypothesis is that the 5ms ticks are too small, and the election timeout could have simply fired in short succession after the vote. For example, there was a slight Go runtime scheduling delay, and there has been a more than 10x5ms stall, which eventually caused the campaign.

[ahrtr]

Specifically, the node 2 has voted for node 3 @ term 2, and immediately went to the candidate state for term 3, even though it had no reason to do so.

I think there are two possible reasons:

• The raft loop processes message async, so it may run into election timeout right after it starts a goroutine to process the message but before it resets the electionElapsed. This is expected behaviour.
• The randomElectionTimeout [50ms - 100ms) is too short. We may want to increase it a little bit, e.g [100ms - 200ms)?

Maybe a better fix for this test, specifically, would be to relax the expectation in line 44 that all 100 entries are committed. In fact, we don't have any guarantee that any entry is going to be committed.

It isn't correct to expect all nodes have all the 100 entries committed. The correct expectation should be that,

• identify the leader after proposing all the 100 entries;
• the leader's committed entries must have been replicated majority of the members/nodes.

Also it seems the PreVote isn't enabled in the test. I think it would be better,

• enable PreVote by default in test. I guess majority applications enable it. At least etcd 3.5+ enable it.
• It's nice to support both cases (PreVote: fase and PreVote:true) in test.