Location via proxy:   [ UP ]  
[Report a bug]   [Manage cookies]                
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

raft/rafttest: TestBasicProgress failed #121745

Closed
cockroach-teamcity opened this issue Apr 3, 2024 · 7 comments
Closed

raft/rafttest: TestBasicProgress failed #121745

cockroach-teamcity opened this issue Apr 3, 2024 · 7 comments
Assignees
@pav-kv
Labels
A-testing Testing tools and infrastructure branch-release-24.1 Used to mark GA and release blockers, technical advisories, and bugs for 24.1 C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. C-test-failure Broken test (automatically or manually discovered). no-test-failure-activity O-robot Originated from a bot. P-3 Issues/test failures with no fix SLA T-kv KV Team X-stale
Milestone
24.1

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Apr 3, 2024 •
edited by cockroach-jira-scripts
Loading

raft/rafttest.TestBasicProgress failed with artifacts on release-24.1 @ d2ac82658f68c96394a811a3eaecafcd808403f3:

2024/04/03 23:05:30 raft.3: stop
2024/04/03 23:05:30 raft.4: stop
2024/04/03 23:05:30 raft.5: stop
raft2024/04/03 23:05:30 INFO: 1 switched to configuration voters=()
raft2024/04/03 23:05:30 INFO: 1 became follower at term 0
raft2024/04/03 23:05:30 INFO: newRaft 1 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
raft2024/04/03 23:05:30 INFO: 1 became follower at term 1
raft2024/04/03 23:05:30 INFO: 1 switched to configuration voters=(1)
raft2024/04/03 23:05:30 INFO: 1 switched to configuration voters=(1 2)
raft2024/04/03 23:05:30 INFO: 1 switched to configuration voters=(1 2 3)
raft2024/04/03 23:05:30 INFO: 1 switched to configuration voters=(1 2 3 4)
raft2024/04/03 23:05:30 INFO: 1 switched to configuration voters=(1 2 3 4 5)
raft2024/04/03 23:05:30 INFO: 2 switched to configuration voters=()
raft2024/04/03 23:05:30 INFO: 2 became follower at term 0
raft2024/04/03 23:05:30 INFO: newRaft 2 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
raft2024/04/03 23:05:30 INFO: 2 became follower at term 1
raft2024/04/03 23:05:30 INFO: 2 switched to configuration voters=(1)
raft2024/04/03 23:05:30 INFO: 2 switched to configuration voters=(1 2)
raft2024/04/03 23:05:30 INFO: 2 switched to configuration voters=(1 2 3)
raft2024/04/03 23:05:30 INFO: 2 switched to configuration voters=(1 2 3 4)
raft2024/04/03 23:05:30 INFO: 2 switched to configuration voters=(1 2 3 4 5)
raft2024/04/03 23:05:30 INFO: 3 switched to configuration voters=()
raft2024/04/03 23:05:30 INFO: 3 became follower at term 0
raft2024/04/03 23:05:30 INFO: newRaft 3 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
raft2024/04/03 23:05:30 INFO: 3 became follower at term 1
raft2024/04/03 23:05:30 INFO: 3 switched to configuration voters=(1)
raft2024/04/03 23:05:30 INFO: 3 switched to configuration voters=(1 2)
raft2024/04/03 23:05:30 INFO: 3 switched to configuration voters=(1 2 3)
raft2024/04/03 23:05:30 INFO: 3 switched to configuration voters=(1 2 3 4)
raft2024/04/03 23:05:30 INFO: 3 switched to configuration voters=(1 2 3 4 5)
raft2024/04/03 23:05:30 INFO: 4 switched to configuration voters=()
raft2024/04/03 23:05:30 INFO: 4 became follower at term 0
raft2024/04/03 23:05:30 INFO: newRaft 4 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
raft2024/04/03 23:05:30 INFO: 4 became follower at term 1
raft2024/04/03 23:05:30 INFO: 4 switched to configuration voters=(1)
raft2024/04/03 23:05:30 INFO: 4 switched to configuration voters=(1 2)
raft2024/04/03 23:05:30 INFO: 4 switched to configuration voters=(1 2 3)
raft2024/04/03 23:05:30 INFO: 4 switched to configuration voters=(1 2 3 4)
raft2024/04/03 23:05:30 INFO: 4 switched to configuration voters=(1 2 3 4 5)
raft2024/04/03 23:05:30 INFO: 5 switched to configuration voters=()
raft2024/04/03 23:05:30 INFO: 5 became follower at term 0
raft2024/04/03 23:05:30 INFO: newRaft 5 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
raft2024/04/03 23:05:30 INFO: 5 became follower at term 1
raft2024/04/03 23:05:30 INFO: 5 switched to configuration voters=(1)
raft2024/04/03 23:05:30 INFO: 5 switched to configuration voters=(1 2)
raft2024/04/03 23:05:30 INFO: 5 switched to configuration voters=(1 2 3)
raft2024/04/03 23:05:30 INFO: 5 switched to configuration voters=(1 2 3 4)
raft2024/04/03 23:05:30 INFO: 5 switched to configuration voters=(1 2 3 4 5)
    node_test.go:47: commits failed to converge!
--- FAIL: TestBasicProgress (5.25s)
Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/replication

This test on roachdash | Improve this report!

Jira issue: CRDB-37487
@cockroach-teamcity cockroach-teamcity added branch-release-24.1 Used to mark GA and release blockers, technical advisories, and bugs for 24.1 C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. T-kv-replication labels Apr 3, 2024
@cockroach-teamcity cockroach-teamcity added this to the 24.1 milestone Apr 3, 2024
@kvoli
Copy link
Collaborator

kvoli commented Apr 4, 2024

I'm not able to reproduce this locally over 10k runs on 4a623b2. I'll pull a newer 24.1 SHA and try again.

dev test pkg/raft/rafttest -f TestBasicProgress --stress --count=10000 -v
...
Target //pkg/raft/rafttest:rafttest_test up-to-date:
  _bazel/bin/pkg/raft/rafttest/rafttest_test_/rafttest_test
INFO: Elapsed time: 101.234s, Critical Path: 0.48s
INFO: 10001 processes: 1 internal, 10000 linux-sandbox.
//pkg/raft/rafttest:rafttest_test                                        PASSED in 0.5s
  Stats over 10000 runs: max = 0.5s, min = 0.2s, avg = 0.2s, dev = 0.0s

Executed 1 out of 1 test: 1 test passes.

@kvoli
Copy link
Collaborator

kvoli commented Apr 4, 2024 •
edited
Loading

No luck on d2ac826 either. This test was recently added when we embedded the up-stream etcd-io/raft lib in cockroach. I'm guessing this test was flaky before embedding. Moving to a GA-blocker.

Full test log 

=== 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)

@kvoli kvoli added GA-blocker P-1 Issues/test failures with a fix SLA of 1 month and removed release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. labels Apr 4, 2024
@andrewbaptist andrewbaptist added the C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. label Apr 4, 2024
@kvoli
Copy link
Collaborator

kvoli commented Apr 4, 2024

@andrewbaptist could you add more detail to why this is a bug? I wasn't able to determine either way based on the test output, but I'm not intimately familiar here.

@andrewbaptist
Copy link
Collaborator

I didn't dig into the detail on why this failed other than also trying to reproduce it. Based on the test and the set of conditions it needs deeper investigation to determine the cause. There aren't any network calls to induce flakiness, and the test normally passes within ~100-200ms, so the 5s to fail here doesn't seem likely to be fixed by a timing change.

I'm also a little confused about the teamcity UI that makes it hard to see trends on this test. The page showing the trend is here vs the default if you click the link

The test itself is quite simple, but there isn't a lot of debuggability as its written. So either it is not expected that we would have all 100 entries on all nodes, but that seems unlikely, or there is some bug that prevents it from happening. Without a repro, we might have to just observe this longer...

@cockroach-teamcity cockroach-teamcity mentioned this issue Apr 9, 2024
Closed
@pav-kv
Copy link
Collaborator

pav-kv commented Apr 10, 2024

This is just a flaky test that we inherited by importing pkg/raft. In the log, we see that the leader has changed in the middle of the test:

...
23:05:24 INFO: 3 became leader at term 2
...
23:05:25 INFO: 2 became leader at term 3
...

and that caused some uncommitted entries wiped from the log (legitimately):

23:05:25 INFO: replace the unstable entries from index 7
23:05:25 INFO: replace the unstable entries from index 7

So we never committed all 100 entries, and the wait loop got stuck waiting for commit index to be >= 100.

@pav-kv pav-kv added A-testing Testing tools and infrastructure and removed P-1 Issues/test failures with a fix SLA of 1 month GA-blocker labels Apr 10, 2024
This was referenced Apr 10, 2024
Open
Open
@pav-kv
Copy link
Collaborator

pav-kv commented Apr 10, 2024

Hypothesis on the root cause of this flake: etcd-io/raft#195 (comment)

@nicktrav nicktrav added the P-3 Issues/test failures with no fix SLA label Apr 22, 2024
@exalate-issue-sync exalate-issue-sync bot added T-kv KV Team and removed T-kv-replication labels Jun 28, 2024
@github-actions GitHub Actions
Copy link

We have marked this test failure issue as stale because it has been
inactive for 1 month. If this failure is still relevant, removing the
stale label or adding a comment will keep it active. Otherwise,
we'll close it in 5 days to keep the test failure queue tidy.

@github-actions github-actions bot closed this as completed Aug 5, 2024
@pav-kv pav-kv reopened this Aug 7, 2024
@github-actions github-actions bot removed the X-stale label Aug 8, 2024
@pav-kv pav-kv closed this as completed Aug 8, 2024
@pav-kv pav-kv reopened this Aug 8, 2024
@miraradeva miraradeva mentioned this issue Sep 6, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@pav-kv pav-kv

Labels
A-testing Testing tools and infrastructure branch-release-24.1 Used to mark GA and release blockers, technical advisories, and bugs for 24.1 C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. C-test-failure Broken test (automatically or manually discovered). no-test-failure-activity O-robot Originated from a bot. P-3 Issues/test failures with no fix SLA T-kv KV Team X-stale
Projects
No open projects
KV
Status: Incoming
Milestone
24.1
Development

No branches or pull requests
5 participants
@nicktrav @pav-kv @cockroach-teamcity @kvoli @andrewbaptist