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.

Sign up for GitHub

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

Jump to bottom

rafttest: reduce waitLeader flakiness #195

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
Open

rafttest: reduce waitLeader flakiness #195

wants to merge 1 commit into from

Conversation

pav-kv
Copy link
Contributor

@pav-kv pav-kv commented Apr 10, 2024

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
rafttest: reduce waitLeader flakiness
5535384 
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.

Signed-off-by: Pavel Kalinnikov <[email protected]>
@pav-kv pav-kv requested a review from ahrtr April 10, 2024 19:11
@pav-kv
Copy link
Contributor Author

pav-kv commented Apr 10, 2024 •
edited
Loading

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
Copy link
Contributor Author

pav-kv commented Apr 10, 2024

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
Copy link
Contributor Author

pav-kv commented Apr 10, 2024 •
edited
Loading

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 pav-kv mentioned this pull request Apr 10, 2024
Closed
@pav-kv
Copy link
Contributor Author

pav-kv commented Apr 10, 2024 •
edited
Loading

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.

pav-kv
pav-kv commented Apr 10, 2024
View reviewed changes
rafttest/node_test.go
@@ -35,7 +35,7 @@ func TestBasicProgress(t *testing.T) {
nodes = append(nodes, n)
}

waitLeader(nodes)
waitStableLeader(nodes)
Copy link
Contributor Author

@pav-kv pav-kv Apr 10, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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. If the leader election is completely unstable, and every single submitted entry that gets routed to a now-leader ends up wiped because there is already a higher-term leader, we won't commit anything.

We can require in this test, however, that most entries are committed (say, at least 70 out of 100), to demonstrate that there is liveness in this implementation.

Alternatively, once we have a leader, we can stop ticking the nodes, so that no re-election will occur and disrupt the 100 entries flow.

@ahrtr
Copy link
Member

ahrtr commented Apr 11, 2024

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.

@pav-kv pav-kv mentioned this pull request Sep 6, 2024
Merged
@miraradeva miraradeva mentioned this pull request Oct 21, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@ahrtr ahrtr Awaiting requested review from ahrtr

At least 1 approving review is required to merge this pull request.

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@pav-kv @ahrtr