Data loss on recovery: SeSaveRecoverMultipleKeysTest("25k","18k") intermittently loses a key (~50% repro rate)

[hexonal]

Describe the bug

RespAdminCommandsTests.SeSaveRecoverMultipleKeysTest("25k","18k") (test/standalone/Garnet.test/RespAdminCommandsTests.cs) intermittently fails after a server restart with tryRecover: true: one specific key, SeSaveRecoverTestKey0693, comes back as an empty string instead of its expected value after recovery, even though it was written and verified present before the restart. All 1999 other keys in the same test recover correctly.

This looks like a real (if narrow) data-durability bug in the recovery path, not simple test flakiness — see reproduction data below.

Steps to reproduce the bug

dotnet test test/standalone/Garnet.test/Garnet.test.csproj -c Release --framework net10.0 --filter "FullyQualifiedName~SeSaveRecoverMultipleKeysTest"

Run it repeatedly (single run isn't enough — this is timing-dependent). Over 18 local runs (macOS, arm64, .NET 10.0.10, Release config) it failed 9 times (50%) — every single failure was the exact same test case, ("25k","18k"), and the exact same key, SeSaveRecoverTestKey0693. It's not a random/different key each time.

We also independently hit this same test (different parameterizations of the same signature — an empty-string assertion failure) twice in CI on unrelated PRs (#1945, #1946), and once saw a full 45-minute CI job timeout/hang after this test's ("16k","16k") case completed with no further log output at all (PR #1949's ubuntu-latest, net10.0, Debug job) — possibly a related but rarer failure mode in the same area, not independently reproduced locally yet.

Expected behavior

SeSaveRecoverTestKey0693 (and every other key) should recover with its original value ("SeSaveRecoverTestValue") after the server restart, matching the assertion already in the test.

What we found so far

The test writes 1000 keys, does a background SAVE, writes 1000 more keys, does COMMITAOF, disposes the server, then restarts it with tryRecover: true at a smaller memorySize/recoveryMemorySize than the original run — forcing recovery to happen under tighter memory pressure than the data was originally written under, which we believe is what makes this reproducible at all (the other, larger-memory test cases in the same parameterized test did not fail in our runs).

We traced (without being able to pin an exact line within the time we spent) that the likely interaction is between:

• The synchronous eviction path added in Tighten up Recovery/replay/eviction interaction with sizeTracker, including at shutdown, to fix intermittent Garnet test hangs #1932 (AllocatorBase.IssueShiftAddress, invoked whenever the LogSizeTracker resizer IsRunning is false — which is true during recovery), and
• The multi-phase async snapshot-checkpoint recovery logic in libs/storage/Tsavorite/cs/src/core/Index/Recovery/Recovery.cs (RecoverHybridLogAsync / RecoverHybridLogFromSnapshotFileAsync), which already has to reason about "evictions happening mid-flight" per its own comments while adjusting HeadAddress.

Our hypothesis (not confirmed at the exact line level): a record landing near a page/segment boundary during this eviction-while-recovering interleaving can end up with its index entry pointing below the newly-adjusted HeadAddress without the on-disk read fallback correctly kicking in for it, making it read back as absent/empty. #1932's own added comments (LogSizeTracker.cs, the resizerTask.IsCompleted "defense in depth... even if OnStopped() somehow did not run" check) suggest the original fix wasn't fully confident it eliminated every timing case in this area, which is consistent with what we're seeing.

We don't have deep expertise in Tsavorite's recovery state machine to pin this down further ourselves with confidence, but wanted to file this promptly given how reliably it reproduces (a maintainer familiar with this code, with the repro rate/key above, should be able to nail it quickly with targeted tracing/logging around key 0693's record address during that specific test case).

Happy to help test a fix, or dig further ourselves if useful — let us know.

[hexonal]

Update: dug into this further and found a real, distinct root cause for (at least part of) it — not the recovery/eviction interaction with #1932 I originally suspected.

Root cause

ContinuePendingRead in libs/storage/Tsavorite/cs/src/core/Index/Tsavorite/Implementation/ContinuePending.cs: after a pending (disk) read's Reader() call succeeds, status is only explicitly set to SUCCESS inside the two branches gated by operationState.readCopyOptions.CopyTo (MainLog or ReadCache). When CopyFrom != None but CopyTo == None — a valid, common configuration (e.g. whenever ReadCopyFrom.Inherit resolves to that) — neither branch runs, and status is left holding whatever FindTagAndTryEphemeralSLock's out-parameter set earlier, which is only meaningful on a failed lock/find (effectively behaves like NOTFOUND here). A fully successful disk read — value correctly retrieved — was therefore reported back as NOTFOUND, discarding the correct value.

This reproduces whenever a plain GET is forced to disk (the record has been evicted below HeadAddress) with that CopyFrom/CopyTo combination — rare in normal operation, but reliable right after recovering into a tighter memory budget, exactly what SeSaveRecoverMultipleKeysTest("25k","18k") does.

Confirmed by comparing against the already-correct synchronous-path equivalent in InternalRead.cs (line ~107/136): there, status = OperationStatus.SUCCESS is set unconditionally right after a successful Reader() call, before any CopyFrom-gated branching. The async/pending path was just missing the equivalent line.

Fix

One line — status = OperationStatus.SUCCESS; in ContinuePendingRead, right before the CopyTo-gated block, matching InternalRead.cs's pattern. PR incoming.

Important: this does NOT fully close the issue

With the fix, the local repro rate for SeSaveRecoverMultipleKeysTest("25k","18k") dropped from ~30% (6/20 runs) to ~4% (6/150 runs) — a real ~7x reduction, confirming the fix addresses a genuine cause, but there's at least one more distinct issue left. In a captured residual failure, ContinuePendingRead's request.logicalAddress was 0 instead of the correct address at completion time, which routes into a < BeginAddress NOTFOUND path — possibly a spurious key-mismatch during AllocatorBase.TryVerifyOrReissuePendingRead's on-disk hash-chain walk reaching PreviousAddress == 0 (end of chain), or a pending-IO-context lifetime/pooling issue. I wasn't able to pin this down with confidence and didn't want to guess at a fix for it in this sensitive async-completion path — leaving this open for whoever picks it up next (possibly me, possibly a maintainer). Happy to share the diagnostic-instrumentation approach that worked for the first bug if useful for chasing this one.

[TedHartMS]

Fixed in #1957