fix(raft): follower reset pendingsnapshot after rejecting install request

[deepthidevaki]

Description

• Extended RandomizedRaftTest to include snapshotting and compaction. This test could reproduce the bug Follower cannot receive snapshot because "chunk received out of order" #10180
• Without this fix, when a follower rejects a snapshot install request because it receives a duplicate chunk, the leader resets the snapshot replication and restart sending the same snapshot. But the follower has not reset its state, so it is still expecting a different chunk and reject the request again. The fix is to reset the pending snapshot when follower rejects a request on any error.

Extended RandomizedRaftTest partially covers #9837

Related issues

closes #10180
closes #10202

Definition of Done

Not all items need to be done depending on the issue and the pull request.

Code changes:

• The changes are backwards compatibility with previous versions
• If it fixes a bug then PRs are created to backport the fix to the last two minor versions. You can trigger a backport by assigning labels (e.g. backport stable/1.3) to the PR, in case that fails you need to create backports manually.

Testing:

• There are unit/integration tests that verify all acceptance criterias of the issue
• New tests are written to ensure backwards compatibility with further versions
• The behavior is tested manually
• The change has been verified by a QA run
• The impact of the changes is verified by a benchmark

Documentation:

• The documentation is updated (e.g. BPMN reference, configuration, examples, get-started guides, etc.)
• New content is added to the release announcement
• If the PR changes how BPMN processes are validated (e.g. support new BPMN element) then the Camunda modeling team should be informed to adjust the BPMN linting.

Please refer to our review guidelines.

[github-actions]

Test Results

   853 files  +    1     853 suites  +1   1h 37m 12s ⏱️ + 1m 51s
6 588 tests +150  6 577 ✔️ +151  11 💤  - 1  0 ❌ ±0 
6 772 runs  +150  6 761 ✔️ +151  11 💤  - 1  0 ❌ ±0 

Results for commit 69df0fa. ± Comparison against base commit fabb2d2.

♻️ This comment has been updated with latest results.

[oleschoenburg]

livenessTestWithSnapshot with seed "6" fails for me, even if I increase maxStepsToReplicateEntries to 10000.

org.opentest4j.AssertionFailedError: [All entries should be committed] 
expected: IndexedRaftLogEntryImpl[index=1, term=2, entry=InitialEntry[], record=PersistedJournalRecord[metadata=RecordMetadata[checksum=966814682, length=45], record=RecordData[index=1, asqn=-1, data=UnsafeBuffer{addressOffset=140332419498078, capacity=17, byteArray=null, byteBuffer=java.nio.DirectByteBufferR[pos=0 lim=10194 cap=10194]}]]]
 but was: null
Expected :IndexedRaftLogEntryImpl[index=1, term=2, entry=InitialEntry[], record=PersistedJournalRecord[metadata=RecordMetadata[checksum=966814682, length=45], record=RecordData[index=1, asqn=-1, data=UnsafeBuffer{addressOffset=140332419498078, capacity=17, byt ...

Actual   :null

[deepthidevaki]

livenessTestWithSnapshot with seed "6" fails for me, even if I increase maxStepsToReplicateEntries to 10000.

Thanks. Will look into it.

[deepthidevaki]

🤔 livenessWithSnapshot passes for me with seed = 6.

 @Property(tries = 10, shrinking = ShrinkingMode.OFF, edgeCases = EdgeCasesMode.NONE, seed = "6")
  void livenessTestWithSnapshot(

Config reported by the test

tries = 10                    | # of calls to property
checks = 10                   | # of not rejected calls
generation = RANDOMIZED       | parameters are randomly generated
after-failure = PREVIOUS_SEED | use the previous seed
when-fixed-seed = ALLOW       | fixing the random seed is allowed
edge-cases#mode = NONE        | edge cases are not explicitly generated
seed = 6                      | random seed to reproduce generated values

[oleschoenburg]

Interesting. At first I thought I couldn't reproduce it either but after bumping "tries" to 1000, it started failing again. Just to make sure, I did a mvn clean compile and then ran the test with:

@Property(tries = 1000, shrinking = ShrinkingMode.OFF, edgeCases = EdgeCasesMode.NONE, seed = "6")

for me this fails again:

timestamp = 2022-08-25T17:29:59.343969738, RandomizedRaftTest:livenessTestWithSnapshot = 
  org.opentest4j.AssertionFailedError:
    [All entries should be committed] 
    expected: IndexedRaftLogEntryImpl[index=1, term=3, entry=InitialEntry[], record=PersistedJournalRecord[metadata=RecordMetadata[checksum=3449732498, length=45], record=RecordData[index=1, asqn=-1, data=UnsafeBuffer{addressOffset=139960984518750, capacity=17, byteArray=null, byteBuffer=java.nio.DirectByteBufferR[pos=0 lim=10194 cap=10194]}]]]
     but was: null

                              |-------------------jqwik-------------------
tries = 72                    | # of calls to property
checks = 72                   | # of not rejected calls
generation = RANDOMIZED       | parameters are randomly generated
after-failure = PREVIOUS_SEED | use the previous seed
when-fixed-seed = ALLOW       | fixing the random seed is allowed
edge-cases#mode = NONE        | edge cases are not explicitly generated
seed = 6                      | random seed to reproduce generated values

EDIT: Ah I think I get it: the number of tries is also required to reproduce, just the seed is not enough. It always fails on try number 72, so running with just 10 tries will not reproduce it even with the correct seed.

[oleschoenburg]

The fix itself looks good to me but I think we should look into the test failures before merging. Anyway, nice find @deepthidevaki 🚀

[deepthidevaki]

I can reproduce it with seed="6" and tries =100. It failed at try 72.

On an initial look, it could have uncovered a new bug in raft. Follower 0 is not able replicate event from the leader. It is caught in an error loop:

10:10:43.887 [] TRACE io.atomix.raft.roles.LeaderAppender - RaftServer{1-partition-1} - Sending AppendRequest{term=26, leader=1, prevLogIndex=1, prevLogTerm=10, entries=2, commitIndex=2} to 0

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

10:10:43.887 [] TRACE io.atomix.raft.roles.LeaderAppender - RaftServer{1-partition-1} - Received AppendResponse{status=OK, term=26, succeeded=false, lastLogIndex=0, lastSnapshotIndex=1} from 0
10:10:43.887 [] TRACE io.atomix.raft.roles.LeaderAppender - RaftServer{1-partition-1} - Reset next index for RaftMemberContext{member=0, term=26, configIndex=0, snapshotIndex=1, nextSnapshotIndex=0, nextSnapshotChunk=null, matchIndex=0, heartbeatTime=1661501443887, appending=0, appendSucceeded=false, appendTime=1661501443887, configuring=false, installing=false, failures=0} to 1
10:10:43.887 [] TRACE io.atomix.raft.roles.LeaderAppender - RaftServer{1-partition-1} - Sending AppendRequest{term=26, leader=1, prevLogIndex=1, prevLogTerm=10, entries=2, commitIndex=2} to 0

I will look into it further.

[deepthidevaki]

Was also able to reproduce with seed "-47087393671576789" in try 9.

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) { https://github.com/camunda/zeebe/blob/ced608bdcf13e3fb99bac9145191d6e742d73aa8/atomix/cluster/src/main/java/io/atomix/raft/roles/PassiveRole.java#L770

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

[deepthidevaki]

After the fix, I ran the test > 125 times with default test configuration. All tests passed. Before it was failing with in 20 runs. Hope it will be fine now 🤞

[oleschoenburg]

❓ With these changes here, a failure while committing the snapshot means that the broker loses data because it already reset the log prior to committing the snapshot. Isn't this problematic?

Say there is a bug where a received snapshot can't be committed. Previously, a running system would have been able to continue (just without snapshot replication, and maybe the next received snapshot can be committed again). Now, with these changes, all followers (or at least those that receive such a snapshot) would lose data immediately and only the leader would be left with the full data.

[oleschoenburg]

That's it, LGTM 🚀

[deepthidevaki]

bors merge

[zeebe-bors-camunda]

Build succeeded:

• Java checks
• Go linting
• Test summary

[backport-action]

Backport failed for stable/1.3, because it was unable to cherry-pick the commit(s).

Please cherry-pick the changes locally.

git fetch origin stable/1.3
git worktree add -d .worktree/backport-10183-to-stable/1.3 origin/stable/1.3
cd .worktree/backport-10183-to-stable/1.3
git checkout -b backport-10183-to-stable/1.3
ancref=$(git merge-base fabb2d2f2e1f3affd1073a9069e21c27a7b8f0bd 69df0fac65c909a3e97a0c39174cd857ad2d9680)
git cherry-pick -x $ancref..69df0fac65c909a3e97a0c39174cd857ad2d9680

[backport-action]

Backport failed for stable/8.0, because it was unable to cherry-pick the commit(s).

Please cherry-pick the changes locally.

git fetch origin stable/8.0
git worktree add -d .worktree/backport-10183-to-stable/8.0 origin/stable/8.0
cd .worktree/backport-10183-to-stable/8.0
git checkout -b backport-10183-to-stable/8.0
ancref=$(git merge-base fabb2d2f2e1f3affd1073a9069e21c27a7b8f0bd 69df0fac65c909a3e97a0c39174cd857ad2d9680)
git cherry-pick -x $ancref..69df0fac65c909a3e97a0c39174cd857ad2d9680