catalog/lease: timeout during lease acquisition

[cockroach-teamcity]

pkg/sql/logictest/tests/cockroach-go-testserver-23.2/cockroach-go-testserver-23_2_test.TestLogic_mixed_version_can_login failed with artifacts on master @ bf013ea0a5311726e65d37e8f047ce39ea2d5f10:

=== RUN   TestLogic_mixed_version_can_login
    test_log_scope.go:170: test logs captured to: /artifacts/tmp/_tmp/43240bca0f37b9843cb84c43ff79147f/logTestLogic_mixed_version_can_login2941405004
    test_log_scope.go:81: use -show-logs to present logs inline
[00:27:12] --- progress: /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/10299/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/sql/logictest/tests/cockroach-go-testserver-23.2/cockroach-go-testserver-23_2_test_/cockroach-go-testserver-23_2_test.runfiles/com_github_cockroachdb_cockroach/pkg/sql/logictest/testdata/logic_test/mixed_version_can_login: 2 statements
    logic.go:1253: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/10299/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/sql/logictest/tests/cockroach-go-testserver-23.2/cockroach-go-testserver-23_2_test_/cockroach-go-testserver-23_2_test.runfiles/com_github_cockroachdb_cockroach/pkg/sql/logictest/testdata/logic_test/mixed_version_can_login:23: error while processing
    logic.go:1253: pq: internal error while retrieving user account memberships: operation "get-user-session" timed out after 10.001s (given timeout 10s): internal error while retrieving user account: get default settings error: interrupted during singleflight acquire-lease:44: context deadline exceeded
[00:27:22] --- done: /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/10299/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/sql/logictest/tests/cockroach-go-testserver-23.2/cockroach-go-testserver-23_2_test_/cockroach-go-testserver-23_2_test.runfiles/com_github_cockroachdb_cockroach/pkg/sql/logictest/testdata/logic_test/mixed_version_can_login with config cockroach-go-testserver-23.2: 3 tests, 0 failures
cockroach logs captured in: /artifacts/tmp/_tmp/43240bca0f37b9843cb84c43ff79147f/cockroach-logs914427257
    panic.go:626: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/43240bca0f37b9843cb84c43ff79147f/logTestLogic_mixed_version_can_login2941405004
--- FAIL: TestLogic_mixed_version_can_login (95.24s)

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/sql-queries

This test on roachdash | Improve this report!

Jira issue: CRDB-36372

[DrewKimball]

It seems like this and #119898 are using a disk-based configuration for the test cluster, and the cache size is the default 128MiB. That might explain the signs of slowdowns in the logs, since CPU, goroutines, and memory all seem pretty normal.

That being said, it seems problematic that some disk-related slowdowns could cause an internal error during lease acquisition. @cockroachdb/sql-foundations should these code paths handle errors more gracefully? Here's the stack trace from the logs:

W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   | get default settings error: interrupted during singleflight ‹acquire-lease:44›: context deadline exceeded
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   | (1) attached stack trace
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   -- stack trace:
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.retrieveSessionInitInfoWithCache.func1
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/user.go:277
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | [...repeated from below...]
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   | Wraps: (2) get default settings error
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   | Wraps: (3) attached stack trace
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   -- stack trace:
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/util/syncutil/singleflight.(*call).result
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/util/syncutil/singleflight/singleflight.go:274
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/util/syncutil/singleflight.Future.WaitForResult
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/util/syncutil/singleflight/singleflight.go:234
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/catalog/lease.acquireNodeLease
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/catalog/lease/lease.go:674
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/catalog/lease.(*Manager).Acquire.func1
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/catalog/lease/lease.go:1216
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/catalog/lease.(*Manager).Acquire
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/catalog/lease/lease.go:1218
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/catalog/lease.(*Manager).AcquireByName
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/catalog/lease/lease.go:1063
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/catalog/descs.(*leasedDescriptors).getByName
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/catalog/descs/leased_descriptors.go:102
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/catalog/descs.(*Collection).getNonVirtualDescriptorID.func6
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/catalog/descs/descriptor.go:580
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/catalog/descs.(*Collection).getNonVirtualDescriptorID
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/catalog/descs/descriptor.go:620
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/catalog/descs.getDescriptorByName
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/catalog/descs/descriptor.go:398
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/catalog/descs.ByNameGetter.Table
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/catalog/descs/getters.go:301
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/catalog/descs.PrefixAndTable
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/catalog/descs/helpers.go:138
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/sessioninit.(*Cache).GetDefaultSettings.func1
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/sessioninit/cache.go:293
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).DescsTxn.func1
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/internal.go:1744
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).txn.func4
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/internal.go:1841
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/kv.(*Txn).exec
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/kv/txn.go:1049
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/kv.runTxn
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/kv/db.go:1092
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/kv.(*DB).TxnWithAdmissionControl
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/kv/db.go:1055
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/kv.(*DB).Txn
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/kv/db.go:1030
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).txn
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/internal.go:1828
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).DescsTxn
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/internal.go:1742
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/sessioninit.(*Cache).GetDefaultSettings
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/sessioninit/cache.go:290
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.retrieveSessionInitInfoWithCache.func1
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/user.go:269
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.retrieveSessionInitInfoWithCache
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/user.go:278
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.GetUserSessionInitInfo.func2
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/user.go:126
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/util/timeutil.RunWithTimeout
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/util/timeutil/timeout.go:29
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.getUserInfoRunFn.func2
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/user.go:245
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.GetUserSessionInitInfo
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/user.go:123
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).handleAuthentication
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/pgwire/auth.go:152
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommands
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:204
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func3
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	github.com/cockroachdb/cockroach/pkg/sql/pgwire/server.go:999
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | runtime.goexit
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   |   | 	src/runtime/asm_arm64.s:1222
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   | Wraps: (4) interrupted during singleflight ‹acquire-lease:44›
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   | Wraps: (5) context deadline exceeded
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  |   | Error types: (1) *withstack.withStack (2) *errutil.withPrefix (3) *withstack.withStack (4) *errutil.withPrefix (5) context.deadlineExceededError
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +  | Error types: (1) *timeutil.TimeoutError (2) *withstack.withStack (3) *errutil.withPrefix (4) *barriers.barrierErr
W240305 00:27:22.939882 4399 sql/pgwire/auth.go:159 ⋮ [T1,Vsystem,n1,peer=‹127.0.0.1:47732›,client=127.0.0.1:47732,hostnossl,user=‹testuser›] 544 +Error types: (1) *withstack.withStack (2) *errutil.withPrefix (3) *barriers.barrierErr

[DrewKimball]

This seems mostly to be related to the testing setup, so I'll assign as P-3.

[DrewKimball]

+cc @cockroachdb/sql-foundations It looks like the lease acquisition timeouts from #116904 are resurfacing here.

[rafiss]

it seems problematic that some disk-related slowdowns could cause an internal error during lease acquisition

the reason for the internal error is that the context used for authenticating has a 10 second deadline. if this lease timeout only appears underneath operation "get-user-session" timed out, then i think we have the correct error handling behavior.

i created cockroachdb/cockroach-go#177 to improve the cache size settings and avoid slowdowns.