microsoft / microsoft/garnet

`--fail-on-recovery-error true` still serves an incomplete AOF tail when no HybridLog checkpoint is readable

Open
#2,150 0 comments 0 reactions 1 assignee Claimed by @TedHartMS View on GitHub
Dominant language
C#
Stars
12k
Forks
703
Avg merge
2d 19h
Merged PRs (30d)
36

Description

## Describe the bug

Garnet can start serving an incomplete database when no HybridLog checkpoint is
readable, even with:

```text
--recover
--fail-on-recovery-error true
```

A minimal standalone reproduction:

1. writes 200 keys;
2. takes a successful checkpoint;
3. writes five more keys as an AOF-only tail;
4. explicitly commits the AOF;
5. shuts down gracefully;
6. makes the sole HybridLog checkpoint metadata unreadable while Garnet is stopped;
7. restarts over the same persistent directory.

On restart, Garnet:

- logs `Skipping unreadable HybridLog checkpoint`;
- throws `TsavoriteNoHybridLogException` internally;
- 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

See
[`--fail-on-recovery-error`](https://github.com/microsoft/garnet/blob/v2.1.8/libs/host/Configuration/Options.cs#L636-L638).

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.

```bash
#!/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" || true
```

Observed output:

```text
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:201
```

Relevant boot log:

```text
"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 connections
```

The 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//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:

```text
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:201
```

This 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:

```text
No Hybrid Log found for recovery; storeVersion = 0
Recovered AOF: begin address = 64, tail address = 21628
Total number of replayed records 200
DBSIZE=200
```

Thus 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:

1. Empty first start with recovery enabled: starts successfully.
2. No checkpoint plus a complete AOF: replays the complete AOF successfully.
3. Valid checkpoint plus truncated AOF tail: recovers checkpoint and tail.
4. Unreadable sole checkpoint plus truncated AOF tail and
`FailOnRecoveryError=true`: refuses to serve.
5. 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`](https://github.com/microsoft/garnet/commit/277ea6c34def67107bd643dd55e269b4e4c0964b).

## 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`](https://github.com/microsoft/garnet/blob/v2.1.8/libs/storage/Tsavorite/cs/src/core/Index/Recovery/Recovery.cs#L364-L370)
throws `TsavoriteNoHybridLogException` after the checkpoint scan finds no valid
HybridLog token.

[`SingleDatabaseManager.RecoverCheckpointAsync`](https://github.com/microsoft/garnet/blob/v2.1.8/libs/server/Databases/SingleDatabaseManager.cs#L57-L93)
catches that exception separately and always continues:

```csharp
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`](https://github.com/microsoft/garnet/blob/v2.1.8/libs/server/AOF/Recover/AofRecover.cs#L89-L97).
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:

```text
storeVersion: -1
storeHlogToken: 00000000-0000-0000-0000-000000000000
storeIndexToken: 00000000-0000-0000-0000-000000000000
```

[`PurgeAllCheckpointsExceptEntry`](https://github.com/microsoft/garnet/blob/v2.1.8/libs/cluster/Server/Replication/CheckpointStore.cs#L77-L107)
then treats the default tokens as the selected checkpoint and deletes every
HybridLog and index token. The observed trace was:

```text
[PurgeAllCheckpointsExceptEntry] ... storeVersion: -1
storeHlogToken: 00000000-...
storeIndexToken: 00000000-...
Deleting log token
Deleting index 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](https://github.com/microsoft/garnet/issues/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=true` being bypassed. Its fix in
[PR #2093](https://github.com/microsoft/garnet/pull/2093) is already present in
both affected releases.
- [PR #2145](https://github.com/microsoft/garnet/pull/2145) explicitly leaves the
`TsavoriteNoHybridLogException` catch 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](https://github.com/microsoft/garnet/issues/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.

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.