Closed knz closed 1 year ago
Hi @nvanbenschoten, please add branch-* labels to identify which branch(es) this release-blocker affects.
:owl: Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.
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
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.
@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 https://github.com/cockroachdb/cockroach/commit/175a9f8c793a19c778e7941dd434d744e9f5533f.
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 BatchRequest
s from a client.
Noticed the storage tag—Is there something for storage to look into here, or do we know what's going on?
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.
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