pkg/sql/logictest/tests/cockroach-go-testserver-upgrade-to-master/cockroach-go-testserver-upgrade-to-master_test: TestLogic_mixed_version_udf_execute_privileges failed

[cockroach-teamcity]

pkg/sql/logictest/tests/cockroach-go-testserver-upgrade-to-master/cockroach-go-testserver-upgrade-to-master_test.TestLogic_mixed_version_udf_execute_privileges failed with artifacts on master @ e9a8c49a495178fa1160cc50b1e89c802816e0c7:

=== RUN   TestLogic_mixed_version_udf_execute_privileges
    test_log_scope.go:167: test logs captured to: /artifacts/tmp/_tmp/70566e04bab5c75f2c441638984bf57c/logTestLogic_mixed_version_udf_execute_privileges4009076817
    test_log_scope.go:81: use -show-logs to present logs inline
[17:04:43] --- progress: /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/7961/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/sql/logictest/tests/cockroach-go-testserver-upgrade-to-master/cockroach-go-testserver-upgrade-to-master_test_/cockroach-go-testserver-upgrade-to-master_test.runfiles/com_github_cockroachdb_cockroach/pkg/sql/logictest/testdata/logic_test/mixed_version_udf_execute_privileges: 7 statements
[17:05:36] --- progress: /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/7961/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/sql/logictest/tests/cockroach-go-testserver-upgrade-to-master/cockroach-go-testserver-upgrade-to-master_test_/cockroach-go-testserver-upgrade-to-master_test.runfiles/com_github_cockroachdb_cockroach/pkg/sql/logictest/testdata/logic_test/mixed_version_udf_execute_privileges: 8 statements
    logic.go:1235: 
        /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/7961/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/sql/logictest/tests/cockroach-go-testserver-upgrade-to-master/cockroach-go-testserver-upgrade-to-master_test_/cockroach-go-testserver-upgrade-to-master_test.runfiles/com_github_cockroachdb_cockroach/pkg/sql/logictest/testdata/logic_test/mixed_version_udf_execute_privileges:62: error while processing
    logic.go:1235: 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 auth info error: interrupted during singleflight acquire-lease:4: context deadline exceeded
[17:05:46] --- done: /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/7961/execroot/com_github_cockroachdb_cockroach/bazel-out/aarch64-fastbuild/bin/pkg/sql/logictest/tests/cockroach-go-testserver-upgrade-to-master/cockroach-go-testserver-upgrade-to-master_test_/cockroach-go-testserver-upgrade-to-master_test.runfiles/com_github_cockroachdb_cockroach/pkg/sql/logictest/testdata/logic_test/mixed_version_udf_execute_privileges with config cockroach-go-testserver-upgrade-to-master: 8 tests, 0 failures
    panic.go:522: -- test log scope end --
cockroach logs captured in: /artifacts/tmp/_tmp/70566e04bab5c75f2c441638984bf57c/cockroach-logs2914718938
--- FAIL: TestLogic_mixed_version_udf_execute_privileges (88.07s)

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-31777

[mgartner]

I'm seeing lots of messages "node might be overloaded". Here's a sample:

I230922 17:05:46.384396 660 kv/kvserver/store_raft.go:699 ⋮ [T1,Vsystem,n1,s1,r12/1:‹/Table/{8-11}›,raft] 790  raft ready handling: 0.58s [append=0.00s, apply=0.00s, sync=0.58s, other=0.00s], wrote [append-batch=49 B, ] pebble stats: [commit-wait 575.346091ms sem 715ns]; node might be overloaded
I230922 17:05:46.384396 699 kv/kvserver/store_raft.go:699 ⋮ [T1,Vsystem,n1,s1,r31/1:‹/{Table/29-NamespaceTab…}›,raft] 791  raft ready handling: 0.57s [append=0.00s, apply=0.00s, sync=0.57s, other=0.00s], wrote [append-batch=255 B, append-ent=193 B (1), ] pebble stats: [commit-wait 574.141968ms sem 445ns]; node might be overloaded
I230922 17:05:46.384455 583 kv/kvserver/store_raft.go:699 ⋮ [T1,Vsystem,n1,s1,r9/1:‹/Table/{5-6}›,raft] 792  raft ready handling: 0.57s [append=0.00s, apply=0.00s, sync=0.57s, other=0.00s], wrote [append-batch=277 B, append-ent=215 B (1), ] pebble stats: [commit-wait 574.160319ms sem 487ns]; node might be overloaded
I230922 17:05:46.686825 658 kv/kvserver/store_raft.go:699 ⋮ [T1,Vsystem,n1,s1,r4/1:‹/System{/tsd-tse}›,raft] 793  raft ready handling: 0.81s [append=0.00s, apply=0.00s, sync=0.81s, other=0.00s], wrote [append-batch=49 B, apply=297 KiB (1)] pebble stats: [commit-wait 805.987335ms sem 439ns]; node might be overloaded

There's also "slow non-blocking raft commit":

I230922 17:05:45.882232 694 kv/kvserver/replica_raft.go:1568 ⋮ [T1,Vsystem,n2,s2,r6/2:‹/Table/{0-3}›,raft] 472  slow non-blocking raft commit: commit-wait 2.45562002s sem 363ns
I230922 17:05:45.882285 694 kv/kvserver/replica_raft.go:1568 ⋮ [T1,Vsystem,n2,s2,r51/2:‹/Table/5{0-1}›,raft] 473  slow non-blocking raft commit: commit-wait 2.455649951s sem 535ns
I230922 17:05:45.882309 694 kv/kvserver/replica_raft.go:1568 ⋮ [T1,Vsystem,n2,s2,r27/3:‹/Table/2{5-6}›,raft] 474  slow non-blocking raft commit: commit-wait 2.455680262s sem 363ns
I230922 17:05:45.882330 694 kv/kvserver/replica_raft.go:1568 ⋮ [T1,Vsystem,n2,s2,r16/2:‹/Table/1{4-5}›,raft] 475  slow non-blocking raft commit: commit-wait 2.455714836s sem 560ns
I230922 17:05:45.882352 694 kv/kvserver/replica_raft.go:1568 ⋮ [T1,Vsystem,n2,s2,r28/3:‹/Table/2{6-7}›,raft] 476  slow non-blocking raft commit: commit-wait 2.455670005s sem 396ns
I230922 17:05:45.882410 694 kv/kvserver/replica_raft.go:1568 ⋮ [T1,Vsystem,n2,s2,r37/3:‹/Table/3{5-6}›,raft] 477  slow non-blocking raft commit: commit-wait 2.455687723s sem 419ns
I230922 17:05:45.882469 694 kv/kvserver/replica_raft.go:1568 ⋮ [T1,Vsystem,n2,s2,r41/2:‹/Table/{39-40}›,raft] 478  slow non-blocking raft commit: commit-wait 2.455766495s sem 471ns
I230922 17:05:45.882492 694 kv/kvserver/replica_raft.go:1568 ⋮ [T1,Vsystem,n2,s2,r35/2:‹/Table/3{3-4}›,raft] 479  slow non-blocking raft commit: commit-wait 2.455751042s sem 403ns
I230922 17:05:45.882536 694 kv/kvserver/replica_raft.go:1568 ⋮ [T1,Vsystem,n2,s2,r26/3:‹/Table/2{4-5}›,raft] 480  slow non-blocking raft commit: commit-wait 2.455790803s sem 477ns
I230922 17:05:45.882610 694 kv/kvserver/replica_raft.go:1568 ⋮ [T1,Vsystem,n2,s2,r17/3:‹/Table/1{5-6}›,raft] 481  slow non-blocking raft commit: commit-wait 2.455830327s sem 555ns
I230922 17:05:45.882692 694 kv/kvserver/replica_raft.go:1568 ⋮ [T1,Vsystem,n2,s2,r13/2:‹/Table/1{1-2}›,raft] 482  slow non-blocking raft commit: commit-wait 2.454803702s sem 867ns

I'm also seeing liveness failures.

[yuzefovich]

I happened to ask a question on slack related to this, and Foundations team mentioned that this type of error usually occurs during the overload, so it checks out. I think it makes sense for Foundations team to investigate this further (in case there is something we can do).

[fqazi]

We'll monitor this for future failure since this is the CI infrastructure potentially getting overloaded (not a release blocker). If we do see it again we can try tweaking this test to reduce the risk of this happening.

[rafiss]

Closing since this isn't reproducible