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

[nixxcz]

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.

ReadInto:

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,
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" || true

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

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:

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

The 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: DeleteOutdatedCheckpoints deletes 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.

[nixxcz]

Thanks! ❤️