microsoft / microsoft/garnet

`DeviceLogCommitCheckpointManager` shares I/O completions across concurrent reads, causing valid checkpoints to be skipped

Open
#2,149 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

Concurrent checkpoint-metadata reads are not isolated in
`DeviceLogCommitCheckpointManager`. Two concurrent `INFO ALL` requests can cause
Garnet to:

- log `Skipping unreadable index checkpoint`;
- report `Invalid metadata length 0`;
- return `disk_checkpoint_entry:(empty)` from one or both requests;

even though the checkpoint metadata file is valid and a serial read immediately
before and after the concurrent requests returns the same checkpoint successfully.

This reproduces on a single fresh node after one checkpoint. It does not require
replication, restart, failover, checkpoint transfer, concurrent writes, multiple
checkpoints, or damaged files.

The apparent cause is that every metadata operation shares the same instance-wide
[`SemaphoreSlim` and `metadataIoErrorCode`](https://github.com/microsoft/garnet/blob/v2.1.7/libs/storage/Tsavorite/cs/src/core/Index/CheckpointManagement/DeviceLogCommitCheckpointManager.cs#L31-L35).

[`ReadInto`](https://github.com/microsoft/garnet/blob/v2.1.7/libs/storage/Tsavorite/cs/src/core/Index/CheckpointManagement/DeviceLogCommitCheckpointManager.cs#L417-L451):

1. clears its leased buffer;
2. starts an asynchronous read;
3. waits on the shared semaphore;
4. copies and returns its buffer.

Every operation uses the same
[`IOCallback`](https://github.com/microsoft/garnet/blob/v2.1.7/libs/storage/Tsavorite/cs/src/core/Index/CheckpointManagement/DeviceLogCommitCheckpointManager.cs#L391-L405),
which releases that shared semaphore without identifying which operation completed.

With reads A and B in flight, A's completion can satisfy B's wait. B then copies
its own still-zeroed buffer and returns it to the pool while B's I/O remains
outstanding. The first four bytes therefore appear to be zero, and
[`GetIndexCheckpointMetadata`](https://github.com/microsoft/garnet/blob/v2.1.7/libs/storage/Tsavorite/cs/src/core/Index/CheckpointManagement/DeviceLogCommitCheckpointManager.cs#L241-L254)
rejects the valid token as truncated or corrupt.

The shared `metadataIoErrorCode` has the same ownership problem: one operation
can reset or observe another operation's result.

`WriteInto` uses the same semaphore, error field, callback and buffer-lifetime
pattern. The reproducer below demonstrates the concurrent-read failure only; it
does not claim that the on-disk metadata was corrupted.

## Steps to reproduce the bug

Requires Bash and Docker. The official Garnet 2.1.7 and Redis CLI images are
sufficient.

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

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

cleanup() {
docker rm -f "$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

for attempt in $(seq 1 30); do
if [ "$(docker run --rm --network "$network" "$client_image" \
redis-cli -h garnet PING 2>/dev/null)" = PONG ]; then
break
fi
sleep 1
done

docker run --rm --network "$network" "$client_image" \
redis-cli -h garnet CLUSTER ADDSLOTSRANGE 0 16383 >/dev/null
docker run --rm --network "$network" "$client_image" \
redis-cli -h garnet SET test-key test-value >/dev/null
docker run --rm --network "$network" "$client_image" \
redis-cli -h garnet SAVE >/dev/null

echo "serial read before concurrent requests:"
docker run --rm --network "$network" "$client_image" sh -ec \
'redis-cli -h garnet INFO ALL | sed -n "/# CheckpointInfo/,/^$/p"'

echo "two concurrent INFO ALL workers:"
docker run --rm --network "$network" "$client_image" sh -ec '
probe() {
misses=0
i=0
while [ "$i" -lt 1000 ]; do
response=$(redis-cli -h garnet INFO ALL)
if printf "%s\n" "$response" |
grep -q "disk_checkpoint_entry:(empty)"; then
misses=$((misses + 1))
fi
i=$((i + 1))
done
echo "worker observed $misses empty disk checkpoint entries"
}

probe & probe & wait
'

echo "metadata length prefix after concurrent requests:"
docker run --rm -v "$data:/data:ro" "$client_image" sh -ec '
find /data/checkpoints \
-path "*/index-checkpoints/*/info.dat.0" \
-exec sh -c '\''
printf "%s: " "$1"
od -An -tu4 -N4 "$1" | tr -d " "
'\'' sh {} \;
'

echo "serial read after concurrent requests:"
docker run --rm --network "$network" "$client_image" sh -ec \
'redis-cli -h garnet INFO ALL | sed -n "/# CheckpointInfo/,/^$/p"'

echo "first warnings:"
docker logs "$node" 2>&1 |
grep -m 3 "Skipping unreadable index checkpoint" || true
```

Observed on one run:

```text
serial read before concurrent requests:
# CheckpointInfo
memory_checkpoint_entry:storeVersion=2,...,storeIndexToken=52e1d0f1-...
disk_checkpoint_entry:storeVersion=2,...,storeIndexToken=52e1d0f1-...

two concurrent INFO ALL workers:
worker observed 145 empty disk checkpoint entries
worker observed 162 empty disk checkpoint entries

metadata length prefix after concurrent requests:
/data/checkpoints/Store/checkpoints/index-checkpoints/52e1d0f1-.../info.dat.0: 91

serial read after concurrent requests:
# CheckpointInfo
memory_checkpoint_entry:storeVersion=2,...,storeIndexToken=52e1d0f1-...
disk_checkpoint_entry:storeVersion=2,...,storeIndexToken=52e1d0f1-...
```

The counts vary, but the warning reproduced on both fresh runs attempted with
two clients.

The server log contains:

```text
warn: TsavoriteKV [main][0] Skipping unreadable index checkpoint:
52e1d0f1-...
Tsavorite.core.TsavoriteException: Invalid metadata length 0 in
index-checkpoints/52e1d0f1-.../info.dat; the metadata file is truncated or corrupt
at Tsavorite.core.DeviceLogCommitCheckpointManager.ThrowIfInvalidMetadataSize(...)
at Tsavorite.core.DeviceLogCommitCheckpointManager.GetIndexCheckpointMetadata(...)
at Tsavorite.core.IndexRecoveryInfo.Recover(...)
at Tsavorite.core.TsavoriteKV`2.GetClosestIndexCheckpointInfo(...)
```

The physical file still has a nonzero length prefix (`91` in this run), and
serial reads before and after the failure recover it successfully. The
“truncated or corrupt” diagnosis is therefore false in this reproducer.

## Expected behavior

Each metadata operation must wait for its own I/O completion and retain its
buffer until that specific operation completes.

Concurrent `INFO ALL` requests should:

- return the same valid `disk_checkpoint_entry`;
- not log `Skipping unreadable index checkpoint`;
- not classify a valid metadata file as having length zero.

The completion signal, error code and buffer lease should be operation-specific,
or access to the entire metadata I/O sequence should be serialized.

Because reads and writes currently share this machinery, regression coverage
should include:

1. two concurrent metadata reads whose completions are deliberately reordered;
2. a metadata read concurrent with a metadata write;
3. verification that no buffer is returned before its associated callback;
4. verification that one operation cannot consume another operation's error.

## Release version

Garnet v2.1.7, official image:

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

The relevant `DeviceLogCommitCheckpointManager` code is unchanged on current
`main` at commit
[`277ea6c`](https://github.com/microsoft/garnet/commit/277ea6c34def67107bd643dd55e269b4e4c0964b).

## 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.

## Additional context

`INFO ALL` populates its checkpoint section by scanning checkpoint metadata on
disk through
[`PopulateCheckpointInfo`](https://github.com/microsoft/garnet/blob/v2.1.7/libs/server/Metrics/Info/GarnetInfoMetrics.cs#L418-L421).
The index scan catches the failed read and skips the token, explaining the
transient `disk_checkpoint_entry:(empty)` result.

I searched open and closed Garnet issues and pull requests for the exact warning,
`Invalid metadata length 0`, `disk_checkpoint_entry:(empty)`,
`DeviceLogCommitCheckpointManager`, its semaphore, concurrent `INFO ALL`,
checkpoint metadata races, and close paraphrases. I found no matching report.

Nearest results, but not duplicates:

- [#2142](https://github.com/microsoft/garnet/issues/2142) is a persistent
checkpoint-cleanup defect: `DeleteOutdatedCheckpoints` deletes HybridLog
metadata and then attempts to parse it. This issue needs only one intact index
checkpoint and concurrent readers.
- [#2076](https://github.com/microsoft/garnet/issues/2076) /
[PR #2093](https://github.com/microsoft/garnet/pull/2093) address ignored
metadata I/O errors and recovery hangs. Version 2.1.7 already contains that
work. It clears read buffers and validates zero lengths, but does not associate
a completion or error field with the operation that owns it.
- [#2134](https://github.com/microsoft/garnet/issues/2134) concerns a 2 GiB
hash-index short write on Linux. This reproducer uses a 64 MiB index and never
overlaps a checkpoint write.
- [PR #2145](https://github.com/microsoft/garnet/pull/2145) concerns failed
checkpoints being reported as successful and aborted-checkpoint cleanup. It
does not change metadata read synchronization.

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.