ccl/changefeedccl: TestNoBackfillAfterNonTargetColumnDrop failed

[cockroach-teamcity]

ccl/changefeedccl.TestNoBackfillAfterNonTargetColumnDrop failed with artifacts on release-23.1 @ 2f96695f75b07c872ec5f146acc1fa198135768f:

I230410 08:30:43.426172 27457 jobs/wait.go:145  [T1,n1] 185  waited for 1 [855392397902675969] queued jobs to complete 58.727163ms
I230410 08:30:43.426332 27457 upgrade/upgrademanager/manager.go:270  [T1,n1] 186  running permanent upgrade for version 22.2-98
I230410 08:30:43.454244 27457 jobs/registry.go:608  [T1,n1] 187  active version is 22.2-98
I230410 08:30:43.478994 27457 upgrade/upgrademanager/manager.go:708  [T1,n1] 188  running Upgrade to 22.2-98: "change TTL for SQL Stats system tables"
I230410 08:30:43.479078 33689 jobs/adopt.go:261  [T1,n1] 189  job 855392398299529217: resuming execution
I230410 08:30:43.480976 33729 jobs/adopt.go:261  [T1,n1] 190  job 855392398299529217: resuming execution
I230410 08:30:43.516437 33694 jobs/registry.go:1538  [T1,n1] 191  MIGRATION job 855392398299529217: stepping through state running
I230410 08:30:43.574252 33777 1@util/log/event_log.go:32  [T1,n1,job=MIGRATION id=855392398299529217,upgrade=22.2-98,intExec=set-SQLStatsTables-TTL] 192 ={"Timestamp":1681115443569180572,"EventType":"set_zone_config","Statement":"ALTER TABLE \"\".system.statement_statistics CONFIGURE ZONE USING \"gc.ttlseconds\" = $1","Tag":"CONFIGURE ZONE","User":"root","DescriptorID":42,"ApplicationName":"$ internal-set-SQLStatsTables-TTL","PlaceholderValues":["3600"],"Target":"TABLE system.public.statement_statistics","Options":["\"gc.ttlseconds\" = 3600"]}
I230410 08:30:43.579053 33594 1@util/log/event_log.go:32  [T1,n1,job=MIGRATION id=855392398299529217,upgrade=22.2-98,intExec=set-SQLStatsTables-TTL] 193 ={"Timestamp":1681115443574819862,"EventType":"set_zone_config","Statement":"ALTER TABLE \"\".system.transaction_statistics CONFIGURE ZONE USING \"gc.ttlseconds\" = $1","Tag":"CONFIGURE ZONE","User":"root","DescriptorID":43,"ApplicationName":"$ internal-set-SQLStatsTables-TTL","PlaceholderValues":["3600"],"Target":"TABLE system.public.transaction_statistics","Options":["\"gc.ttlseconds\" = 3600"]}
I230410 08:30:43.584855 33759 1@util/log/event_log.go:32  [T1,n1,job=MIGRATION id=855392398299529217,upgrade=22.2-98,intExec=set-SQLStatsTables-TTL] 194 ={"Timestamp":1681115443579342547,"EventType":"set_zone_config","Statement":"ALTER TABLE \"\".system.statement_activity CONFIGURE ZONE USING \"gc.ttlseconds\" = $1","Tag":"CONFIGURE ZONE","User":"root","DescriptorID":60,"ApplicationName":"$ internal-set-SQLStatsTables-TTL","PlaceholderValues":["3600"],"Target":"TABLE system.public.statement_activity","Options":["\"gc.ttlseconds\" = 3600"]}
I230410 08:30:43.591831 33822 1@util/log/event_log.go:32  [T1,n1,job=MIGRATION id=855392398299529217,upgrade=22.2-98,intExec=set-SQLStatsTables-TTL] 195 ={"Timestamp":1681115443585152857,"EventType":"set_zone_config","Statement":"ALTER TABLE \"\".system.transaction_activity CONFIGURE ZONE USING \"gc.ttlseconds\" = $1","Tag":"CONFIGURE ZONE","User":"root","DescriptorID":61,"ApplicationName":"$ internal-set-SQLStatsTables-TTL","PlaceholderValues":["3600"],"Target":"TABLE system.public.transaction_activity","Options":["\"gc.ttlseconds\" = 3600"]}
I230410 08:30:43.592901 33694 jobs/registry.go:1538  [T1,n1] 196  MIGRATION job 855392398299529217: stepping through state succeeded
I230410 08:30:43.619706 27457 jobs/wait.go:145  [T1,n1] 197  waited for 1 [855392398299529217] queued jobs to complete 140.653498ms
I230410 08:30:43.619766 27457 server/server_sql.go:1597  [T1,n1] 198  done ensuring all necessary startup migrations have run
I230410 08:30:43.620213 33899 kv/kvclient/rangefeed/rangefeedcache/watcher.go:335  [T1,n1] 199  tenant-settings-watcher: established range feed cache
I230410 08:30:43.622386 33893 jobs/job_scheduler.go:407  [T1,n1] 200  waiting 4m0s before scheduled jobs daemon start
I230410 08:30:43.624954 33901 kv/kvclient/rangefeed/rangefeedcache/watcher.go:335  [T1,n1] 201  tenant-capability-watcher: established range feed cache
I230410 08:30:43.633928 33901 multitenant/tenantcapabilities/tenantcapabilitieswatcher/watcher.go:149  [T1,n1] 202  received results of a full table scan for tenant capabilities
I230410 08:30:43.636661 33897 server/auto_upgrade.go:78  [T1,n1] 203  no need to upgrade, cluster already at the newest version
I230410 08:30:43.654427 33895 sql/syntheticprivilegecache/cache.go:199  [T1,n1] 204  warmed privileges for virtual tables in 30.553765ms
I230410 08:30:43.698896 31600 3@pebble/event.go:734  [n1,s1,pebble] 205  [JOB 7] WAL created 000006
I230410 08:30:43.702075 27457 1@server/server_sql.go:1702  [T1,n1] 206  serving sql connections
I230410 08:30:43.747289 33870 util/log/event_log.go:32  [T1,n1,client=127.0.0.1:56260,user=root] 207 ={"Timestamp":1681115443745499958,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.rangefeed.enabled\" = true","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"kv.rangefeed.enabled","Value":"true"}
I230410 08:30:43.753274 33870 util/log/event_log.go:32  [T1,n1,client=127.0.0.1:56260,user=root] 208 ={"Timestamp":1681115443751696880,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.closed_timestamp.target_duration\" = '1s'","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"kv.closed_timestamp.target_duration","Value":"00:00:01"}
I230410 08:30:43.757203 33870 util/log/event_log.go:32  [T1,n1,client=127.0.0.1:56260,user=root] 209 ={"Timestamp":1681115443755515314,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"changefeed.experimental_poll_interval\" = '10ms'","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"changefeed.experimental_poll_interval","Value":"00:00:00.01"}
I230410 08:30:43.761189 33870 util/log/event_log.go:32  [T1,n1,client=127.0.0.1:56260,user=root] 210 ={"Timestamp":1681115443759653874,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"sql.defaults.vectorize\" = \"on\"","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"sql.defaults.vectorize","Value":"on"}
I230410 08:30:43.772443 33870 sql/schemachanger/scbuild/build.go:45  [T1,n1,client=127.0.0.1:56260,user=root] 211  building declarative schema change targets for CREATE DATABASE
I230410 08:30:43.805160 33870 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:56260,user=root] 212 ={"Timestamp":1681115443772381227,"EventType":"create_database","Statement":"CREATE DATABASE d","Tag":"CREATE DATABASE","User":"root","DescriptorID":104,"DatabaseName":"d"}
    helpers_test.go:895: making pubsub feed factory
I230410 08:30:43.843436 33870 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:56260,user=root] 213 ={"Timestamp":1681115443808880622,"EventType":"create_table","Statement":"CREATE TABLE d.public.hasfams (id INT8 PRIMARY KEY, a STRING, b STRING, c STRING, FAMILY id_a (id, a), FAMILY b_and_c (b, c))","Tag":"CREATE TABLE","User":"root","DescriptorID":106,"TableName":"d.public.hasfams"}
I230410 08:30:43.870956 27457 ccl/changefeedccl/testfeed_test.go:795  [-] 214  Starting feed job: "CREATE CHANGEFEED FOR TABLE hasfams FAMILY b_and_c INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 08:30:43.871497 33870 sql/schemachanger/scbuild/build.go:45  [T1,n1,client=127.0.0.1:56260,user=root] 215  building declarative schema change targets for CREATE CHANGEFEED
I230410 08:30:43.872226 34164 1@ccl/changefeedccl/changefeed_stmt.go:965  [T1,n1,client=127.0.0.1:56260,user=root] 216  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 08:30:43.924011 34164 12@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:56260,user=root] 217 ={"Timestamp":1681115443924006273,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:1263: failed to start feed for job 0: pq: opening client: google: could not find default credentials. See https://developers.google.com/accounts/docs/application-default-credentials for more information.
I230410 08:30:43.925865 31860 sql/stats/automatic_stats.go:550  [T1,n1] 218  quiescing auto stats refresher
W230410 08:30:43.926021 34139 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 219  failed to gc transaction record: could not GC completed transaction anchored at /Table/3/1/106/2/1: node unavailable; try another peer
I230410 08:30:43.929153 33299 jobs/registry.go:1538  [T1,n1] 220  KEY VISUALIZER job 100: stepping through state succeeded
W230410 08:30:43.933392 33299 jobs/adopt.go:518  [T1,n1] 221  could not clear job claim: clear-job-claim: node unavailable; try another peer
I230410 08:30:43.933737 33010 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:38741,class=default,rpc] 222  connection heartbeat loop ended with err: <nil>
W230410 08:30:43.933848 31840 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 223  exiting heartbeat loop
W230410 08:30:43.935284 31840 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 226  exiting heartbeat loop with error: node unavailable; try another peer
E230410 08:30:43.935319 31840 server/server_sql.go:508  [T1,n1] 227  failed to run update of instance with new session ID: node unavailable; try another peer
I230410 08:30:43.934177 32140 jobs/registry.go:1538  [T1,n1] 224  AUTO SPAN CONFIG RECONCILIATION job 855392392905424897: stepping through state succeeded
E230410 08:30:43.935425 32140 jobs/registry.go:943  [T1,n1] 228  error getting live session: node unavailable; try another peer
I230410 08:30:43.934341 31488 server/start_listen.go:103  [T1,n1] 225  server shutting down: instructing cmux to stop accepting
W230410 08:30:43.942256 33546 jobs/adopt.go:518  [T1,n1] 229  could not clear job claim: clear-job-claim: failed to send RPC: sending to all replicas failed; last error: ba: Scan [/Table/15/1/102,/Table/15/1/103), [txn: 8f2fb633], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 08:30:43.944758 33435 jobs/adopt.go:518  [T1,n1] 230  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 08:30:43.948428 27457 server/server_sql.go:1666  [T1,n1] 231  server shutdown without a prior graceful drain
    --- FAIL: TestNoBackfillAfterNonTargetColumnDrop/pubsub (2.41s)

Help

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

/cc @cockroachdb/cdc

This test on roachdash | Improve this report!

Jira issue: CRDB-26777

Epic CRDB-11732

[cockroach-teamcity]

ccl/changefeedccl.TestNoBackfillAfterNonTargetColumnDrop failed with artifacts on release-23.1 @ f4145091448687af29b54054a61c32f96303af96:

I230410 14:59:25.865915 18049 jobs/wait.go:145  [T10,nsql1] 354  waited for 1 [855468820773961729] queued jobs to complete 62.720818ms
I230410 14:59:25.865978 18049 server/server_sql.go:1597  [T10,nsql1] 355  done ensuring all necessary startup migrations have run
I230410 14:59:25.866563 18049 1@server/server_sql.go:1702  [T10,nsql1] 356  serving sql connections
I230410 14:59:25.866563 24900 jobs/job_scheduler.go:407  [T10,nsql1] 357  waiting 3m0s before scheduled jobs daemon start
I230410 14:59:25.873364 24609 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r47/1:/Table/4{5-6}] 358  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
I230410 14:59:25.874666 24902 sql/syntheticprivilegecache/cache.go:199  [T10,nsql1] 359  warmed privileges for virtual tables in 6.744289ms
I230410 14:59:25.883903 24886 util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:54388,user=root] 360 ={"Timestamp":1681138765881684967,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.rangefeed.enabled\" = true","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"kv.rangefeed.enabled","Value":"true"}
I230410 14:59:25.887262 24886 util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:54388,user=root] 361 ={"Timestamp":1681138765884201256,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.closed_timestamp.target_duration\" = '1s'","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"kv.closed_timestamp.target_duration","Value":"00:00:01"}
I230410 14:59:25.890207 24886 util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:54388,user=root] 362 ={"Timestamp":1681138765887685166,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"changefeed.experimental_poll_interval\" = '10ms'","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"changefeed.experimental_poll_interval","Value":"00:00:00.01"}
I230410 14:59:25.892721 24886 util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:54388,user=root] 363 ={"Timestamp":1681138765890513657,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"sql.defaults.vectorize\" = \"on\"","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"sql.defaults.vectorize","Value":"on"}
I230410 14:59:25.893108 24886 sql/schemachanger/scbuild/build.go:45  [T10,nsql1,client=127.0.0.1:54388,user=root] 364  building declarative schema change targets for CREATE DATABASE
I230410 14:59:25.912086 24886 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:54388,user=root] 365 ={"Timestamp":1681138765893010172,"EventType":"create_database","Statement":"CREATE DATABASE d","Tag":"CREATE DATABASE","User":"root","DescriptorID":104,"DatabaseName":"d"}
    helpers_test.go:895: making pubsub feed factory
I230410 14:59:25.952219 24886 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:54388,user=root] 366 ={"Timestamp":1681138765913085396,"EventType":"create_table","Statement":"CREATE TABLE d.public.hasfams (id INT8 PRIMARY KEY, a STRING, b STRING, c STRING, FAMILY id_a (id, a), FAMILY b_and_c (b, c))","Tag":"CREATE TABLE","User":"root","DescriptorID":106,"TableName":"d.public.hasfams"}
I230410 14:59:25.976175 18049 ccl/changefeedccl/testfeed_test.go:795  [-] 367  Starting feed job: "CREATE CHANGEFEED FOR TABLE hasfams FAMILY b_and_c INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 14:59:25.976445 24886 sql/schemachanger/scbuild/build.go:45  [T10,nsql1,client=127.0.0.1:54388,user=root] 368  building declarative schema change targets for CREATE CHANGEFEED
I230410 14:59:25.976704 25094 1@ccl/changefeedccl/changefeed_stmt.go:965  [T10,nsql1,client=127.0.0.1:54388,user=root] 369  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 14:59:25.994803 25094 12@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:54388,user=root] 370 ={"Timestamp":1681138765994798307,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:1263: failed to start feed for job 0: pq: opening client: google: could not find default credentials. See https://developers.google.com/accounts/docs/application-default-credentials for more information.
I230410 14:59:25.996245 21675 sql/stats/automatic_stats.go:550  [T10,nsql1] 371  quiescing auto stats refresher
I230410 14:59:25.996463 21434 server/start_listen.go:103  [T10,nsql1] 372  server shutting down: instructing cmux to stop accepting
I230410 14:59:25.996517 21640 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:35881,class=rangefeed,rpc] 373  connection heartbeat loop ended with err: <nil>
W230410 14:59:25.996608 21627 sql/sqlliveness/slinstance/slinstance.go:334  [T10,nsql1] 374  exiting heartbeat loop
W230410 14:59:25.996631 21627 sql/sqlliveness/slinstance/slinstance.go:321  [T10,nsql1] 375  exiting heartbeat loop with error: node unavailable; try another peer
W230410 14:59:25.996853 24426 jobs/adopt.go:518  [-] 376  could not clear job claim: clear-job-claim: node unavailable; try another peer
I230410 14:59:25.996866 21610 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:35881,class=default,rpc] 377  connection heartbeat loop ended with err: <nil>
I230410 14:59:25.996916 21441 rpc/context.go:2302  [T10,nsql1,rnode=63,raddr=127.0.0.1:35881,class=system,rpc] 378  connection heartbeat loop ended with err: <nil>
I230410 14:59:25.996928 22213 jobs/registry.go:1538  [T10,nsql1] 379  AUTO SPAN CONFIG RECONCILIATION job 855468815887761409: stepping through state succeeded
E230410 14:59:25.997010 22213 jobs/registry.go:943  [-] 380  error getting live session: node unavailable; try another peer
W230410 14:59:25.996970 21438 ccl/kvccl/kvtenantccl/connector.go:249  [T10,nsql1,tenant-connector] 381  error consuming GossipSubscription RPC: recv msg error: grpc: context canceled [code 1/Canceled]
W230410 14:59:25.997098 21439 ccl/kvccl/kvtenantccl/setting_overrides.go:46  [T10,nsql1,tenant-connector] 382  error consuming TenantSettings RPC: recv msg error: grpc: context canceled [code 1/Canceled]
E230410 14:59:25.997155 21681 jobs/registry.go:987  [T10,nsql1] 383  error expiring job sessions: expire-sessions: failed to read query result: query execution canceled
E230410 14:59:25.997208 21681 jobs/registry.go:995  [T10,nsql1] 384  failed to serve pause and cancel requests: txn exec: context canceled
W230410 14:59:26.000724 23920 jobs/adopt.go:518  [-] 385  could not clear job claim: clear-job-claim: tenant-side-limiter pool closed: shutting down
W230410 14:59:26.002189 18049 server/server_sql.go:1666  [T10,nsql1] 386  server shutdown without a prior graceful drain
I230410 14:59:26.002635 18572 sql/stats/automatic_stats.go:550  [T1,n1] 387  quiescing auto stats refresher
W230410 14:59:26.002750 24914 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 388  failed to gc transaction record: could not GC completed transaction anchored at /Tenant/10/Table/15/1/855468820773961729/0: node unavailable; try another peer
I230410 14:59:26.008055 19977 jobs/registry.go:1538  [T1,n1] 389  KEY VISUALIZER job 100: stepping through state succeeded
W230410 14:59:26.012144 19977 jobs/adopt.go:518  [T1,n1] 390  could not clear job claim: clear-job-claim: node unavailable; try another peer
I230410 14:59:26.012434 18318 server/start_listen.go:103  [T1,n1] 391  server shutting down: instructing cmux to stop accepting
I230410 14:59:26.012681 19939 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:35881,class=default,rpc] 392  connection heartbeat loop ended with err: <nil>
W230410 14:59:26.012804 20291 jobs/adopt.go:518  [T1,n1] 393  could not clear job claim: clear-job-claim: failed to send RPC: sending to all replicas failed; last error: ba: Scan [/Table/15/1/102,/Table/15/1/103), [txn: 66dadcc9], [can-forward-ts] RPC error: node unavailable; try another peer
I230410 14:59:26.013315 18889 jobs/registry.go:1538  [T1,n1] 394  AUTO SPAN CONFIG RECONCILIATION job 855468806268583937: stepping through state succeeded
W230410 14:59:26.021540 18889 jobs/adopt.go:518  [T1,n1] 397  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 14:59:26.013373 18550 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 395  exiting heartbeat loop
W230410 14:59:26.017167 20122 jobs/adopt.go:518  [T1,n1] 396  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 14:59:26.036306 18550 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 398  exiting heartbeat loop with error: node unavailable; try another peer
E230410 14:59:26.036488 18550 server/server_sql.go:508  [T1,n1] 399  failed to run update of instance with new session ID: node unavailable; try another peer
W230410 14:59:26.038982 18049 server/server_sql.go:1666  [T1,n1] 400  server shutdown without a prior graceful drain
    --- FAIL: TestNoBackfillAfterNonTargetColumnDrop/pubsub (4.97s)

Help

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

This test on roachdash | Improve this report!