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

[cockroach-teamcity]

pkg/ccl/spanconfigccl/spanconfigsqlwatcherccl/spanconfigsqlwatcherccl_test.TestSQLWatcherOnEventError failed with artifacts on release-22.2 @ 31eb3ce6ceb18123fd2e7eac464b25e203d7de0f:

I230218 08:33:09.958975 890758 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r51/1:/Table/5{1-2}] 507 +     0.619ms      0.619ms    event:kv/kvserver/allocator/allocatorimpl/allocator.go:682 [n1,replicate,s1,r51/1:/Table/5{1-2}] add voter - missing voter need=3, have=1, priority=10001.00
I230218 08:33:09.958975 890758 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r51/1:/Table/5{1-2}] 507 +     0.704ms      0.084ms    event:kv/kvserver/replicate_queue.go:866 [n1,replicate,s1,r51/1:/Table/5{1-2}] next replica action: add voter
I230218 08:33:09.958975 890758 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r51/1:/Table/5{1-2}] 507 +     0.861ms      0.157ms    event:kv/kvserver/allocator/allocatorimpl/allocator.go:1037 [n1,replicate,s1,r51/1:/Table/5{1-2}] allocate voter: []
I230218 08:33:09.961667 885282 sql/syntheticprivilegecache/cache.go:206  [n1] 508  warmed privileges for virtual tables in 60.47079ms
W230218 08:33:09.965828 811817 kv/kvserver/replica_proposal.go:490  [n1,s1,r4/1:/System{/tsd-tse},raft] 509  lease <empty> expired before being followed by lease repl=(n1,s1):1 seq=1 start=0,0 epo=1 pro=1676709189.964821364,0; foreground traffic may have been impacted
I230218 08:33:09.966958 891663 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r4/1:/System{/tsd-tse}] 510  error processing replica: 0 of 1 live stores are able to take a new replica for the range (1 already has a voter, 0 already have a non-voter); likely not enough nodes in cluster
I230218 08:33:09.966958 891663 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r4/1:/System{/tsd-tse}] 510 +trace:
I230218 08:33:09.966958 891663 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r4/1:/System{/tsd-tse}] 510 +     0.000ms      0.000ms    === operation:process replica _unfinished:1 _verbose:1 node:1 replicate: store:1 range:4/1:/System{/tsd-tse}
I230218 08:33:09.966958 891663 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r4/1:/System{/tsd-tse}] 510 +     0.250ms      0.250ms    event:kv/kvserver/allocator/allocatorimpl/allocator.go:682 [n1,replicate,s1,r4/1:/System{/tsd-tse}] add voter - missing voter need=3, have=1, priority=10001.00
I230218 08:33:09.966958 891663 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r4/1:/System{/tsd-tse}] 510 +     0.282ms      0.032ms    event:kv/kvserver/replicate_queue.go:866 [n1,replicate,s1,r4/1:/System{/tsd-tse}] next replica action: add voter
I230218 08:33:09.966958 891663 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r4/1:/System{/tsd-tse}] 510 +     0.367ms      0.084ms    event:kv/kvserver/allocator/allocatorimpl/allocator.go:1037 [n1,replicate,s1,r4/1:/System{/tsd-tse}] allocate voter: []
I230218 08:33:09.972991 811813 3@pebble/event.go:678  [n1,pebble,s1] 511  [JOB 6] WAL created 000005
I230218 08:33:09.976140 805484 1@server/server_sql.go:1451  [n1] 512  serving sql connections
I230218 08:33:09.977398 805484 testutils/testcluster/testcluster.go:1339  [-] 513  WaitForFullReplication
I230218 08:33:09.977537 805484 testutils/testcluster/testcluster.go:1343  [-] 514  WaitForFullReplication took: 368ns
I230218 08:33:09.977715 805484 2@rpc/context.go:1774  [n1,rnode=1,raddr=127.0.0.1:34123,class=default] 515  dialing
I230218 08:33:10.050656 894362 util/log/event_log.go:32  [n1,client=127.0.0.1:37074,user=root] 516 ={"Timestamp":1676709190028595263,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.rangefeed.enabled\" = true","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"kv.rangefeed.enabled","Value":"true"}
I230218 08:33:10.094869 894362 util/log/event_log.go:32  [n1,client=127.0.0.1:37074,user=root] 517 ={"Timestamp":1676709190058971980,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.closed_timestamp.target_duration\" = '100ms'","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"kv.closed_timestamp.target_duration","Value":"00:00:00.1"}
W230218 08:33:10.169386 811829 kv/kvserver/replica_proposal.go:490  [n1,s1,r23/1:/Table/2{2-3},raft] 518  lease <empty> expired before being followed by lease repl=(n1,s1):1 seq=1 start=0,0 epo=1 pro=1676709190.167501234,0; foreground traffic may have been impacted
I230218 08:33:10.176968 901700 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r23/1:/Table/2{2-3}] 519  error processing replica: 0 of 1 live stores are able to take a new replica for the range (1 already has a voter, 0 already have a non-voter); likely not enough nodes in cluster
I230218 08:33:10.176968 901700 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r23/1:/Table/2{2-3}] 519 +trace:
I230218 08:33:10.176968 901700 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r23/1:/Table/2{2-3}] 519 +     0.000ms      0.000ms    === operation:process replica _unfinished:1 _verbose:1 node:1 replicate: store:1 range:23/1:/Table/2{2-3}
I230218 08:33:10.176968 901700 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r23/1:/Table/2{2-3}] 519 +     0.194ms      0.194ms    event:kv/kvserver/allocator/allocatorimpl/allocator.go:682 [n1,replicate,s1,r23/1:/Table/2{2-3}] add voter - missing voter need=3, have=1, priority=10001.00
I230218 08:33:10.176968 901700 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r23/1:/Table/2{2-3}] 519 +     0.239ms      0.044ms    event:kv/kvserver/replicate_queue.go:866 [n1,replicate,s1,r23/1:/Table/2{2-3}] next replica action: add voter
I230218 08:33:10.176968 901700 13@kv/kvserver/replicate_queue.go:817  [n1,replicate,s1,r23/1:/Table/2{2-3}] 519 +     0.333ms      0.094ms    event:kv/kvserver/allocator/allocatorimpl/allocator.go:1037 [n1,replicate,s1,r23/1:/Table/2{2-3}] allocate voter: []
I230218 08:33:10.220490 894362 5@util/log/event_log.go:32  [n1,client=127.0.0.1:37074,user=root] 520 ={"Timestamp":1676709190117699231,"EventType":"create_table","Statement":"CREATE TABLE defaultdb.public.t ()","Tag":"CREATE TABLE","User":"root","DescriptorID":104,"TableName":"defaultdb.public.t"}
I230218 08:33:10.222227 805484 spanconfig/spanconfigsqlwatcher/sqlwatcher.go:244  [-] 521  established range feed over system.descriptors starting at time 1676709190.095893637,0
I230218 08:33:10.222410 805484 spanconfig/spanconfigsqlwatcher/sqlwatcher.go:303  [-] 522  established range feed over system.zones starting at time 1676709190.095893637,0
I230218 08:33:10.224092 805484 spanconfig/spanconfigsqlwatcher/sqlwatcher.go:399  [-] 523  established range feed over system.protected_ts_records starting at time 1676709190.095893637,0
    sqlwatcher_test.go:460: handler should never run
I230218 08:33:10.234792 805484 testutils/testcluster/testcluster.go:128  [-] 524  TestCluster quiescing nodes
W230218 08:33:10.235023 811565 kv/kvserver/replica_proposal.go:490  [n1,s1,r33/1:/Table/3{2-3},raft] 525  lease <empty> expired before being followed by lease repl=(n1,s1):1 seq=1 start=0,0 epo=1 pro=1676709190.233308221,0; foreground traffic may have been impacted
I230218 08:33:10.236189 893316 2@rpc/context.go:1393  [n1] 526  closing [{n1: 127.0.0.1:34123 (default)} {n0: 127.0.0.1:34123 (default)}]
W230218 08:33:10.245611 816472 sql/sqlliveness/slinstance/slinstance.go:242  [n1] 527  exiting heartbeat loop
W230218 08:33:10.246151 866759 kv/kvserver/intentresolver/intent_resolver.go:799  [-] 528  failed to gc transaction record: could not GC completed transaction anchored at /Table/30/1/100/0/"public"/4/1: node unavailable; try another peer
W230218 08:33:10.246541 811565 kv/kvserver/store.go:2585  [n1,s1,r33/1:/Table/3{2-3},raft] 529  unable to gossip on capacity change: node unavailable; try another peer
W230218 08:33:10.246541 811565 kv/kvserver/store.go:2585  [n1,s1,r33/1:/Table/3{2-3},raft] 529 +(1) node unavailable; try another peer
W230218 08:33:10.246541 811565 kv/kvserver/store.go:2585  [n1,s1,r33/1:/Table/3{2-3},raft] 529 +Error types: (1) *roachpb.NodeUnavailableError
W230218 08:33:10.247802 817426 kv/txn.go:705  [n1] 530  failure aborting transaction: node unavailable; try another peer; abort caused by: expire-sessions: failed to read query result: context canceled
E230218 08:33:10.250288 817426 jobs/registry.go:744  [n1] 531  error expiring job sessions: expire-sessions: failed to read query result: context canceled
W230218 08:33:10.250467 817426 kv/txn.go:705  [n1] 532  failure aborting transaction: node unavailable; try another peer; abort caused by: txn exec: context canceled
E230218 08:33:10.250544 817426 jobs/registry.go:752  [n1] 533  failed to serve pause and cancel requests: txn exec: context canceled
W230218 08:33:10.250604 817426 jobs/registry.go:821  [n1] 534  canceling all adopted jobs due to stopper quiescing
W230218 08:33:10.253153 903355 kv/txn.go:705  [n1,intExec=select-running/get-claimed-jobs] 535  failure aborting transaction: node unavailable; try another peer; abort caused by: connExecutor closing
E230218 08:33:10.253580 817877 jobs/registry.go:805  [n1] 536  error processing claimed jobs: could not query for claimed jobs: select-running/get-claimed-jobs: failed to read query result: context canceled
E230218 08:33:10.265287 816760 sql/stats/automatic_stats.go:580  [n1] 537  failed to get tables for automatic stats: get-tables: node unavailable; try another peer
I230218 08:33:10.265586 816760 sql/stats/automatic_stats.go:509  [n1] 538  quiescing auto stats refresher
W230218 08:33:10.266359 904143 kv/txn.go:705  [n1,client=127.0.0.1:37074,user=root] 539  failure aborting transaction: node unavailable; try another peer; abort caused by: result is ambiguous: server shutdown
W230218 08:33:10.266541 904143 1@sql/event_log.go:641  [n1,client=127.0.0.1:37074,user=root] 540  unable to save 1 entries to system.eventlog: result is ambiguous: server shutdown
--- FAIL: TestSQLWatcherOnEventError (1.43s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

Same failure on other branches

• pkg/ccl/spanconfigccl/spanconfigsqlwatcherccl/spanconfigsqlwatcherccl_test: TestSQLWatcherOnEventError failed #82031 pkg/ccl/spanconfigccl/spanconfigsqlwatcherccl/spanconfigsqlwatcherccl_test: TestSQLWatcherOnEventError failed [C-test-failure O-robot branch-release-22.1 sync-me sync-me-5]
• pkg/ccl/spanconfigccl/spanconfigsqlwatcherccl/spanconfigsqlwatcherccl_test: TestSQLWatcherOnEventError failed #76765 pkg/ccl/spanconfigccl/spanconfigsqlwatcherccl/spanconfigsqlwatcherccl_test: TestSQLWatcherOnEventError failed [C-test-failure O-robot branch-master sync-me-8]

/cc @cockroachdb/kv

This test on roachdash | Improve this report!

Jira issue: CRDB-24633

[github-actions]

We have marked this test failure issue as stale because it has been
inactive for 1 month. If this failure is still relevant, removing the
stale label or adding a comment will keep it active. Otherwise,
we'll close it in 5 days to keep the test failure queue tidy.

[arulajmani]

Fixed by #99824