Failed to take snapshot in leader because index entry is not found

[deepthidevaki]

Describe the bug

2022-07-12 01:28:37.329 CEST
Failed to take a snapshot for Broker-1-StreamProcessor-2
"io.camunda.zeebe.broker.system.partitions.NoEntryAtSnapshotPosition: Failed to take snapshot. Expected to find an indexed entry for determined snapshot position 1494387075 (processedPosition = 1494736551, exportedPosition=1494387075), but found no matching indexed entry which contains this position.

This occurred in the leader.

Related to #7911 . But in that issue, it was followers who could not take snapshot and that is a valid scenario. However, leaders should always be able to take snapshot.

The impact of this bug is low (See following section). There is no data inconsistency or loss. The snapshot is taken later when new events are exported. However if exporting does not resume, it will not take new snapshot. So reprocessing time will be high.

To Reproduce

Following events happened in the broker leading to the above error.

1. Broker receives a new snapshot and replace existing log.

 2022-07-12 01:26:19.338 CEST
RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Committed snapshot FileBasedSnapshot{directory=/usr/local/zeebe/data/raft-partition/partitions/2/snapshots/494998838-19-1494391974-1494387075, checksumFile=/usr/local/zeebe/data/raft-partition/partitions/2/snapshots/494998838-19-1494391974-1494387075.checksum, checksum=1722253646, metadata=FileBasedSnapshotMetadata{index=494998838, term=19, processedPosition=1494391974, exporterPosition=1494387075}}
2022-07-12 01:26:19.339 CEST
RaftServer{raft-partition-partition-2}{role=FOLLOWER} - Delete existing log (lastIndex '494887084') and replace with received snapshot (index '494998838')
2022-07-12 01:26:19.773 CEST
Transition to FOLLOWER on term 19 requested.
...
2022-07-12 01:26:19.922 CEST
Transition to FOLLOWER on term 19 completed

2. Broker later becomes the leader

2022-07-12 01:26:37.184 CEST
Transition to LEADER on term 20 starting

2022-07-12 01:26:37.217 CEST
Recovered exporter 'Broker-1-Exporter-2' from snapshot at lastExportedPosition 1494387075

3. No new records are exported

2022-07-12 01:27:38.251 CEST
Unexpected exception occurred on periodically flushing bulk, will retry later.
2022-07-12 01:28:08.589 CEST
Error on exporting record with key 4503600188691487
2022-07-12 01:28:37.329 CEST

4. Tries to take snapshot at the same exportedPosition but with different processedPosition, but fails.

2022-07-12 01:28:37.329 CEST
Failed to take a snapshot for Broker-1-StreamProcessor-2
"io.camunda.zeebe.broker.system.partitions.NoEntryAtSnapshotPosition: Failed to take snapshot. Expected to find an indexed entry for determined snapshot position 1494387075 (processedPosition = 1494736551, exportedPosition=1494387075), but found no matching indexed entry which contains this position.

Hypothesis

It fails to get the index because, it is trying to get the "previous" entry -> entry at index 494998838. Since there is already a snapshot at that index, raft leader would have only replicated event from index 494998839. The record with the position 1494387075 is at index 494998839. So there is no inconsistency in the logs but it cannot take snapshot because the previous index is already compacted.

Expected behavior

Leader should take a snapshot if exporter position has not changed, but it has processed new events.

Log/Stacktrace

Logs

Full Stacktrace

"io.camunda.zeebe.broker.system.partitions.NoEntryAtSnapshotPosition: Failed to take snapshot. Expected to find an indexed entry for determined snapshot position 1494387075 (processedPosition = 1494736551, exportedPosition=1494387075), but found no matching indexed entry which contains this position.
	at io.camunda.zeebe.broker.system.partitions.impl.StateControllerImpl.takeTransientSnapshotInternal(StateControllerImpl.java:160) ~[zeebe-broker-8.1.0-SNAPSHOT.jar:8.1.0-SNAPSHOT]
	at io.camunda.zeebe.broker.system.partitions.impl.StateControllerImpl.lambda$takeTransientSnapshot$0(StateControllerImpl.java:69) ~[zeebe-broker-8.1.0-SNAPSHOT.jar:8.1.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.ActorJob.invoke(ActorJob.java:79) ~[zeebe-scheduler-8.1.0-SNAPSHOT.jar:8.1.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.ActorJob.execute(ActorJob.java:44) ~[zeebe-scheduler-8.1.0-SNAPSHOT.jar:8.1.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.ActorTask.execute(ActorTask.java:116) ~[zeebe-scheduler-8.1.0-SNAPSHOT.jar:8.1.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.ActorThread.executeCurrentTask(ActorThread.java:97) ~[zeebe-scheduler-8.1.0-SNAPSHOT.jar:8.1.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.ActorThread.doWork(ActorThread.java:81) ~[zeebe-scheduler-8.1.0-SNAPSHOT.jar:8.1.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.ActorThread.run(ActorThread.java:189) ~[zeebe-scheduler-8.1.0-SNAPSHOT.jar:8.1.0-SNAPSHOT]

[oleschoenburg]

Happened again: https://console.cloud.google.com/errors/detail/CNS4is-G4-2f2QE?project=camunda-cloud-240911