Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ccl/changefeedccl: TestChangefeedUserDefinedTypes failed #101042

Closed
cockroach-teamcity opened this issue Apr 10, 2023 · 1 comment · Fixed by #101130
Closed

ccl/changefeedccl: TestChangefeedUserDefinedTypes failed #101042

cockroach-teamcity opened this issue Apr 10, 2023 · 1 comment · Fixed by #101130
Labels
A-cdc Change Data Capture branch-release-23.1 Used to mark GA and release blockers, technical advisories, and bugs for 23.1 C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. T-cdc
Milestone
23.1

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Apr 10, 2023 •
edited by exalate-issue-sync bot
Loading

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

I230410 08:30:36.335591 21194 3@pebble/event.go:734  [n1,s1,pebble] 203  [JOB 7] WAL created 000006
I230410 08:30:36.338097 20837 1@server/server_sql.go:1702  [T1,n1] 204  serving sql connections
I230410 08:30:36.360806 23639 util/log/event_log.go:32  [T1,n1,client=127.0.0.1:36866,user=root] 205 ={"Timestamp":1681115436358971830,"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:36.366418 23639 util/log/event_log.go:32  [T1,n1,client=127.0.0.1:36866,user=root] 206 ={"Timestamp":1681115436364869468,"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:36.370099 23639 util/log/event_log.go:32  [T1,n1,client=127.0.0.1:36866,user=root] 207 ={"Timestamp":1681115436368561370,"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:36.378032 23639 util/log/event_log.go:32  [T1,n1,client=127.0.0.1:36866,user=root] 208 ={"Timestamp":1681115436372203721,"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:36.378948 23639 sql/schemachanger/scbuild/build.go:45  [T1,n1,client=127.0.0.1:36866,user=root] 209  building declarative schema change targets for CREATE DATABASE
I230410 08:30:36.385531 23639 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:36866,user=root] 210 ={"Timestamp":1681115436378882960,"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:36.398199 23639 util/log/event_log.go:32  [T1,n1,client=127.0.0.1:36866,user=root] 211 ={"Timestamp":1681115436396222977,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"sql.defaults.use_declarative_schema_changer\" = 'off'","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"sql.defaults.use_declarative_schema_changer","Value":"off"}
I230410 08:30:36.404840 23639 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:36866,user=root] 212 ={"Timestamp":1681115436400598897,"EventType":"create_type","Statement":"CREATE TYPE d.public.t AS ENUM ('hello', 'howdy', 'hi')","Tag":"CREATE TYPE","User":"root","DescriptorID":106,"TypeName":"d.public.t"}
I230410 08:30:36.423766 23639 sql/type_change.go:146  [T1,n1,client=127.0.0.1:36866,user=root] 213  queued new type change job 855392375353376769 for type 106
I230410 08:30:36.424168 23639 sql/type_change.go:146  [T1,n1,client=127.0.0.1:36866,user=root] 214  queued new type change job 855392375354687489 for type 107
I230410 08:30:36.456124 23639 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:36866,user=root] 215 ={"Timestamp":1681115436407305927,"EventType":"create_table","Statement":"CREATE TABLE d.public.tt (x INT8 PRIMARY KEY, y t)","Tag":"CREATE TABLE","User":"root","DescriptorID":108,"TableName":"d.public.tt"}
I230410 08:30:36.459918 23745 jobs/adopt.go:261  [T1,n1,client=127.0.0.1:36866,user=root] 216  job 855392375354687489: resuming execution
I230410 08:30:36.459948 23744 jobs/adopt.go:261  [T1,n1,client=127.0.0.1:36866,user=root] 217  job 855392375353376769: resuming execution
I230410 08:30:36.464492 23750 jobs/adopt.go:261  [T1,n1] 218  job 855392375354687489: resuming execution
I230410 08:30:36.464562 23749 jobs/adopt.go:261  [T1,n1] 219  job 855392375353376769: resuming execution
I230410 08:30:36.471014 23679 jobs/registry.go:1538  [T1,n1] 220  TYPEDESC SCHEMA CHANGE job 855392375353376769: stepping through state running
I230410 08:30:36.472129 23765 jobs/registry.go:1538  [T1,n1] 221  TYPEDESC SCHEMA CHANGE job 855392375354687489: stepping through state running
I230410 08:30:36.480538 23679 sql/schema_changer.go:1314  [T1,n1,job=TYPEDESC SCHEMA CHANGE id=855392375353376769] 222  waiting for a single version...
I230410 08:30:36.480627 23765 sql/schema_changer.go:1314  [T1,n1,job=TYPEDESC SCHEMA CHANGE id=855392375354687489] 223  waiting for a single version...
I230410 08:30:36.485172 23679 sql/schema_changer.go:1319  [T1,n1,job=TYPEDESC SCHEMA CHANGE id=855392375353376769] 224  waiting for a single version... done (at v 2), took 4.633964ms
I230410 08:30:36.485234 23679 sql/schema_changer.go:1314  [T1,n1,job=TYPEDESC SCHEMA CHANGE id=855392375353376769] 225  waiting for a single version...
I230410 08:30:36.486000 23765 sql/schema_changer.go:1319  [T1,n1,job=TYPEDESC SCHEMA CHANGE id=855392375354687489] 226  waiting for a single version... done (at v 2), took 5.37285ms
I230410 08:30:36.486057 23765 jobs/registry.go:1538  [T1,n1] 227  TYPEDESC SCHEMA CHANGE job 855392375354687489: stepping through state succeeded
I230410 08:30:36.488343 23679 sql/schema_changer.go:1319  [T1,n1,job=TYPEDESC SCHEMA CHANGE id=855392375353376769] 228  waiting for a single version... done (at v 2), took 3.107939ms
I230410 08:30:36.488400 23679 jobs/registry.go:1538  [T1,n1] 229  TYPEDESC SCHEMA CHANGE job 855392375353376769: stepping through state succeeded
I230410 08:30:36.520111 23639 jobs/wait.go:145  [T1,n1,client=127.0.0.1:36866,user=root] 230  waited for 2 [855392375353376769 855392375354687489] queued jobs to complete 60.225751ms
I230410 08:30:36.520185 23639 sql/schema_changer.go:1314  [T1,n1,client=127.0.0.1:36866,user=root] 231  waiting for a single version...
I230410 08:30:36.523430 23639 sql/schema_changer.go:1319  [T1,n1,client=127.0.0.1:36866,user=root] 232  waiting for a single version... done (at v 2), took 3.24398ms
I230410 08:30:36.535628 23639 sql/schema_changer.go:1314  [T1,n1,client=127.0.0.1:36866,user=root] 233  waiting for a single version...
I230410 08:30:36.539129 23639 sql/schema_changer.go:1319  [T1,n1,client=127.0.0.1:36866,user=root] 234  waiting for a single version... done (at v 2), took 3.501599ms
I230410 08:30:36.555286 20837 ccl/changefeedccl/testfeed_test.go:795  [-] 235  Starting feed job: "CREATE CHANGEFEED FOR TABLE tt INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 08:30:36.555800 23926 1@ccl/changefeedccl/changefeed_stmt.go:965  [T1,n1,client=127.0.0.1:36866,user=root] 236  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 08:30:36.581799 23926 12@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:36866,user=root] 237 ={"Timestamp":1681115436581793947,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:1151: 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:36.583676 21487 sql/stats/automatic_stats.go:550  [T1,n1] 238  quiescing auto stats refresher
W230410 08:30:36.583712 23783 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 239  failed to gc transaction record: could not GC completed transaction anchored at /Table/15/1/855392375353376769/0: node unavailable; try another peer
I230410 08:30:36.584051 22721 jobs/registry.go:1538  [T1,n1] 240  KEY VISUALIZER job 100: stepping through state succeeded
W230410 08:30:36.584624 21416 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 241  exiting heartbeat loop
W230410 08:30:36.584657 21416 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 242  exiting heartbeat loop with error: node unavailable; try another peer
E230410 08:30:36.584680 21416 server/server_sql.go:508  [T1,n1] 243  failed to run update of instance with new session ID: node unavailable; try another peer
E230410 08:30:36.584749 23030 jobs/registry.go:943  [T1,n1] 244  error getting live session: node unavailable; try another peer
I230410 08:30:36.584836 22577 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:34055,class=default,rpc] 245  connection heartbeat loop ended with err: <nil>
I230410 08:30:36.583733 21102 server/start_listen.go:103  [T1,n1] 246  server shutting down: instructing cmux to stop accepting
W230410 08:30:36.590377 23204 jobs/adopt.go:518  [T1,n1] 247  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 08:30:36.606507 22721 jobs/adopt.go:518  [T1,n1] 248  could not clear job claim: clear-job-claim: failed to send RPC: sending to all replicas failed; last error: ba: Scan [/Table/15/1/100,/Table/15/1/101), [txn: a011b22d], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 08:30:36.610424 20837 server/server_sql.go:1666  [T1,n1] 249  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedUserDefinedTypes/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-26774

Epic CRDB-11732
@cockroach-teamcity cockroach-teamcity added branch-release-23.1 Used to mark GA and release blockers, technical advisories, and bugs for 23.1 C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Apr 10, 2023
@cockroach-teamcity cockroach-teamcity added this to the 23.1 milestone Apr 10, 2023
@blathers-crl blathers-crl bot added the A-cdc Change Data Capture label Apr 10, 2023
@cockroach-teamcity
Copy link
Member Author

ccl/changefeedccl.TestChangefeedUserDefinedTypes failed with artifacts on release-23.1 @ 369be46ba7ca5b8d081698c6c70c8641c688065b:

I230410 14:53:34.009283 34420 jobs/adopt.go:261  [T10,nsql1] 377  job 855467668122927105: resuming execution
I230410 14:53:34.021565 34417 jobs/registry.go:1538  [T10,nsql1] 378  TYPEDESC SCHEMA CHANGE job 855467668127055873: stepping through state running
I230410 14:53:34.022981 34303 jobs/registry.go:1538  [T10,nsql1] 379  TYPEDESC SCHEMA CHANGE job 855467668122927105: stepping through state running
I230410 14:53:34.046413 34417 sql/schema_changer.go:1314  [T10,nsql1,job=TYPEDESC SCHEMA CHANGE id=855467668127055873] 380  waiting for a single version...
I230410 14:53:34.049279 34417 sql/schema_changer.go:1319  [T10,nsql1,job=TYPEDESC SCHEMA CHANGE id=855467668127055873] 381  waiting for a single version... done (at v 2), took 2.866422ms
I230410 14:53:34.049529 34417 jobs/registry.go:1538  [T10,nsql1] 382  TYPEDESC SCHEMA CHANGE job 855467668127055873: stepping through state succeeded
I230410 14:53:34.061266 34303 sql/schema_changer.go:1314  [T10,nsql1,job=TYPEDESC SCHEMA CHANGE id=855467668122927105] 383  waiting for a single version...
I230410 14:53:34.065003 34303 sql/schema_changer.go:1319  [T10,nsql1,job=TYPEDESC SCHEMA CHANGE id=855467668122927105] 384  waiting for a single version... done (at v 2), took 3.736567ms
I230410 14:53:34.065063 34303 sql/schema_changer.go:1314  [T10,nsql1,job=TYPEDESC SCHEMA CHANGE id=855467668122927105] 385  waiting for a single version...
I230410 14:53:34.071166 34303 sql/schema_changer.go:1319  [T10,nsql1,job=TYPEDESC SCHEMA CHANGE id=855467668122927105] 386  waiting for a single version... done (at v 2), took 6.101264ms
I230410 14:53:34.071235 34303 jobs/registry.go:1538  [T10,nsql1] 387  TYPEDESC SCHEMA CHANGE job 855467668122927105: stepping through state succeeded
I230410 14:53:34.131683 34058 jobs/wait.go:145  [T10,nsql1,client=127.0.0.1:34242,user=root] 388  waited for 2 [855467668122927105 855467668127055873] queued jobs to complete 134.322962ms
I230410 14:53:34.131757 34058 sql/schema_changer.go:1314  [T10,nsql1,client=127.0.0.1:34242,user=root] 389  waiting for a single version...
I230410 14:53:34.135446 34058 sql/schema_changer.go:1319  [T10,nsql1,client=127.0.0.1:34242,user=root] 390  waiting for a single version... done (at v 2), took 3.68737ms
I230410 14:53:34.135496 34058 sql/schema_changer.go:1314  [T10,nsql1,client=127.0.0.1:34242,user=root] 391  waiting for a single version...
I230410 14:53:34.139844 34058 sql/schema_changer.go:1319  [T10,nsql1,client=127.0.0.1:34242,user=root] 392  waiting for a single version... done (at v 2), took 4.346787ms
I230410 14:53:34.203392 26962 ccl/changefeedccl/testfeed_test.go:795  [-] 393  Starting feed job: "CREATE CHANGEFEED FOR TABLE tt INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 14:53:34.204040 34757 1@ccl/changefeedccl/changefeed_stmt.go:965  [T10,nsql1,client=127.0.0.1:34242,user=root] 394  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 14:53:34.220004 34757 12@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:34242,user=root] 395 ={"Timestamp":1681138414219999809,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:1151: 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:53:34.227937 30756 sql/stats/automatic_stats.go:550  [T10,nsql1] 396  quiescing auto stats refresher
I230410 14:53:34.228061 30639 server/start_listen.go:103  [T10,nsql1] 397  server shutting down: instructing cmux to stop accepting
I230410 14:53:34.228620 31001 jobs/registry.go:1538  [T10,nsql1] 398  AUTO SPAN CONFIG RECONCILIATION job 855467660823068673: stepping through state succeeded
W230410 14:53:34.228679 30644 ccl/kvccl/kvtenantccl/setting_overrides.go:46  [T10,nsql1,tenant-connector] 399  error consuming TenantSettings RPC: recv msg error: grpc: context canceled [code 1/Canceled]
W230410 14:53:34.229109 30721 sql/sqlliveness/slinstance/slinstance.go:334  [T10,nsql1] 400  exiting heartbeat loop
W230410 14:53:34.229154 30721 sql/sqlliveness/slinstance/slinstance.go:321  [T10,nsql1] 401  exiting heartbeat loop with error: node unavailable; try another peer
E230410 14:53:34.229276 33280 jobs/registry.go:943  [-] 402  error getting live session: node unavailable; try another peer
E230410 14:53:34.230572 30762 jobs/registry.go:995  [T10,nsql1] 403  failed to serve pause and cancel requests: could not query jobs table: cancel/pause-requested: failed to read query result: query execution canceled
I230410 14:53:34.230619 30671 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:43741,class=default,rpc] 404  connection heartbeat loop ended with err: <nil>
I230410 14:53:34.230672 30126 rpc/context.go:2302  [T10,nsql1,rnode=63,raddr=127.0.0.1:43741,class=system,rpc] 405  connection heartbeat loop ended with err: <nil>
W230410 14:53:34.230807 30643 ccl/kvccl/kvtenantccl/connector.go:249  [T10,nsql1,tenant-connector] 406  error consuming GossipSubscription RPC: recv msg error: grpc: context canceled [code 1/Canceled]
W230410 14:53:34.233359 31001 jobs/adopt.go:518  [-] 407  could not clear job claim: clear-job-claim: tenant-side-limiter pool closed: shutting down
E230410 14:53:34.235627 30764 jobs/registry.go:1015  [T10,nsql1] 408  error claiming jobs: could not query jobs table: claim-jobs: failed to read query result: query execution canceled
W230410 14:53:34.239556 33711 jobs/adopt.go:518  [-] 409  could not clear job claim: clear-job-claim: tenant-side-limiter pool closed: shutting down
W230410 14:53:34.248326 26962 server/server_sql.go:1658  [T10,nsql1] 410  server shutdown without a prior graceful drain
W230410 14:53:34.248856 34663 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 411  failed to gc transaction record: could not GC completed transaction anchored at /Tenant/10/Table/15/1/855467668122927105/0: node unavailable; try another peer
I230410 14:53:34.249135 27624 sql/stats/automatic_stats.go:550  [T1,n1] 412  quiescing auto stats refresher
I230410 14:53:34.253924 29029 jobs/registry.go:1538  [T1,n1] 413  KEY VISUALIZER job 100: stepping through state succeeded
I230410 14:53:34.258207 27236 server/start_listen.go:103  [T1,n1] 414  server shutting down: instructing cmux to stop accepting
W230410 14:53:34.259528 27590 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 415  exiting heartbeat loop
W230410 14:53:34.259923 27590 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 420  exiting heartbeat loop with error: node unavailable; try another peer
E230410 14:53:34.259958 27590 server/server_sql.go:506  [T1,n1] 421  failed to run update of instance with new session ID: node unavailable; try another peer
I230410 14:53:34.259640 27836 jobs/registry.go:1538  [T1,n1] 416  AUTO SPAN CONFIG RECONCILIATION job 855467650142601217: stepping through state succeeded
E230410 14:53:34.260047 27836 jobs/registry.go:943  [T1,n1] 422  error getting live session: node unavailable; try another peer
W230410 14:53:34.259694 29320 jobs/adopt.go:518  [T1,n1] 417  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: 3b90bc14], [can-forward-ts] RPC error: node unavailable; try another peer
E230410 14:53:34.259690 27630 jobs/registry.go:995  [T1,n1] 418  failed to serve pause and cancel requests: could not query jobs table: cancel/pause-requested: failed to read query result: query execution canceled
I230410 14:53:34.259721 28014 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:43741,class=default,rpc] 419  connection heartbeat loop ended with err: <nil>
W230410 14:53:34.268767 28734 jobs/adopt.go:518  [T1,n1] 423  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 14:53:34.270603 29029 jobs/adopt.go:518  [T1,n1] 424  could not clear job claim: clear-job-claim: node unavailable; try another peer
    --- FAIL: TestChangefeedUserDefinedTypes/pubsub (5.97s)
Help

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

This test on roachdash | Improve this report!

@samiskin samiskin mentioned this issue Apr 10, 2023
Merged
@blathers-crl blathers-crl bot mentioned this issue Apr 10, 2023
Merged
@craig craig bot closed this as completed in 9c55b61 Apr 10, 2023
@craig craig bot closed this as completed in #101130 Apr 10, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
A-cdc Change Data Capture branch-release-23.1 Used to mark GA and release blockers, technical advisories, and bugs for 23.1 C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. T-cdc
Projects
None yet
Milestone
23.1
Development

Successfully merging a pull request may close this issue.

changefeedccl: fix pubsub v2 unit tests on AWS samiskin/cockroach
2 participants
@cockroach-teamcity @shermanCRL