pkg/ccl/spanconfigccl/spanconfigsqlwatcherccl/spanconfigsqlwatcherccl_test: TestSQLWatcherMultiple failed

[cockroach-teamcity]

pkg/ccl/spanconfigccl/spanconfigsqlwatcherccl/spanconfigsqlwatcherccl_test.TestSQLWatcherMultiple failed on release-26.1 @ efd67f7020170561855aa0e49a88989d319019d5:

W251213 12:58:49.149694 45664 sql/execinfra/processorsbase.go:560  [T10,Vtest-tenant,n1,intExec=claim-jobs] 2258 +Error types: (1) *colexecerror.StorageError (2) *errbase.opaqueWrapper (3) *errutil.withPrefix (4) *kvpb.AmbiguousResultError (5) *secondary.withSecondaryError (6) *kvpb.NodeUnavailableError
W251213 12:58:49.165919 14911 sql/sqlliveness/slinstance/slinstance.go:331  [T10,Vtest-tenant,n1] 2261  exiting heartbeat loop
W251213 12:58:49.240030 14911 sql/sqlliveness/slinstance/slinstance.go:318  [T10,Vtest-tenant,n1] 2281  exiting heartbeat loop with error: node unavailable; try another peer
E251213 12:58:49.240407 14911 server/server_sql.go:524  [T10,Vtest-tenant,n1] 2282  failed to run update of instance with new session ID: node unavailable; try another peer
W251213 12:58:49.167148 14852 kv/kvclient/kvtenant/setting_overrides.go:65  [T10,Vtest-tenant,n1,tenant-connector] 2264  error consuming TenantSettings RPC: grpc: context canceled [code 1/Canceled]
E251213 12:58:49.241310 14933 jobs/registry.go:992  [T10,Vtest-tenant,n1] 2283  error claiming jobs: could not query jobs table: claim-jobs: failed to read query result: query execution canceled
W251213 12:58:49.165173 14942 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T10,Vtest-tenant,n1,rangefeed=lease,mux_n=1,gen=2] 2259  error closing mux rangefeed client: context canceled
I251213 12:58:49.174501 15885 4@util/log/event_log.go:90  [T1,Vsystem,n1,client=127.0.0.1:55486,hostssl,user=root] 2279 ={"Timestamp":1765630729174490952,"EventType":"client_session_end","InstanceID":1,"Network":"tcp","RemoteAddress":"127.0.0.1:55486","SessionID":"1880c79640fa38480000000000000001","Duration":227096085174}
W251213 12:58:49.167439 14851 kv/kvclient/kvtenant/connector.go:412  [T10,Vtest-tenant,n1,tenant-connector] 2265  error consuming GossipSubscription RPC: grpc: context canceled [code 1/Canceled]
W251213 12:58:49.165722 15868 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T10,Vtest-tenant,n1,rangefeed=statement-hints-watcher,mux_n=1,gen=2] 2260  error closing mux rangefeed client: context canceled
E251213 12:58:49.244161 45314 jobs/registry.go:920  [T10,Vtest-tenant,n1] 2284  error getting live session: node unavailable; try another peer
I251213 12:58:49.176082 15970 4@util/log/event_log.go:90  [T10,Vtest-tenant,n1,client=127.0.0.1:55496,hostssl,user=root] 2280 ={"Timestamp":1765630729176074102,"EventType":"client_session_end","InstanceID":1,"Network":"tcp","RemoteAddress":"127.0.0.1:55496","SessionID":"1880c796718647b70000000000000001","Duration":226283183565}
W251213 12:58:49.167769 18749 sql/stats/automatic_stats.go:1087  [T10,Vtest-tenant,n1] 2266  failed to create statistics on table 15: create-stats: failed to read query result: query execution canceled
W251213 12:58:49.166374 16158 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T10,Vtest-tenant,rangefeed=sql-watcher-zones-rangefeed,n1,mux_n=1,gen=2] 2262  error closing mux rangefeed client: context canceled
I251213 12:58:49.169091 11614 server/start_listen.go:114  [T1,Vsystem,n1] 2267  server shutting down: instructing cmux to stop accepting
W251213 12:58:49.166886 15835 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T10,Vtest-tenant,n1,rangefeed=table-stats-cache,mux_n=1,gen=2] 2263  error closing mux rangefeed client: context canceled
W251213 12:58:49.169924 17697 sql/stats/automatic_stats.go:1087  [T1,Vsystem,n1] 2271  failed to create statistics on table 50: create-stats: failed to read query result: query execution canceled
W251213 12:58:49.169234 13570 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T1,Vsystem,n1,rangefeed=statement-hints-watcher,mux_n=1,gen=2] 2268  error closing mux rangefeed client: context canceled
W251213 12:58:49.169414 14248 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T1,Vsystem,n1,rangefeed=settings-watcher,mux_n=1,gen=2] 2269  error closing mux rangefeed client: context canceled
W251213 12:58:49.169646 13531 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T1,Vsystem,n1,rangefeed=table-stats-cache,mux_n=1,gen=2] 2270  error closing mux rangefeed client: context canceled
W251213 12:58:49.170086 12152 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T1,Vsystem,n1,rangefeed=lease,mux_n=1,gen=2] 2272  error closing mux rangefeed client: context canceled
W251213 12:58:49.171282 12070 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T1,Vsystem,n1,rangefeed=spanconfig-subscriber,mux_n=1,gen=2] 2273  error closing mux rangefeed client: context canceled
W251213 12:58:49.172754 16155 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T10,Vtest-tenant,rangefeed=sql-watcher-protected-ts-records-rangefeed,n1,mux_n=1,gen=2] 2274  error closing mux rangefeed client: context canceled
W251213 12:58:49.173200 14959 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T10,Vtest-tenant,n1,rangefeed=sql_instances,mux_n=1,gen=2] 2275  error closing mux rangefeed client: context canceled
W251213 12:58:49.173479 16145 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T10,Vtest-tenant,rangefeed=sql-watcher-descriptor-rangefeed,n1,mux_n=1,gen=2] 2276  error closing mux rangefeed client: context canceled
W251213 12:58:49.173732 16162 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T10,Vtest-tenant,rangefeed=sql-watcher-descriptor-rangefeed,n1,mux_n=1,gen=2] 2277  error closing mux rangefeed client: context canceled
W251213 12:58:49.173962 14982 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T10,Vtest-tenant,n1,rangefeed=system-config-cache,mux_n=1,gen=2] 2278  error closing mux rangefeed client: context canceled
    sqlwatcher_test.go:341: 
        	Error Trace:	pkg/ccl/spanconfigccl/spanconfigsqlwatcherccl/sqlwatcher_test.go:341
        	            				src/runtime/asm_amd64.s:1693
        	Error:      	Should be true
        	Test:       	TestSQLWatcherMultiple
    sqlwatcher_test.go:341: 
        	Error Trace:	pkg/ccl/spanconfigccl/spanconfigsqlwatcherccl/sqlwatcher_test.go:341
        	            				src/runtime/asm_amd64.s:1693
        	Error:      	Should be true
        	Test:       	TestSQLWatcherMultiple
I251213 12:58:49.264169 14255 1@util/log/event_log.go:90  [n1,tenant-orchestration,tenant=test-tenant] 2285 ={"Timestamp":1765630729264160768,"EventType":"tenant_shared_service_stop","NodeID":1,"TenantID":10,"InstanceID":1,"TenantName":"test-tenant"}
W251213 12:58:49.264950 14255 sql/event_log.go:618  [n1,tenant-orchestration,tenant=test-tenant] 2286  failed to start task to save 1 events in eventlog: node unavailable; try another peer
W251213 12:58:49.265441 14255 server/server_sql.go:1809  [T10,Vtest-tenant,n1] 2287  server shutdown without a prior graceful drain
I251213 12:58:49.266299 14255 server/server_controller_channel_orchestrator.go:487  [n1,tenant-orchestration,tenant=test-tenant] 2288  propagate-ungraceful-stop task terminating
I251213 12:58:49.283936 14253 server/server_controller_channel_orchestrator.go:288  [T1,Vsystem,n1] 2289  propagate-close task terminating
W251213 12:58:50.991593 11688 15@kv/kvclient/kvcoord/dist_sender.go:2839  [T1,Vsystem,n1,ts-poll] 2290  slow replica RPC: have been waiting 20.18s (0 attempts) for RPC Merge [/System/tsd/cr.node.raft.transport.reverse-sent/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-max/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p99.999/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p99.99/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p99.9/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p99/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p90/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p75/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p50/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-avg/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-count/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-sum/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.gossip.bytes.sent/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.requested.elastic-cpu/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.kvflowcontrol.tokens.eval.elastic.available/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_queue_length.kv.locking-normal-pri/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.elastic_cpu.returned_nanos/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.admitted.elastic-cpu/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.kvflowcontrol.streams.eval.elastic.total_count/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.errored.sql-sql-response/10s/2025-12-13T12:00:00Z/1],... 5444 skipped ..., Merge [/System/tsd/cr.store.intentage/10s/2025-12-13T12:00:00Z/1-10], Merge [/System/tsd/cr.store.gcbytesage/10s/2025-12-13T12:00:00Z/1-10], Merge [/System/tsd/cr.store.livebytes/10s/2025-12-13T12:00:00Z/1-10], Merge [/System/tsd/cr.store.keybytes/10s/2025-12-13T12:00:00Z/1-10], Merge [/System/tsd/cr.store.totalbytes/10s/2025-12-13T12:00:00Z/1-10] to replica (n1,s1):1; resp: (err: result is ambiguous: server shutdown)
W251213 12:58:50.994458 11688 ts/db.go:213  [T1,Vsystem,n1,ts-poll] 2291  error writing time series data: result is ambiguous: server shutdown
W251213 12:58:50.994826 11688 ts/db.go:216  [T1,Vsystem,n1,ts-poll] 2292  node unavailable; try another peer
W251213 12:58:51.010820 11178 server/server_sql.go:1809  [T1,Vsystem,n1] 2293  server shutdown without a prior graceful drain
W251213 12:58:51.022378 11178 15@kv/kvserver/spanlatch/manager.go:678  [-] 2294  Merge [/System/tsd/cr.node.raft.transport.reverse-sent/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-max/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p99.999/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p99.99/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p99.9/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p99/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p90/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p75/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-p50/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-avg/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-count/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_durations.elastic-cpu.normal-pri-sum/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.gossip.bytes.sent/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.requested.elastic-cpu/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.kvflowcontrol.tokens.eval.elastic.available/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.wait_queue_length.kv.locking-normal-pri/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.elastic_cpu.returned_nanos/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.admitted.elastic-cpu/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.kvflowcontrol.streams.eval.elastic.total_count/10s/2025-12-13T12:00:00Z/1], Merge [/System/tsd/cr.node.admission.errored.sql-sql-response/10s/2025-12-13T12:00:00Z/1],... 5444 skipped ..., Merge [/System/tsd/cr.store.intentage/10s/2025-12-13T12:00:00Z/1-10], Merge [/System/tsd/cr.store.gcbytesage/10s/2025-12-13T12:00:00Z/1-10], Merge [/System/tsd/cr.store.livebytes/10s/2025-12-13T12:00:00Z/1-10], Merge [/System/tsd/cr.store.keybytes/10s/2025-12-13T12:00:00Z/1-10], Merge [/System/tsd/cr.store.totalbytes/10s/2025-12-13T12:00:00Z/1-10] has held latch for 19.8s. Some possible causes are slow disk reads, slow raft replication, and expensive request processing.
I251213 12:58:51.026616 11178 server/server_controller.go:416  [T1,Vsystem,n1] 2295  server controller shutting down
I251213 12:58:51.026954 11178 server/server_controller.go:425  [T1,Vsystem,n1] 2296  waiting for tenant servers to report stopped
--- FAIL: TestSQLWatcherMultiple (246.73s)

Parameters:

• attempt=1
• race=true
• run=1
• shard=1

Help

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

Same failure on other branches

• pkg/ccl/spanconfigccl/spanconfigsqlwatcherccl/spanconfigsqlwatcherccl_test: TestSQLWatcherMultiple failed #159266 pkg/ccl/spanconfigccl/spanconfigsqlwatcherccl/spanconfigsqlwatcherccl_test: TestSQLWatcherMultiple failed [C-test-failure O-robot T-sql-foundations branch-master release-blocker]

/cc @cockroachdb/sql-foundations

This test on roachdash | Improve this report!

Jira issue: CRDB-57864