roachtest: failover/non-system/deadlock/lease=expiration failed

[cockroach-teamcity]

roachtest.failover/non-system/deadlock/lease=expiration failed with artifacts on master @ 8551145a0c99c4c95a28ec470e699d0c20ca97ab:

(assertions.go:363).Fail: 
	Error Trace:	github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/failover.go:1456
	            				github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tests/failover.go:845
	            				main/pkg/cmd/roachtest/monitor.go:120
	            				golang.org/x/sync/errgroup/external/org_golang_x_sync/errgroup/errgroup.go:78
	            				src/runtime/asm_amd64.s:1695
	Error:      	Received unexpected error:
	            	context deadline exceeded
	Test:       	failover/non-system/deadlock/lease=expiration
(require.go:1357).NoError: FailNow called
(monitor.go:154).Wait: monitor failure: monitor user task failed: t.Fatal() was called
test artifacts and logs in: /artifacts/failover/non-system/deadlock/lease=expiration/cpu_arch=arm64/run_1

Parameters:

• ROACHTEST_arch=arm64
• ROACHTEST_cloud=azure
• ROACHTEST_coverageBuild=false
• ROACHTEST_cpu=2
• ROACHTEST_encrypted=false
• ROACHTEST_runtimeAssertionsBuild=false
• ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

Grafana is not yet available for azure clusters

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-41823

[tbg]

I first thought this might be like #129918 but here, the deadlock failure SQL query times out despite the cluster supposedly being completely healthy. Also, I don't see the timeout server-side.

The timing is odd too. We call (*deadlockFailer).Fail right around here:

2024/09/02 08:56:37 failover.go:844: failing n4 (deadlock)

and then it only fails ~42s later,

2024/09/02 08:57:19 test_impl.go:423: test failure #1: full stack retained in failure_1.log: (assertions.go:363).Fail:

and this is despite the 20s timeout here:

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

Line 1448 in 1af6df1

ctx, cancel := context.WithTimeout(ctx, 20*time.Second) // can take a while to lock

The logs for n4 show nothing related to this. There's a lot of snapshots, though, which might be caused by this code from the test

/pkg/cmd/roachtest/tests/failover.go#L843-L846

				// Ranges may occasionally escape their constraints. Move them
				// to where they should be.
				relocateRanges(t, ctx, conn, `database_name = 'kv'`, []int{1, 2, 3}, []int{4, 5, 6})
				relocateRanges(t, ctx, conn, `database_name != 'kv'`, []int{node}, []int{1, 2, 3})

I had the theory that perhaps the range deadlock query was attempting to deadlock multiple ranges serially (the deadlocker does that). This could deadlock the deadlocker: if the first deadlocked replica ends up deadlocking the store's mutex, trying to acquire another replica mutex from the store after would also deadlock.

However, it looks like we fell over on the very first attempt to deadlock anything. There's little in the logs, everything looks tame to me. The stacks for n4 show no deadlocked goroutines, in fact Replica doesn't even show up outside the expected store replica visitor loop.

n4 has 1001 ranges according to the debug.zip,

$ cat debug/nodes/4/ranges.json | jq length
1001

but surely locking the first one shouldn't take that long?

I don't think I understand what's going on here.

[tbg]

I checked the background workload that's running in this test,

run_085524.924200468_n7_cockroach-workload-r: 2024/09/02 08:55:24 cluster.go:2468: > ./cockroach workload run kv --read-percent 50 --concurrency 256 --max-rate 2048 --timeout 1m --tolerate-errors --histograms=perf/stats.json {pgurl:1-3}

and it's performing without a hitch, even though the ranges are on n4-n6 (and the gateways n1-n3). Based on that, removing release-blocker label.

[tbg]

#129995 might fix this too, but more in the sense of papering over whatever went wrong here, which is unfortunate.

[arulajmani]

I echo the puzzlement here. I'm also surprised to see no mention of builtins.go in the stacks or "crdb_internal.unsafe_lock_replica on r%d with lock=%t" log line on n4.

[arulajmani]

Do we want to close this out once #129995 lands? Other than landing that patch, this looks pretty unactionable.

[tbg]

Aspirationally fixed in #129995.