kvcoord: flake in TestMultiRangeScanReverseScanInconsistent

[knz]

$ ./dev test --stress //pkg/kv/kvclient/kvcoord --filter=TestMultiRangeScanReverseScanInconsistent
...
--- FAIL: TestMultiRangeScanReverseScanInconsistent (1.52s)
    test_log_scope.go:161: test logs captured to: /tmp/_tmp/e1d742d7ffb97ae3adc81944eac18765/logTestMultiRangeScanReverseScanInconsistent3519145941
    test_log_scope.go:79: use -show-logs to present logs inline
    --- FAIL: TestMultiRangeScanReverseScanInconsistent/INCONSISTENT (0.70s)
        dist_sender_server_test.go:1160: 0: expected 1 row; got 0
            []
    dist_sender_server_test.go:1168: -- test log scope end --
FAIL

Also found here: https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_UnitTests_BazelUnitTests/7504394?buildTab=overview&showRootCauses=false&expandBuildProblemsSection=true&expandBuildTestsSection=true&expandBuildChangesSection=true&expandBuildDeploymentsSection=true#%2Ftmp

cc @nvanbenschoten for triage

Jira issue: CRDB-21459

[blathers-crl]

Hi @nvanbenschoten, please add branch-* labels to identify which branch(es) this release-blocker affects.

_{🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.}

[nvanbenschoten]

I can still hit this on master (1a58583a0f911b6dd2a6b0bfca17ec510727b0d9) after about 1m of stress:

# unskip the test
dev test pkg/kv/kvclient/kvcoord -f=TestMultiRangeScanReverseScanInconsistent --stress

[andrewbaptist]

I'm going to need some help on this from the storage team. I added a ton of debugging statements through the stack to try and figure out why my writes are getting "lost" and created a more straightforward test to reproduce this TestMinimal in this branch.

https://github.com/andrewbaptist/cockroach/tree/23.03.15-pebble_invalid

From what I can tell we are putting the key correctly and see this log:

 I230315 23:11:18.082595 13 storage/mvcc.go:2196 ⋮ [T1,n1,s1,r5/1:‹{/Systemtse-b}›] 66042  Calling put ‹"a"/1678921878.081010000,0›, ‹/BYTES/value›

However, it fails with

 I230315 23:11:18.085546 1701 storage/pebble_mvcc_scanner.go:641 ⋮ [T1,n1,s1,r5/1:‹{/Systemtse-b}›] 66157  Starting scan, ‹"a"›, ‹"b"›
 I230315 23:11:18.085552 1701 storage/pebble_iterator.go:364 ⋮ [-] 66158  pebbleIterator
 I230315 23:11:18.085554 1701 storage/pebble_iterator.go:373 ⋮ [-] 66159  not valid? <nil>
 I230315 23:11:18.085557 1701 storage/intent_interleaving_iter.go:600 ⋮ [-] 66160  computePos invalid
 I230315 23:11:18.085559 1701 storage/pebble_mvcc_scanner.go:1648 ⋮ [-] 66161  iter not valid
 I230315 23:11:18.085561 1701 storage/pebble_mvcc_scanner.go:646 ⋮ [T1,n1,s1,r5/1:‹{/Systemtse-b}›] 66162  seek failed <nil>
 I230315 23:11:18.085569 1701 kv/kvserver/replica_evaluate.go:550 ⋮ [T1,n1,s1,r5/1:‹{/Systemtse-b}›] 66163  evaluated Scan command ‹header:<key:"a" end_key:"b" >›, txn=<nil> : resp=‹header:<> col_batches:<>›, err=<nil>    I230315 23:11:18.085584 13 kv/kvclient/kvcoord_test/dist_sender_server_test.go:1109 ⋮ [-] 66164  Scan complete at time &{‹0x14003422e70› 0 0 1678921878082825001 0 0 {{{0 0}} {1678921878085579000 0 false} false 0}}

Note that the scan time is greater than the put time, however, it never even gets the item back from pebble.
1678921878082825001 > 1678921878.081010000

This feels like a pebble bug, but I haven't created a non-KV test to reproduce this. Fortunately, the test reproduces the issue quickly.

I haven't bisected to figure out when this problem started.

[nvanbenschoten]

@andrewbaptist nice job getting to a minimal reproduction. It's interesting that we see this flake when issuing an INCONSISTENT scan. INCONSISTENT scans don't acquire latches, so they bypass replica-level synchronization. One thing to check is that you can still reproduce even if you disable raft proposal acknowledgment ahead of application. You can do that using the StoreTestingKnobs.DisableCanAckBeforeApplication flag. We might have missed this in 175a9f8.

[andrewbaptist]

I verified changing the know does fix the issue.

I don't fully understand what that knob does or why we would need it in tests. This seems like a real linearizability violation from the perspective that a write is missed in a future scan (at a later time with a later timestamp). Maybe we can chat more on this tomorrow. Also, note that the Put is called before the later scan, and we are not ever going directly through the engine, these are all BatchRequests from a client.

[jbowens]

Noticed the storage tag—Is there something for storage to look into here, or do we know what's going on?

[andrewbaptist]

No - sorry - I will remove it - I thought it was a storage bug first when I didn't realize the difference between raft append and log application.