Node restarts lead to unstable cluster

[otto-dev]

I'm observing the following behavior after some restarts of nodes in an rqlite cluster.

A node eventually wins the election and becomes the leader. However, the node quickly reverts to the follower state.

There are several warnings about "appendEntries rejected" and "sending older logs," which indicates that there is an inconsistency in the Raft log between the nodes. The node continuously tries to send older logs to synchronize with other nodes.

I was seeing this after making some changes to a Nomad rqlite job-spec, which caused staggered restarts. How do I recover from this?

[rqlited] 2023/03/20 03:10:16 preexisting node configuration detected, ignoring bootstrap request
[rqlited] 2023/03/20 03:10:16 node HTTP API available at https://[fde4:5061:9259:1::1003]:4001
[rqlited] 2023/03/20 03:10:16 connect using the command-line tool via 'rqlite -H fde4:5061:9259:1::1003 -p 4001'
2023-03-20T03:10:16.232Z [INFO]  raft: entering follower state: follower="Node at [fde4:5061:9259:1::1003]:4002 [Follower]" leader-address= leader-id=
2023-03-20T03:10:17.277Z [WARN]  raft: heartbeat timeout reached, starting election: last-leader-addr= last-leader-id=
2023-03-20T03:10:17.277Z [INFO]  raft: entering candidate state: node="Node at [fde4:5061:9259:1::1003]:4002 [Candidate]" term=1290
2023-03-20T03:10:17.307Z [INFO]  raft: duplicate requestVote for same term: term=1290
2023-03-20T03:10:17.308Z [WARN]  raft: duplicate requestVote from: candidate=[fde4:5061:9259:1::1003]:4002
2023-03-20T03:10:17.308Z [INFO]  raft: election won: term=1290 tally=2
2023-03-20T03:10:17.308Z [INFO]  raft: entering leader state: leader="Node at [fde4:5061:9259:1::1003]:4002 [Leader]"
2023-03-20T03:10:17.309Z [INFO]  raft: added peer, starting replication: peer=1
2023-03-20T03:10:17.309Z [INFO]  raft: added peer, starting replication: peer=2
2023-03-20T03:10:17.310Z [INFO]  raft: entering follower state: follower="Node at [fde4:5061:9259:1::1003]:4002 [Follower]" leader-address= leader-id=
2023-03-20T03:10:17.324Z [WARN]  raft: appendEntries rejected, sending older logs: peer="{Voter 1 [fde4:5061:9259:1::1002]:4002}" next=631
2023-03-20T03:10:17.791Z [WARN]  raft: rejecting vote request since our last term is greater: candidate=[fde4:5061:9259:1::1001]:4002 last-term=1290 last-candidate-term=1289
2023-03-20T03:10:17.806Z [WARN]  raft: failed to get previous log: previous-index=787 last-index=632 error="log not found"
2023-03-20T03:10:17.810Z [WARN]  raft: previous log term mis-match: ours=1290 remote=1013
2023-03-20T03:10:19.201Z [WARN]  raft: heartbeat timeout reached, starting election: last-leader-addr=[fde4:5061:9259:1::1001]:4002 last-leader-id=1
2023-03-20T03:10:19.201Z [INFO]  raft: entering candidate state: node="Node at [fde4:5061:9259:1::1003]:4002 [Candidate]" term=1293


....



2023-03-20T03:10:19.443Z [INFO]  raft: duplicate requestVote for same term: term=1293
2023-03-20T03:10:19.484Z [WARN]  raft: failed to get previous log: previous-index=788 last-index=633 error="log not found"
2023-03-20T03:10:20.470Z [WARN]  raft: failed to get previous log: previous-index=789 last-index=633 error="log not found"
2023-03-20T03:10:21.942Z [WARN]  raft: failed to get previous log: previous-index=790 last-index=633 error="log not found"
2023-03-20T03:10:23.579Z [WARN]  raft: failed to get previous log: previous-index=791 last-index=633 error="log not found"
2023-03-20T03:10:23.591Z [WARN]  raft: previous log term mis-match: ours=1293 remote=1014
2023-03-20T03:10:25.438Z [WARN]  raft: failed to get previous log: previous-index=792 last-index=633 error="log not found"
2023-03-20T03:10:26.988Z [WARN]  raft: failed to get previous log: previous-index=793 last-index=633 error="log not found"


...


2023-03-20T03:31:01.261Z [INFO]  raft: election won: term=2522 tally=2
2023-03-20T03:31:01.261Z [INFO]  raft: entering leader state: leader="Node at [fde4:5061:9259:1::1003]:4002 [Leader]"
2023-03-20T03:31:01.261Z [INFO]  raft: added peer, starting replication: peer=1
2023-03-20T03:31:01.261Z [INFO]  raft: added peer, starting replication: peer=2
2023-03-20T03:31:01.263Z [WARN]  raft: appendEntries rejected, sending older logs: peer="{Voter 1 [fde4:5061:9259:1::1002]:4002}" next=1251
2023-03-20T03:31:01.264Z [INFO]  raft: entering follower state: follower="Node at [fde4:5061:9259:1::1003]:4002 [Follower]" leader-address= leader-id=
2023-03-20T03:31:01.265Z [WARN]  raft: appendEntries rejected, sending older logs: peer="{Voter 1 [fde4:5061:9259:1::1002]:4002}" next=1250
2023-03-20T03:31:01.709Z [WARN]  raft: rejecting vote request since our last term is greater: candidate=[fde4:5061:9259:1::1001]:4002 last-term=2522 last-candidate-term=2521
2023-03-20T03:31:01.710Z [WARN]  raft: failed to get previous log: previous-index=1515 last-index=1252 error="log not found"
2023-03-20T03:31:01.711Z [WARN]  raft: previous log term mis-match: ours=2522 remote=2061
2023-03-20T03:31:02.861Z [WARN]  raft: failed to get previous log: previous-index=1516 last-index=1252 error="log not found"

[otoolep]

What kind of environment are you running in? OS? Containers? What does restart exactly mean? What do you change?

Can I also see the output for /status and /nodes from each node before the restart, and after the restart.

[otto-dev]

Thank you for your leads, I will try to find out what's going on using your leads and report back. I'm seeing the issue frequently now, so it must be possible to track down the cause. I'm running rqlite in docker containers managed by Nomad. Restarting means restarting the docker containers, e.g. after a certificate update. This is in a staging environment with frequent certificate expiry.

[otoolep]

Also /debug/vars.

[otoolep]

I suggest you try to simplify your setup as much as possible -- see if you can reproduce this without TLS enabled, etc.

[otto-dev]

Thank you.

I identified a bug in a script that was responsible for staggered restarts. The script exited with a failure, which triggered an instantaneous restart instead of a staggered (delayed) restart. This may have also led to re-allocation of rqlite nodes on different machines. I'm quite sure this was the cause of the problem.

So it wasn't a problem with rqlite at all. Sorry for the inconvenience.