`--fail-on-recovery-error true` still serves an incomplete AOF tail when no HybridLog checkpoint is readable
Describe the bug
Garnet can start serving an incomplete database when no HybridLog checkpoint is readable, even with:
--recover
--fail-on-recovery-error trueA minimal standalone reproduction:
- writes 200 keys;
- takes a successful checkpoint;
- writes five more keys as an AOF-only tail;
- explicitly commits the AOF;
- shuts down gracefully;
- makes the sole HybridLog checkpoint metadata unreadable while Garnet is stopped;
- restarts over the same persistent directory.
On restart, Garnet:
- logs
Skipping unreadable HybridLog checkpoint; - throws
TsavoriteNoHybridLogExceptioninternally; - handles that exception as though this were a fresh start;
- recovers and replays only the retained AOF tail;
- announces
Ready to accept connections; - serves 5 keys instead of the 205 durably written keys.
The recovery failure is logged, so this is not silent in the logging sense. The problem is fail-open startup: the node serves incomplete state despite the option whose documented behavior is:
Server bootup should fail if errors happen during bootup of AOF and checkpointing
This is not a request to recover deliberately corrupted metadata. The expected behavior is to refuse to serve when the remaining checkpoint/AOF history cannot reconstruct the database.
Steps to reproduce the bug
Requires Bash and Docker. The script preserves complete pre-injection and pre-boot data-directory copies under the printed temporary directory.
#!/usr/bin/env bash
set -euo pipefail
suffix="$$"
network="garnet-recovery-failopen-${suffix}"
node="garnet-recovery-failopen-${suffix}"
root="$(mktemp -d)"
data="$root/data"
image="ghcr.io/microsoft/garnet:2.1.8"
client_image="redis:7-alpine"
mkdir -p \
"$data" \
"$root/pre-injection" \
"$root/pre-boot" \
"$root/post-boot"
chmod 0777 \
"$root" \
"$data" \
"$root/pre-injection" \
"$root/pre-boot" \
"$root/post-boot"
cleanup() {
docker rm -f "$node" >/dev/null 2>&1 || true
docker network rm "$network" >/dev/null 2>&1 || true
echo "Captured data remains at: $root"
}
trap cleanup EXIT
docker network create "$network" >/dev/null
start_node() {
docker run -d \
--name "$node" \
--network "$network" \
--network-alias garnet \
-v "$data:/data" \
"$image" \
--aof \
--recover \
--fail-on-recovery-error true \
--logger-level Trace \
--bind 0.0.0.0 \
--port 6379 \
--checkpointdir /data/checkpoints \
--index 64m >/dev/null
}
wait_ready() {
for attempt in $(seq 1 30); do
if [ "$(docker run --rm --network "$network" "$client_image" \
redis-cli -h garnet PING 2>/dev/null || true)" = PONG ]; then
return 0
fi
sleep 1
done
return 1
}
start_node
wait_ready
docker run --rm --network "$network" "$client_image" sh -ec '
i=1
while [ "$i" -le 200 ]; do
redis-cli -h garnet SET "base:$i" "value:$i" >/dev/null
i=$((i + 1))
done
redis-cli -h garnet SAVE >/dev/null
i=201
while [ "$i" -le 205 ]; do
redis-cli -h garnet SET "tail:$i" "value:$i" >/dev/null
i=$((i + 1))
done
printf "before_stop_dbsize="
redis-cli -h garnet DBSIZE
printf "commitaof="
redis-cli -h garnet COMMITAOF
'
docker stop -t 30 "$node" >/dev/null
docker rm "$node" >/dev/null
# Preserve the complete untouched directory, then change only the sole
# HybridLog checkpoint metadata file.
docker run --rm -v "$root:/work" "$client_image" sh -ec '
cp -a /work/data/. /work/pre-injection/
metadata=$(find \
/work/data/checkpoints/Store/checkpoints/cpr-checkpoints \
-name info.dat.0)
count=$(printf "%s\n" "$metadata" | grep -c .)
[ "$count" -eq 1 ]
size=$(stat -c %s "$metadata")
prefix=$(od -An -tu4 -N4 "$metadata" | tr -d " ")
echo "metadata=$metadata size=$size prefix=$prefix"
[ "$size" -gt 0 ]
[ "$prefix" -gt 0 ]
dd \
if=/dev/zero \
of="$metadata" \
bs="$size" \
count=1 \
conv=notrunc \
status=none
cp -a /work/data/. /work/pre-boot/
'
start_node
if wait_ready; then
echo "restart_result=READY"
docker run --rm --network "$network" "$client_image" sh -ec '
printf "after_restart_dbsize="
redis-cli -h garnet DBSIZE
printf "base_1="
redis-cli -h garnet GET base:1
printf "tail_201="
redis-cli -h garnet GET tail:201
'
else
echo "restart_result=REFUSED"
fi
docker logs "$node" >"$root/restart.log" 2>&1
docker run --rm -v "$root:/work" "$client_image" sh -ec '
cp -a /work/data/. /work/post-boot/
'
echo "recovery markers:"
grep -E \
'FailOnRecoveryError|Skipping unreadable HybridLog|No Hybrid Log found|Recovered AOF|replayed records|Ready to accept connections' \
"$root/restart.log" || trueObserved output:
before_stop_dbsize=205
commitaof=AOF file committed
metadata=.../cpr-checkpoints/4f140e6f-.../info.dat.0 size=512 prefix=268
restart_result=READY
after_restart_dbsize=5
base_1=
tail_201=value:201Relevant boot log:
"FailOnRecoveryError": true
Skipping unreadable HybridLog checkpoint: 4f140e6f-...
Tsavorite.core.TsavoriteException: Invalid metadata length 0 in
cpr-checkpoints/4f140e6f-.../info.dat; the metadata file is truncated or corrupt
No Hybrid Log found for recovery; storeVersion = 0;
Tsavorite.core.TsavoriteNoHybridLogException:
Unable to find valid HybridLog token
Recovered AOF: begin address = 21628, tail address = 22212, DB ID: 0
Total number of replayed records 5
* Ready to accept connectionsThe checkpoint contains the first 200 keys. The AOF begins at address 21628 because the successful checkpoint advanced/truncated its recoverable prefix. Only the five post-checkpoint records remain reconstructive without that checkpoint.
The test modifies only cpr-checkpoints/<token>/info.dat.0. A recursive
comparison of the complete pre-injection and pre-boot snapshots reported
exactly that one differing file.
Controls
Untouched checkpoint
Booting a copy of the complete pre-injection directory with the same command
recovers correctly:
Recovered store to version 1
Recovered AOF: begin address = 21628, tail address = 22212, DB ID: 0
Total number of replayed records 5
DBSIZE=205
base:1=value:1
tail:201=value:201This uses the same AOF addresses as the injected run. The difference is whether the checkpoint is readable.
Complete AOF without any checkpoint
A separate control writes 200 keys, never takes a checkpoint, commits the AOF, and restarts with the same recovery options:
No Hybrid Log found for recovery; storeVersion = 0
Recovered AOF: begin address = 64, tail address = 21628
Total number of replayed records 200
DBSIZE=200Thus a fresh/AOF-only start can remain supported. It differs observably from the unsafe case:
- no checkpoint metadata exists;
- the AOF starts at the first valid address, 64;
- the full dataset is replayable.
Expected behavior
With --fail-on-recovery-error true, Garnet should refuse to serve when:
- checkpoint tokens exist but none can be read; and
- the retained AOF does not start at the first valid address and therefore cannot reconstruct the missing checkpointed prefix.
The server should report the recovery failure clearly and preserve the checkpoint artifacts for diagnosis.
A fresh directory, or an AOF-only database whose complete log begins at address 64, should still be allowed to start.
Possible regression coverage:
- Empty first start with recovery enabled: starts successfully.
- No checkpoint plus a complete AOF: replays the complete AOF successfully.
- Valid checkpoint plus truncated AOF tail: recovers checkpoint and tail.
- Unreadable sole checkpoint plus truncated AOF tail and
FailOnRecoveryError=true: refuses to serve. - The same cluster-mode case: refuses to serve without purging the unreadable checkpoint artifacts.
Release version
Reproduced against both:
- Garnet v2.1.8:
ghcr.io/microsoft/garnet@sha256:20d9f41b02bcdf8aae1ad734fb7e31ef98b06efffdfa487eeea49687bdd3ff55 - Garnet v2.1.7:
ghcr.io/microsoft/garnet@sha256:19bc507a8d84da467951a5db16b3e9976358f0b0f22029f38d4edae26769e072
The relevant behavior is unchanged on current main at
277ea6c.
IDE
Not applicable; reproduced with the official Docker images and RESP commands.
OS version
Reproduced with the official Linux/arm64 containers using Docker Engine 29.7.2 on macOS 26.6.2 arm64.
Additional context
Why FailOnRecoveryError is bypassed
FindRecoveryInfo
throws TsavoriteNoHybridLogException after the checkpoint scan finds no valid
HybridLog token.
SingleDatabaseManager.RecoverCheckpointAsync
catches that exception separately and always continues:
catch (TsavoriteNoHybridLogException ex)
{
// No hybrid log being found is not the same as an error in recovery. e.g. fresh start
Logger?.LogInformation(
ex,
"No Hybrid Log found for recovery; storeVersion = {storeVersion};",
storeVersion);
}Only the following general catch (Exception) consults
FailOnRecoveryError.
That assumption is valid for a genuinely fresh start but not when checkpoint tokens were found and rejected as unreadable. It is also not safe when the recovered AOF begins after address 64.
AOF replay then starts at the retained log's current
BeginAddress.
No exception occurs while replaying the valid tail, so the AOF-side
FailOnRecoveryError check is never reached.
Cluster-mode amplification
The standalone reproducer above preserves the unreadable checkpoint directories.
In cluster mode the same data-loss outcome reproduces, and an additional
destructive behavior occurs. CheckpointStore.GetLatestCheckpointEntryFromDisk
returns a non-null entry with:
storeVersion: -1
storeHlogToken: 00000000-0000-0000-0000-000000000000
storeIndexToken: 00000000-0000-0000-0000-000000000000PurgeAllCheckpointsExceptEntry
then treats the default tokens as the selected checkpoint and deletes every
HybridLog and index token. The observed trace was:
[PurgeAllCheckpointsExceptEntry] ... storeVersion: -1
storeHlogToken: 00000000-...
storeIndexToken: 00000000-...
Deleting log token <actual token>
Deleting index token <actual token>The node subsequently starts with only the AOF tail. Purging should not run from an invalid/default recovery selection, particularly before recovery success is known.
Duplicate search
I searched open and closed Garnet issues and pull requests for
FailOnRecoveryError, TsavoriteNoHybridLogException,
PurgeAllCheckpointsExceptEntry, unreadable/corrupt checkpoint metadata,
incomplete/empty recovery, fail-open recovery, and AOF BeginAddress. I found no
matching report.
Nearest results, but not duplicates:
- #2076 reported a pre-listen
hang when no valid HybridLog token was found. It did not demonstrate a
successfully committed checkpoint plus truncated AOF, incomplete state being
served, or
FailOnRecoveryError=truebeing bypassed. Its fix in PR #2093 is already present in both affected releases. - PR #2145 explicitly leaves the
TsavoriteNoHybridLogExceptioncatch unchanged to support a never-checkpointed fresh start. This report demonstrates a distinguishable non-fresh case: an unreadable checkpoint token exists and the AOF begins after address 64. - #2149 reports transient false metadata-read failures caused by concurrent reads. This reproduction permanently changes the metadata while Garnet is stopped. It demonstrates the unsafe recovery response to having no readable checkpoint; it does not claim that #2149 caused the persisted metadata state.
Source: microsoft/garnet