Follower cannot receive new entries because it did not reset the log on receiving snapshot

[deepthidevaki]

Here is what happens:

15:22:09.891 [] INFO  io.atomix.raft.impl.RaftContext - RaftServer{0-partition-1} - Found leader 2
15:22:09.891 [] TRACE io.atomix.raft.impl.RaftContext - RaftServer{0-partition-1} - Set leader 2
15:22:09.891 [] TRACE io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Sending ConfigureResponse{status=OK}
15:22:09.891 [] TRACE io.atomix.raft.impl.RandomizedElectionTimer - Election timeout scheduled for PT4.468S
15:22:09.891 [] TRACE io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Received AppendRequest{term=74, leader=2, prevLogIndex=2, prevLogTerm=37, entries=0, commitIndex=2}
15:22:09.891 [] DEBUG io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Rejected AppendRequest{term=74, leader=2, prevLogIndex=2, prevLogTerm=37, entries=0, commitIndex=2}: Previous index (2) is greater than the local log's last index (1)
15:22:09.891 [] TRACE io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=74, succeeded=false, lastLogIndex=1, lastSnapshotIndex=0}

Node 0 log has one entry which is at index 1.

15:22:09.892 [] TRACE io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Received AppendRequest{term=74, leader=2, prevLogIndex=1, prevLogTerm=19, entries=2, commitIndex=2}
15:22:09.892 [] DEBUG io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Rejected AppendRequest{term=74, leader=2, prevLogIndex=1, prevLogTerm=19, entries=2, commitIndex=2}: Previous entry term (19) does not equal the local log's last term (5)
15:22:09.893 [] TRACE io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=74, succeeded=false, lastLogIndex=0, lastSnapshotIndex=0}

Node 0 log's entry at index 1 has term 5. Leader's index 1 has term 19.

15:22:09.895 [] TRACE io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Received InstallRequest{currentTerm=74, leader=2, index=1, term=19, version=1, chunkId=HeapByteBuffer{position=0, remaining=7, limit=7, capacity=7, mark=java.nio.HeapByteBuffer[pos=0 lim=7 cap=7], hash=263875441}, nextChunkId=null, data=HeapByteBuffer{position=0, remaining=57, limit=57, capacity=57, mark=java.nio.HeapByteBuffer[pos=0 lim=57 cap=57], hash=1020455180}, initial=false, complete=true}
15:22:09.895 [] DEBUG io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Received snapshot 1 chunk from 2
15:22:09.895 [] DEBUG io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Committing snapshot io.atomix.raft.snapshot.InMemorySnapshot@176fb1
15:22:09.895 [] INFO  io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Committed snapshot io.atomix.raft.snapshot.InMemorySnapshot@176fb1
15:22:09.895 [] TRACE io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Sending InstallResponse{status=OK}

Leader sends snapshot at index 1. Node 0 commits it. But does not reset the log. (Bug!) We expect the follower to reset the log when ever it receives a new snapshot from the leader.

Now Node 0 has snapshot at index 1 and term 19 and log with entry at index 1 and term 5.(Bug!!)

15:22:09.896 [] TRACE io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Received AppendRequest{term=74, leader=2, prevLogIndex=1, prevLogTerm=19, entries=2, commitIndex=3}
15:22:09.896 [] DEBUG io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Rejected AppendRequest{term=74, leader=2, prevLogIndex=1, prevLogTerm=19, entries=2, commitIndex=3}: Previous entry term (19) does not equal the local log's last term (5)
15:22:09.896 [] TRACE io.atomix.raft.roles.FollowerRole - RaftServer{0-partition-1}{role=FOLLOWER} - Sending AppendResponse{status=OK, term=74, succeeded=false, lastLogIndex=0, lastSnapshotIndex=1}

Node 0 receives entry at index 2. Expected behavior => there is a snapshot at index 1, so it can append entry at 2. But since we have an entry at index 1 in the log, it is using that to verify the previous entry. So it fails. And this repeats. 

Fix for this is to ensure that the log is reset when a follower receives a snapshot from the leader.

Why is the log not reset?

• Because of this check if (lastIndex < index) {

  zeebe/atomix/cluster/src/main/java/io/atomix/raft/roles/PassiveRole.java

  Line 770 in ced608b

  if (lastIndex < index) {

Can we remove this check?

• This check was needed because of the snapshot replication outside of raft. We can remove this now. But simply removing this does not work. The same code is also used to reset the log in the init of a role. This is needed to guarantee that if the node crashes after snapshot is committed, but before resetting the log, the log is reset immediately after restart.

Proposed solution:

1. Remove this check and reset the log always when the follower receives a snapshot
2. Reset the log before the snapshot is committed.
3. Remove the reset of the log during init. No need for that because of Step 2

Originally posted by @deepthidevaki in #10183 (comment)