roachtest: kv/restart/nodes=12 failed

[cockroach-teamcity]

roachtest.kv/restart/nodes=12 failed with artifacts on master @ 6c99966f604f3521acdb925b9f689529ffd46df3:

test artifacts and logs in: /artifacts/kv/restart/nodes=12/run_1
(assertions.go:262).Fail: 
	Error Trace:	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/kv.go:1021
	            				main/pkg/cmd/roachtest/test_runner.go:993
	            				GOROOT/src/runtime/asm_amd64.s:1594
	Error:      	"0" is not greater than "0.5"
	Test:       	kv/restart/nodes=12
(cluster.go:1969).Run: output in run_060156.319224414_n13_cockroach-workload-r: ./cockroach workload run kv --min-block-bytes=8192 --max-block-bytes=8192 --tolerate-errors --read-percent=50  --duration=30m0s --concurrency=64 {pgurl:1-11} returned: context canceled

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=8 , ROACHTEST_encrypted=false , ROACHTEST_fs=ext4 , ROACHTEST_localSSD=true , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-25597

[aliher1911]

Test was reenabled last week after some fixes (#98271) but it looks like the underlying overload behaviour is unchanged.
After node is added after a downtime SQL throughput tanks while node is trying to catch up. Number of leaseholders on the overloaded node is 0 so the change mentioned in PR works. Since throughput drops, overload must be affecting something else.

[aliher1911]

Seems that my interpretation of lease stats is not correct. Node doesn't have leases but other nodes still try to move them to n12.

Queries are stuck with:

W230318 06:26:27.536186 369697 kv/kvclient/kvcoord/dist_sender.go:1675 ⋮ [T1,n10,client=10.128.0.71:50218,user=root] 12986  slow range RPC: have been waiting 145.10s (1 attempts) for RPC Put [/Table/106/1/‹-112334951631669349›/‹0›,/Min), EndTxn(parallel commit) [/Table/106/1/‹-112334951631669349›/‹0›], [txn: d66aaf7d], [can-forward-ts] to r4816:‹/Table/106/1/-112{980658418560248-058367329429228}› [(n12,s12):5, (n7,s7):4, (n9,s9):3, next=6, gen=64, sticky=9223372036.854775807,2147483647]; resp: result is ambiguous: context done during DistSender.Send: ba: ‹Put [/Table/106/1/-112334951631669349/0,/Min), EndTxn(parallel commit) [/Table/106/1/-112334951631669349/0], [txn: d66aaf7d], [can-forward-ts]› RPC error: grpc: ‹context canceled› [code 1/Canceled]

While we try to move some leases right after node comes back:

I230318 06:23:27.300854 3410055 13@kv/kvserver/replicate_queue.go:2033 ⋮ [T1,n10,replicate,s10,r18220/6:‹/Table/106/1/-88{6091…-5998…}›] 33251  transferring lease to s12
I230318 06:23:42.441713 3429253 13@kv/kvserver/replicate_queue.go:2033 ⋮ [T1,n10,replicate,s10,r6461/1:‹/Table/106/1/91{49588…-50511…}›] 33252  transferring lease to s12
I230318 06:23:56.174176 3442526 13@kv/kvserver/replicate_queue.go:2033 ⋮ [T1,n10,replicate,s10,r13280/2:‹/Table/106/1/617{4277…-5199…}›] 33253  transferring lease to s12
I230318 06:24:03.337125 3449366 13@kv/kvserver/replicate_queue.go:2033 ⋮ [T1,n10,replicate,s10,r16913/4:‹/Table/106/1/-6830{948…-026…}›] 33254  transferring lease to s12

[aliher1911]

When you are going to look at it, maybe you can fix

cockroach/pkg/cmd/roachtest/tests/kv.go

Line 988 in b3d3e64

t.Status(fmt.Sprintf("waiting %x after stopping node to allow the node to fall behind", duration))

formatter from %x to %s? I don't want to raise a PR because of 1 char. It prints timestamp as hex currently.

[kvoli]

The restarting node (n12) should be treated as suspect and not be receiving any leases for 30s after restarting.

n12 joins back at 06:23.18.71.

I230318 06:23:18.715307 400 1@gossip/gossip.go:1420 ⋮ [T1,n12] 26  node has connected to cluster via gossip

The earliest lease transfer I see towards n12 is at 06:23:25.54, which is 7 seconds after n12 connects to gossip.

2283:I230318 06:23:25.542903 3477207 13@kv/kvserver/replicate_queue.go:2033 ⋮ [T1,n9,replicate,s9,r18364/5:‹/Table/106/1/720{0787…-1709…}›] 35975  transferring lease to s12
...

So it appears that the node isn't being treated as suspect after immediately rejoining and is receiving leases as a result.

I'll look more into why that is the case.

[kvoli]

With the fix in ##99033 to ensure stores are suspect this test should be less flaky. After 30s and before the restarting node hits overload, it may still receive a few leases and cause this test to flake. Removing the GA blocker.

[github-actions]

We have marked this test failure issue as stale because it has been
inactive for 1 month. If this failure is still relevant, removing the
stale label or adding a comment will keep it active. Otherwise,
we'll close it in 5 days to keep the test failure queue tidy.