roachtest: failover/chaos/read-write/lease=leader failed

[cockroach-teamcity]

roachtest.failover/chaos/read-write/lease=leader failed with artifacts on release-25.2.6-rc @ e9b11cf62097fae46d98b46d128f47e88b4fac55:

(assertions.go:369).Fail: 
	Error Trace:	pkg/cmd/roachtest/tests/failover.go:1730
	            				pkg/cmd/roachtest/tests/failover.go:334
	            				pkg/cmd/roachtest/monitor.go:115
	            				external/org_golang_x_sync/errgroup/errgroup.go:78
	            				src/runtime/asm_amd64.s:1700
	Error:      	Received unexpected error:
	            	pq: internal error while retrieving user account memberships: operation "get-user-session" timed out after 10.011s (given timeout 10s): internal error while retrieving user account: get default settings error: interrupted during singleflight acquire-lease:100: context deadline exceeded
	Test:       	failover/chaos/read-write/lease=leader
(require.go:1357).NoError: FailNow called
(monitor.go:149).Wait: monitor failure: monitor user task failed: t.Fatal() was called
(cluster.go:2451).Run: context canceled
(cluster.go:2451).Run: context canceled
(cluster.go:2451).Run: context canceled
(cluster.go:2451).Run: context canceled
test artifacts and logs in: /artifacts/failover/chaos/read-write/lease=leader/run_1

Parameters:

• arch=amd64
• cloud=gce
• coverageBuild=false
• cpu=2
• encrypted=false
• fs=ext4
• localSSD=false
• runtimeAssertionsBuild=false
• ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

See: Grafana

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-54590

[iskettaneh]

At time 09:06:28, I see N1 suddenly start bursting in errors like this:

retrieval failed for user=‹"roachprod"›: internal error while retrieving user account memberships: operation "get-user-session" timed out after 10s (given timeout 10s): internal error while retrieving user account: get auth info error: interrupted during singleflight ‹acquire-lease:1›: context deadline exceeded
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +(1) attached stack trace
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +  -- stack trace:
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +  | github.com/cockroachdb/cockroach/pkg/sql.GetUserSessionInitInfo
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +  | 	pkg/sql/user.go:199
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +  | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).handleAuthentication
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +  | 	pkg/sql/pgwire/auth.go:154
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +  | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommands
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +  | 	pkg/sql/pgwire/conn.go:204
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +  | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +  | 	pkg/sql/pgwire/server.go:1197
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +  | runtime.goexit
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +  | 	src/runtime/asm_amd64.s:1700
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +Wraps: (2) internal error while retrieving user account memberships
W250919 09:06:28.459787 162011 sql/pgwire/auth.go:161 ⋮ [T1,Vsystem,n1,client=10.142.3.14:37512,hostssl,user=‹roachprod›] 3156 +Wraps: (3) operation "get-user-session" timed out after 10s (given timeout 10s): internal error while retrieving user account: get auth info error: interrupted during singleflight ‹acquire-lease:1›: context deadline exceeded

The above log line kept being printed over and over until the test failed.

This pushed N1's CPU to be very very high:

And the goroutine scheduling latency spiked.

@rafiss
Is this a similar issue to #150832?

[blathers-crl]

This issue has multiple T-eam labels. Please make sure it only has one, or else issue synchronization will not work correctly.

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

[rafiss]

This is not related to #150832 -- that issue only affected 25.3 and later.

In general, the operation "get-user-session" timed out after 10.48s (given timeout 10s) error is a symptom that indicates that some underlying system range (in this case looks like the range for system.lease) was not available within the 10 second timeout, and this is preventing new SQL logins. The next step is to figure out the cause of why that range was not available.

This test is intentionally causing chaos and failovers, so from looking at logs, it's hard to tell which unavailability errors are expected as part of the failover versus the errors that indicate that CRDB did not correctly recover from the failover. Could the KV team help diagnose that question?

One thing I'm curious about is before 09:06:28, there are other issues happening on n1. Are these expected?

E250919 09:05:52.524878 160828 kv/kvclient/kvcoord/dist_sender_circuit_breaker.go:1054 ⋮ [T1,Vsystem,n1] 3141  r676/6:(n5,s5) circuit breaker tripped: probe failed: [NotLeaseHolderError] ‹refusing to acquire lease on follower›; r676: replica (n5,s5):6 not lease holder; lease holder unknown (stalled for 4.661s, erroring for 0s)
E250919 09:05:58.524619 161046 kv/kvclient/kvcoord/dist_sender_circuit_breaker.go:1054 ⋮ [T1,Vsystem,n1] 3142  r370/6:(n5,s5) circuit breaker tripped: probe failed: [NotLeaseHolderError] ‹refusing to acquire lease on follower›; r370: replica (n5,s5):6 not lease holder; lease holder unknown (stalled for 4.777s, erroring for 4.778s)
W250919 09:06:02.524886 160523 kv/kvclient/kvcoord/dist_sender.go:2775 ⋮ [T1,Vsystem,n1,txn-hb=0a364a99] 3143  slow replica RPC: have been waiting 17.14s (0 attempts) for RPC HeartbeatTxn [/Table/106/1/‹-3921117133968985385›/‹0›], [txn: 0a364a99] to replica (n5,s5):6; resp: r676/6:(n5,s5) is unavailable (circuit breaker tripped): context canceled
W250919 09:06:02.525154 160537 kv/kvclient/kvcoord/dist_sender.go:2775 ⋮ [T1,Vsystem,n1,txn-hb=c60839a9] 3145  slow replica RPC: have been waiting 16.87s (0 attempts) for RPC HeartbeatTxn [/Table/106/1/‹-3926328681696888740›/‹0›], [txn: c60839a9] to replica (n5,s5):6; resp: r676/6:(n5,s5) is unavailable (circuit breaker tripped): context canceled
W250919 09:06:02.525842 144556 kv/kvclient/kvcoord/dist_sender.go:2775 ⋮ [T1,Vsystem,n1,client=10.142.3.14:42772,hostssl,user=‹roachprod›] 3146  slow replica RPC: have been waiting 17.87s (0 attempts) for RPC Put [/Table/106/1/‹-3926328681696888740›/‹0›], EndTxn(parallel commit) [/Table/106/1/‹-3926328681696888740›/‹0›], [txn: c60839a9], [can-forward-ts] to replica (n5,s5):6; resp: r676/6:(n5,s5) is unavailable (circuit breaker tripped): context canceled
W250919 09:06:02.524890 144590 kv/kvclient/kvcoord/dist_sender.go:2775 ⋮ [T1,Vsystem,n1,client=10.142.3.14:42806,hostssl,user=‹roachprod›] 3144  slow replica RPC: have been waiting 18.14s (1 attempts) for RPC Put [/Table/106/1/‹-3921117133968985385›/‹0›], EndTxn(parallel commit) [/Table/106/1/‹-3921117133968985385›/‹0›], [txn: 0a364a99], [can-forward-ts] to replica (n5,s5):6; resp: r676/6:(n5,s5) is unavailable (circuit breaker tripped): context canceled
W250919 09:06:08.524260 160575 kv/kvclient/kvcoord/dist_sender.go:2775 ⋮ [T1,Vsystem,n1,txn-hb=879b0a9d] 3147  slow replica RPC: have been waiting 21.82s (0 attempts) for RPC HeartbeatTxn [/Table/106/1/‹5053844642473328815›/‹0›], [txn: 879b0a9d] to replica (n5,s5):6; resp: r370/6:(n5,s5) is unavailable (circuit breaker tripped): context canceled
W250919 09:06:08.524483 144561 kv/kvclient/kvcoord/dist_sender.go:2775 ⋮ [T1,Vsystem,n1,client=10.142.3.14:42666,hostssl,user=‹roachprod›] 3148  slow replica RPC: have been waiting 20.20s (0 attempts) for RPC Put [/Table/106/1/‹5042474192951647440›/‹0›], EndTxn(parallel commit) [/Table/106/1/‹5042474192951647440›/‹0›], [txn: 15908ee0], [can-forward-ts] to replica (n5,s5):6; resp: r370/6:(n5,s5) is unavailable (circuit breaker tripped): context canceled
W250919 09:06:08.524579 151938 kv/kvclient/kvcoord/dist_sender.go:2775 ⋮ [T1,Vsystem,n1,client=10.142.3.14:40900,hostssl,user=‹roachprod›] 3149  slow replica RPC: have been waiting 22.82s (1 attempts) for RPC Put [/Table/106/1/‹5053844642473328815›/‹0›], EndTxn(parallel commit) [/Table/106/1/‹5053844642473328815›/‹0›], [txn: 879b0a9d], [can-forward-ts] to replica (n5,s5):6; resp: r370/6:(n5,s5) is unavailable (circuit breaker tripped): context canceled
W250919 09:06:08.524777 160605 kv/kvclient/kvcoord/dist_sender.go:2775 ⋮ [T1,Vsystem,n1,txn-hb=b0643995] 3150  slow replica RPC: have been waiting 21.31s (0 attempts) for RPC HeartbeatTxn [/Table/106/1/‹5052859623114923137›/‹0›], [txn: b0643995] to replica (n5,s5):6; resp: r370/6:(n5,s5) is unavailable (circuit breaker tripped): context canceled
W250919 09:06:08.524853 144579 kv/kvclient/kvcoord/dist_sender.go:2775 ⋮ [T1,Vsystem,n1,client=10.142.3.14:42720,hostssl,user=‹roachprod›] 3151  slow replica RPC: have been waiting 22.31s (0 attempts) for RPC Put [/Table/106/1/‹5052859623114923137›/‹0›], EndTxn(parallel commit) [/Table/106/1/‹5052859623114923137›/‹0›], [txn: b0643995], [can-forward-ts] to replica (n5,s5):6; resp: r370/6:(n5,s5) is unavailable (circuit breaker tripped): context canceled
W250919 09:06:08.524965 160708 kv/kvclient/kvcoord/dist_sender.go:2775 ⋮ [T1,Vsystem,n1,txn-hb=15908ee0] 3152  slow replica RPC: have been waiting 19.20s (0 attempts) for RPC HeartbeatTxn [/Table/106/1/‹5042474192951647440›/‹0›], [txn: 15908ee0] to replica (n5,s5):6; resp: r370/6:(n5,s5) is unavailable (circuit breaker tripped): context canceled
I250919 09:06:17.640000 161784 sql/sqlliveness/slstorage/slstorage.go:391 â‹® [n1,intExec=find-scheduled-jobs] 3153  deleted session 0101808c0a052bafc24170a46bb1073de0789b which expired at 1758272775.645773992,0

Based on test.log, it appears that the chaos right before this time was:

2025/09/19 09:05:38 failover.go:376: failing n5 to n9 (blackhole-send)
2025/09/19 09:05:38 cluster.go:2471: running cmd `sudo iptables -A OUTPUT -p ...` on nodes [:5]
2025/09/19 09:05:38 cluster.go:2473: details in run_090538.868748824_n5_sudo-iptables-A-OUTP.log
2025/09/19 09:05:40 failover.go:376: failing n6 to n7 (blackhole-send)
2025/09/19 09:05:40 cluster.go:2471: running cmd `sudo iptables -A OUTPUT -p ...` on nodes [:6]
2025/09/19 09:05:40 cluster.go:2473: details in run_090540.018766750_n6_sudo-iptables-A-OUTP.log

I don't immediately understand why that could cause slow replica RPCs on n1 or if that's expected, but KV folks may have a better mental model. There are similar errors happening on other nodes.