microsoft / microsoft/garnet

`DeleteOutdatedCheckpoints` retains a deleted hlog token, causing metadata parse failures on every later checkpoint

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

Description

## Describe the bug

In cluster mode with AOF enabled, the second checkpoint leaves `CheckpointStore` pointing at a partially deleted checkpoint. Every subsequent checkpoint then:

- logs `Best effort read of checkpoint metadata failed`;
- throws `ArgumentNullException` from `Int32.Parse` in `HybridLogRecoveryInfo.Initialize`;
- logs `Skipping hlog truncation ... because checkpoint metadata could not be read`;
- retains the same failing checkpoint token as the list head.

The first checkpoint's metadata is valid immediately after it is written. During the second checkpoint, [`DeleteOutdatedCheckpoints`](https://github.com/microsoft/garnet/blob/v2.1.7/libs/cluster/Server/Replication/CheckpointStore.cs#L163-L214) performs this sequence:

1. The old hybrid-log token is not shared, so lines 180–182 delete it.
2. The old index token is shared with the incremental checkpoint, so lines 184–185 break without advancing `curr`.
3. Lines 202–203 call `GetLogFileSize` using the hybrid-log token that was just deleted.
4. [`GetLogCheckpointMetadata`](https://github.com/microsoft/garnet/blob/v2.1.7/libs/cluster/Server/Replication/GarnetClusterCheckpointManager.cs#L144-L162) reads an empty metadata file.
5. [`HybridLogRecoveryInfo.Initialize`](https://github.com/microsoft/garnet/blob/v2.1.7/libs/storage/Tsavorite/cs/src/core/Index/CheckpointManagement/RecoveryInfo.cs#L128-L132) receives `null` from its first `ReadLine()` and calls `Int32.Parse(null)`.
6. Line 213 assigns the same partially deleted entry back to `head`, so every later checkpoint repeats the failure against the same token.

This is deterministic and data-independent. It requires neither a replica nor storage tiering, recovery, a large dataset, or concurrent writes.

Later checkpoints themselves still land. The failure is in cleanup: the head never advances, CPR checkpoint directories accumulate, and `ShiftBeginAddress(..., truncateLog: true)` is skipped each time. On a long-running persistent node this causes retained checkpoint and hybrid-log data to grow on disk.

## Steps to reproduce the bug

Requires Bash and Docker. `--index 64m` only keeps the checkpoint artifact small.

```bash
#!/usr/bin/env bash
set -euo pipefail

suffix="$$"
network="garnet-checkpoint-metadata-${suffix}"
node="garnet-checkpoint-metadata-${suffix}"
client="garnet-checkpoint-client-${suffix}"
data="$(mktemp -d)"
image="ghcr.io/microsoft/garnet:2.1.7"
client_image="redis:7-alpine"

cleanup() {
docker rm -f "$client" "$node" >/dev/null 2>&1 || true
docker network rm "$network" >/dev/null 2>&1 || true
rm -rf "$data"
}
trap cleanup EXIT

chmod 0777 "$data"
docker network create "$network" >/dev/null

docker run -d \
--name "$node" \
--network "$network" \
--network-alias garnet \
-v "$data:/data" \
"$image" \
--cluster \
--aof \
--bind 0.0.0.0 \
--port 6379 \
--checkpointdir /data/checkpoints \
--index 64m >/dev/null

docker run --rm \
--name "$client" \
--network "$network" \
-v "$data:/data:ro" \
"$client_image" sh -ec '
ready=0
for attempt in $(seq 1 30); do
if [ "$(redis-cli -h garnet PING 2>/dev/null)" = PONG ]; then
ready=1
break
fi
sleep 1
done
[ "$ready" = 1 ]

redis-cli -h garnet CLUSTER ADDSLOTSRANGE 0 16383 >/dev/null

i=1
while [ "$i" -le 8 ]; do
redis-cli -h garnet SET "key:$i" "value$i" >/dev/null
i=$((i + 1))
done

inventory() {
find /data/checkpoints/Store/checkpoints/cpr-checkpoints \
-name info.dat.0 \
-exec stat -c "%n %s bytes" {} \; |
sort
}

redis-cli -h garnet SAVE
echo "after checkpoint 1:"
inventory

sleep 2
redis-cli -h garnet SAVE
echo "after checkpoint 2:"
inventory

sleep 2
redis-cli -h garnet SAVE
echo "after checkpoint 3:"
inventory
'

docker logs "$node" 2>&1 |
grep -E 'Best effort read|Skipping hlog truncation' || true
```

Observed output:

```text
OK
after checkpoint 1:
/data/checkpoints/Store/checkpoints/cpr-checkpoints/dab48e3f-.../info.dat.0 512 bytes

OK
after checkpoint 2:
/data/checkpoints/Store/checkpoints/cpr-checkpoints/37daf799-.../info.dat.0 512 bytes
/data/checkpoints/Store/checkpoints/cpr-checkpoints/dab48e3f-.../info.dat.0 0 bytes

OK
after checkpoint 3:
/data/checkpoints/Store/checkpoints/cpr-checkpoints/1ec2b85d-.../info.dat.0 512 bytes
/data/checkpoints/Store/checkpoints/cpr-checkpoints/37daf799-.../info.dat.0 512 bytes
/data/checkpoints/Store/checkpoints/cpr-checkpoints/dab48e3f-.../info.dat.0 0 bytes
```

The first token initially has a valid 512-byte metadata file. Checkpoint 2 reduces that file to zero bytes, and both later cleanup attempts fail against that same token:

```text
fail: GarnetServer[0] Best effort read of checkpoint metadata failed
System.ArgumentNullException: Value cannot be null. (Parameter 's')
at System.Int32.Parse(String s)
at Tsavorite.core.HybridLogRecoveryInfo.Initialize(StreamReader reader)
in .../RecoveryInfo.cs:line 131
at Garnet.cluster.GarnetClusterCheckpointManager.ConvertMetadata(Byte[] checkpointMetadata)
in .../GarnetClusterCheckpointManager.cs:line 80

warn: ReplicationManager[0] Skipping hlog truncation for checkpoint
dab48e3f-4315-4a9a-b5b0-77d8d096669a because checkpoint metadata could not be read
...
at Garnet.cluster.CheckpointStore.DeleteOutdatedCheckpoints()
in .../CheckpointStore.cs:line 202
```

Checkpoint 3 produces the same pair of messages for `dab48e3f-...`.

On Windows, the read of the empty file additionally logs:

```text
[DeviceLogManager] OverlappedStream GetQueuedCompletionStatus error: 38
msg: Reached the end of the file.
```

The Linux container does not need that device-level EOF message to reproduce the same parse failure.

## Expected behavior

Checkpoint cleanup must not read a hybrid-log token after deleting it.

When an old checkpoint has a deletable hlog token but a shared index token, cleanup should either:

- invalidate and advance past the old checkpoint entry while retaining the shared index files for the newer entry; or
- defer the deletion until the entry can be removed consistently.

After repeated checkpoints:

- no metadata parsing exception should occur;
- `head` should identify an actually readable checkpoint;
- obsolete checkpoint entries/directories should be removed;
- hybrid-log truncation should not be skipped.

A regression test should take at least two checkpoints in cluster mode with AOF enabled and assert both the logs and retained checkpoint inventory. A single checkpoint cannot exercise this path.

## Release version

Garnet v2.1.7, official image:

```text
ghcr.io/microsoft/garnet@sha256:19bc507a8d84da467951a5db16b3e9976358f0b0f22029f38d4edae26769e072
```

The relevant files are unchanged on current `main` at [`f845a86`](https://github.com/microsoft/garnet/commit/f845a8639da27dc919567ef35d04a5a550203194) compared with v2.1.7.

## IDE

Not applicable; reproduced with Docker and RESP commands only.

## OS version

Reproduced with the official Linux/arm64 container using Docker Engine 29.7.2 on macOS 26.6.2 arm64.

The same failure stack has also been observed with Garnet 2.1.7 on Windows Server, where it includes `ERROR_HANDLE_EOF` / “Reached the end of the file.”

## Additional context

The cleanup and safe-truncation logic was introduced by [PR #1773](https://github.com/microsoft/garnet/pull/1773). Its existing replication cleanup test takes repeated checkpoints but does not assert that these warnings are absent or that old checkpoint metadata remains readable/gets removed.

I searched open and closed issues and PRs for the two log messages, `HybridLogRecoveryInfo`, `DeleteOutdatedCheckpoints`, `Int32.Parse`, `info.dat.0`, checkpoint cleanup/retention, and close paraphrases. I did not find a matching report.

Nearest results, but not duplicates:

- [#2072](https://github.com/microsoft/garnet/issues/2072) is a post-checkpoint `NullReferenceException` in object cleanup that makes later checkpoints full. It has a different stack and occurs after checkpoint/truncation success.
- [#2134](https://github.com/microsoft/garnet/issues/2134) is a 2 GiB hash-index short-write problem on Linux. This reproducer uses a 64 MiB index, affects hybrid-log metadata, and reproduces on Linux/arm64 where that native x64 I/O mechanism is not involved.
- [PR #2093](https://github.com/microsoft/garnet/pull/2093) made sector-rounded metadata reads tolerate `ERROR_HANDLE_EOF` and clear the read buffer. That code is already included in 2.1.7. Here EOF is secondary: cleanup first deletes the token and then reads its now-empty metadata file.

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.