`DeviceLogCommitCheckpointManager` shares I/O completions across concurrent reads, causing valid checkpoints to be skipped
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.
- clears its leased buffer;
- starts an asynchronous read;
- waits on the shared semaphore;
- copies and returns its buffer.
Every operation uses the same
IOCallback,
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
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.
#!/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" || trueObserved on one run:
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:
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:
- two concurrent metadata reads whose completions are deliberately reordered;
- a metadata read concurrent with a metadata write;
- verification that no buffer is returned before its associated callback;
- verification that one operation cannot consume another operation's error.
Release version
Garnet v2.1.7, official image:
ghcr.io/microsoft/garnet@sha256:19bc507a8d84da467951a5db16b3e9976358f0b0f22029f38d4edae26769e072The relevant DeviceLogCommitCheckpointManager code is unchanged on current
main at commit
277ea6c.
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.
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 is a persistent
checkpoint-cleanup defect:
DeleteOutdatedCheckpointsdeletes HybridLog metadata and then attempts to parse it. This issue needs only one intact index checkpoint and concurrent readers. - #2076 / PR #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 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 concerns failed checkpoints being reported as successful and aborted-checkpoint cleanup. It does not change metadata read synchronization.
Source: microsoft/garnet