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: TestChangefeedTopicNames failed #101018

Closed
cockroach-teamcity opened this issue Apr 9, 2023 · 14 comments · Fixed by #101130
Closed

ccl/changefeedccl: TestChangefeedTopicNames failed #101018

cockroach-teamcity opened this issue Apr 9, 2023 · 14 comments · 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 9, 2023 •
edited by exalate-issue-sync bot
Loading

ccl/changefeedccl.TestChangefeedTopicNames failed with artifacts on release-23.1 @ cfbd751ae4c82e2c4b5314376cd6e6c29cc30aea:

I230409 13:52:52.336601 109732 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 861 ={"Timestamp":1681048372328718006,"EventType":"create_table","Statement":"CREATE TABLE d.public.table😱89 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.table😱89"}
I230409 13:52:52.351830 109732 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 862 ={"Timestamp":1681048372344302756,"EventType":"create_table","Statement":"CREATE TABLE d.public.table90 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.table90"}
I230409 13:52:52.379564 109732 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 863 ={"Timestamp":1681048372360337675,"EventType":"create_table","Statement":"CREATE TABLE d.public.table91 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.table91"}
I230409 13:52:52.414842 109732 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 864 ={"Timestamp":1681048372387531902,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tab le92\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.\"tab le92\""}
I230409 13:52:52.432234 109732 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 865 ={"Timestamp":1681048372421435749,"EventType":"create_table","Statement":"CREATE TABLE d.public.table93 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.table93"}
I230409 13:52:52.448424 109732 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 866 ={"Timestamp":1681048372440173304,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl%ve94\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.\"tabl%ve94\""}
I230409 13:52:52.465135 109732 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 867 ={"Timestamp":1681048372457834423,"EventType":"create_table","Statement":"CREATE TABLE d.public.table95 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.table95"}
I230409 13:52:52.479742 109732 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 868 ={"Timestamp":1681048372471433469,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta%11ble96\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.\"ta%11ble96\""}
I230409 13:52:52.497886 109732 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 869 ={"Timestamp":1681048372486979408,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"\u000ctable97\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.\"\u000ctable97\""}
I230409 13:52:52.514764 109732 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 870 ={"Timestamp":1681048372506469719,"EventType":"create_table","Statement":"CREATE TABLE d.public.table98 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.table98"}
I230409 13:52:52.537722 109732 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 871 ={"Timestamp":1681048372524402778,"EventType":"create_table","Statement":"CREATE TABLE d.public.ta😶ble99 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.ta😶ble99"}
I230409 13:52:52.552626 109732 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 872 ={"Timestamp":1681048372543889347,"EventType":"create_table","Statement":"CREATE TABLE d.public.table100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.table100"}
I230409 13:52:52.591710 102667 ccl/changefeedccl/testfeed_test.go:795  [-] 873  Starting feed job: "CREATE CHANGEFEED FOR TABLE table1, TABLE table2, TABLE table3, TABLE \"tabl}e4\", TABLE \" table5\", TABLE table6, TABLE \"%ptabLe7\", TABLE \"tAble😴8\", TABLE table9, TABLE tablͦe10, TABLE table11, TABLE \"table\v12\", TABLE \"tabl.e13\", TABLE \"t\vable14\", TABLE table15, TABLE \"tab'l͜e16\", TABLE table17, TABLE t̜able18, TABLE table19, TABLE table20, TABLE table21, TABLE table22, TABLE table23, TABLE table24, TABLE \"tab'le25\", TABLE table26, TABLE \"table%p27\", TABLE \"t\"\"able28\", TABLE table29, TABLE table30, TABLE table31, TABLE \"ta ble32\", TABLE table33, TABLE table34, TABLE \"taBLe35\", TABLE \"tͧ\"\"a%60ble36\", TABLE \"table\v37\", TABLE \"ta,ble38\", TABLE \"t(%pable39\", TABLE table40, TABLE table41, TABLE \"tabl%pe42\", TABLE ta🙁ble43, TABLE table44, TABLE table45, TABLE table46, TABLE table47, TABLE \"tab\"\"le48\", TABLE t🙄able49, TABLE table50, TABLE \"tabLe51\", TABLE table52, TABLE tabl_e53, TABLE table54, TABLE table😵55, TABLE table56, TABLE \"tab%8ale57\", TABLE table58, TABLE \"\rtable59\", TABLE \"😪tab l😘e\\\\U000192EC60\", TABLE \"ta \\gble!61\", TABLE table62, TABLE \"table\"\"63\", TABLE table64, TABLE \"table\"\"65\", TABLE table66, TABLE \"ta,ble67\", TABLE 😷table68, TABLE \"ta-\vb'le69\", TABLE ta͏ble70, TABLE t🙄able71, TABLE table72, TABLE table73, TABLE table͍74, TABLE table75, TABLE table76, TABLE table77, TABLE \"tabl e.78\", TABLE table79, TABLE table80, TABLE \"tab le \\\\U000EA71481\", TABLE table82, TABLE \"ta)ble83\", TABLE \"ta%pble84\", TABLE table85, TABLE table86, TABLE table87, TABLE \"tabl%qe88\", TABLE table😱89, TABLE table90, TABLE table91, TABLE \"tab le92\", TABLE table93, TABLE \"tabl%ve94\", TABLE table95, TABLE \"ta%11ble96\", TABLE \"\ftable97\", TABLE table98, TABLE ta😶ble99, TABLE table100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230409 13:52:52.592376 109732 sql/schemachanger/scbuild/build.go:45  [T10,nsql1,client=127.0.0.1:35752,user=root] 874  building declarative schema change targets for CREATE CHANGEFEED
I230409 13:52:52.592834 116442 1@ccl/changefeedccl/changefeed_stmt.go:965  [T10,nsql1,client=127.0.0.1:35752,user=root] 875  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230409 13:52:52.655917 116442 12@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35752,user=root] 876 ={"Timestamp":1681048372655911926,"EventType":"changefeed_failed","FailureType":"user_input"}
I230409 13:52:52.660335 106504 sql/stats/automatic_stats.go:550  [T10,nsql1] 877  quiescing auto stats refresher
I230409 13:52:52.660423 106355 server/start_listen.go:103  [T10,nsql1] 878  server shutting down: instructing cmux to stop accepting
W230409 13:52:52.661606 106110 sql/sqlliveness/slinstance/slinstance.go:334  [T10,nsql1] 879  exiting heartbeat loop
W230409 13:52:52.661641 106110 sql/sqlliveness/slinstance/slinstance.go:321  [T10,nsql1] 880  exiting heartbeat loop with error: node unavailable; try another peer
    changefeed_test.go:8465: 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.
E230409 13:52:52.662268 106823 spanconfig/spanconfigjob/job.go:208  [T10,nsql1,job=AUTO SPAN CONFIG RECONCILIATION id=855172607923322881] 881  reconciler failed with failed to get protected timestamp state: failed to read records: protectedts-GetRecords: failed to read query result: query execution canceled, retrying...
E230409 13:52:52.662364 106823 jobs/registry.go:943  [-] 882  error getting live session: node unavailable; try another peer
E230409 13:52:52.662481 106510 jobs/registry.go:987  [T10,nsql1] 883  error expiring job sessions: expire-sessions: failed to read query result: query execution canceled
E230409 13:52:52.662552 106510 jobs/registry.go:995  [T10,nsql1] 884  failed to serve pause and cancel requests: txn exec: context canceled
I230409 13:52:52.662691 106470 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:46671,class=rangefeed,rpc] 885  connection heartbeat loop ended with err: <nil>
W230409 13:52:52.662750 106360 ccl/kvccl/kvtenantccl/setting_overrides.go:46  [T10,nsql1,tenant-connector] 886  error consuming TenantSettings RPC: recv msg error: grpc: context canceled [code 1/Canceled]
W230409 13:52:52.662848 106359 ccl/kvccl/kvtenantccl/connector.go:249  [T10,nsql1,tenant-connector] 887  error consuming GossipSubscription RPC: recv msg error: grpc: context canceled [code 1/Canceled]
I230409 13:52:52.662924 106362 rpc/context.go:2302  [T10,nsql1,rnode=63,raddr=127.0.0.1:46671,class=system,rpc] 888  connection heartbeat loop ended with err: <nil>
I230409 13:52:52.663214 106372 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:46671,class=default,rpc] 889  connection heartbeat loop ended with err: <nil>
E230409 13:52:52.663663 106512 jobs/registry.go:1015  [T10,nsql1] 890  error claiming jobs: could not query jobs table: claim-jobs: failed to read query result: query execution canceled
W230409 13:52:52.665357 109333 jobs/adopt.go:518  [-] 891  could not clear job claim: clear-job-claim: tenant-side-limiter pool closed: shutting down
W230409 13:52:52.669128 108963 jobs/adopt.go:518  [-] 892  could not clear job claim: clear-job-claim: tenant-side-limiter pool closed: shutting down
W230409 13:52:52.671252 102667 server/server_sql.go:1666  [T10,nsql1] 893  server shutdown without a prior graceful drain
I230409 13:52:52.671421 104745 jobs/registry.go:1538  [T1,n1] 894  KEY VISUALIZER job 100: stepping through state succeeded
I230409 13:52:52.671467 103396 sql/stats/automatic_stats.go:550  [T1,n1] 895  quiescing auto stats refresher
E230409 13:52:52.671612 103402 jobs/registry.go:987  [T1,n1] 896  error expiring job sessions: expire-sessions: failed to read query result: query execution canceled
W230409 13:52:52.671626 115637 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 897  failed to gc transaction record: could not GC completed transaction anchored at /Local/Range/Tenant/10/RangeDescriptor: node unavailable; try another peer
I230409 13:52:52.671632 103021 server/start_listen.go:103  [T1,n1] 898  server shutting down: instructing cmux to stop accepting
E230409 13:52:52.671687 103402 jobs/registry.go:995  [T1,n1] 899  failed to serve pause and cancel requests: txn exec: context canceled
W230409 13:52:52.671921 103366 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 900  exiting heartbeat loop
W230409 13:52:52.671944 103366 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 901  exiting heartbeat loop with error: node unavailable; try another peer
E230409 13:52:52.671987 103366 server/server_sql.go:508  [T1,n1] 902  failed to run update of instance with new session ID: node unavailable; try another peer
I230409 13:52:52.672041 104520 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:46671,class=default,rpc] 903  connection heartbeat loop ended with err: <nil>
E230409 13:52:52.672146 104848 jobs/registry.go:943  [T1,n1] 904  error getting live session: node unavailable; try another peer
I230409 13:52:52.672310 103700 jobs/registry.go:1538  [T1,n1] 905  AUTO SPAN CONFIG RECONCILIATION job 855172598174154753: stepping through state succeeded
W230409 13:52:52.678700 105081 jobs/adopt.go:518  [T1,n1] 906  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: 9b4841de], [can-forward-ts] RPC error: node unavailable; try another peer
W230409 13:52:52.679075 104745 jobs/adopt.go:518  [T1,n1] 907  could not clear job claim: clear-job-claim: failed to send RPC: sending to all replicas failed; last error: routing information detected to be stale: ba: Scan [/Table/15/1/100,/Table/15/1/101), [txn: 8bfcccdc], [can-forward-ts] RPC error: node unavailable; try another peer
W230409 13:52:52.684689 102667 server/server_sql.go:1666  [T1,n1] 908  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (7.17s)
Help

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

/cc @cockroachdb/cdc

This test on roachdash | Improve this report!

Jira issue: CRDB-26753

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 9, 2023
@cockroach-teamcity cockroach-teamcity added this to the 23.1 milestone Apr 9, 2023
@cockroach-teamcity
Copy link
Member Author

ccl/changefeedccl.TestChangefeedTopicNames failed with artifacts on release-23.1 @ cfbd751ae4c82e2c4b5314376cd6e6c29cc30aea:

I230409 13:54:47.791608 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 836 ={"Timestamp":1681048487770396800,"EventType":"create_table","Statement":"CREATE TABLE d.public.table82 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":187,"TableName":"d.public.table82"}
I230409 13:54:47.820955 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 837 ={"Timestamp":1681048487811557565,"EventType":"create_table","Statement":"CREATE TABLE d.public.table83 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":188,"TableName":"d.public.table83"}
I230409 13:54:47.842088 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 838 ={"Timestamp":1681048487827916508,"EventType":"create_table","Statement":"CREATE TABLE d.public.table84 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":189,"TableName":"d.public.table84"}
I230409 13:54:47.858896 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 839 ={"Timestamp":1681048487850291145,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tab%vle85\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":190,"TableName":"d.public.\"tab%vle85\""}
I230409 13:54:47.884558 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 840 ={"Timestamp":1681048487866752323,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tablE86\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":191,"TableName":"d.public.\"tablE86\""}
I230409 13:54:47.907716 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 841 ={"Timestamp":1681048487894705407,"EventType":"create_table","Statement":"CREATE TABLE d.public.table87 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":192,"TableName":"d.public.table87"}
I230409 13:54:47.960327 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 842 ={"Timestamp":1681048487946782650,"EventType":"create_table","Statement":"CREATE TABLE d.public.table88 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.table88"}
I230409 13:54:47.988407 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 843 ={"Timestamp":1681048487972025492,"EventType":"create_table","Statement":"CREATE TABLE d.public.table89 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.table89"}
I230409 13:54:48.013613 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 844 ={"Timestamp":1681048487995989045,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"\"\"ta bl͛e90\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.\"\"\"ta bl͛e90\""}
I230409 13:54:48.037710 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 845 ={"Timestamp":1681048488027876966,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"taBle91\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.\"taBle91\""}
I230409 13:54:48.056154 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 846 ={"Timestamp":1681048488046211611,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"Table92\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.\"Table92\""}
I230409 13:54:48.080180 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 847 ={"Timestamp":1681048488071431955,"EventType":"create_table","Statement":"CREATE TABLE d.public.table93 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.table93"}
I230409 13:54:48.096254 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 848 ={"Timestamp":1681048488087600393,"EventType":"create_table","Statement":"CREATE TABLE d.public.table94 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.table94"}
I230409 13:54:48.118076 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 849 ={"Timestamp":1681048488104774032,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"table%q95\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.\"table%q95\""}
I230409 13:54:48.141136 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 850 ={"Timestamp":1681048488125067435,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tä́Ble96\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.\"tä́Ble96\""}
I230409 13:54:48.158271 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 851 ={"Timestamp":1681048488148960251,"EventType":"create_table","Statement":"CREATE TABLE d.public.table97 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.table97"}
I230409 13:54:48.180844 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 852 ={"Timestamp":1681048488164669847,"EventType":"create_table","Statement":"CREATE TABLE d.public.table98 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.table98"}
I230409 13:54:48.197202 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 853 ={"Timestamp":1681048488188539526,"EventType":"create_table","Statement":"CREATE TABLE d.public.table99 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.table99"}
I230409 13:54:48.212110 101343 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 854 ={"Timestamp":1681048488203921798,"EventType":"create_table","Statement":"CREATE TABLE d.public.table100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.table100"}
I230409 13:54:48.220133 94254 ccl/changefeedccl/testfeed_test.go:795  [-] 855  Starting feed job: "CREATE CHANGEFEED FOR TABLE table1, TABLE table2, TABLE \"table\n3\", TABLE t😒able4, TABLE \"tabLe5\", TABLE table6, TABLE tab😭l̤e7, TABLE \" table8\", TABLE \"t😧abLe9\", TABLE table10, TABLE \"tab\vl😄e11\", TABLE table12, TABLE \"tab%vle13\", TABLE table14, TABLE \"table 😑15\", TABLE \"tabl e16\", TABLE \"table%v17\", TABLE \"tab&l e18\", TABLE table19, TABLE table20, TABLE table21, TABLE tảble22, TABLE t😻able23, TABLE \" tabl%ve24\", TABLE table25, TABLE table26, TABLE table27, TABLE \"t\\vable28\", TABLE tabl_e29, TABLE table30, TABLE table31, TABLE table32, TABLE \"%qta\"\"ble33\", TABLE table34, TABLE table35, TABLE \"ta}ble36\", TABLE table37, TABLE table38, TABLE table39, TABLE tab😳le40, TABLE table41, TABLE \"Table42\", TABLE table43, TABLE \"tabl e44\", TABLE \"t?able45\", TABLE \"t\\\\xd0Able46\", TABLE table47, TABLE \"\ftable48\", TABLE \"t\nable49\", TABLE tabͩle50, TABLE \"table'51\", TABLE table52, TABLE \"tab,le53\", TABLE table54, TABLE table55, TABLE \"\rtab😥le56\", TABLE table57, TABLE table58, TABLE table59, TABLE \"t\\\\U00038F08able60\", TABLE 😟table61, TABLE table62, TABLE table63, TABLE table64, TABLE \"t a)ble65\", TABLE \"tab\tle66\", TABLE \"table\\\\xc167\", TABLE \"table%p68\", TABLE table69, TABLE \"Table70\", TABLE table̥71, TABLE \"'table72\", TABLE \"\"\"tabl{e73\", TABLE table74, TABLE table75, TABLE \"tab le76\", TABLE table77, TABLE \"\\\\x03ta\"\"ble78\", TABLE \" tab\"\"le79\", TABLE table80, TABLE table͐81, TABLE table82, TABLE table83, TABLE table84, TABLE \"tab%vle85\", TABLE \"tablE86\", TABLE table87, TABLE table88, TABLE table89, TABLE \"\"\"ta bl͛e90\", TABLE \"taBle91\", TABLE \"Table92\", TABLE table93, TABLE table94, TABLE \"table%q95\", TABLE \"tä́Ble96\", TABLE table97, TABLE table98, TABLE table99, TABLE table100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230409 13:54:48.220800 101343 sql/schemachanger/scbuild/build.go:45  [T10,nsql1,client=127.0.0.1:53394,user=root] 856  building declarative schema change targets for CREATE CHANGEFEED
I230409 13:54:48.221325 108468 1@ccl/changefeedccl/changefeed_stmt.go:965  [T10,nsql1,client=127.0.0.1:53394,user=root] 857  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230409 13:54:48.240732 108468 12@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:53394,user=root] 858 ={"Timestamp":1681048488240726667,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:8465: 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.
I230409 13:54:48.242613 98094 sql/stats/automatic_stats.go:550  [T10,nsql1] 859  quiescing auto stats refresher
I230409 13:54:48.243478 97838 server/start_listen.go:103  [T10,nsql1] 860  server shutting down: instructing cmux to stop accepting
W230409 13:54:48.243673 97875 ccl/kvccl/kvtenantccl/setting_overrides.go:46  [T10,nsql1,tenant-connector] 861  error consuming TenantSettings RPC: recv msg error: grpc: context canceled [code 1/Canceled]
W230409 13:54:48.243780 97792 sql/sqlliveness/slinstance/slinstance.go:334  [T10,nsql1] 862  exiting heartbeat loop
W230409 13:54:48.243802 97792 sql/sqlliveness/slinstance/slinstance.go:321  [T10,nsql1] 863  exiting heartbeat loop with error: node unavailable; try another peer
I230409 13:54:48.244678 98777 jobs/registry.go:1538  [T10,nsql1] 864  AUTO SPAN CONFIG RECONCILIATION job 855172984600363009: stepping through state succeeded
E230409 13:54:48.244803 98777 jobs/registry.go:943  [-] 865  error getting live session: node unavailable; try another peer
I230409 13:54:48.245116 97877 rpc/context.go:2302  [T10,nsql1,rnode=63,raddr=127.0.0.1:40485,class=system,rpc] 866  connection heartbeat loop ended with err: <nil>
E230409 13:54:48.245172 98102 jobs/registry.go:1015  [T10,nsql1] 867  error claiming jobs: could not query jobs table: claim-jobs: failed to read query result: query execution canceled
I230409 13:54:48.245242 98034 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:40485,class=default,rpc] 868  connection heartbeat loop ended with err: <nil>
W230409 13:54:48.245503 97874 ccl/kvccl/kvtenantccl/connector.go:249  [T10,nsql1,tenant-connector] 869  error consuming GossipSubscription RPC: recv msg error: grpc: context canceled [code 1/Canceled]
W230409 13:54:48.247976 100961 jobs/adopt.go:518  [-] 870  could not clear job claim: clear-job-claim: tenant-side-limiter pool closed: shutting down
W230409 13:54:48.260336 94254 server/server_sql.go:1666  [T10,nsql1] 871  server shutdown without a prior graceful drain
I230409 13:54:48.260649 94910 sql/stats/automatic_stats.go:550  [T1,n1] 872  quiescing auto stats refresher
W230409 13:54:48.260995 106268 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 873  failed to gc transaction record: could not GC completed transaction anchored at /Local/Range/Tenant/10/RangeDescriptor: node unavailable; try another peer
I230409 13:54:48.266151 94555 server/start_listen.go:103  [T1,n1] 874  server shutting down: instructing cmux to stop accepting
W230409 13:54:48.266261 94750 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 875  exiting heartbeat loop
W230409 13:54:48.266317 94750 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 876  exiting heartbeat loop with error: node unavailable; try another peer
I230409 13:54:48.266340 95171 jobs/registry.go:1538  [T1,n1] 877  AUTO SPAN CONFIG RECONCILIATION job 855172974373502977: stepping through state succeeded
I230409 13:54:48.266308 96318 jobs/registry.go:1538  [T1,n1] 879  KEY VISUALIZER job 100: stepping through state succeeded
I230409 13:54:48.266404 96115 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:40485,class=default,rpc] 880  connection heartbeat loop ended with err: <nil>
E230409 13:54:48.266353 94750 server/server_sql.go:508  [T1,n1] 878  failed to run update of instance with new session ID: node unavailable; try another peer
E230409 13:54:48.266480 96514 jobs/registry.go:943  [T1,n1] 881  error getting live session: node unavailable; try another peer
W230409 13:54:48.270662 96660 jobs/adopt.go:518  [T1,n1] 882  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: 67c2750a], [can-forward-ts] RPC error: node unavailable; try another peer
W230409 13:54:48.272411 94254 server/server_sql.go:1666  [T1,n1] 883  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (7.82s)
Help

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

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

I230410 08:31:27.660075 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 516 ={"Timestamp":1681115487656608463,"EventType":"create_table","Statement":"CREATE TABLE d.public.table71 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":176,"TableName":"d.public.table71"}
I230410 08:31:27.677794 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 517 ={"Timestamp":1681115487670459805,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl%qe72\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":177,"TableName":"d.public.\"tabl%qe72\""}
I230410 08:31:27.711412 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 518 ={"Timestamp":1681115487705296041,"EventType":"create_table","Statement":"CREATE TABLE d.public.table73 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":178,"TableName":"d.public.table73"}
I230410 08:31:27.733513 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 519 ={"Timestamp":1681115487722722524,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabLe74\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":179,"TableName":"d.public.\"tabLe74\""}
I230410 08:31:27.752915 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 520 ={"Timestamp":1681115487749429055,"EventType":"create_table","Statement":"CREATE TABLE d.public.table75 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":180,"TableName":"d.public.table75"}
I230410 08:31:27.777923 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 521 ={"Timestamp":1681115487772946827,"EventType":"create_table","Statement":"CREATE TABLE d.public.table76 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":181,"TableName":"d.public.table76"}
I230410 08:31:27.803147 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 522 ={"Timestamp":1681115487799624123,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t%vable77\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":182,"TableName":"d.public.\"t%vable77\""}
I230410 08:31:27.817723 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 523 ={"Timestamp":1681115487814223581,"EventType":"create_table","Statement":"CREATE TABLE d.public.🙀table78 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":183,"TableName":"d.public.🙀table78"}
I230410 08:31:27.847931 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 524 ={"Timestamp":1681115487844381971,"EventType":"create_table","Statement":"CREATE TABLE d.public.table79 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":184,"TableName":"d.public.table79"}
I230410 08:31:27.865527 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 525 ={"Timestamp":1681115487862138197,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta\tble80\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":185,"TableName":"d.public.\"ta\tble80\""}
I230410 08:31:27.900713 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 526 ={"Timestamp":1681115487897263461,"EventType":"create_table","Statement":"CREATE TABLE d.public.table81 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":186,"TableName":"d.public.table81"}
I230410 08:31:27.917142 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 527 ={"Timestamp":1681115487913819562,"EventType":"create_table","Statement":"CREATE TABLE d.public.table82 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":187,"TableName":"d.public.table82"}
I230410 08:31:27.951552 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 528 ={"Timestamp":1681115487948300349,"EventType":"create_table","Statement":"CREATE TABLE d.public.table83 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":188,"TableName":"d.public.table83"}
I230410 08:31:27.969389 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 529 ={"Timestamp":1681115487964553161,"EventType":"create_table","Statement":"CREATE TABLE d.public.table84 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":189,"TableName":"d.public.table84"}
I230410 08:31:27.987804 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 530 ={"Timestamp":1681115487984591480,"EventType":"create_table","Statement":"CREATE TABLE d.public.table85 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":190,"TableName":"d.public.table85"}
I230410 08:31:28.010556 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 531 ={"Timestamp":1681115488003676077,"EventType":"create_table","Statement":"CREATE TABLE d.public.table86 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":191,"TableName":"d.public.table86"}
I230410 08:31:28.067083 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 532 ={"Timestamp":1681115488062408754,"EventType":"create_table","Statement":"CREATE TABLE d.public.table87 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":192,"TableName":"d.public.table87"}
I230410 08:31:28.105210 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 533 ={"Timestamp":1681115488101632971,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"table!88\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.\"table!88\""}
I230410 08:31:28.126847 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 534 ={"Timestamp":1681115488118230730,"EventType":"create_table","Statement":"CREATE TABLE d.public.table😚89 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.table😚89"}
I230410 08:31:28.152480 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 535 ={"Timestamp":1681115488148934364,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t😷a(%pble90\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.\"t😷a(%pble90\""}
I230410 08:31:28.180138 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 536 ={"Timestamp":1681115488176552098,"EventType":"create_table","Statement":"CREATE TABLE d.public.table91 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.table91"}
I230410 08:31:28.181723 113834 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r12/1:/Table/{8-11}] 537  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 08:31:28.198798 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 538 ={"Timestamp":1681115488195097753,"EventType":"create_table","Statement":"CREATE TABLE d.public.table92 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.table92"}
I230410 08:31:28.245929 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 539 ={"Timestamp":1681115488219495589,"EventType":"create_table","Statement":"CREATE TABLE d.public.table93 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.table93"}
I230410 08:31:28.264117 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 540 ={"Timestamp":1681115488260381391,"EventType":"create_table","Statement":"CREATE TABLE d.public.t😐able94 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.t😐able94"}
I230410 08:31:28.285069 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 541 ={"Timestamp":1681115488281574287,"EventType":"create_table","Statement":"CREATE TABLE d.public.table95 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.table95"}
I230410 08:31:28.375129 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 542 ={"Timestamp":1681115488312914118,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tab)le96\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.\"tab)le96\""}
I230410 08:31:28.396785 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 543 ={"Timestamp":1681115488388442611,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabLe97\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.\"tabLe97\""}
I230410 08:31:28.426213 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 544 ={"Timestamp":1681115488421883349,"EventType":"create_table","Statement":"CREATE TABLE d.public.table98 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.table98"}
I230410 08:31:28.446276 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 545 ={"Timestamp":1681115488439225598,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta\\\\U00002D17ble99\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.\"ta\\\\U00002D17ble99\""}
I230410 08:31:28.463004 110918 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 546 ={"Timestamp":1681115488458432378,"EventType":"create_table","Statement":"CREATE TABLE d.public.table100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.table100"}
I230410 08:31:28.481750 108153 ccl/changefeedccl/testfeed_test.go:795  [-] 547  Starting feed job: "CREATE CHANGEFEED FOR TABLE table1, TABLE table2, TABLE \"t̗ab le3\", TABLE \"'table4\", TABLE \"%vtable5\", TABLE table6, TABLE tabl😒e7, TABLE table8, TABLE table9, TABLE \"t able10\", TABLE table11, TABLE table12, TABLE \"ta'ble13\", TABLE \"%ptable14\", TABLE \"tab le15\", TABLE table16, TABLE \"table\"\"17\", TABLE \"ta\nblE18\", TABLE table19, TABLE table20, TABLE table21, TABLE table22, TABLE \"table%a523\", TABLE table24, TABLE \"Table25\", TABLE table26, TABLE \"t\\\\U00031099able27\", TABLE table28, TABLE table29, TABLE \"t a ble30\", TABLE \"😞Table31\", TABLE table32, TABLE table33, TABLE table34, TABLE \"tabl%ve35\", TABLE table36, TABLE \"😩ta\\\\xa3b/l}e%b337\", TABLE tabͣle38, TABLE table39, TABLE table40, TABLE table41, TABLE table42, TABLE \"tab'le 43\", TABLE t😤able44, TABLE table45, TABLE \"taBle46\", TABLE ta😋ble47, TABLE table48, TABLE table49, TABLE \" table50\", TABLE table51, TABLE table52, TABLE table53, TABLE \"tabLe54\", TABLE \"t'able55\", TABLE table56, TABLE ta😮b😐le57, TABLE \"tab)le 58\", TABLE \"tablE59\", TABLE table60, TABLE \"ta%vble61\", TABLE \"tab'le62\", TABLE table63, TABLE table64, TABLE \"tablE65\", TABLE table66, TABLE table67, TABLE table68, TABLE table69, TABLE \"taBle70\", TABLE table71, TABLE \"tabl%qe72\", TABLE table73, TABLE \"tabLe74\", TABLE table75, TABLE table76, TABLE \"t%vable77\", TABLE 🙀table78, TABLE table79, TABLE \"ta\tble80\", TABLE table81, TABLE table82, TABLE table83, TABLE table84, TABLE table85, TABLE table86, TABLE table87, TABLE \"table!88\", TABLE table😚89, TABLE \"t😷a(%pble90\", TABLE table91, TABLE table92, TABLE table93, TABLE t😐able94, TABLE table95, TABLE \"tab)le96\", TABLE \"tabLe97\", TABLE table98, TABLE \"ta\\\\U00002D17ble99\", TABLE table100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 08:31:28.482400 110918 sql/schemachanger/scbuild/build.go:45  [T1,n1,client=127.0.0.1:38330,user=root] 548  building declarative schema change targets for CREATE CHANGEFEED
I230410 08:31:28.482961 114178 1@ccl/changefeedccl/changefeed_stmt.go:965  [T1,n1,client=127.0.0.1:38330,user=root] 549  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 08:31:28.546336 114178 12@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:38330,user=root] 550 ={"Timestamp":1681115488546331094,"EventType":"changefeed_failed","FailureType":"user_input"}
I230410 08:31:28.557499 108894 sql/stats/automatic_stats.go:550  [T1,n1] 551  quiescing auto stats refresher
W230410 08:31:28.557607 114073 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 552  failed to gc transaction record: could not GC completed transaction anchored at /Table/3/1/204/2/1: node unavailable; try another peer
I230410 08:31:28.562354 110313 jobs/registry.go:1538  [T1,n1] 553  KEY VISUALIZER job 100: stepping through state succeeded
    changefeed_test.go:8465: 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.
W230410 08:31:28.566620 110313 jobs/adopt.go:518  [T1,n1] 554  could not clear job claim: clear-job-claim: node unavailable; try another peer
I230410 08:31:28.566887 108486 server/start_listen.go:103  [T1,n1] 555  server shutting down: instructing cmux to stop accepting
I230410 08:31:28.567553 110021 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:34319,class=default,rpc] 556  connection heartbeat loop ended with err: <nil>
W230410 08:31:28.567963 108856 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 557  exiting heartbeat loop
W230410 08:31:28.568005 108856 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 558  exiting heartbeat loop with error: node unavailable; try another peer
E230410 08:31:28.568027 108856 server/server_sql.go:508  [T1,n1] 559  failed to run update of instance with new session ID: node unavailable; try another peer
I230410 08:31:28.568858 109124 jobs/registry.go:1538  [T1,n1] 560  AUTO SPAN CONFIG RECONCILIATION job 855392532141244417: stepping through state succeeded
E230410 08:31:28.568966 109124 jobs/registry.go:943  [T1,n1] 561  error getting live session: node unavailable; try another peer
W230410 08:31:28.569084 110625 jobs/adopt.go:518  [T1,n1] 562  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: c8cb2640], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 08:31:28.573169 108153 server/server_sql.go:1666  [T1,n1] 563  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (4.51s)
Help

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

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

I230410 08:34:11.959277 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 851 ={"Timestamp":1681115651924084916,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta\tble86\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":191,"TableName":"d.public.\"ta\tble86\""}
I230410 08:34:11.974615 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 852 ={"Timestamp":1681115651966008217,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"%ptab\\rle87\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":192,"TableName":"d.public.\"%ptab\\rle87\""}
I230410 08:34:11.989351 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 853 ={"Timestamp":1681115651981077537,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t%p😙abl/e88\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.\"t%p😙abl/e88\""}
I230410 08:34:12.014294 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 854 ={"Timestamp":1681115651996914790,"EventType":"create_table","Statement":"CREATE TABLE d.public.table89 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.table89"}
I230410 08:34:12.048829 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 855 ={"Timestamp":1681115652037999110,"EventType":"create_table","Statement":"CREATE TABLE d.public.table90 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.table90"}
I230410 08:34:12.068415 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 856 ={"Timestamp":1681115652057609439,"EventType":"create_table","Statement":"CREATE TABLE d.public.tab😱le91 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.tab😱le91"}
I230410 08:34:12.094874 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 857 ={"Timestamp":1681115652077330604,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t ab le92\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.\"t ab le92\""}
I230410 08:34:12.112060 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 858 ={"Timestamp":1681115652101980743,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl}e93\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.\"tabl}e93\""}
I230410 08:34:12.133643 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 859 ={"Timestamp":1681115652121880600,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl\\\\x57e 94\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.\"tabl\\\\x57e 94\""}
I230410 08:34:12.155772 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 860 ={"Timestamp":1681115652146811693,"EventType":"create_table","Statement":"CREATE TABLE d.public.table95 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.table95"}
I230410 08:34:12.198412 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 861 ={"Timestamp":1681115652164773763,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"table\\\\U000CFFE896\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.\"table\\\\U000CFFE896\""}
I230410 08:34:12.217768 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 862 ={"Timestamp":1681115652207682466,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta😟ble%v97\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.\"ta😟ble%v97\""}
I230410 08:34:12.253609 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 863 ={"Timestamp":1681115652224190428,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tablE98\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.\"tablE98\""}
I230410 08:34:12.279980 113683 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r50/1:/Table/{48-50}] 864  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 08:34:12.284744 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 865 ={"Timestamp":1681115652265324167,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"Table99\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.\"Table99\""}
I230410 08:34:12.305431 106952 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 866 ={"Timestamp":1681115652296644570,"EventType":"create_table","Statement":"CREATE TABLE d.public.tabl😧e100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.tabl😧e100"}
I230410 08:34:12.316363 99945 ccl/changefeedccl/testfeed_test.go:795  [-] 867  Starting feed job: "CREATE CHANGEFEED FOR TABLE \"tab'le 1\", TABLE table2, TABLE \"ta'ble3\", TABLE table4, TABLE \"t\\\\xb2a\\\\uFAB0ble5\", TABLE table6, TABLE table7, TABLE table8, TABLE table9, TABLE table10, TABLE table11, TABLE table̞12, TABLE \"tab le13\", TABLE \"%v\\\\u1703table14\", TABLE \"ta\fble15\", TABLE \"ta.\"\"ble16\", TABLE \"ta\\rble17\", TABLE \"ta\"\"b\tl😕e18\", TABLE tabl̖e19, TABLE table20, TABLE table21, TABLE \"tabl\\\\u4318e22\", TABLE \"tabLe23\", TABLE \"t \nable24\", TABLE \"tab{le25\", TABLE table26, TABLE table27, TABLE \"t%qable28\", TABLE table29, TABLE table30, TABLE table31, TABLE \"t a&ble32\", TABLE \"t%vab(le33\", TABLE \"ta\\\\uA69Dble34\", TABLE \"t%pable35\", TABLE \"t abl(e36\", TABLE tabl😴e37, TABLE \"%qt\\nable38\", TABLE table39, TABLE \"tabl\\\\uA1ADe40\", TABLE \"ta\tble41\", TABLE ẗable42, TABLE table43, TABLE \"t\\fa̾ble44\", TABLE table45, TABLE table46, TABLE table47, TABLE \"t!a ble48\", TABLE table49, TABLE table50, TABLE table51, TABLE table52, TABLE \"table\v53\", TABLE table54, TABLE table55, TABLE table56, TABLE table57, TABLE table58, TABLE table59, TABLE table60, TABLE \"tab_l%15e61\", TABLE table62, TABLE table63, TABLE table64, TABLE table65, TABLE table66, TABLE \"table\\f67\", TABLE table68, TABLE \"table\"\"%v69\", TABLE table70, TABLE table71, TABLE \"tab le72\", TABLE \"t able73\", TABLE \",tabLe74\", TABLE table75, TABLE \"t%qable76\", TABLE \"tab%vle%1e77\", TABLE table78, TABLE \"\rtable79\", TABLE \"%vtable80\", TABLE table81, TABLE table82, TABLE table83, TABLE table84, TABLE \" table85\", TABLE \"ta\tble86\", TABLE \"%ptab\\rle87\", TABLE \"t%p😙abl/e88\", TABLE table89, TABLE table90, TABLE tab😱le91, TABLE \"t ab le92\", TABLE \"tabl}e93\", TABLE \"tabl\\\\x57e 94\", TABLE table95, TABLE \"table\\\\U000CFFE896\", TABLE \"ta😟ble%v97\", TABLE \"tablE98\", TABLE \"Table99\", TABLE tabl😧e100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 08:34:12.318845 106952 sql/schemachanger/scbuild/build.go:45  [T10,nsql1,client=127.0.0.1:59368,user=root] 868  building declarative schema change targets for CREATE CHANGEFEED
I230410 08:34:12.319309 113630 1@ccl/changefeedccl/changefeed_stmt.go:965  [T10,nsql1,client=127.0.0.1:59368,user=root] 869  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 08:34:12.340156 113630 12@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:59368,user=root] 870 ={"Timestamp":1681115652340150775,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:8465: 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:34:12.341869 103657 sql/stats/automatic_stats.go:550  [T10,nsql1] 871  quiescing auto stats refresher
I230410 08:34:12.342630 100623 server/start_listen.go:103  [T10,nsql1] 872  server shutting down: instructing cmux to stop accepting
W230410 08:34:12.343604 103611 sql/sqlliveness/slinstance/slinstance.go:334  [T10,nsql1] 873  exiting heartbeat loop
W230410 08:34:12.343658 103611 sql/sqlliveness/slinstance/slinstance.go:321  [T10,nsql1] 874  exiting heartbeat loop with error: node unavailable; try another peer
I230410 08:34:12.343788 103941 jobs/registry.go:1538  [T10,nsql1] 875  AUTO SPAN CONFIG RECONCILIATION job 855393069272367105: stepping through state succeeded
E230410 08:34:12.343878 103941 jobs/registry.go:943  [-] 876  error getting live session: node unavailable; try another peer
W230410 08:34:12.343932 103524 ccl/kvccl/kvtenantccl/setting_overrides.go:46  [T10,nsql1,tenant-connector] 877  error consuming TenantSettings RPC: recv msg error: grpc: context canceled [code 1/Canceled]
I230410 08:34:12.344106 103600 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:40693,class=rangefeed,rpc] 878  connection heartbeat loop ended with err: <nil>
I230410 08:34:12.344172 103553 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:40693,class=default,rpc] 879  connection heartbeat loop ended with err: <nil>
I230410 08:34:12.344220 103526 rpc/context.go:2302  [T10,nsql1,rnode=63,raddr=127.0.0.1:40693,class=system,rpc] 880  connection heartbeat loop ended with err: <nil>
W230410 08:34:12.344655 103523 ccl/kvccl/kvtenantccl/connector.go:249  [T10,nsql1,tenant-connector] 881  error consuming GossipSubscription RPC: recv msg error: grpc: error reading from server: read tcp 127.0.0.1:53050->127.0.0.1:40693: use of closed network connection [code 14/Unavailable]
E230410 08:34:12.344950 102113 jobs/registry.go:1055  [T10,nsql1] 882  error processing claimed jobs: could not query for claimed jobs: select-running/get-claimed-jobs: failed to read query result: query execution canceled
W230410 08:34:12.346751 106510 jobs/adopt.go:518  [-] 883  could not clear job claim: clear-job-claim: tenant-side-limiter pool closed: shutting down
W230410 08:34:12.347016 99945 server/server_sql.go:1666  [T10,nsql1] 884  server shutdown without a prior graceful drain
W230410 08:34:12.347197 112531 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 885  failed to gc transaction record: could not GC completed transaction anchored at /Local/Range/Tenant/10/RangeDescriptor: node unavailable; try another peer
I230410 08:34:12.347274 100590 sql/stats/automatic_stats.go:550  [T1,n1] 886  quiescing auto stats refresher
I230410 08:34:12.347284 101965 jobs/registry.go:1538  [T1,n1] 887  KEY VISUALIZER job 100: stepping through state succeeded
I230410 08:34:12.347488 100230 server/start_listen.go:103  [T1,n1] 888  server shutting down: instructing cmux to stop accepting
I230410 08:34:12.347537 100513 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:40693,class=default,rpc] 889  connection heartbeat loop ended with err: <nil>
W230410 08:34:12.347844 100426 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 890  exiting heartbeat loop
W230410 08:34:12.347884 100426 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 891  exiting heartbeat loop with error: node unavailable; try another peer
E230410 08:34:12.347909 100426 server/server_sql.go:508  [T1,n1] 892  failed to run update of instance with new session ID: node unavailable; try another peer
I230410 08:34:12.347952 100945 jobs/registry.go:1538  [T1,n1] 893  AUTO SPAN CONFIG RECONCILIATION job 855393059955343361: stepping through state succeeded
E230410 08:34:12.347956 99774 jobs/registry.go:943  [T1,n1] 894  error getting live session: node unavailable; try another peer
E230410 08:34:12.348535 100598 jobs/registry.go:1055  [T1,n1] 895  error processing claimed jobs: could not query for claimed jobs: select-running/get-claimed-jobs: failed to read query result: query execution canceled
W230410 08:34:12.354684 102291 jobs/adopt.go:518  [T1,n1] 897  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: 7896add9], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 08:34:12.354680 101965 jobs/adopt.go:518  [T1,n1] 896  could not clear job claim: clear-job-claim: failed to send RPC: sending to all replicas failed; last error: routing information detected to be stale: ba: Scan [/Table/15/1/100,/Table/15/1/101), [txn: 48bf6ff0], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 08:34:12.358881 99945 server/server_sql.go:1666  [T1,n1] 898  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (7.17s)
Help

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

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

I230410 08:36:18.444451 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 653 ={"Timestamp":1681115778439845570,"EventType":"create_table","Statement":"CREATE TABLE d.public.table͘71 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":176,"TableName":"d.public.table͘71"}
I230410 08:36:18.460844 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 654 ={"Timestamp":1681115778457765147,"EventType":"create_table","Statement":"CREATE TABLE d.public.table72 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":177,"TableName":"d.public.table72"}
I230410 08:36:18.475940 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 655 ={"Timestamp":1681115778471549356,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"%ptab'le73\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":178,"TableName":"d.public.\"%ptab'le73\""}
I230410 08:36:18.494042 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 656 ={"Timestamp":1681115778490481831,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tab le74\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":179,"TableName":"d.public.\"tab le74\""}
I230410 08:36:18.510571 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 657 ={"Timestamp":1681115778507029820,"EventType":"create_table","Statement":"CREATE TABLE d.public.table75 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":180,"TableName":"d.public.table75"}
I230410 08:36:18.532278 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 658 ={"Timestamp":1681115778528925142,"EventType":"create_table","Statement":"CREATE TABLE d.public.table76 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":181,"TableName":"d.public.table76"}
I230410 08:36:18.549733 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 659 ={"Timestamp":1681115778546474968,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t'able77\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":182,"TableName":"d.public.\"t'able77\""}
I230410 08:36:18.563559 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 660 ={"Timestamp":1681115778560345044,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tab̘l%ve78\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":183,"TableName":"d.public.\"tab̘l%ve78\""}
I230410 08:36:18.578572 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 661 ={"Timestamp":1681115778575240261,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl\n😘e79\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":184,"TableName":"d.public.\"tabl\n😘e79\""}
I230410 08:36:18.596103 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 662 ={"Timestamp":1681115778592048157,"EventType":"create_table","Statement":"CREATE TABLE d.public.table80 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":185,"TableName":"d.public.table80"}
I230410 08:36:18.610389 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 663 ={"Timestamp":1681115778607050000,"EventType":"create_table","Statement":"CREATE TABLE d.public.tabļe81 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":186,"TableName":"d.public.tabļe81"}
I230410 08:36:18.624480 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 664 ={"Timestamp":1681115778620810398,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta%pb?le82\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":187,"TableName":"d.public.\"ta%pb?le82\""}
I230410 08:36:18.638892 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 665 ={"Timestamp":1681115778635158484,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl e83\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":188,"TableName":"d.public.\"tabl e83\""}
I230410 08:36:18.655432 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 666 ={"Timestamp":1681115778649725156,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t\\\\x9bable84\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":189,"TableName":"d.public.\"t\\\\x9bable84\""}
I230410 08:36:18.659029 116510 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r15/1:/Table/1{3-4}] 667  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 08:36:18.674753 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 668 ={"Timestamp":1681115778670159223,"EventType":"create_table","Statement":"CREATE TABLE d.public.\" table85\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":190,"TableName":"d.public.\" table85\""}
I230410 08:36:18.692163 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 669 ={"Timestamp":1681115778688766477,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta-ble86\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":191,"TableName":"d.public.\"ta-ble86\""}
I230410 08:36:18.715544 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 670 ={"Timestamp":1681115778711314260,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tab\\\\xe8le87\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":192,"TableName":"d.public.\"tab\\\\xe8le87\""}
I230410 08:36:18.731414 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 671 ={"Timestamp":1681115778727711453,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"taBl\\\\xcbe🙀88\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.\"taBl\\\\xcbe🙀88\""}
I230410 08:36:18.748881 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 672 ={"Timestamp":1681115778745331639,"EventType":"create_table","Statement":"CREATE TABLE d.public.table89 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.table89"}
I230410 08:36:18.763342 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 673 ={"Timestamp":1681115778759840654,"EventType":"create_table","Statement":"CREATE TABLE d.public.table90 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.table90"}
I230410 08:36:18.782272 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 674 ={"Timestamp":1681115778774118561,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl%pe91\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.\"tabl%pe91\""}
I230410 08:36:18.798036 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 675 ={"Timestamp":1681115778793975302,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"%9btable92\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.\"%9btable92\""}
I230410 08:36:18.812616 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 676 ={"Timestamp":1681115778809203436,"EventType":"create_table","Statement":"CREATE TABLE d.public.table93 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.table93"}
I230410 08:36:18.826911 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 677 ={"Timestamp":1681115778823258769,"EventType":"create_table","Statement":"CREATE TABLE d.public.table94 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.table94"}
I230410 08:36:18.842856 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 678 ={"Timestamp":1681115778838934168,"EventType":"create_table","Statement":"CREATE TABLE d.public.table95 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.table95"}
I230410 08:36:18.858162 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 679 ={"Timestamp":1681115778854638458,"EventType":"create_table","Statement":"CREATE TABLE d.public.table96 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.table96"}
I230410 08:36:18.874845 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 680 ={"Timestamp":1681115778871419154,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta\\gb̢le97\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.\"ta\\gb̢le97\""}
I230410 08:36:18.893072 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 681 ={"Timestamp":1681115778889885665,"EventType":"create_table","Statement":"CREATE TABLE d.public.table98 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.table98"}
I230410 08:36:18.909091 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 682 ={"Timestamp":1681115778905349904,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"table\\\\x6199\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.\"table\\\\x6199\""}
I230410 08:36:18.935869 119938 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 683 ={"Timestamp":1681115778931956828,"EventType":"create_table","Statement":"CREATE TABLE d.public.table100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.table100"}
I230410 08:36:18.948559 117236 ccl/changefeedccl/testfeed_test.go:795  [-] 684  Starting feed job: "CREATE CHANGEFEED FOR TABLE \"tabl(e\n1\", TABLE table2, TABLE \"tabl?e3\", TABLE ta😎ble4, TABLE ta😁ble5, TABLE \"tab%ple6\", TABLE \"table%p7\", TABLE table8, TABLE table9, TABLE table10, TABLE \"ta ble11\", TABLE \"\"\"tab😏le12\", TABLE table13, TABLE \"tab%ple)14\", TABLE table15, TABLE table16, TABLE table17, TABLE table18, TABLE \" table19\", TABLE table20, TABLE table21, TABLE table22, TABLE \"Tabl e23\", TABLE table24, TABLE table25, TABLE \"t able26\", TABLE table27, TABLE table28, TABLE table29, TABLE tab🙁le30, TABLE table31, TABLE \"tAble32\", TABLE table😺33, TABLE table34, TABLE \"t%vable35\", TABLE ẗabl😀e36, TABLE table37, TABLE \"tab😻l e38\", TABLE table39, TABLE table40, TABLE \"ta'ble41\", TABLE \"tab'l e42\", TABLE \"\ft able43\", TABLE \"%vtable44\", TABLE table45, TABLE \"tab\tle46\", TABLE tāble47, TABLE table48, TABLE table49, TABLE \"table%q50\", TABLE \"\\ftab%ple\\g51\", TABLE \"t%qable52\", TABLE table53, TABLE t😳a😓ble54, TABLE table55, TABLE table56, TABLE table57, TABLE table58, TABLE table59, TABLE table60, TABLE table61, TABLE table62, TABLE table63, TABLE table64, TABLE table65, TABLE table66, TABLE \"table\v67\", TABLE table68, TABLE \"ta'ble69\", TABLE \"ta%pbl%12e70\", TABLE table͘71, TABLE table72, TABLE \"%ptab'le73\", TABLE \"tab le74\", TABLE table75, TABLE table76, TABLE \"t'able77\", TABLE \"tab̘l%ve78\", TABLE \"tabl\n😘e79\", TABLE table80, TABLE tabļe81, TABLE \"ta%pb?le82\", TABLE \"tabl e83\", TABLE \"t\\\\x9bable84\", TABLE \" table85\", TABLE \"ta-ble86\", TABLE \"tab\\\\xe8le87\", TABLE \"taBl\\\\xcbe🙀88\", TABLE table89, TABLE table90, TABLE \"tabl%pe91\", TABLE \"%9btable92\", TABLE table93, TABLE table94, TABLE table95, TABLE table96, TABLE \"ta\\gb̢le97\", TABLE table98, TABLE \"table\\\\x6199\", TABLE table100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 08:36:18.954640 119938 sql/schemachanger/scbuild/build.go:45  [T1,n1,client=127.0.0.1:40280,user=root] 685  building declarative schema change targets for CREATE CHANGEFEED
I230410 08:36:18.955181 122927 1@ccl/changefeedccl/changefeed_stmt.go:965  [T1,n1,client=127.0.0.1:40280,user=root] 686  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 08:36:18.974973 122927 12@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:40280,user=root] 687 ={"Timestamp":1681115778974967453,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:8465: 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.
W230410 08:36:18.976620 122316 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 688  failed to gc transaction record: could not GC completed transaction anchored at /Table/3/1/186/2/1: node unavailable; try another peer
I230410 08:36:18.976645 112620 server/start_listen.go:103  [T1,n1] 689  server shutting down: instructing cmux to stop accepting
I230410 08:36:18.976676 119250 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:37447,class=default,rpc] 690  connection heartbeat loop ended with err: <nil>
I230410 08:36:18.976742 117888 sql/stats/automatic_stats.go:550  [T1,n1] 691  quiescing auto stats refresher
W230410 08:36:18.976946 117789 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 692  exiting heartbeat loop
I230410 08:36:18.976988 119152 jobs/registry.go:1538  [T1,n1] 693  KEY VISUALIZER job 100: stepping through state succeeded
I230410 08:36:18.977043 118247 jobs/registry.go:1538  [T1,n1] 695  AUTO SPAN CONFIG RECONCILIATION job 855393487134654465: stepping through state succeeded
W230410 08:36:18.976991 117789 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 694  exiting heartbeat loop with error: node unavailable; try another peer
E230410 08:36:18.977089 117789 server/server_sql.go:508  [T1,n1] 696  failed to run update of instance with new session ID: node unavailable; try another peer
E230410 08:36:18.977132 119152 jobs/registry.go:943  [T1,n1] 697  error getting live session: node unavailable; try another peer
W230410 08:36:18.984635 119428 jobs/adopt.go:518  [T1,n1] 698  could not clear job claim: clear-job-claim: failed to send RPC: sending to all replicas failed; last error: ba: Scan [/Table/15/1/101,/Table/15/1/102), [txn: 9d6334a1], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 08:36:18.984684 119448 jobs/adopt.go:518  [T1,n1] 699  could not clear job claim: clear-job-claim: failed to send RPC: sending to all replicas failed; last error: routing information detected to be stale: ba: Scan [/Table/15/1/102,/Table/15/1/103), [txn: d7dd1f82], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 08:36:18.988651 117236 server/server_sql.go:1666  [T1,n1] 700  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (3.45s)
Help

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

ccl/changefeedccl.TestChangefeedTopicNames failed with artifacts on release-23.1 @ 416beb787ce5cf90695f13ebb7c95f749dc14061:

I230410 14:23:52.125080 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 810 ={"Timestamp":1681136632120407590,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta/ble70\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":175,"TableName":"d.public.\"ta/ble70\""}
I230410 14:23:52.140648 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 811 ={"Timestamp":1681136632137253763,"EventType":"create_table","Statement":"CREATE TABLE d.public.table71 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":176,"TableName":"d.public.table71"}
I230410 14:23:52.157544 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 812 ={"Timestamp":1681136632153966401,"EventType":"create_table","Statement":"CREATE TABLE d.public.table72 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":177,"TableName":"d.public.table72"}
I230410 14:23:52.171879 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 813 ={"Timestamp":1681136632168220347,"EventType":"create_table","Statement":"CREATE TABLE d.public.table73 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":178,"TableName":"d.public.table73"}
I230410 14:23:52.186212 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 814 ={"Timestamp":1681136632182383219,"EventType":"create_table","Statement":"CREATE TABLE d.public.t̟able74 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":179,"TableName":"d.public.t̟able74"}
I230410 14:23:52.201002 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 815 ={"Timestamp":1681136632197112287,"EventType":"create_table","Statement":"CREATE TABLE d.public.table75 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":180,"TableName":"d.public.table75"}
I230410 14:23:52.215796 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 816 ={"Timestamp":1681136632212393267,"EventType":"create_table","Statement":"CREATE TABLE d.public.table😗76 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":181,"TableName":"d.public.table😗76"}
I230410 14:23:52.236520 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 817 ={"Timestamp":1681136632233007421,"EventType":"create_table","Statement":"CREATE TABLE d.public.😘table77 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":182,"TableName":"d.public.😘table77"}
I230410 14:23:52.254947 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 818 ={"Timestamp":1681136632251466811,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"😹tabl*e\\\\xcd78\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":183,"TableName":"d.public.\"😹tabl*e\\\\xcd78\""}
I230410 14:23:52.270423 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 819 ={"Timestamp":1681136632266763314,"EventType":"create_table","Statement":"CREATE TABLE d.public.table79 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":184,"TableName":"d.public.table79"}
I230410 14:23:52.288114 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 820 ={"Timestamp":1681136632284005168,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl'e80\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":185,"TableName":"d.public.\"tabl'e80\""}
I230410 14:23:52.302929 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 821 ={"Timestamp":1681136632299396414,"EventType":"create_table","Statement":"CREATE TABLE d.public.table81 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":186,"TableName":"d.public.table81"}
I230410 14:23:52.318011 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 822 ={"Timestamp":1681136632313988386,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta%9eble82\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":187,"TableName":"d.public.\"ta%9eble82\""}
I230410 14:23:52.337236 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 823 ={"Timestamp":1681136632333482267,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t'able83\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":188,"TableName":"d.public.\"t'able83\""}
I230410 14:23:52.352921 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 824 ={"Timestamp":1681136632348723289,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"\rtable84\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":189,"TableName":"d.public.\"\rtable84\""}
I230410 14:23:52.368880 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 825 ={"Timestamp":1681136632365461772,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"(t/able85\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":190,"TableName":"d.public.\"(t/able85\""}
I230410 14:23:52.382712 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 826 ={"Timestamp":1681136632379348877,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"table%v86\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":191,"TableName":"d.public.\"table%v86\""}
I230410 14:23:52.396592 105670 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r8/1:/Table/{4-5}] 827  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:23:52.396677 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 828 ={"Timestamp":1681136632393256264,"EventType":"create_table","Statement":"CREATE TABLE d.public.table87 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":192,"TableName":"d.public.table87"}
I230410 14:23:52.411580 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 829 ={"Timestamp":1681136632408116660,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t\"\"able88\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.\"t\"\"able88\""}
I230410 14:23:52.430155 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 830 ={"Timestamp":1681136632426859751,"EventType":"create_table","Statement":"CREATE TABLE d.public.😤ta̩ble89 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.😤ta̩ble89"}
I230410 14:23:52.444727 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 831 ={"Timestamp":1681136632441287247,"EventType":"create_table","Statement":"CREATE TABLE d.public.table90 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.table90"}
I230410 14:23:52.472294 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 832 ={"Timestamp":1681136632467958562,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta'%64ble91\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.\"ta'%64ble91\""}
I230410 14:23:52.498987 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 833 ={"Timestamp":1681136632491929550,"EventType":"create_table","Statement":"CREATE TABLE d.public.table92 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.table92"}
I230410 14:23:52.515770 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 834 ={"Timestamp":1681136632510830823,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta'ble93\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.\"ta'ble93\""}
I230410 14:23:52.542540 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 835 ={"Timestamp":1681136632536489241,"EventType":"create_table","Statement":"CREATE TABLE d.public.table😬94 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.table😬94"}
I230410 14:23:52.557176 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 836 ={"Timestamp":1681136632553600399,"EventType":"create_table","Statement":"CREATE TABLE d.public.table95 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.table95"}
I230410 14:23:52.572069 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 837 ={"Timestamp":1681136632567932629,"EventType":"create_table","Statement":"CREATE TABLE d.public.\" tab%83le😪96\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.\" tab%83le😪96\""}
I230410 14:23:52.587463 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 838 ={"Timestamp":1681136632583643554,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta&ble97\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.\"ta&ble97\""}
I230410 14:23:52.601228 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 839 ={"Timestamp":1681136632597768577,"EventType":"create_table","Statement":"CREATE TABLE d.public.tab😬le98 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.tab😬le98"}
I230410 14:23:52.618039 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 840 ={"Timestamp":1681136632614113741,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t\\\\x59able99\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.\"t\\\\x59able99\""}
I230410 14:23:52.631578 103138 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 841 ={"Timestamp":1681136632627880546,"EventType":"create_table","Statement":"CREATE TABLE d.public.table100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.table100"}
I230410 14:23:52.644336 100376 ccl/changefeedccl/testfeed_test.go:795  [-] 842  Starting feed job: "CREATE CHANGEFEED FOR TABLE table1, TABLE \"{tabl%qe2\", TABLE table3, TABLE \"tab\"\" le 4\", TABLE \"t,a😠ble5\", TABLE table6, TABLE table7, TABLE \" tab le8\", TABLE table9, TABLE \"tAble10\", TABLE table11, TABLE t😙ablė12, TABLE \"tab😞Le%q13\", TABLE table14, TABLE table15, TABLE \"t)able16\", TABLE table17, TABLE \"tab%ple18\", TABLE table19, TABLE table20, TABLE \"tab*l\te21\", TABLE table22, TABLE table23, TABLE table24, TABLE table25, TABLE \"table%q26\", TABLE table27, TABLE table28, TABLE table29, TABLE table30, TABLE table31, TABLE \"table\"\"32\", TABLE \"table\\n33\", TABLE \"\vt able34\", TABLE \" t\vable35\", TABLE \"t*able36\", TABLE table37, TABLE \"\vtable38\", TABLE table39, TABLE table40, TABLE table41, TABLE table42, TABLE \"ta%qble43\", TABLE \"ta\nble44\", TABLE \"table\\\\uCFDF45\", TABLE \"\\\\x11tab le46\", TABLE table47, TABLE table48, TABLE \"table*49\", TABLE \"table\f50\", TABLE \"ta blE51\", TABLE table52, TABLE \"tabLe53\", TABLE \"table\r54\", TABLE table55, TABLE tab͢le56, TABLE table57, TABLE table58, TABLE table59, TABLE \"t\rab😚le60\", TABLE tab̖le61, TABLE \"tab̞%ple62\", TABLE table̕63, TABLE table64, TABLE table65, TABLE table66, TABLE tab̥le67, TABLE \"table 68\", TABLE table69, TABLE \"ta/ble70\", TABLE table71, TABLE table72, TABLE table73, TABLE t̟able74, TABLE table75, TABLE table😗76, TABLE 😘table77, TABLE \"😹tabl*e\\\\xcd78\", TABLE table79, TABLE \"tabl'e80\", TABLE table81, TABLE \"ta%9eble82\", TABLE \"t'able83\", TABLE \"\rtable84\", TABLE \"(t/able85\", TABLE \"table%v86\", TABLE table87, TABLE \"t\"\"able88\", TABLE 😤ta̩ble89, TABLE table90, TABLE \"ta'%64ble91\", TABLE table92, TABLE \"ta'ble93\", TABLE table😬94, TABLE table95, TABLE \" tab%83le😪96\", TABLE \"ta&ble97\", TABLE tab😬le98, TABLE \"t\\\\x59able99\", TABLE table100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 14:23:52.645024 103138 sql/schemachanger/scbuild/build.go:45  [T1,n1,client=127.0.0.1:57986,user=root] 843  building declarative schema change targets for CREATE CHANGEFEED
I230410 14:23:52.645536 106116 1@ccl/changefeedccl/changefeed_stmt.go:965  [T1,n1,client=127.0.0.1:57986,user=root] 844  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 14:23:52.664887 106116 12@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:57986,user=root] 845 ={"Timestamp":1681136632664882859,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:8465: 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.
W230410 14:23:52.666450 105967 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 846  failed to gc transaction record: could not GC completed transaction anchored at /Table/3/1/202/2/1: node unavailable; try another peer
I230410 14:23:52.666518 101094 sql/stats/automatic_stats.go:550  [T1,n1] 847  quiescing auto stats refresher
W230410 14:23:52.667415 100857 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 848  exiting heartbeat loop
W230410 14:23:52.667463 100857 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 849  exiting heartbeat loop with error: node unavailable; try another peer
E230410 14:23:52.667487 100857 server/server_sql.go:508  [T1,n1] 850  failed to run update of instance with new session ID: node unavailable; try another peer
I230410 14:23:52.667710 100442 server/start_listen.go:103  [T1,n1] 851  server shutting down: instructing cmux to stop accepting
E230410 14:23:52.667889 102580 jobs/registry.go:943  [T1,n1] 852  error getting live session: node unavailable; try another peer
I230410 14:23:52.667958 102391 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:44495,class=default,rpc] 853  connection heartbeat loop ended with err: <nil>
I230410 14:23:52.668069 101279 jobs/registry.go:1538  [T1,n1] 854  AUTO SPAN CONFIG RECONCILIATION job 855461820547891201: stepping through state succeeded
I230410 14:23:52.668493 102345 jobs/registry.go:1538  [T1,n1] 855  KEY VISUALIZER job 100: stepping through state succeeded
W230410 14:23:52.671966 102672 jobs/adopt.go:518  [T1,n1] 856  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: 959f6f4b], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 14:23:52.677453 100376 server/server_sql.go:1666  [T1,n1] 857  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (3.36s)
Help

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

This test on roachdash | Improve this report!

@blathers-crl blathers-crl bot added the A-cdc Change Data Capture label Apr 10, 2023
@cockroach-teamcity
Copy link
Member Author

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

I230410 15:00:21.581387 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 854 ={"Timestamp":1681138821542657271,"EventType":"create_table","Statement":"CREATE TABLE d.public.table85 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":190,"TableName":"d.public.table85"}
I230410 15:00:21.607906 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 855 ={"Timestamp":1681138821592650097,"EventType":"create_table","Statement":"CREATE TABLE d.public.table86 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":191,"TableName":"d.public.table86"}
I230410 15:00:21.746489 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 856 ={"Timestamp":1681138821661335097,"EventType":"create_table","Statement":"CREATE TABLE d.public.table87 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":192,"TableName":"d.public.table87"}
I230410 15:00:21.832089 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 857 ={"Timestamp":1681138821776736323,"EventType":"create_table","Statement":"CREATE TABLE d.public.table88 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.table88"}
I230410 15:00:21.915462 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 858 ={"Timestamp":1681138821871147029,"EventType":"create_table","Statement":"CREATE TABLE d.public.table89 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.table89"}
I230410 15:00:22.016944 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 859 ={"Timestamp":1681138821989874635,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"\\\\x0ctable90\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.\"\\\\x0ctable90\""}
I230410 15:00:22.070880 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 860 ={"Timestamp":1681138822050505896,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"taBle91\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.\"taBle91\""}
I230410 15:00:22.105959 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 861 ={"Timestamp":1681138822090276186,"EventType":"create_table","Statement":"CREATE TABLE d.public.\".table92\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.\".table92\""}
I230410 15:00:22.144704 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 862 ={"Timestamp":1681138822134573303,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl|e93\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.\"tabl|e93\""}
I230410 15:00:22.183706 109304 2@util/log/event_log.go:32  [T1,n1] 863 ={"Timestamp":1681138822183701064,"EventType":"runtime_stats","MemRSSBytes":511672320,"GoroutineCount":909,"MemStackSysBytes":10551296,"GoAllocBytes":159711680,"GoTotalBytes":289046872,"GoStatsStaleness":0.001626452,"HeapFragmentBytes":54304320,"HeapReservedBytes":29827072,"HeapReleasedBytes":131481600,"CGoAllocBytes":25417408,"CGoTotalBytes":172326912,"CGoCallRate":0.000068811685,"GCPausePercent":0.00000007813527,"GCRunCount":189,"NetHostRecvBytes":65731246,"NetHostSendBytes":65724838}
I230410 15:00:22.183900 109304 2@server/status/runtime_log.go:47  [T1,n1] 864  runtime stats: 488 MiB RSS, 909 goroutines (stacks: 10 MiB), 152 MiB/276 MiB Go alloc/total(stale) (heap fragmentation: 52 MiB, heap reserved: 28 MiB, heap released: 125 MiB), 24 MiB/164 MiB CGO alloc/total (0.0 CGO/sec), 0.0/0.0 %(u/s)time, 0.0 %gc (189x), 63 MiB/63 MiB (r/w)net
I230410 15:00:22.194232 123563 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r8/1:/Table/{4-5}] 865  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 15:00:22.228724 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 866 ={"Timestamp":1681138822199057117,"EventType":"create_table","Statement":"CREATE TABLE d.public.table94 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.table94"}
I230410 15:00:22.252614 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 867 ={"Timestamp":1681138822241469947,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabLe95\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.\"tabLe95\""}
I230410 15:00:22.321385 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 868 ={"Timestamp":1681138822301003299,"EventType":"create_table","Statement":"CREATE TABLE d.public.table96 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.table96"}
I230410 15:00:22.379187 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 869 ={"Timestamp":1681138822370924216,"EventType":"create_table","Statement":"CREATE TABLE d.public.table😝97 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.table😝97"}
I230410 15:00:22.438525 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 870 ={"Timestamp":1681138822423117093,"EventType":"create_table","Statement":"CREATE TABLE d.public.table98 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.table98"}
I230410 15:00:22.494973 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 871 ={"Timestamp":1681138822464333948,"EventType":"create_table","Statement":"CREATE TABLE d.public.table99 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.table99"}
I230410 15:00:22.569098 115975 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 872 ={"Timestamp":1681138822508136564,"EventType":"create_table","Statement":"CREATE TABLE d.public.table100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.table100"}
I230410 15:00:22.610747 108865 ccl/changefeedccl/testfeed_test.go:795  [-] 873  Starting feed job: "CREATE CHANGEFEED FOR TABLE tabͥle1, TABLE table2, TABLE table3, TABLE table4, TABLE table5, TABLE \"t%vabl\\\\x09e6\", TABLE 😥table7, TABLE table8, TABLE table9, TABLE \"?t%0eable10\", TABLE table11, TABLE table12, TABLE \"ta'ble13\", TABLE table14, TABLE table15, TABLE table16, TABLE table17, TABLE table18, TABLE table19, TABLE table20, TABLE table21, TABLE \"'table 22\", TABLE table23, TABLE table24, TABLE table25, TABLE \"tabl%ve-26\", TABLE t͇able27, TABLE \"ta \fble28\", TABLE table29, TABLE table30, TABLE tab😎le31, TABLE table32, TABLE \"Ta&ble33\", TABLE \"taBl/e34\", TABLE table35, TABLE \"tab͊ le36\", TABLE table͙37, TABLE \"t'a\"\"b😏le38\", TABLE \"ta%qb\rle39\", TABLE \"tab\vle40\", TABLE \"t%qa😱ble41\", TABLE table42, TABLE \"t\"\"able43\", TABLE \"'t*able44\", TABLE table45, TABLE table46, TABLE table47, TABLE \"tabl*e😆48\", TABLE table49, TABLE table50, TABLE table51, TABLE table52, TABLE \"t%q\n🙁able53\", TABLE \"tab͗l%ve54\", TABLE tabl😴e55, TABLE \"table'56\", TABLE \"t%qable57\", TABLE \"_%vtable58\", TABLE \"tab le59\", TABLE table60, TABLE \"tabl&e61\", TABLE table62, TABLE \"taͨb le63\", TABLE table64, TABLE table65, TABLE table66, TABLE table67, TABLE table68, TABLE table69, TABLE table70, TABLE table71, TABLE table72, TABLE table73, TABLE \"tabl e74\", TABLE \"ta%15ble75\", TABLE table76, TABLE ta😖ble77, TABLE 😕tabl͊e78, TABLE \"ta ble79\", TABLE table80, TABLE table81, TABLE table82, TABLE tab͉le83, TABLE table84, TABLE table85, TABLE table86, TABLE table87, TABLE table88, TABLE table89, TABLE \"\\\\x0ctable90\", TABLE \"taBle91\", TABLE \".table92\", TABLE \"tabl|e93\", TABLE table94, TABLE \"tabLe95\", TABLE table96, TABLE table😝97, TABLE table98, TABLE table99, TABLE table100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 15:00:22.613860 115975 sql/schemachanger/scbuild/build.go:45  [T10,nsql1,client=127.0.0.1:40176,user=root] 874  building declarative schema change targets for CREATE CHANGEFEED
I230410 15:00:22.614752 120464 1@ccl/changefeedccl/changefeed_stmt.go:965  [T10,nsql1,client=127.0.0.1:40176,user=root] 875  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 15:00:22.709081 120464 12@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:40176,user=root] 876 ={"Timestamp":1681138822709075467,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:8465: 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 15:00:22.712159 112628 sql/stats/automatic_stats.go:550  [T10,nsql1] 877  quiescing auto stats refresher
W230410 15:00:22.713196 112518 ccl/kvccl/kvtenantccl/connector.go:249  [T10,nsql1,tenant-connector] 878  error consuming GossipSubscription RPC: recv msg error: grpc: context canceled [code 1/Canceled]
W230410 15:00:22.713313 111581 sql/sqlliveness/slinstance/slinstance.go:334  [T10,nsql1] 879  exiting heartbeat loop
W230410 15:00:22.713330 111581 sql/sqlliveness/slinstance/slinstance.go:321  [T10,nsql1] 880  exiting heartbeat loop with error: node unavailable; try another peer
I230410 15:00:22.713327 112625 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:39063,class=rangefeed,rpc] 881  connection heartbeat loop ended with err: <nil>
I230410 15:00:22.713393 112514 server/start_listen.go:103  [T10,nsql1] 882  server shutting down: instructing cmux to stop accepting
E230410 15:00:22.713458 115317 jobs/registry.go:943  [-] 885  error getting live session: node unavailable; try another peer
I230410 15:00:22.713457 112521 rpc/context.go:2302  [T10,nsql1,rnode=63,raddr=127.0.0.1:39063,class=system,rpc] 884  connection heartbeat loop ended with err: <nil>
I230410 15:00:22.713420 112576 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:39063,class=default,rpc] 883  connection heartbeat loop ended with err: <nil>
W230410 15:00:22.713643 112519 ccl/kvccl/kvtenantccl/setting_overrides.go:46  [T10,nsql1,tenant-connector] 886  error consuming TenantSettings RPC: recv msg error: grpc: context canceled [code 1/Canceled]
E230410 15:00:22.713687 112636 jobs/registry.go:1055  [T10,nsql1] 887  error processing claimed jobs: could not query for claimed jobs: select-running/get-claimed-jobs: failed to read query result: query execution canceled
E230410 15:00:22.714150 112896 spanconfig/spanconfigjob/job.go:208  [T10,nsql1,job=AUTO SPAN CONFIG RECONCILIATION id=855468984076206081] 888  reconciler failed with failed to get protected timestamp state: failed to read records: protectedts-GetRecords: failed to read query result: query execution canceled, retrying...
W230410 15:00:22.744834 115649 jobs/adopt.go:518  [-] 889  could not clear job claim: clear-job-claim: tenant-side-limiter pool closed: shutting down
W230410 15:00:22.745127 108865 server/server_sql.go:1666  [T10,nsql1] 890  server shutdown without a prior graceful drain
I230410 15:00:22.745407 109575 sql/stats/automatic_stats.go:550  [T1,n1] 891  quiescing auto stats refresher
W230410 15:00:22.746196 109372 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 892  exiting heartbeat loop
W230410 15:00:22.746231 109372 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 893  exiting heartbeat loop with error: node unavailable; try another peer
E230410 15:00:22.746254 109372 server/server_sql.go:508  [T1,n1] 894  failed to run update of instance with new session ID: node unavailable; try another peer
E230410 15:00:22.746902 111081 jobs/registry.go:943  [T1,n1] 895  error getting live session: node unavailable; try another peer
I230410 15:00:22.747062 110393 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:39063,class=default,rpc] 896  connection heartbeat loop ended with err: <nil>
I230410 15:00:22.747455 110894 jobs/registry.go:1538  [T1,n1] 897  KEY VISUALIZER job 100: stepping through state succeeded
I230410 15:00:22.747848 109182 server/start_listen.go:103  [T1,n1] 898  server shutting down: instructing cmux to stop accepting
I230410 15:00:22.748874 109751 jobs/registry.go:1538  [T1,n1] 899  AUTO SPAN CONFIG RECONCILIATION job 855468973249495041: stepping through state succeeded
W230410 15:00:22.750713 111188 jobs/adopt.go:518  [T1,n1] 900  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: c7709a5c], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 15:00:22.756934 108865 server/server_sql.go:1666  [T1,n1] 901  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (10.70s)
Help

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

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

I230410 15:03:17.346097 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 712 ={"Timestamp":1681138997341405667,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t able88\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.\"t able88\""}
I230410 15:03:17.354025 115032 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r88/1:/{Table/131-Max}] 713  initiating a split of this range at key /Table/132 [r89] (span config)
I230410 15:03:17.363715 114926 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r89/1:/{Table/132-Max}] 714  initiating a split of this range at key /Table/133 [r90] (span config)
I230410 15:03:17.369984 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 715 ={"Timestamp":1681138997363113496,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta'ble89\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.\"ta'ble89\""}
I230410 15:03:17.372063 115078 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r90/1:/{Table/133-Max}] 716  initiating a split of this range at key /Table/134 [r91] (span config)
I230410 15:03:17.379025 109178 3@pebble/event.go:734  [n1,s1,pebble] 717  [JOB 8] WAL created 000007
I230410 15:03:17.382284 115097 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r91/1:/{Table/134-Max}] 718  initiating a split of this range at key /Table/135 [r92] (span config)
I230410 15:03:17.389645 115131 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r92/1:/{Table/135-Max}] 719  initiating a split of this range at key /Table/136 [r93] (span config)
I230410 15:03:17.390926 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 720 ={"Timestamp":1681138997383373160,"EventType":"create_table","Statement":"CREATE TABLE d.public.t̃able90 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.t̃able90"}
I230410 15:03:17.402173 115150 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r93/1:/{Table/136-Max}] 721  initiating a split of this range at key /Table/137 [r94] (span config)
I230410 15:03:17.413071 115173 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r94/1:/{Table/137-Max}] 722  initiating a split of this range at key /Table/138 [r95] (span config)
I230410 15:03:17.421244 115207 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r95/1:/{Table/138-Max}] 723  initiating a split of this range at key /Table/139 [r96] (span config)
I230410 15:03:17.427317 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 724 ={"Timestamp":1681138997414959317,"EventType":"create_table","Statement":"CREATE TABLE d.public.table91 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.table91"}
I230410 15:03:17.433164 115239 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r96/1:/{Table/139-Max}] 725  initiating a split of this range at key /Table/140 [r97] (span config)
I230410 15:03:17.447803 115251 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r45/1:/Table/4{3-4}] 726  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 15:03:17.453163 115267 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r97/1:/{Table/140-Max}] 727  initiating a split of this range at key /Table/141 [r98] (span config)
I230410 15:03:17.455693 115274 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r6/1:/Table/{0-3}] 728  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 15:03:17.466935 115303 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r98/1:/{Table/141-Max}] 729  initiating a split of this range at key /Table/142 [r99] (span config)
I230410 15:03:17.472475 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 730 ={"Timestamp":1681138997462392861,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t able92\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.\"t able92\""}
I230410 15:03:17.550910 114400 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r99/1:/{Table/142-Max}] 731  initiating a split of this range at key /Table/143 [r100] (span config)
I230410 15:03:17.560147 115264 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r100/1:/{Table/143-Max}] 732  initiating a split of this range at key /Table/144 [r101] (span config)
I230410 15:03:17.570730 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 733 ={"Timestamp":1681138997566949101,"EventType":"create_table","Statement":"CREATE TABLE d.public.table93 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.table93"}
I230410 15:03:17.589217 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 734 ={"Timestamp":1681138997581990737,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t\\gable94\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.\"t\\gable94\""}
I230410 15:03:17.614147 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 735 ={"Timestamp":1681138997610060049,"EventType":"create_table","Statement":"CREATE TABLE d.public.table95 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.table95"}
I230410 15:03:17.637475 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 736 ={"Timestamp":1681138997633577402,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl(e96\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.\"tabl(e96\""}
I230410 15:03:17.662832 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 737 ={"Timestamp":1681138997658736722,"EventType":"create_table","Statement":"CREATE TABLE d.public.table97 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.table97"}
I230410 15:03:17.693744 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 738 ={"Timestamp":1681138997689209865,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl e98\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.\"tabl e98\""}
I230410 15:03:17.715464 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 739 ={"Timestamp":1681138997709888741,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t̆ab\nle99\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.\"t̆ab\nle99\""}
I230410 15:03:17.736116 111718 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 740 ={"Timestamp":1681138997727663411,"EventType":"create_table","Statement":"CREATE TABLE d.public.table100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.table100"}
I230410 15:03:17.769293 108796 ccl/changefeedccl/testfeed_test.go:795  [-] 741  Starting feed job: "CREATE CHANGEFEED FOR TABLE table1, TABLE tableͫ2, TABLE \"tabl\re3\", TABLE \"\rtab😛le4\", TABLE \"ta'ble😈5\", TABLE \"t%vabͪle6\", TABLE tab😛le7, TABLE tabl̆e8, TABLE t😯able9, TABLE ta̹ble10, TABLE \"ta\\\\u17A4ble11\", TABLE \"tab\"\"le12\", TABLE \"tabLë13\", TABLE ta😏ble14, TABLE \"tabl|e15\", TABLE \"ta'ble16\", TABLE \"t\nable 17\", TABLE table18, TABLE table19, TABLE table20, TABLE table21, TABLE \"tabLe22\", TABLE table23, TABLE table24, TABLE \"t abl e͋25\", TABLE \"tab,le26\", TABLE table27, TABLE t😤able28, TABLE table29, TABLE table30, TABLE \"t%qable31\", TABLE \"ta'ble32\", TABLE tab͆le33, TABLE table34, TABLE \"tab%ple35\", TABLE \"tablE36\", TABLE \"t able37\", TABLE \"t able38\", TABLE table39, TABLE table40, TABLE table41, TABLE \"tabl\\\\U00028E42e42\", TABLE \"tab%fa\tle🙁43\", TABLE tab😡le44, TABLE \"tabLe45\", TABLE \"table\n46\", TABLE table47, TABLE table48, TABLE \"tabl%qe49\", TABLE table50, TABLE table51, TABLE table52, TABLE \"ta\t😞ble53\", TABLE table54, TABLE t😺able55, TABLE \"table%p56\", TABLE \"tablE57\", TABLE \"table%c158\", TABLE \"table\"\"😅59\", TABLE table60, TABLE \"%e2table61\", TABLE \"tabl e62\", TABLE \"ta(ble63\", TABLE \"%a7tab͓'le64\", TABLE \"ta%vble65\", TABLE table66, TABLE table67, TABLE \"tab le😻68\", TABLE \"tabl%qe69\", TABLE \"t'able70\", TABLE table71, TABLE \"tab\rle72\", TABLE table73, TABLE table74, TABLE 😵table75, TABLE table76, TABLE tab😱le77, TABLE table78, TABLE table79, TABLE table80, TABLE \" table81\", TABLE \"t\nabLe82\", TABLE \"table\\\\u684383\", TABLE t̐able84, TABLE table85, TABLE table86, TABLE table87, TABLE \"t able88\", TABLE \"ta'ble89\", TABLE t̃able90, TABLE table91, TABLE \"t able92\", TABLE table93, TABLE \"t\\gable94\", TABLE table95, TABLE \"tabl(e96\", TABLE table97, TABLE \"tabl e98\", TABLE \"t̆ab\nle99\", TABLE table100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 15:03:17.770040 111718 sql/schemachanger/scbuild/build.go:45  [T1,n1,client=127.0.0.1:42380,user=root] 742  building declarative schema change targets for CREATE CHANGEFEED
I230410 15:03:17.770654 115653 1@ccl/changefeedccl/changefeed_stmt.go:965  [T1,n1,client=127.0.0.1:42380,user=root] 743  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 15:03:17.801836 115653 12@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:42380,user=root] 744 ={"Timestamp":1681138997801831422,"EventType":"changefeed_failed","FailureType":"user_input"}
I230410 15:03:17.803542 109552 sql/stats/automatic_stats.go:550  [T1,n1] 745  quiescing auto stats refresher
W230410 15:03:17.803785 115403 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 746  failed to gc transaction record: could not GC completed transaction anchored at /Local/Range/Table/143/RangeDescriptor: node unavailable; try another peer
I230410 15:03:17.804574 109810 jobs/registry.go:1538  [T1,n1] 747  AUTO SPAN CONFIG RECONCILIATION job 855469563770011649: stepping through state succeeded
    changefeed_test.go:8465: 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 15:03:17.806868 110932 jobs/registry.go:1538  [T1,n1] 748  KEY VISUALIZER job 100: stepping through state succeeded
W230410 15:03:17.808418 109378 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 749  exiting heartbeat loop
W230410 15:03:17.810278 109378 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 752  exiting heartbeat loop with error: node unavailable; try another peer
I230410 15:03:17.808802 110481 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:36137,class=default,rpc] 750  connection heartbeat loop ended with err: <nil>
I230410 15:03:17.808986 109129 server/start_listen.go:103  [T1,n1] 751  server shutting down: instructing cmux to stop accepting
E230410 15:03:17.810451 109378 server/server_sql.go:508  [T1,n1] 753  failed to run update of instance with new session ID: node unavailable; try another peer
W230410 15:03:17.820883 110932 jobs/adopt.go:518  [T1,n1] 754  could not clear job claim: clear-job-claim: node unavailable; try another peer
E230410 15:03:17.822256 109560 jobs/registry.go:1055  [T1,n1] 755  error processing claimed jobs: could not query for claimed jobs: failed to read query result: query execution canceled
W230410 15:03:17.823428 111170 jobs/adopt.go:518  [T1,n1] 756  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 15:03:17.823654 109810 jobs/adopt.go:518  [T1,n1] 757  could not clear job claim: clear-job-claim: failed to send RPC: sending to all replicas failed; last error: ba: Scan [/Table/15/1/855469563770011649,/Table/15/1/855469563770011650), [txn: 3e1b3773], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 15:03:17.832151 111299 jobs/adopt.go:518  [T1,n1] 758  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 15:03:17.837091 108796 server/server_sql.go:1666  [T1,n1] 759  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (5.58s)
Help

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

ccl/changefeedccl.TestChangefeedTopicNames failed with artifacts on release-23.1 @ 57c6f6e0e6051dc23772d8997f8ef09fbb896ab0:

I230410 14:50:25.165845 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 689 ={"Timestamp":1681138225162225312,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"\\\\U000091E8ta😌ble72\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":177,"TableName":"d.public.\"\\\\U000091E8ta😌ble72\""}
I230410 14:50:25.184061 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 690 ={"Timestamp":1681138225180227453,"EventType":"create_table","Statement":"CREATE TABLE d.public.table73 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":178,"TableName":"d.public.table73"}
I230410 14:50:25.198469 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 691 ={"Timestamp":1681138225194908774,"EventType":"create_table","Statement":"CREATE TABLE d.public.table74 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":179,"TableName":"d.public.table74"}
I230410 14:50:25.215610 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 692 ={"Timestamp":1681138225211813559,"EventType":"create_table","Statement":"CREATE TABLE d.public.table75 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":180,"TableName":"d.public.table75"}
I230410 14:50:25.231871 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 693 ={"Timestamp":1681138225228156660,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"table%v76\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":181,"TableName":"d.public.\"table%v76\""}
I230410 14:50:25.246323 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 694 ={"Timestamp":1681138225243056908,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta%vble77\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":182,"TableName":"d.public.\"ta%vble77\""}
I230410 14:50:25.278170 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 695 ={"Timestamp":1681138225267275153,"EventType":"create_table","Statement":"CREATE TABLE d.public.table78 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":183,"TableName":"d.public.table78"}
I230410 14:50:25.305380 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 696 ={"Timestamp":1681138225294838055,"EventType":"create_table","Statement":"CREATE TABLE d.public.table79 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":184,"TableName":"d.public.table79"}
I230410 14:50:25.319914 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 697 ={"Timestamp":1681138225316416719,"EventType":"create_table","Statement":"CREATE TABLE d.public.table80 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":185,"TableName":"d.public.table80"}
I230410 14:50:25.369876 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 698 ={"Timestamp":1681138225366345474,"EventType":"create_table","Statement":"CREATE TABLE d.public.table81 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":186,"TableName":"d.public.table81"}
I230410 14:50:25.388256 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 699 ={"Timestamp":1681138225384457547,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl\\\\x55e82\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":187,"TableName":"d.public.\"tabl\\\\x55e82\""}
I230410 14:50:25.403312 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 700 ={"Timestamp":1681138225399882005,"EventType":"create_table","Statement":"CREATE TABLE d.public.table83 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":188,"TableName":"d.public.table83"}
I230410 14:50:25.433434 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 701 ={"Timestamp":1681138225418426162,"EventType":"create_table","Statement":"CREATE TABLE d.public.ta̧ble84 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":189,"TableName":"d.public.ta̧ble84"}
I230410 14:50:25.451292 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 702 ={"Timestamp":1681138225447784316,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl,\\\\x8ee85\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":190,"TableName":"d.public.\"tabl,\\\\x8ee85\""}
I230410 14:50:25.466098 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 703 ={"Timestamp":1681138225462418351,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"taBle86\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":191,"TableName":"d.public.\"taBle86\""}
I230410 14:50:25.485521 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 704 ={"Timestamp":1681138225481736423,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta,ble87\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":192,"TableName":"d.public.\"ta,ble87\""}
I230410 14:50:25.504112 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 705 ={"Timestamp":1681138225500707554,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t\table88\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.\"t\table88\""}
I230410 14:50:25.521661 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 706 ={"Timestamp":1681138225515158469,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta.ble89\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.\"ta.ble89\""}
I230410 14:50:25.535062 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 707 ={"Timestamp":1681138225531679390,"EventType":"create_table","Statement":"CREATE TABLE d.public.table90 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.table90"}
I230410 14:50:25.548961 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 708 ={"Timestamp":1681138225545707993,"EventType":"create_table","Statement":"CREATE TABLE d.public.table91 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.table91"}
I230410 14:50:25.571310 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 709 ={"Timestamp":1681138225566696542,"EventType":"create_table","Statement":"CREATE TABLE d.public.t😾able92 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.t😾able92"}
I230410 14:50:25.599820 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 710 ={"Timestamp":1681138225596144689,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta b le93\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.\"ta b le93\""}
I230410 14:50:25.635816 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 711 ={"Timestamp":1681138225632295292,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tåb* le94\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.\"tåb* le94\""}
I230410 14:50:25.650201 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 712 ={"Timestamp":1681138225646613040,"EventType":"create_table","Statement":"CREATE TABLE d.public.table95 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.table95"}
I230410 14:50:25.707717 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 713 ={"Timestamp":1681138225692859954,"EventType":"create_table","Statement":"CREATE TABLE d.public.t😆able96 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.t😆able96"}
I230410 14:50:25.726952 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 714 ={"Timestamp":1681138225723636724,"EventType":"create_table","Statement":"CREATE TABLE d.public.table97 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.table97"}
I230410 14:50:25.743851 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 715 ={"Timestamp":1681138225737379824,"EventType":"create_table","Statement":"CREATE TABLE d.public.table98 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.table98"}
I230410 14:50:25.759017 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 716 ={"Timestamp":1681138225755455195,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl\te99\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.\"tabl\te99\""}
I230410 14:50:25.774423 119191 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 717 ={"Timestamp":1681138225770621630,"EventType":"create_table","Statement":"CREATE TABLE d.public.table100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.table100"}
I230410 14:50:25.799131 116490 ccl/changefeedccl/testfeed_test.go:795  [-] 718  Starting feed job: "CREATE CHANGEFEED FOR TABLE table1, TABLE table2, TABLE table3, TABLE table4, TABLE table5, TABLE \"ta.ble6\", TABLE table7, TABLE table8, TABLE \"Table9\", TABLE ta̓ble😊10, TABLE \"table%e611\", TABLE \"taBle12\", TABLE table13, TABLE \"table!14\", TABLE 😬table15, TABLE tab😭le16, TABLE table17, TABLE \"ta ble\r18\", TABLE table19, TABLE table20, TABLE \"tabl̛*e21\", TABLE \"tabl e22\", TABLE \"table\f23\", TABLE \"tablE24\", TABLE table25, TABLE \"ta ble26\", TABLE \"ta'ble27\", TABLE \"%ptable28\", TABLE \"ta%adble29\", TABLE table30, TABLE table31, TABLE table32, TABLE table33, TABLE table34, TABLE table35, TABLE \"tab&le36\", TABLE table37, TABLE \"taBle38\", TABLE \"table%q39\", TABLE \"'table40\", TABLE table41, TABLE \"ta b\nle42\", TABLE table43, TABLE table44, TABLE \"taB%vle45\", TABLE table46, TABLE \"tabl%f5e47\", TABLE table48, TABLE table49, TABLE table50, TABLE \"ta\vble 51\", TABLE table52, TABLE \"tab\\\\x6fle53\", TABLE table54, TABLE \"tabl.e55\", TABLE \"ta%pble56\", TABLE table57, TABLE table58, TABLE table59, TABLE table60, TABLE table61, TABLE \"\\\\x09table62\", TABLE table63, TABLE table64, TABLE table65, TABLE \"\\\\U0009FB62t'abl%qe66\", TABLE \"tabl%qe 67\", TABLE table68, TABLE table͌69, TABLE \"tabl\"\"e70\", TABLE ta😐b😳le71, TABLE \"\\\\U000091E8ta😌ble72\", TABLE table73, TABLE table74, TABLE table75, TABLE \"table%v76\", TABLE \"ta%vble77\", TABLE table78, TABLE table79, TABLE table80, TABLE table81, TABLE \"tabl\\\\x55e82\", TABLE table83, TABLE ta̧ble84, TABLE \"tabl,\\\\x8ee85\", TABLE \"taBle86\", TABLE \"ta,ble87\", TABLE \"t\table88\", TABLE \"ta.ble89\", TABLE table90, TABLE table91, TABLE t😾able92, TABLE \"ta b le93\", TABLE \"tåb* le94\", TABLE table95, TABLE t😆able96, TABLE table97, TABLE table98, TABLE \"tabl\te99\", TABLE table100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 14:50:25.807020 119191 sql/schemachanger/scbuild/build.go:45  [T1,n1,client=127.0.0.1:49426,user=root] 719  building declarative schema change targets for CREATE CHANGEFEED
I230410 14:50:25.807702 122276 1@ccl/changefeedccl/changefeed_stmt.go:965  [T1,n1,client=127.0.0.1:49426,user=root] 720  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 14:50:25.830998 122276 12@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:49426,user=root] 721 ={"Timestamp":1681138225830992867,"EventType":"changefeed_failed","FailureType":"user_input"}
I230410 14:50:25.835754 117156 sql/stats/automatic_stats.go:550  [T1,n1] 722  quiescing auto stats refresher
W230410 14:50:25.835845 122125 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 723  failed to gc transaction record: could not GC completed transaction anchored at /Table/3/1/205/2/1: node unavailable; try another peer
I230410 14:50:25.837584 118399 jobs/registry.go:1538  [T1,n1] 724  KEY VISUALIZER job 100: stepping through state succeeded
I230410 14:50:25.837920 117417 jobs/registry.go:1538  [T1,n1] 725  AUTO SPAN CONFIG RECONCILIATION job 855467038862180353: stepping through state succeeded
    changefeed_test.go:8465: 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.
W230410 14:50:25.839306 117134 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 726  exiting heartbeat loop
W230410 14:50:25.839361 117134 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 727  exiting heartbeat loop with error: node unavailable; try another peer
E230410 14:50:25.839387 117134 server/server_sql.go:506  [T1,n1] 728  failed to run update of instance with new session ID: node unavailable; try another peer
I230410 14:50:25.839720 118498 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:40635,class=default,rpc] 729  connection heartbeat loop ended with err: <nil>
I230410 14:50:25.840514 116789 server/start_listen.go:103  [T1,n1] 730  server shutting down: instructing cmux to stop accepting
E230410 14:50:25.840955 117164 jobs/registry.go:1055  [T1,n1] 731  error processing claimed jobs: could not query for claimed jobs: failed to read query result: query execution canceled
W230410 14:50:25.841308 118633 jobs/adopt.go:518  [T1,n1] 732  could not clear job claim: clear-job-claim: failed to send RPC: sending to all replicas failed; last error: ba: Scan [/Table/15/1/101,/Table/15/1/102), [txn: cb1f8d50], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 14:50:25.845651 118399 jobs/adopt.go:518  [T1,n1] 733  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 14:50:25.850234 118582 jobs/adopt.go:518  [T1,n1] 734  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 14:50:25.853650 117417 jobs/adopt.go:518  [T1,n1] 735  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 14:50:25.857236 116490 server/server_sql.go:1658  [T1,n1] 736  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (4.15s)
Help

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

ccl/changefeedccl.TestChangefeedTopicNames failed with artifacts on release-23.1 @ 2624cead5e77d06fa1c224f65072ef947c186d16:

I230410 15:28:42.166238 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 978 ={"Timestamp":1681140522154191486,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tablE84\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":189,"TableName":"d.public.\"tablE84\""}
I230410 15:28:42.182602 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 979 ={"Timestamp":1681140522173774206,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta%ble85\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":190,"TableName":"d.public.\"ta%ble85\""}
I230410 15:28:42.195602 141119 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r61/1:/Table/6{0-1}] 980  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 15:28:42.207235 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 981 ={"Timestamp":1681140522195150424,"EventType":"create_table","Statement":"CREATE TABLE d.public.table86 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":191,"TableName":"d.public.table86"}
I230410 15:28:42.245020 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 982 ={"Timestamp":1681140522215542365,"EventType":"create_table","Statement":"CREATE TABLE d.public.table87 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":192,"TableName":"d.public.table87"}
I230410 15:28:42.275939 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 983 ={"Timestamp":1681140522265501324,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"table%3688\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.\"table%3688\""}
I230410 15:28:42.325374 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 984 ={"Timestamp":1681140522304770953,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"\tt!abl e89\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.\"\tt!abl e89\""}
I230410 15:28:42.363890 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 985 ={"Timestamp":1681140522348411550,"EventType":"create_table","Statement":"CREATE TABLE d.public.table90 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.table90"}
I230410 15:28:42.394143 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 986 ={"Timestamp":1681140522383242911,"EventType":"create_table","Statement":"CREATE TABLE d.public.table91 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.table91"}
I230410 15:28:42.423212 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 987 ={"Timestamp":1681140522409247976,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tAbͫ'le92\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.\"tAbͫ'le92\""}
I230410 15:28:42.445286 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 988 ={"Timestamp":1681140522431221141,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t\\fable93\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.\"t\\fable93\""}
I230410 15:28:42.472245 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 989 ={"Timestamp":1681140522463009488,"EventType":"create_table","Statement":"CREATE TABLE d.public.table94 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.table94"}
I230410 15:28:42.498937 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 990 ={"Timestamp":1681140522486362071,"EventType":"create_table","Statement":"CREATE TABLE d.public.table95 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.table95"}
I230410 15:28:42.533059 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 991 ={"Timestamp":1681140522511662358,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta%vb l😇e96\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.\"ta%vb l😇e96\""}
I230410 15:28:42.554435 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 992 ={"Timestamp":1681140522544432415,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tab/le97\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.\"tab/le97\""}
I230410 15:28:42.573214 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 993 ={"Timestamp":1681140522564550928,"EventType":"create_table","Statement":"CREATE TABLE d.public.table98 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.table98"}
I230410 15:28:42.595436 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 994 ={"Timestamp":1681140522583929833,"EventType":"create_table","Statement":"CREATE TABLE d.public.\" table99\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.\" table99\""}
I230410 15:28:42.637439 135228 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 995 ={"Timestamp":1681140522602319095,"EventType":"create_table","Statement":"CREATE TABLE d.public.table100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.table100"}
I230410 15:28:42.657032 127180 ccl/changefeedccl/testfeed_test.go:795  [-] 996  Starting feed job: "CREATE CHANGEFEED FOR TABLE \" t'able1\", TABLE \"t😥a b\fle2\", TABLE table3, TABLE \"tabl\\ve4\", TABLE table5, TABLE table6, TABLE table7, TABLE table8, TABLE t́able9, TABLE \"tab le10\", TABLE table11, TABLE \"t\\\\U000443A0able12\", TABLE \"tabl{e13\", TABLE table14, TABLE table15, TABLE \"tab le%p16\", TABLE \"table%p17\", TABLE tabl😂e18, TABLE \"tab\"\"le19\", TABLE table20, TABLE table21, TABLE table22, TABLE table23, TABLE \"tabl\ne24\", TABLE table25, TABLE table26, TABLE table27, TABLE \"ta*ble28\", TABLE table29, TABLE table30, TABLE table31, TABLE table32, TABLE \"ta\tble\r33\", TABLE table34, TABLE \"tabl%pe35\", TABLE table36, TABLE \",tabl%ve37\", TABLE table38, TABLE \" tabl e39\", TABLE \"\rtable40\", TABLE \"t\fa😇ble%41\", TABLE table42, TABLE table43, TABLE \"t\"\"able44\", TABLE table45, TABLE table46, TABLE \"tabl%0de47\", TABLE \"tab%23le48\", TABLE table49, TABLE \"tabl'e50\", TABLE \"tAble51\", TABLE table52, TABLE table53, TABLE \" table54\", TABLE \"ta.\\\\xf8ble55\", TABLE \"table'😳56\", TABLE table57, TABLE \"ta-b̚l%e58\", TABLE table59, TABLE table60, TABLE \"tabl%e61\", TABLE \"tab\\\\xd2le62\", TABLE \"%qtable63\", TABLE \"t%vable64\", TABLE \"t\"\"ablȇ65\", TABLE \"tablE66\", TABLE t😌able67, TABLE table68, TABLE \"tab\\\\u1F6B le69\", TABLE \" tabl😇e70\", TABLE table71, TABLE table72, TABLE table73, TABLE table74, TABLE table75, TABLE \"t\\\\U000C9A35able76\", TABLE table77, TABLE \"ta\\\\U0008321Able78\", TABLE \"\"\"table79\", TABLE \"tabLe80\", TABLE table81, TABLE 😠table82, TABLE tablě83, TABLE \"tablE84\", TABLE \"ta%ble85\", TABLE table86, TABLE table87, TABLE \"table%3688\", TABLE \"\tt!abl e89\", TABLE table90, TABLE table91, TABLE \"tAbͫ'le92\", TABLE \"t\\fable93\", TABLE table94, TABLE table95, TABLE \"ta%vb l😇e96\", TABLE \"tab/le97\", TABLE table98, TABLE \" table99\", TABLE table100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 15:28:42.657866 135228 sql/schemachanger/scbuild/build.go:45  [T10,nsql1,client=127.0.0.1:35542,user=root] 997  building declarative schema change targets for CREATE CHANGEFEED
I230410 15:28:42.658331 142397 1@ccl/changefeedccl/changefeed_stmt.go:965  [T10,nsql1,client=127.0.0.1:35542,user=root] 998  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 15:28:42.679997 142397 12@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:35542,user=root] 999 ={"Timestamp":1681140522679991392,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:8465: 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 15:28:42.682742 131932 sql/stats/automatic_stats.go:550  [T10,nsql1] 1000  quiescing auto stats refresher
E230410 15:28:42.682812 131887 jobs/registry.go:995  [T10,nsql1] 1001  failed to serve pause and cancel requests: txn exec: context canceled
W230410 15:28:42.684250 114637 ccl/kvccl/kvtenantccl/connector.go:249  [T10,nsql1,tenant-connector] 1002  error consuming GossipSubscription RPC: recv msg error: grpc: context canceled [code 1/Canceled]
I230410 15:28:42.684424 131852 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:41617,class=default,rpc] 1003  connection heartbeat loop ended with err: <nil>
I230410 15:28:42.684509 114640 rpc/context.go:2302  [T10,nsql1,rnode=63,raddr=127.0.0.1:41617,class=system,rpc] 1004  connection heartbeat loop ended with err: <nil>
W230410 15:28:42.684817 131115 sql/sqlliveness/slinstance/slinstance.go:334  [T10,nsql1] 1005  exiting heartbeat loop
W230410 15:28:42.684849 131115 sql/sqlliveness/slinstance/slinstance.go:321  [T10,nsql1] 1006  exiting heartbeat loop with error: node unavailable; try another peer
W230410 15:28:42.684964 114638 ccl/kvccl/kvtenantccl/setting_overrides.go:46  [T10,nsql1,tenant-connector] 1007  error consuming TenantSettings RPC: recv msg error: grpc: error reading from server: read tcp 127.0.0.1:40610->127.0.0.1:41617: use of closed network connection [code 14/Unavailable]
I230410 15:28:42.685258 132093 jobs/registry.go:1538  [T10,nsql1] 1008  AUTO SPAN CONFIG RECONCILIATION job 855474562927132673: stepping through state succeeded
E230410 15:28:42.685439 132093 jobs/registry.go:943  [-] 1009  error getting live session: node unavailable; try another peer
I230410 15:28:42.686442 114633 server/start_listen.go:103  [T10,nsql1] 1010  server shutting down: instructing cmux to stop accepting
W230410 15:28:42.687925 134437 jobs/adopt.go:518  [-] 1011  could not clear job claim: clear-job-claim: tenant-side-limiter pool closed: shutting down
W230410 15:28:42.718135 134890 jobs/adopt.go:518  [-] 1012  could not clear job claim: clear-job-claim: tenant-side-limiter pool closed: shutting down
W230410 15:28:42.730639 127180 server/server_sql.go:1676  [T10,nsql1] 1013  server shutdown without a prior graceful drain
W230410 15:28:42.731002 140597 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 1014  failed to gc transaction record: could not GC completed transaction anchored at /Local/Range/Tenant/10/RangeDescriptor: node unavailable; try another peer
I230410 15:28:42.731106 128457 server/start_listen.go:103  [T1,n1] 1015  server shutting down: instructing cmux to stop accepting
W230410 15:28:42.731275 128640 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 1016  exiting heartbeat loop
I230410 15:28:42.731285 129271 jobs/registry.go:1538  [T1,n1] 1017  AUTO SPAN CONFIG RECONCILIATION job 855474553448562689: stepping through state succeeded
I230410 15:28:42.731337 128737 sql/stats/automatic_stats.go:550  [T1,n1] 1020  quiescing auto stats refresher
W230410 15:28:42.731302 128640 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 1018  exiting heartbeat loop with error: node unavailable; try another peer
E230410 15:28:42.731404 128640 server/server_sql.go:507  [T1,n1] 1021  failed to run update of instance with new session ID: node unavailable; try another peer
E230410 15:28:42.731430 129271 jobs/registry.go:943  [T1,n1] 1022  error getting live session: node unavailable; try another peer
I230410 15:28:42.731288 129481 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:41617,class=default,rpc] 1019  connection heartbeat loop ended with err: <nil>
I230410 15:28:42.733638 130218 jobs/registry.go:1538  [T1,n1] 1023  KEY VISUALIZER job 100: stepping through state succeeded
W230410 15:28:42.736035 130363 jobs/adopt.go:518  [T1,n1] 1024  could not clear job claim: clear-job-claim: failed to send RPC: sending to all replicas failed; last error: ba: Scan [/Table/15/1/101,/Table/15/1/102), [txn: 2ac4c2a6], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 15:28:42.741864 127180 server/server_sql.go:1676  [T1,n1] 1025  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (7.66s)
Help

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

ccl/changefeedccl.TestChangefeedTopicNames failed with artifacts on release-23.1 @ fbc5d56e5998990d3be5860e0263e781890f89e1:

I230410 16:10:35.892304 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 842 ={"Timestamp":1681143035878553956,"EventType":"create_table","Statement":"CREATE TABLE d.public.table82 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":187,"TableName":"d.public.table82"}
I230410 16:10:35.910980 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 843 ={"Timestamp":1681143035900840629,"EventType":"create_table","Statement":"CREATE TABLE d.public.table83 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":188,"TableName":"d.public.table83"}
I230410 16:10:35.927286 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 844 ={"Timestamp":1681143035918121281,"EventType":"create_table","Statement":"CREATE TABLE d.public.table84 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":189,"TableName":"d.public.table84"}
I230410 16:10:35.947868 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 845 ={"Timestamp":1681143035934337968,"EventType":"create_table","Statement":"CREATE TABLE d.public.table85 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":190,"TableName":"d.public.table85"}
I230410 16:10:35.969322 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 846 ={"Timestamp":1681143035958423517,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabLe 86\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":191,"TableName":"d.public.\"tabLe 86\""}
I230410 16:10:35.993422 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 847 ={"Timestamp":1681143035979943763,"EventType":"create_table","Statement":"CREATE TABLE d.public.table87 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":192,"TableName":"d.public.table87"}
I230410 16:10:36.014123 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 848 ={"Timestamp":1681143036004629241,"EventType":"create_table","Statement":"CREATE TABLE d.public.table88 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.table88"}
I230410 16:10:36.050313 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 849 ={"Timestamp":1681143036030709316,"EventType":"create_table","Statement":"CREATE TABLE d.public.table89 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.table89"}
I230410 16:10:36.076066 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 850 ={"Timestamp":1681143036066201525,"EventType":"create_table","Statement":"CREATE TABLE d.public.table90 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.table90"}
I230410 16:10:36.114698 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 851 ={"Timestamp":1681143036105378757,"EventType":"create_table","Statement":"CREATE TABLE d.public.table91 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.table91"}
I230410 16:10:36.137041 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 852 ={"Timestamp":1681143036121672407,"EventType":"create_table","Statement":"CREATE TABLE d.public.table92 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.table92"}
I230410 16:10:36.153066 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 853 ={"Timestamp":1681143036144446132,"EventType":"create_table","Statement":"CREATE TABLE d.public.table93 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.table93"}
I230410 16:10:36.169183 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 854 ={"Timestamp":1681143036159826255,"EventType":"create_table","Statement":"CREATE TABLE d.public.table94 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.table94"}
I230410 16:10:36.208024 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 855 ={"Timestamp":1681143036175701406,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t'abl%46e95\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.\"t'abl%46e95\""}
I230410 16:10:36.246062 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 856 ={"Timestamp":1681143036232616017,"EventType":"create_table","Statement":"CREATE TABLE d.public.tab😴le96 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.tab😴le96"}
I230410 16:10:36.269850 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 857 ={"Timestamp":1681143036255068579,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"\\\\xb5tabl'e97\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.\"\\\\xb5tabl'e97\""}
I230410 16:10:36.313261 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 858 ={"Timestamp":1681143036305020149,"EventType":"create_table","Statement":"CREATE TABLE d.public.table98 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.table98"}
I230410 16:10:36.360859 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 859 ={"Timestamp":1681143036334000072,"EventType":"create_table","Statement":"CREATE TABLE d.public.table99 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.table99"}
I230410 16:10:36.388389 124004 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 860 ={"Timestamp":1681143036378949856,"EventType":"create_table","Statement":"CREATE TABLE d.public.table100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.table100"}
I230410 16:10:36.402370 108362 ccl/changefeedccl/testfeed_test.go:795  [-] 861  Starting feed job: "CREATE CHANGEFEED FOR TABLE table1, TABLE \"t'able2\", TABLE table3, TABLE \"tabl|e4\", TABLE table5, TABLE table6, TABLE \" table7\", TABLE table8, TABLE table9, TABLE \"table%v10\", TABLE \"😊t%0dable11\", TABLE table12, TABLE table13, TABLE table14, TABLE \"\fta'b%le\f15\", TABLE \"tabl\re16\", TABLE table17, TABLE table18, TABLE table19, TABLE \"table\n20\", TABLE \"t\\\\uB459\nable21\", TABLE table22, TABLE table23, TABLE t͡able24, TABLE \"tabl\\\\xd0e25\", TABLE \"tab\\\\u269D\vle26\", TABLE \"table\n27\", TABLE tabl🙁e28, TABLE \"t%qable29\", TABLE \"tab%qle30\", TABLE table̸31, TABLE table32, TABLE table33, TABLE \"tabl%ve34\", TABLE \"\\\\U000AFBC3table35\", TABLE \"table%q36\", TABLE table37, TABLE \"tab%p\\\\xa9le38\", TABLE tͫable39, TABLE table40, TABLE table41, TABLE \"t able42\", TABLE tabl😪e43, TABLE table44, TABLE table45, TABLE table46, TABLE \"tab'le\"\" 47\", TABLE \"tablE48\", TABLE table49, TABLE \"table\\g50\", TABLE table51, TABLE table52, TABLE \"t%pable53\", TABLE \"tabl\\ne54\", TABLE \"ta'ble🙁55\", TABLE table56, TABLE table57, TABLE \"ta%vble58\", TABLE \"\ntable59\", TABLE table60, TABLE table61, TABLE \"ta-ble62\", TABLE \"tabL%b1e63\", TABLE table64, TABLE \"tab\nl͈e65\", TABLE \"taBl\\ge66\", TABLE table67, TABLE table68, TABLE \"\ttable69\", TABLE table70, TABLE table71, TABLE table72, TABLE table73, TABLE \"\rtable74\", TABLE \"table%v75\", TABLE \"t%pable76\", TABLE table77, TABLE table78, TABLE \"table 79\", TABLE table😆80, TABLE \"tabl\te81\", TABLE table82, TABLE table83, TABLE table84, TABLE table85, TABLE \"tabLe 86\", TABLE table87, TABLE table88, TABLE table89, TABLE table90, TABLE table91, TABLE table92, TABLE table93, TABLE table94, TABLE \"t'abl%46e95\", TABLE tab😴le96, TABLE \"\\\\xb5tabl'e97\", TABLE table98, TABLE table99, TABLE table100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 16:10:36.403018 124004 sql/schemachanger/scbuild/build.go:45  [T10,nsql1,client=127.0.0.1:33280,user=root] 862  building declarative schema change targets for CREATE CHANGEFEED
I230410 16:10:36.403528 130756 1@ccl/changefeedccl/changefeed_stmt.go:965  [T10,nsql1,client=127.0.0.1:33280,user=root] 863  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 16:10:36.426334 130756 12@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33280,user=root] 864 ={"Timestamp":1681143036426327746,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:8465: 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 16:10:36.427982 120488 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:37441,class=rangefeed,rpc] 865  connection heartbeat loop ended with err: <nil>
I230410 16:10:36.428011 120142 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:37441,class=default,rpc] 867  connection heartbeat loop ended with err: <nil>
I230410 16:10:36.428015 120232 rpc/context.go:2302  [T10,nsql1,rnode=63,raddr=127.0.0.1:37441,class=system,rpc] 866  connection heartbeat loop ended with err: <nil>
I230410 16:10:36.428030 120522 sql/stats/automatic_stats.go:550  [T10,nsql1] 868  quiescing auto stats refresher
W230410 16:10:36.428126 120446 sql/sqlliveness/slinstance/slinstance.go:334  [T10,nsql1] 869  exiting heartbeat loop
W230410 16:10:36.428164 120446 sql/sqlliveness/slinstance/slinstance.go:321  [T10,nsql1] 870  exiting heartbeat loop with error: node unavailable; try another peer
W230410 16:10:36.428159 120230 ccl/kvccl/kvtenantccl/setting_overrides.go:46  [T10,nsql1,tenant-connector] 871  error consuming TenantSettings RPC: recv msg error: grpc: error reading from server: read tcp 127.0.0.1:47878->127.0.0.1:37441: use of closed network connection [code 14/Unavailable]
I230410 16:10:36.428227 120225 server/start_listen.go:103  [T10,nsql1] 872  server shutting down: instructing cmux to stop accepting
I230410 16:10:36.428227 120969 jobs/registry.go:1538  [T10,nsql1] 873  AUTO SPAN CONFIG RECONCILIATION job 855482799741403137: stepping through state succeeded
W230410 16:10:36.428234 120229 ccl/kvccl/kvtenantccl/connector.go:249  [T10,nsql1,tenant-connector] 874  error consuming GossipSubscription RPC: recv msg error: grpc: error reading from server: read tcp 127.0.0.1:47878->127.0.0.1:37441: use of closed network connection [code 14/Unavailable]
E230410 16:10:36.428283 123618 jobs/registry.go:943  [-] 875  error getting live session: node unavailable; try another peer
W230410 16:10:36.428393 123129 jobs/adopt.go:518  [-] 876  could not clear job claim: clear-job-claim: node unavailable; try another peer
E230410 16:10:36.431470 120476 jobs/registry.go:1015  [T10,nsql1] 877  error claiming jobs: could not query jobs table: claim-jobs: failed to read query result: query execution canceled
W230410 16:10:36.434145 108362 server/server_sql.go:1676  [T10,nsql1] 878  server shutdown without a prior graceful drain
I230410 16:10:36.434527 117377 sql/stats/automatic_stats.go:550  [T1,n1] 879  quiescing auto stats refresher
W230410 16:10:36.434557 116587 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 880  exiting heartbeat loop
W230410 16:10:36.434586 116587 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 881  exiting heartbeat loop with error: node unavailable; try another peer
E230410 16:10:36.434608 116587 server/server_sql.go:507  [T1,n1] 882  failed to run update of instance with new session ID: node unavailable; try another peer
I230410 16:10:36.434760 118610 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:37441,class=default,rpc] 883  connection heartbeat loop ended with err: <nil>
W230410 16:10:36.434884 129089 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 884  failed to gc transaction record: could not GC completed transaction anchored at /Local/Range/Tenant/10/RangeDescriptor: node unavailable; try another peer
E230410 16:10:36.435193 118506 jobs/registry.go:943  [T1,n1] 885  error getting live session: node unavailable; try another peer
I230410 16:10:36.435221 118803 jobs/registry.go:1538  [T1,n1] 886  KEY VISUALIZER job 100: stepping through state succeeded
I230410 16:10:36.435313 117012 server/start_listen.go:103  [T1,n1] 887  server shutting down: instructing cmux to stop accepting
I230410 16:10:36.435617 117687 jobs/registry.go:1538  [T1,n1] 888  AUTO SPAN CONFIG RECONCILIATION job 855482789821808641: stepping through state succeeded
W230410 16:10:36.440206 108362 server/server_sql.go:1676  [T1,n1] 889  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (7.83s)
Help

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

ccl/changefeedccl.TestChangefeedTopicNames failed with artifacts on release-23.1 @ fbc5d56e5998990d3be5860e0263e781890f89e1:

I230410 16:13:00.759461 119530 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r84/1:/{Table/127-Max}] 884  initiating a split of this range at key /Table/128 [r85] (span config)
I230410 16:13:00.767968 119457 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r85/1:/{Table/128-Max}] 885  initiating a split of this range at key /Table/129 [r86] (span config)
I230410 16:13:00.770812 116131 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:55614,user=root] 886 ={"Timestamp":1681143180761391695,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tab%vle92\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.\"tab%vle92\""}
I230410 16:13:00.780345 119579 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r86/1:/{Table/129-Max}] 887  initiating a split of this range at key /Table/130 [r87] (span config)
I230410 16:13:00.799815 119592 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r87/1:/{Table/130-Max}] 888  initiating a split of this range at key /Table/131 [r88] (span config)
I230410 16:13:00.812954 119606 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r88/1:/{Table/131-Max}] 889  initiating a split of this range at key /Table/132 [r89] (span config)
I230410 16:13:00.822389 113607 3@pebble/event.go:734  [n1,s1,pebble] 890  [JOB 8] WAL created 000007
I230410 16:13:00.837971 119647 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r89/1:/{Table/132-Max}] 891  initiating a split of this range at key /Table/133 [r90] (span config)
I230410 16:13:00.842607 116131 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:55614,user=root] 892 ={"Timestamp":1681143180818734322,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t\"\"abl%qe93\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.\"t\"\"abl%qe93\""}
I230410 16:13:00.845403 119615 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r90/1:/{Table/133-Max}] 893  initiating a split of this range at key /Table/134 [r91] (span config)
I230410 16:13:00.854510 119684 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r91/1:/{Table/134-Max}] 894  initiating a split of this range at key /Table/135 [r92] (span config)
I230410 16:13:00.863864 116131 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:55614,user=root] 895 ={"Timestamp":1681143180859905147,"EventType":"create_table","Statement":"CREATE TABLE d.public.table94 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.table94"}
I230410 16:13:00.866033 119716 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r92/1:/{Table/135-Max}] 896  initiating a split of this range at key /Table/136 [r93] (span config)
I230410 16:13:00.875197 119746 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r93/1:/{Table/136-Max}] 897  initiating a split of this range at key /Table/137 [r94] (span config)
I230410 16:13:00.885337 119775 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r94/1:/{Table/137-Max}] 898  initiating a split of this range at key /Table/138 [r95] (span config)
I230410 16:13:00.893049 116131 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:55614,user=root] 899 ={"Timestamp":1681143180889293677,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta)ble95\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.\"ta)ble95\""}
I230410 16:13:00.903333 119815 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r95/1:/{Table/138-Max}] 900  initiating a split of this range at key /Table/139 [r96] (span config)
I230410 16:13:00.911574 119835 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r96/1:/{Table/139-Max}] 901  initiating a split of this range at key /Table/140 [r97] (span config)
I230410 16:13:00.916757 116131 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:55614,user=root] 902 ={"Timestamp":1681143180913172759,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tAble96\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.\"tAble96\""}
I230410 16:13:00.919942 119866 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r97/1:/{Table/140-Max}] 903  initiating a split of this range at key /Table/141 [r98] (span config)
I230410 16:13:00.930852 119727 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r98/1:/{Table/141-Max}] 904  initiating a split of this range at key /Table/142 [r99] (span config)
I230410 16:13:00.937573 116131 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:55614,user=root] 905 ={"Timestamp":1681143180933370174,"EventType":"create_table","Statement":"CREATE TABLE d.public.table97 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.table97"}
I230410 16:13:00.953131 119948 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r99/1:/{Table/142-Max}] 906  initiating a split of this range at key /Table/143 [r100] (span config)
I230410 16:13:00.960616 119957 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r100/1:/{Table/143-Max}] 907  initiating a split of this range at key /Table/144 [r101] (span config)
I230410 16:13:00.960737 116131 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:55614,user=root] 908 ={"Timestamp":1681143180956976019,"EventType":"create_table","Statement":"CREATE TABLE d.public.😧table98 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.😧table98"}
I230410 16:13:00.969612 120009 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r101/1:/{Table/144-Max}] 909  initiating a split of this range at key /Table/145 [r102] (span config)
I230410 16:13:00.977405 120024 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r102/1:/{Table/145-Max}] 910  initiating a split of this range at key /Table/146 [r103] (span config)
I230410 16:13:00.990321 116131 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:55614,user=root] 911 ={"Timestamp":1681143180980465574,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t😌ab le99\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.\"t😌ab le99\""}
I230410 16:13:00.997837 120048 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r103/1:/{Table/146-Max}] 912  initiating a split of this range at key /Table/147 [r104] (span config)
I230410 16:13:01.044246 116131 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:55614,user=root] 913 ={"Timestamp":1681143181029362591,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tab le100\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.\"tab le100\""}
I230410 16:13:01.083460 112719 ccl/changefeedccl/testfeed_test.go:795  [-] 914  Starting feed job: "CREATE CHANGEFEED FOR TABLE table1, TABLE table2, TABLE table3, TABLE table4, TABLE \"\\\\u5684table5\", TABLE \"ta̝\vble6\", TABLE \"ta\"\"ble7\", TABLE \"table\\\\x228\", TABLE \" t\\\\x62aBle\\n9\", TABLE table10, TABLE table11, TABLE \"tabl\"\"e12\", TABLE \"tab\\gle13\", TABLE ṫable14, TABLE \"tab\\\\x9fle15\", TABLE \"ta|ble16\", TABLE \"tablE17\", TABLE \"tabl\\\\x0be\\v18\", TABLE table19, TABLE table20, TABLE 😝tabl😅e21, TABLE \"ta%28ble22\", TABLE table23, TABLE \"tab le24\", TABLE table25, TABLE \"tabl\"\"e26\", TABLE \"tab̴l%ve27\", TABLE table28, TABLE table_29, TABLE \"table\\\\U0002B82E30\", TABLE \" table31\", TABLE \"t able32\", TABLE \"table%f633\", TABLE \"ta\rble34\", TABLE \" TaBle'35\", TABLE \"ta ble36\", TABLE \"t\tabLe37\", TABLE \"tablE%9238\", TABLE table39, TABLE table40, TABLE table41, TABLE table42, TABLE table43, TABLE \"tab\\fle{44\", TABLE \"t(able45\", TABLE table46, TABLE \"Table47\", TABLE table48, TABLE tabl͙e49, TABLE \"t able50\", TABLE table51, TABLE table52, TABLE table53, TABLE \"t\nable54\", TABLE table55, TABLE \"tabl'e56\", TABLE tab😁le57, TABLE table58, TABLE 😚table59, TABLE table60, TABLE table61, TABLE \"t\\gable62\", TABLE table63, TABLE tab́le64, TABLE \"\\rtabl'e65\", TABLE table66, TABLE \"tabl\ne67\", TABLE table68, TABLE \"tablE69\", TABLE \"tab\\\\U000F4452🙁le70\", TABLE \"tabl e71\", TABLE table72, TABLE table73, TABLE \"tabLe74\", TABLE \"tablE75\", TABLE \"ta%5dble76\", TABLE table77, TABLE \"ta\"\"ble78\", TABLE table79, TABLE \"t abl%qe'80\", TABLE table😅81, TABLE \"table%q82\", TABLE \"ta(ble83\", TABLE table84, TABLE \"\\ftable85\", TABLE table86, TABLE table87, TABLE \"T😲able88\", TABLE table89, TABLE table90, TABLE \"ta\"\"ble91\", TABLE \"tab%vle92\", TABLE \"t\"\"abl%qe93\", TABLE table94, TABLE \"ta)ble95\", TABLE \"tAble96\", TABLE table97, TABLE 😧table98, TABLE \"t😌ab le99\", TABLE \"tab le100\" INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 16:13:01.084178 116131 sql/schemachanger/scbuild/build.go:45  [T1,n1,client=127.0.0.1:55614,user=root] 915  building declarative schema change targets for CREATE CHANGEFEED
I230410 16:13:01.084664 120136 1@ccl/changefeedccl/changefeed_stmt.go:965  [T1,n1,client=127.0.0.1:55614,user=root] 916  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 16:13:01.114814 120136 12@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:55614,user=root] 917 ={"Timestamp":1681143181114808172,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:8465: 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 16:13:01.116546 113942 sql/stats/automatic_stats.go:550  [T1,n1] 918  quiescing auto stats refresher
W230410 16:13:01.116589 120038 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 919  failed to gc transaction record: could not GC completed transaction anchored at /Local/Range/Table/144/RangeDescriptor: node unavailable; try another peer
I230410 16:13:01.116703 113558 server/start_listen.go:103  [T1,n1] 920  server shutting down: instructing cmux to stop accepting
I230410 16:13:01.117374 114804 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:35747,class=default,rpc] 921  connection heartbeat loop ended with err: <nil>
W230410 16:13:01.117577 113906 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 922  exiting heartbeat loop
W230410 16:13:01.117598 113906 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 923  exiting heartbeat loop with error: node unavailable; try another peer
E230410 16:13:01.117619 113906 server/server_sql.go:507  [T1,n1] 924  failed to run update of instance with new session ID: node unavailable; try another peer
E230410 16:13:01.117815 113950 jobs/registry.go:1015  [T1,n1] 925  error claiming jobs: could not query jobs table: claim-jobs: failed to read query result: query execution canceled
I230410 16:13:01.117959 114195 jobs/registry.go:1538  [T1,n1] 926  AUTO SPAN CONFIG RECONCILIATION job 855483270579650561: stepping through state succeeded
E230410 16:13:01.118037 114195 jobs/registry.go:943  [T1,n1] 927  error getting live session: node unavailable; try another peer
I230410 16:13:01.118108 115364 jobs/registry.go:1538  [T1,n1] 928  KEY VISUALIZER job 100: stepping through state succeeded
W230410 16:13:01.122475 115734 jobs/adopt.go:518  [T1,n1] 929  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: 1fe2e1b9], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 16:13:01.124658 115466 jobs/adopt.go:518  [T1,n1] 930  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 16:13:01.127664 112719 server/server_sql.go:1676  [T1,n1] 931  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (5.91s)
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
@cockroach-teamcity
Copy link
Member Author

ccl/changefeedccl.TestChangefeedTopicNames failed with artifacts on release-23.1 @ f0779e9002757c07fe549f55509224d93e6f2a32:

I230410 18:08:51.459513 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1024 ={"Timestamp":1681150131424410132,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"'%ptable\r86\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":191,"TableName":"d.public.\"'%ptable\r86\""}
I230410 18:08:51.503340 134728 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r60/1:/Table/{59-60}] 1025  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 18:08:51.558809 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1026 ={"Timestamp":1681150131497583525,"EventType":"create_table","Statement":"CREATE TABLE d.public.table87 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":192,"TableName":"d.public.table87"}
I230410 18:08:51.608754 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1027 ={"Timestamp":1681150131581032562,"EventType":"create_table","Statement":"CREATE TABLE d.public.table88 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.table88"}
I230410 18:08:51.673804 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1028 ={"Timestamp":1681150131665344715,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t\\gab͕l\ne\u000c89\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.\"t\\gab͕l\ne\u000c89\""}
I230410 18:08:51.710761 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1029 ={"Timestamp":1681150131693056809,"EventType":"create_table","Statement":"CREATE TABLE d.public.table90 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.table90"}
I230410 18:08:51.771867 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1030 ={"Timestamp":1681150131744470486,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"table 91\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.\"table 91\""}
I230410 18:08:51.825537 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1031 ={"Timestamp":1681150131787048567,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"table 92\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.\"table 92\""}
I230410 18:08:51.893241 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1032 ={"Timestamp":1681150131857871143,"EventType":"create_table","Statement":"CREATE TABLE d.public.table93 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.table93"}
I230410 18:08:51.923381 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1033 ={"Timestamp":1681150131908675408,"EventType":"create_table","Statement":"CREATE TABLE d.public.table94 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.table94"}
I230410 18:08:51.973380 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1034 ={"Timestamp":1681150131958570115,"EventType":"create_table","Statement":"CREATE TABLE d.public.\" tab😾le95\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.\" tab😾le95\""}
I230410 18:08:52.024356 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1035 ={"Timestamp":1681150132003292717,"EventType":"create_table","Statement":"CREATE TABLE d.public.t😿able96 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.t😿able96"}
I230410 18:08:52.052057 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1036 ={"Timestamp":1681150132034113731,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"taBle97\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.\"taBle97\""}
I230410 18:08:52.080973 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1037 ={"Timestamp":1681150132063719218,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"table\"\"98\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.\"table\"\"98\""}
I230410 18:08:52.133221 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1038 ={"Timestamp":1681150132095866361,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"table%q99\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.\"table%q99\""}
I230410 18:08:52.199298 127684 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1039 ={"Timestamp":1681150132182613498,"EventType":"create_table","Statement":"CREATE TABLE d.public.table100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.table100"}
I230410 18:08:52.236499 120095 ccl/changefeedccl/testfeed_test.go:795  [-] 1040  Starting feed job: "CREATE CHANGEFEED FOR TABLE table1, TABLE table2, TABLE table3, TABLE table4, TABLE \"tAble5\", TABLE \"t}😴able6\", TABLE table7, TABLE table8, TABLE table9, TABLE \"tabl\re10\", TABLE table11, TABLE tabl̀e12, TABLE table13, TABLE table14, TABLE \"%ptable15\", TABLE table16, TABLE table17, TABLE \"tabl e͌18\", TABLE \"taBle19\", TABLE table20, TABLE table21, TABLE \"t\"\"abl\\ne'22\", TABLE table23, TABLE \"Table24\", TABLE t😹able25, TABLE \"(tabl e26\", TABLE table27, TABLE table28, TABLE table29, TABLE tabl😘e30, TABLE \"ta(bl'e31\", TABLE table32, TABLE table33, TABLE table34, TABLE \"tab'%ple35\", TABLE \"tA ble36\", TABLE \"%qtable\\n37\", TABLE 😨table38, TABLE table39, TABLE \"tabl\"\"e40\", TABLE table41, TABLE table42, TABLE \"tab\"\"le43\", TABLE table44, TABLE \"tablE45\", TABLE table46, TABLE \"table\"\"47\", TABLE table48, TABLE table49, TABLE \"tAble50\", TABLE \"ta ble51\", TABLE table52, TABLE table53, TABLE table54, TABLE \"ta_bl%pe55\", TABLE table56, TABLE table57, TABLE \"t\fa%qbl/e58\", TABLE table59, TABLE table60, TABLE \"ta\"\"ble61\", TABLE \"ta\\\\U0002DBC3bl😢e62\", TABLE \"table\\\\uD81663\", TABLE table64, TABLE \"\ttable65\", TABLE table66, TABLE table67, TABLE table68, TABLE \"t\"\"ab̷ le69\", TABLE table70, TABLE \"Table71\", TABLE table72, TABLE \"tabl\ne73\", TABLE table74, TABLE \"tabl\"\"e75\", TABLE table76, TABLE table77, TABLE table78, TABLE table79, TABLE table80, TABLE \"table%q81\", TABLE \"tAble82\", TABLE table83, TABLE table84, TABLE table85, TABLE \"'%ptable\r86\", TABLE table87, TABLE table88, TABLE \"t\\gab͕l\ne\f89\", TABLE table90, TABLE \"table 91\", TABLE \"table 92\", TABLE table93, TABLE table94, TABLE \" tab😾le95\", TABLE t😿able96, TABLE \"taBle97\", TABLE \"table\"\"98\", TABLE \"table%q99\", TABLE table100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
    changefeed_test.go:8465: 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 18:08:52.237276 127684 sql/schemachanger/scbuild/build.go:45  [T10,nsql1,client=127.0.0.1:44510,user=root] 1041  building declarative schema change targets for CREATE CHANGEFEED
I230410 18:08:52.237766 135899 1@ccl/changefeedccl/changefeed_stmt.go:965  [T10,nsql1,client=127.0.0.1:44510,user=root] 1042  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 18:08:52.276640 135899 12@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:44510,user=root] 1043 ={"Timestamp":1681150132276633490,"EventType":"changefeed_failed","FailureType":"user_input"}
I230410 18:08:52.280692 123992 sql/stats/automatic_stats.go:550  [T10,nsql1] 1044  quiescing auto stats refresher
W230410 18:08:52.281163 123904 sql/sqlliveness/slinstance/slinstance.go:334  [T10,nsql1] 1045  exiting heartbeat loop
W230410 18:08:52.281195 123904 sql/sqlliveness/slinstance/slinstance.go:321  [T10,nsql1] 1046  exiting heartbeat loop with error: node unavailable; try another peer
W230410 18:08:52.281340 123846 ccl/kvccl/kvtenantccl/connector.go:249  [T10,nsql1,tenant-connector] 1047  error consuming GossipSubscription RPC: recv msg error: grpc: context canceled [code 1/Canceled]
W230410 18:08:52.281427 127065 jobs/adopt.go:518  [-] 1048  could not clear job claim: clear-job-claim: node unavailable; try another peer
E230410 18:08:52.281498 124000 jobs/registry.go:1055  [T10,nsql1] 1049  error processing claimed jobs: could not query for claimed jobs: select-running/get-claimed-jobs: failed to read query result: query execution canceled
I230410 18:08:52.281589 123842 server/start_listen.go:103  [T10,nsql1] 1050  server shutting down: instructing cmux to stop accepting
E230410 18:08:52.281931 126786 jobs/registry.go:943  [-] 1051  error getting live session: node unavailable; try another peer
I230410 18:08:52.281997 124317 jobs/registry.go:1538  [T10,nsql1] 1052  AUTO SPAN CONFIG RECONCILIATION job 855506039361011713: stepping through state succeeded
E230410 18:08:52.283071 123998 jobs/registry.go:987  [T10,nsql1] 1053  error expiring job sessions: expire-sessions: failed to read query result: query execution canceled
E230410 18:08:52.283150 123998 jobs/registry.go:995  [T10,nsql1] 1054  failed to serve pause and cancel requests: txn exec: context canceled
W230410 18:08:52.283337 123847 ccl/kvccl/kvtenantccl/setting_overrides.go:46  [T10,nsql1,tenant-connector] 1055  error consuming TenantSettings RPC: recv msg error: grpc: context canceled [code 1/Canceled]
I230410 18:08:52.283723 123849 rpc/context.go:2302  [T10,nsql1,rnode=63,raddr=127.0.0.1:33979,class=system,rpc] 1056  connection heartbeat loop ended with err: <nil>
I230410 18:08:52.283776 123911 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:33979,class=default,rpc] 1057  connection heartbeat loop ended with err: <nil>
W230410 18:08:52.291420 120095 server/server_sql.go:1676  [T10,nsql1] 1058  server shutdown without a prior graceful drain
I230410 18:08:52.291872 120891 sql/stats/automatic_stats.go:550  [T1,n1] 1059  quiescing auto stats refresher
I230410 18:08:52.292814 121126 jobs/registry.go:1538  [T1,n1] 1060  AUTO SPAN CONFIG RECONCILIATION job 855506028087836673: stepping through state succeeded
I230410 18:08:52.296474 122264 jobs/registry.go:1538  [T1,n1] 1061  KEY VISUALIZER job 100: stepping through state succeeded
W230410 18:08:52.296760 122604 jobs/adopt.go:518  [T1,n1] 1062  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: 779aff6a], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 18:08:52.302830 122457 jobs/adopt.go:518  [T1,n1] 1063  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 18:08:52.302897 120871 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 1064  exiting heartbeat loop
W230410 18:08:52.302913 120871 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 1065  exiting heartbeat loop with error: node unavailable; try another peer
E230410 18:08:52.302933 120871 server/server_sql.go:507  [T1,n1] 1066  failed to run update of instance with new session ID: node unavailable; try another peer
I230410 18:08:52.303209 122025 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:33979,class=default,rpc] 1067  connection heartbeat loop ended with err: <nil>
W230410 18:08:52.303435 122264 jobs/adopt.go:518  [T1,n1] 1068  could not clear job claim: clear-job-claim: node unavailable; try another peer
I230410 18:08:52.303633 120508 server/start_listen.go:103  [T1,n1] 1069  server shutting down: instructing cmux to stop accepting
W230410 18:08:52.308679 121126 jobs/adopt.go:518  [T1,n1] 1070  could not clear job claim: clear-job-claim: failed to send RPC: sending to all replicas failed; last error: ba: Scan [/Table/15/1/855506028087836673,/Table/15/1/855506028087836674), [txn: 7521be27], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 18:08:52.309357 120095 server/server_sql.go:1676  [T1,n1] 1071  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (12.15s)
Help

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

ccl/changefeedccl.TestChangefeedTopicNames failed with artifacts on release-23.1 @ 5df8416c2420ff701f637508db991431ecea22f6:

I230410 18:18:46.938364 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1030 ={"Timestamp":1681150726920876102,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"%qta%qb le88\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.\"%qta%qb le88\""}
I230410 18:18:46.993937 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1031 ={"Timestamp":1681150726976529641,"EventType":"create_table","Statement":"CREATE TABLE d.public.table89 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.table89"}
I230410 18:18:47.045932 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1032 ={"Timestamp":1681150727009233997,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabLe90\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.\"tabLe90\""}
I230410 18:18:47.083728 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1033 ={"Timestamp":1681150727069154292,"EventType":"create_table","Statement":"CREATE TABLE d.public.\" table91\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.\" table91\""}
I230410 18:18:47.118788 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1034 ={"Timestamp":1681150727092498452,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta'ble92\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.\"ta'ble92\""}
I230410 18:18:47.172020 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1035 ={"Timestamp":1681150727134938927,"EventType":"create_table","Statement":"CREATE TABLE d.public.table93 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.table93"}
I230410 18:18:47.266618 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1036 ={"Timestamp":1681150727229062685,"EventType":"create_table","Statement":"CREATE TABLE d.public.table94 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.table94"}
I230410 18:18:47.269701 157241 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r40/1:/Table/3{8-9}] 1037  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 18:18:47.296973 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1038 ={"Timestamp":1681150727278168673,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tabl%ve95\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.\"tabl%ve95\""}
I230410 18:18:47.342552 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1039 ={"Timestamp":1681150727306147906,"EventType":"create_table","Statement":"CREATE TABLE d.public.table96 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.table96"}
I230410 18:18:47.422385 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1040 ={"Timestamp":1681150727399969413,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"tab'le97\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.\"tab'le97\""}
I230410 18:18:47.544438 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1041 ={"Timestamp":1681150727521578938,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta Bl\re98\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.\"ta Bl\re98\""}
I230410 18:18:47.577248 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1042 ={"Timestamp":1681150727560587816,"EventType":"create_table","Statement":"CREATE TABLE d.public.table99 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.table99"}
I230410 18:18:47.622321 149753 5@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1043 ={"Timestamp":1681150727607733081,"EventType":"create_table","Statement":"CREATE TABLE d.public.table100 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.table100"}
I230410 18:18:47.648301 142456 ccl/changefeedccl/testfeed_test.go:795  [-] 1044  Starting feed job: "CREATE CHANGEFEED FOR TABLE \" table1\", TABLE table2, TABLE \"tabl\"\"e3\", TABLE table4, TABLE table̓5, TABLE \"tabl(e̊6\", TABLE tabl̀e7, TABLE table8, TABLE t͔able9, TABLE table10, TABLE table11, TABLE \"ta'ble12\", TABLE \"\\gtable13\", TABLE \"ta'b\rle14\", TABLE table15, TABLE table16, TABLE \"table%v17\", TABLE \" ta😟ble18\", TABLE table19, TABLE tabͬle20, TABLE table21, TABLE \"ta Ble22\", TABLE table23, TABLE table24, TABLE \"table 25\", TABLE table26, TABLE table27, TABLE \"\ntable28\", TABLE table29, TABLE table30, TABLE ta͏ble31, TABLE \"ta%b\nle32\", TABLE table33, TABLE \"tab%ple34\", TABLE \"'table35\", TABLE table36, TABLE \"tab\\rle37\", TABLE tab_le38, TABLE \".ta̷ble39\", TABLE table40, TABLE table41, TABLE \" table42\", TABLE \"t\vab)le43\", TABLE \"tab/le44\", TABLE \"ta{b le45\", TABLE \"tab\\\\U000736E7le46\", TABLE table47, TABLE \"tab%ple48\", TABLE \"tab!le\\\\uDE2C49\", TABLE \"ta\rble50\", TABLE \"t😦Able|51\", TABLE table52, TABLE table53, TABLE \"tablE54\", TABLE \"ta blE55\", TABLE \"-tabLe 56\", TABLE table57, TABLE \"tabl%ve58\", TABLE \" table59\", TABLE table60, TABLE \" table61\", TABLE table62, TABLE \"tabl😉e\"\"63\", TABLE table64, TABLE tableͨ65, TABLE \"t?able66\", TABLE \"|tabl\re67\", TABLE table68, TABLE table69, TABLE table70, TABLE table71, TABLE \"tab\nle72\", TABLE table73, TABLE table74, TABLE \"\\ntable75\", TABLE \"t(able76\", TABLE \"tabl\\ge77\", TABLE table78, TABLE \"ta\\\\U000A86B0ble79\", TABLE \"tab\rle80\", TABLE tabl😎e81, TABLE \"tAble 82\", TABLE table83, TABLE \"T\rable84\", TABLE table85, TABLE table86, TABLE ẗable87, TABLE \"%qta%qb le88\", TABLE table89, TABLE \"tabLe90\", TABLE \" table91\", TABLE \"ta'ble92\", TABLE table93, TABLE table94, TABLE \"tabl%ve95\", TABLE table96, TABLE \"tab'le97\", TABLE \"ta Bl\re98\", TABLE table99, TABLE table100 INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 18:18:47.648997 149753 sql/schemachanger/scbuild/build.go:45  [T10,nsql1,client=127.0.0.1:33788,user=root] 1045  building declarative schema change targets for CREATE CHANGEFEED
I230410 18:18:47.649562 157864 1@ccl/changefeedccl/changefeed_stmt.go:965  [T10,nsql1,client=127.0.0.1:33788,user=root] 1046  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 18:18:47.688845 157864 12@util/log/event_log.go:32  [T10,nsql1,client=127.0.0.1:33788,user=root] 1047 ={"Timestamp":1681150727688840217,"EventType":"changefeed_failed","FailureType":"user_input"}
    changefeed_test.go:8465: 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 18:18:47.690558 146317 sql/stats/automatic_stats.go:550  [T10,nsql1] 1048  quiescing auto stats refresher
W230410 18:18:47.691564 146058 ccl/kvccl/kvtenantccl/connector.go:249  [T10,nsql1,tenant-connector] 1049  error consuming GossipSubscription RPC: recv msg error: grpc: context canceled [code 1/Canceled]
I230410 18:18:47.691832 146054 server/start_listen.go:103  [T10,nsql1] 1050  server shutting down: instructing cmux to stop accepting
E230410 18:18:47.691968 146323 jobs/registry.go:995  [T10,nsql1] 1051  failed to serve pause and cancel requests: could not query jobs table: cancel/pause-requested: failed to read query result: query execution canceled
E230410 18:18:47.692640 146325 jobs/registry.go:1015  [T10,nsql1] 1052  error claiming jobs: could not query jobs table: claim-jobs: failed to read query result: query execution canceled
E230410 18:18:47.693144 146325 jobs/registry.go:1055  [T10,nsql1] 1053  error processing claimed jobs: could not query for claimed jobs: select-running/get-claimed-jobs: failed to read query result: query execution canceled
W230410 18:18:47.693306 146267 sql/sqlliveness/slinstance/slinstance.go:334  [T10,nsql1] 1054  exiting heartbeat loop
W230410 18:18:47.693342 146267 sql/sqlliveness/slinstance/slinstance.go:321  [T10,nsql1] 1055  exiting heartbeat loop with error: node unavailable; try another peer
W230410 18:18:47.693395 146059 ccl/kvccl/kvtenantccl/setting_overrides.go:46  [T10,nsql1,tenant-connector] 1056  error consuming TenantSettings RPC: recv msg error: grpc: context canceled [code 1/Canceled]
I230410 18:18:47.693842 146604 jobs/registry.go:1538  [T10,nsql1] 1057  AUTO SPAN CONFIG RECONCILIATION job 855507992962367489: stepping through state succeeded
E230410 18:18:47.693949 146604 jobs/registry.go:943  [-] 1058  error getting live session: node unavailable; try another peer
I230410 18:18:47.694147 145889 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:44203,class=rangefeed,rpc] 1059  connection heartbeat loop ended with err: <nil>
I230410 18:18:47.694224 146061 rpc/context.go:2302  [T10,nsql1,rnode=63,raddr=127.0.0.1:44203,class=system,rpc] 1060  connection heartbeat loop ended with err: <nil>
I230410 18:18:47.694295 146242 rpc/context.go:2302  [T10,nsql1,rnode=1,raddr=127.0.0.1:44203,class=default,rpc] 1061  connection heartbeat loop ended with err: <nil>
W230410 18:18:47.697213 148963 jobs/adopt.go:518  [-] 1062  could not clear job claim: clear-job-claim: tenant-side-limiter pool closed: shutting down
W230410 18:18:47.699828 149359 jobs/adopt.go:518  [-] 1063  could not clear job claim: clear-job-claim: tenant-side-limiter pool closed: shutting down
W230410 18:18:47.702309 142456 server/server_sql.go:1676  [T10,nsql1] 1064  server shutdown without a prior graceful drain
I230410 18:18:47.702652 143099 sql/stats/automatic_stats.go:550  [T1,n1] 1065  quiescing auto stats refresher
I230410 18:18:47.708089 144591 jobs/registry.go:1538  [T1,n1] 1066  KEY VISUALIZER job 100: stepping through state succeeded
W230410 18:18:47.712500 144591 jobs/adopt.go:518  [T1,n1] 1067  could not clear job claim: clear-job-claim: node unavailable; try another peer
I230410 18:18:47.712834 142734 server/start_listen.go:103  [T1,n1] 1068  server shutting down: instructing cmux to stop accepting
I230410 18:18:47.714017 143258 jobs/registry.go:1538  [T1,n1] 1069  AUTO SPAN CONFIG RECONCILIATION job 855507980365692929: stepping through state succeeded
W230410 18:18:47.715650 143079 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 1070  exiting heartbeat loop
W230410 18:18:47.715701 143079 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 1071  exiting heartbeat loop with error: node unavailable; try another peer
E230410 18:18:47.715730 143079 server/server_sql.go:507  [T1,n1] 1072  failed to run update of instance with new session ID: node unavailable; try another peer
E230410 18:18:47.716696 144209 jobs/registry.go:943  [T1,n1] 1073  error getting live session: node unavailable; try another peer
I230410 18:18:47.716902 143953 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:44203,class=default,rpc] 1074  connection heartbeat loop ended with err: <nil>
W230410 18:18:47.716963 144952 jobs/adopt.go:518  [T1,n1] 1075  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: 49a2f7b8], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 18:18:47.720541 143258 jobs/adopt.go:518  [T1,n1] 1076  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 18:18:47.738547 142456 server/server_sql.go:1676  [T1,n1] 1077  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (11.66s)
Help

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

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

ccl/changefeedccl.TestChangefeedTopicNames failed with artifacts on release-23.1 @ 79a789ccba9c3bf79c70f5292ed70fe335204ec2:

I230410 20:06:34.795021 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 674 ={"Timestamp":1681157194791468819,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t abl-e83\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":188,"TableName":"d.public.\"t abl-e83\""}
I230410 20:06:34.829306 125404 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r60/1:/Table/{59-60}] 675  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 20:06:34.840183 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 676 ={"Timestamp":1681157194836566435,"EventType":"create_table","Statement":"CREATE TABLE d.public.table84 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":189,"TableName":"d.public.table84"}
I230410 20:06:34.854855 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 677 ={"Timestamp":1681157194850971954,"EventType":"create_table","Statement":"CREATE TABLE d.public.table85 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":190,"TableName":"d.public.table85"}
I230410 20:06:34.886415 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 678 ={"Timestamp":1681157194882280245,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta*ble😙86\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":191,"TableName":"d.public.\"ta*ble😙86\""}
I230410 20:06:34.910987 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 679 ={"Timestamp":1681157194905620336,"EventType":"create_table","Statement":"CREATE TABLE d.public.table87 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":192,"TableName":"d.public.table87"}
I230410 20:06:34.935842 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 680 ={"Timestamp":1681157194928477032,"EventType":"create_table","Statement":"CREATE TABLE d.public.table88 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":193,"TableName":"d.public.table88"}
I230410 20:06:34.996436 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 681 ={"Timestamp":1681157194981696874,"EventType":"create_table","Statement":"CREATE TABLE d.public.tabl̘e89 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":194,"TableName":"d.public.tabl̘e89"}
I230410 20:06:35.052729 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 682 ={"Timestamp":1681157195048707297,"EventType":"create_table","Statement":"CREATE TABLE d.public.table90 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":195,"TableName":"d.public.table90"}
I230410 20:06:35.081288 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 683 ={"Timestamp":1681157195066180035,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"ta\\nble91\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":196,"TableName":"d.public.\"ta\\nble91\""}
I230410 20:06:35.095124 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 684 ={"Timestamp":1681157195091612982,"EventType":"create_table","Statement":"CREATE TABLE d.public.table92 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":197,"TableName":"d.public.table92"}
I230410 20:06:35.115733 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 685 ={"Timestamp":1681157195108442129,"EventType":"create_table","Statement":"CREATE TABLE d.public.tabl̈́e93 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":198,"TableName":"d.public.tabl̈́e93"}
I230410 20:06:35.131301 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 686 ={"Timestamp":1681157195127578481,"EventType":"create_table","Statement":"CREATE TABLE d.public.table94 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":199,"TableName":"d.public.table94"}
I230410 20:06:35.149441 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 687 ={"Timestamp":1681157195145810091,"EventType":"create_table","Statement":"CREATE TABLE d.public.table95 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":200,"TableName":"d.public.table95"}
I230410 20:06:35.172678 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 688 ={"Timestamp":1681157195169087651,"EventType":"create_table","Statement":"CREATE TABLE d.public.table96 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":201,"TableName":"d.public.table96"}
I230410 20:06:35.207952 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 689 ={"Timestamp":1681157195201844337,"EventType":"create_table","Statement":"CREATE TABLE d.public.table̘97 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":202,"TableName":"d.public.table̘97"}
I230410 20:06:35.228705 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 690 ={"Timestamp":1681157195221652317,"EventType":"create_table","Statement":"CREATE TABLE d.public.table98 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":203,"TableName":"d.public.table98"}
I230410 20:06:35.261503 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 691 ={"Timestamp":1681157195257241720,"EventType":"create_table","Statement":"CREATE TABLE d.public.table99 (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":204,"TableName":"d.public.table99"}
I230410 20:06:35.278403 122539 5@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 692 ={"Timestamp":1681157195272634393,"EventType":"create_table","Statement":"CREATE TABLE d.public.\"t\\\\U000D8583able100\" (a INT8 PRIMARY KEY)","Tag":"CREATE TABLE","User":"root","DescriptorID":205,"TableName":"d.public.\"t\\\\U000D8583able100\""}
I230410 20:06:35.285513 125825 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r62/1:/{Table/61-Max}] 693  initiating a split of this range at key /Table/106 [r63] (span config)
I230410 20:06:35.287070 125989 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r15/1:/Table/1{3-4}] 694  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 20:06:35.293462 126050 13@kv/kvserver/replicate_queue.go:842  [T1,n1,replicate,s1,r62/1:/Table/{61-106}] 695  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 20:06:35.294148 126078 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r63/1:/{Table/106-Max}] 696  initiating a split of this range at key /Table/107 [r64] (span config)
I230410 20:06:35.300923 126153 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r64/1:/{Table/107-Max}] 697  initiating a split of this range at key /Table/108 [r65] (span config)
I230410 20:06:35.319790 126125 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r65/1:/{Table/108-Max}] 698  initiating a split of this range at key /Table/109 [r66] (span config)
I230410 20:06:35.321696 120037 ccl/changefeedccl/testfeed_test.go:795  [-] 699  Starting feed job: "CREATE CHANGEFEED FOR TABLE \"tab le1\", TABLE table2, TABLE table3, TABLE \"table(4\", TABLE table5, TABLE table6, TABLE table7, TABLE table8, TABLE \"t😅aBle9\", TABLE \"tab͢l%q\\\\xf0e10\", TABLE tabl😂e11, TABLE table12, TABLE \"tAb(%ple13\", TABLE \"t😅aB\\nle14\", TABLE \"\ntabͮle15\", TABLE table16, TABLE table17, TABLE table18, TABLE table19, TABLE table20, TABLE \"tabl/e21\", TABLE \"tabl'e22\", TABLE table23, TABLE \"tabl&e24\", TABLE \"tablE25\", TABLE table26, TABLE \"%vtable27\", TABLE table28, TABLE \"tabl\fe29\", TABLE table30, TABLE table31, TABLE table32, TABLE tab̾le33, TABLE table34, TABLE \"t able35\", TABLE table36, TABLE table😃37, TABLE \"table\"\"38\", TABLE \"tab\"\"le39\", TABLE table40, TABLE table41, TABLE \"tabl e42\", TABLE \"ta%53ble43\", TABLE table44, TABLE \"\\\\u9371table45\", TABLE table46, TABLE \"%ptable47\", TABLE table48, TABLE \" table49\", TABLE \"taBle50\", TABLE table51, TABLE tabl😏e52, TABLE \"tabl.e53\", TABLE tabl͝e54, TABLE table55, TABLE table56, TABLE \"table%v57\", TABLE table58, TABLE t😀able59, TABLE table60, TABLE table61, TABLE table62, TABLE table63, TABLE \"%4atable64\", TABLE \"\ntable65\", TABLE \"tabl%qe66\", TABLE \"t. able67\", TABLE table68, TABLE \"!table69\", TABLE table70, TABLE table71, TABLE \"t😾abl'e72\", TABLE table73, TABLE table74, TABLE table75, TABLE \"tabl-e76\", TABLE table77, TABLE table78, TABLE \"table 79\", TABLE \"ta\nble80\", TABLE table81, TABLE table82, TABLE \"t abl-e83\", TABLE table84, TABLE table85, TABLE \"ta*ble😙86\", TABLE table87, TABLE table88, TABLE tabl̘e89, TABLE table90, TABLE \"ta\\nble91\", TABLE table92, TABLE tabl̈́e93, TABLE table94, TABLE table95, TABLE table96, TABLE table̘97, TABLE table98, TABLE table99, TABLE \"t\\\\U000D8583able100\" INTO 'gcpubsub://testfeed?region=testfeedRegion'"
I230410 20:06:35.322281 122539 sql/schemachanger/scbuild/build.go:45  [T1,n1,client=127.0.0.1:53626,user=root] 700  building declarative schema change targets for CREATE CHANGEFEED
I230410 20:06:35.322751 126168 1@ccl/changefeedccl/changefeed_stmt.go:965  [T1,n1,client=127.0.0.1:53626,user=root] 701  changefeed planning to connect to destination gcpubsub://testfeed?region=testfeedRegion
I230410 20:06:35.331254 126065 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r66/1:/{Table/109-Max}] 702  initiating a split of this range at key /Table/110 [r67] (span config)
I230410 20:06:35.349029 126197 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r67/1:/{Table/110-Max}] 703  initiating a split of this range at key /Table/111 [r68] (span config)
I230410 20:06:35.357188 126134 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r68/1:/{Table/111-Max}] 704  initiating a split of this range at key /Table/112 [r69] (span config)
I230410 20:06:35.364397 126168 12@util/log/event_log.go:32  [T1,n1,client=127.0.0.1:53626,user=root] 705 ={"Timestamp":1681157195364392581,"EventType":"changefeed_failed","FailureType":"user_input"}
I230410 20:06:35.365332 126156 kv/kvserver/replica_command.go:410  [T1,n1,split,s1,r69/1:/{Table/112-Max}] 706  initiating a split of this range at key /Table/113 [r70] (span config)
    changefeed_test.go:8464: 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.
W230410 20:06:35.370288 126055 kv/kvserver/intentresolver/intent_resolver.go:826  [-] 707  failed to gc transaction record: could not GC completed transaction anchored at /Local/Range/Table/106/RangeDescriptor: node unavailable; try another peer
I230410 20:06:35.370414 120730 sql/stats/automatic_stats.go:550  [T1,n1] 708  quiescing auto stats refresher
E230410 20:06:35.370678 126156 kv/kvserver/queue.go:1142  [T1,n1,split,s1,r69/1:/{Table/112-Max}] 709  unable to split [n1,s1,r69/1:/{Table/112-Max}] at key /Table/113: split at key /Table/113 failed: failed to send RPC: sending to all replicas failed; last error: node unavailable; try another peer
I230410 20:06:35.370927 122068 jobs/registry.go:1538  [T1,n1] 710  KEY VISUALIZER job 100: stepping through state succeeded
W230410 20:06:35.371071 120570 sql/sqlliveness/slinstance/slinstance.go:334  [T1,n1] 711  exiting heartbeat loop
W230410 20:06:35.371110 120570 sql/sqlliveness/slinstance/slinstance.go:321  [T1,n1] 712  exiting heartbeat loop with error: node unavailable; try another peer
E230410 20:06:35.371132 120570 server/server_sql.go:507  [T1,n1] 713  failed to run update of instance with new session ID: node unavailable; try another peer
E230410 20:06:35.371171 122199 jobs/registry.go:943  [T1,n1] 714  error getting live session: node unavailable; try another peer
I230410 20:06:35.371470 120947 jobs/registry.go:1538  [T1,n1] 715  AUTO SPAN CONFIG RECONCILIATION job 855529196345982977: stepping through state succeeded
I230410 20:06:35.371926 121823 rpc/context.go:2302  [T1,n1,rnode=1,raddr=127.0.0.1:45431,class=default,rpc] 716  connection heartbeat loop ended with err: <nil>
I230410 20:06:35.371943 120301 server/start_listen.go:103  [T1,n1] 717  server shutting down: instructing cmux to stop accepting
E230410 20:06:35.372021 120763 jobs/registry.go:1055  [T1,n1] 718  error processing claimed jobs: could not query for claimed jobs: select-running/get-claimed-jobs: failed to read query result: query execution canceled
W230410 20:06:35.375622 122068 jobs/adopt.go:518  [T1,n1] 719  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: c463ba37], [can-forward-ts] RPC error: node unavailable; try another peer
W230410 20:06:35.380850 122360 jobs/adopt.go:518  [T1,n1] 720  could not clear job claim: clear-job-claim: node unavailable; try another peer
W230410 20:06:35.397551 120037 server/server_sql.go:1676  [T1,n1] 721  server shutdown without a prior graceful drain
    --- FAIL: TestChangefeedTopicNames/pubsub (4.67s)
Help

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

This test on roachdash | Improve this report!

@blathers-crl blathers-crl bot mentioned this issue Apr 10, 2023
Merged
@craig craig bot closed this as completed in #101130 Apr 10, 2023
@craig craig bot closed this as completed in 9c55b61 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