cli: TestDemoLocality failed [failed connection attempt; no certificates found]

[cockroach-teamcity]

cli.TestDemoLocality failed with artifacts on master @ c3417908798c54be899e0b9af748c2e568d83627:

sync.runtime_notifyListWait(0x4001f96a50, 0x17b)
	GOROOT/src/runtime/sema.go:587 +0x154
sync.(*Cond).Wait(0x4001f96a40)
	GOROOT/src/sync/cond.go:71 +0xcc
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker(0x400c8df2d0, {0x7500c08, 0x40047152c0}, {0x752d660, 0x4005310008}, 0x4007e06008)
	pkg/kv/kvserver/scheduler.go:378 +0x368
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2({0x7500c08, 0x40047152c0}, 0x7500c08?)
	pkg/kv/kvserver/scheduler.go:314 +0xe0
created by github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start in goroutine 7534
	pkg/kv/kvserver/scheduler.go:328 +0x168

goroutine 12004 [select, 14 minutes]:
google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run(0x4002d00640, {0x74ff2b8, 0x400a13e910})
	external/org_golang_google_grpc/internal/grpcsync/callback_serializer.go:83 +0xc4
created by google.golang.org/grpc/internal/grpcsync.NewCallbackSerializer in goroutine 12003
	external/org_golang_google_grpc/internal/grpcsync/callback_serializer.go:55 +0x118

goroutine 8330 [select, 14 minutes]:
github.com/cockroachdb/cockroach/pkg/sql.(*runnerCoordinator).init.func1({0x4006db6240?, 0x7500c08?})
	pkg/sql/distsql_running.go:169 +0xb0
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1({0x7500c08, 0x40047152c0})
	pkg/util/stop/stopper.go:440 +0x88
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx in goroutine 6415
	pkg/util/stop/stopper.go:438 +0x104

goroutine 10499 [select, 14 minutes]:
github.com/cockroachdb/cockroach/pkg/kv/kvserver/rangefeed.(*UnbufferedSender).run(0x4004019a00, {0x74ff2b8, 0x400581d180}, 0x4003ccc090, 0x4002672090)
	pkg/kv/kvserver/rangefeed/unbuffered_sender.go:153 +0xa0
github.com/cockroachdb/cockroach/pkg/kv/kvserver/rangefeed.(*StreamManager).Start.func1({0x74ff2b8, 0x400581d180})
	pkg/kv/kvserver/rangefeed/stream_manager.go:192 +0xc0
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1({0x74ff2b8, 0x400581d180})
	pkg/util/stop/stopper.go:440 +0x88
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx in goroutine 10498
	pkg/util/stop/stopper.go:438 +0x104

goroutine 8960 [select]:
github.com/cockroachdb/cockroach/pkg/sql.(*runnerCoordinator).init.func1({0x40019c9e40?, 0x7500c08?})
	pkg/sql/distsql_running.go:169 +0xb0
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1({0x7500c08, 0x400a1a0640})
	pkg/util/stop/stopper.go:440 +0x88
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx in goroutine 8883
	pkg/util/stop/stopper.go:438 +0x104

goroutine 8942 [select, 10 minutes]:
github.com/cockroachdb/cockroach/pkg/sql.(*runnerCoordinator).init.func1({0x4001ac0480?, 0x7500c08?})
	pkg/sql/distsql_running.go:169 +0xb0
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1({0x7500c08, 0x400a1a0640})
	pkg/util/stop/stopper.go:440 +0x88
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx in goroutine 8883
	pkg/util/stop/stopper.go:438 +0x104

Help

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

/cc @cockroachdb/sql-foundations @cockroachdb/server @cockroachdb/server

This test on roachdash | Improve this report!

Jira issue: CRDB-55340

[blathers-crl]

This issue has multiple T-eam labels. Please make sure it only has one, or else issue synchronization will not work correctly.

_{🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.}

[blathers-crl]

This issue has multiple T-eam labels. Please make sure it only has one, or else issue synchronization will not work correctly.

_{🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.}

[spilchen]

The test logs can be found in bazel-testlogs/pkg/cli/cli_test/shard_13_of_16/test.log

We hit a 15 minute test timeout:

panic: test timed out after 15m0s
    running tests:
        TestDemoLocality (14m56s)

It's attempting to start a 3 node system. One of nodes (2) is repeatedly (for 15 minutes) hitting errors like this:

E251010 16:35:04.432130 12339 2@rpc/peer.go:694  [testclient,user=root,nsql=2,rnode=2,raddr=127.0.0.1:33463,class=default,rpc] 718  failed connection attempt (last connected 15.014s ago): problem using security settings: no certificates found; does certs dir exist?
...
E251010 16:49:42.212880 12339 2@rpc/peer.go:694  [testclient,user=root,nsql=2,rnode=2,raddr=127.0.0.1:33463,class=default,rpc] 9091  failed connection attempt (last connected 14m52.795s ago): problem using security settings: no certificates found; does certs dir exist?

Other nodes appear to be waiting for this node to come up to establish quorum.

I251010 16:49:39.256598 9768 13@kv/kvserver/replicate_queue.go:859  [T1,Vsystem,n1,replicate,s1,r27/1:/Table/2{4-5}] 9086  error processing replica: avoid up-replicating to fragile quorum: 0 of 2 live stores are able to take a new replica for the range (2 already have a voter, 0 already have a non-voter); likely not enough nodes in cluster

[cockroach-teamcity]

cli.TestDemoLocality failed with artifacts on master @ 287d7b96c9c9764394028ad601a73c02913624d5:

W251014 12:49:05.096274 30424 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T1,Vsystem,start-demo-cluster,phase=2,start-n1,n1,rangefeed=tenant-boundaries-watcher,mux_n=1,gen=2] 2281  error closing mux rangefeed client: context canceled
W251014 12:49:05.096284 26042 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T1,Vsystem,n1,rangefeed=sql_instances,mux_n=1,gen=2] 2282  error closing mux rangefeed client: context canceled
W251014 12:49:05.096287 30645 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T1,Vsystem,n1,job=AUTO SPAN CONFIG RECONCILIATION id=1115343232809959425,rangefeed=sql-watcher-protected-ts-records-rangefeed,mux_n=1,gen=2] 2283  error closing mux rangefeed client: context canceled
W251014 12:49:05.096325 31016 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T1,Vsystem,n1,rangefeed=statement-hints-watcher,mux_n=1,gen=2] 2284  error closing mux rangefeed client: context canceled
W251014 12:49:05.096371 31019 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T1,Vsystem,start-demo-cluster,phase=2,start-n1,n1,rangefeed=tenant-entry-watcher,mux_n=1,gen=2] 2285  error closing mux rangefeed client: context canceled
I251014 12:49:05.096371 30280 jobs/registry.go:1568  [T1,Vsystem,n1,job=1115343232809959425] 2286  AUTO SPAN CONFIG RECONCILIATION job 1115343232809959425: stepping through state succeeded
E251014 12:49:05.096690 30280 jobs/registry.go:918  [T1,Vsystem,n1] 2287  error getting live session: node unavailable; try another peer
W251014 12:49:05.096840 31045 15@kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:407  [T1,Vsystem,n1,rangefeed=tenant-settings-watcher,mux_n=1,gen=2] 2288  error closing mux rangefeed client: context canceled
I251014 12:49:05.260953 26630 13@kv/kvserver/allocator/plan/replicate.go:421  [T1,Vsystem,n1,replicate,s1,r15/1:/Table/1{2-3}] 2289  adding voter n4,s4: [1*:80]
I251014 12:49:05.262126 26630 15@kv/kvserver/replica_command.go:1923  [T1,Vsystem,n1,replicate,s1,r15/1:/Table/1{2-3}] 2290  could not successfully add and upreplicate LEARNER replica(s) on [n4,s4], rolling back: change replicas of r15 failed: fetching current range descriptor value: aborted in DistSender: result is ambiguous: node unavailable; try another peer
I251014 12:49:05.262224 26630 13@kv/kvserver/replicate_queue.go:859  [T1,Vsystem,n1,replicate,s1,r15/1:/Table/1{2-3}] 2291  error processing replica: change replicas of r15 failed: fetching current range descriptor value: aborted in DistSender: result is ambiguous: node unavailable; try another peer
W251014 12:49:05.262344 26630 13@kv/kvserver/queue.go:1478  [T1,Vsystem,n1,replicate,s1,r15/1:/Table/1{2-3}] 2292  queue processing resulted in non-benign error: change replicas of r15 failed: fetching current range descriptor value: aborted in DistSender: result is ambiguous: node unavailable; try another peer
I251014 12:49:05.262419 26630 13@kv/kvserver/queue.go:1629  [T1,Vsystem,n1,replicate] 2293  purgatory is now empty
W251014 12:49:05.262441 29244 13@kv/kvserver/queue.go:1478  [T1,Vsystem,n1,replicate,s1,r56/1:/Table/5{4-5}] 2294  queue processing resulted in non-benign error: node unavailable; try another peer
W251014 12:49:05.262471 29244 13@kv/kvserver/queue.go:1204  [T1,Vsystem,n1,replicate,s1,r56/1:/Table/5{4-5}] 2295  queue.replicate: processing replica [outer]: task did not start node unavailable; try another peer
W251014 12:49:05.262500 29244 13@kv/kvserver/queue.go:1478  [T1,Vsystem,n1,replicate,s1,r53/1:/Table/5{1-2}] 2296  queue processing resulted in non-benign error: node unavailable; try another peer
W251014 12:49:05.262517 29244 13@kv/kvserver/queue.go:1204  [T1,Vsystem,n1,replicate,s1,r53/1:/Table/5{1-2}] 2297  queue.replicate: processing replica [outer]: task did not start node unavailable; try another peer
W251014 12:49:05.262538 29244 13@kv/kvserver/queue.go:1478  [T1,Vsystem,n1,replicate,s1,r13/1:/Table/{9-11}] 2298  queue processing resulted in non-benign error: node unavailable; try another peer
W251014 12:49:05.262556 29244 13@kv/kvserver/queue.go:1204  [T1,Vsystem,n1,replicate,s1,r13/1:/Table/{9-11}] 2299  queue.replicate: processing replica [outer]: task did not start node unavailable; try another peer
E251014 12:49:05.402617 29143 2@rpc/peer.go:673  [testclient,user=root,nsql=1,rnode=1,raddr=127.0.0.1:37933,class=default,rpc] 2300  disconnected (was healthy for 3.002s): grpc: node unavailable; try another peer [code 2/Unknown]
E251014 12:49:05.403343 29143 2@rpc/peer.go:694  [testclient,user=root,nsql=1,rnode=1,raddr=127.0.0.1:37933,class=default,rpc] 2301  failed connection attempt (last connected 1ms ago): grpc: connection error: desc = "transport: error while dialing: dial tcp 127.0.0.1:37933: connect: connection refused" [code 14/Unavailable]
W251014 12:49:06.062117 6925 server/server_sql.go:1812  [T1,Vsystem,n1] 2302  server shutdown without a prior graceful drain
I251014 12:49:06.068899 6925 server/server_controller.go:416  [T1,Vsystem,n1] 2303  server controller shutting down
I251014 12:49:06.068930 6925 server/server_controller.go:425  [T1,Vsystem,n1] 2304  waiting for tenant servers to report stopped
    demo_locality_test.go:41: 
          /home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/674/execroot/com_github_cockroachdb_cockroach/bazel-out/s390x-fastbuild/bin/pkg/cli/cli_test_/cli_test.runfiles/com_github_cockroachdb_cockroach/pkg/cli/testdata/demo/test_demo_locality:11:
          exec
          demo
          --nodes=9
          --execute=select node_id, locality from crdb_internal.gossip_nodes order by node_id
        output didn't match expected:
          @@ -1,11 +1,5 @@
          -node_id	locality
          -1	region=us-east1,az=b
          -2	region=us-east1,az=c
          -3	region=us-east1,az=d
          -4	region=us-west1,az=a
          -5	region=us-west1,az=b
          -6	region=us-west1,az=c
          -7	region=europe-west1,az=b
          -8	region=europe-west1,az=c
          -9	region=europe-west1,az=d
          +ERROR: cannot load certificates.
          +Check your certificate settings, set --certs-dir, or use --insecure for insecure clusters.
           
          +initial connection heartbeat failed: problem using security settings: no certificates found; does certs dir exist?
          +
    testutils.go:290: -- test log scope end --
I251014 12:49:06.095525 6925 cli/testutils.go:297  [-] 2305  stopping server and cleaning up CLI test
--- FAIL: TestDemoLocality (18.44s)

Help

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

This test on roachdash | Improve this report!

[spilchen]

We are hitting errors like "ERROR: cannot load certificates.". @cockroachdb/server team can you take a look?

[cockroach-teamcity]

cli.TestDemoLocality failed with artifacts on master @ 4b80cd59c6299f26b2b4f02a96064d5127ccad94:

google.golang.org/grpc/internal/transport.(*Stream).Read(0xc0352359e0, {0xc026fe8c40, 0x5, 0x5})
	external/org_golang_google_grpc/internal/transport/transport.go:498 +0xc6
google.golang.org/grpc.(*parser).recvMsg(0xc026fe8c30, 0x7fffffff)
	external/org_golang_google_grpc/rpc_util.go:600 +0x5e
google.golang.org/grpc.recvAndDecompress(0xc026fe8c30, 0xc0352359e0, {0x0, 0x0}, 0x7fffffff, 0x0, {0x885a5190, 0x8c835840})
	external/org_golang_google_grpc/rpc_util.go:730 +0x3c
google.golang.org/grpc.recv(0xc026fe8c30, {0x3ff6998f3c0, 0xc001002d00}, 0xc0352359e0, {0x0, 0x0}, {0x875718c0, 0xc0951498c0}, 0x7fffffff, 0x0, ...)
	external/org_golang_google_grpc/rpc_util.go:796 +0x84
google.golang.org/grpc.(*serverStream).RecvMsg(0xc0679ea960, {0x875718c0, 0xc0951498c0})
	external/org_golang_google_grpc/stream.go:1712 +0x140
github.com/cockroachdb/cockroach/pkg/server.(*Node).batchStreamImpl(0xc002462a88, {0x3ff6dd880d8, 0xc09784e210})
	pkg/server/node.go:1899 +0xc0
github.com/cockroachdb/cockroach/pkg/server.(*Node).BatchStream(0xc002462a88, {0x885fc848, 0xc09784e210})
	pkg/server/node.go:1886 +0x6c
github.com/cockroachdb/cockroach/pkg/kv/kvpb._Internal_BatchStream_Handler({0x87565780, 0xc002462a88}, {0x885e95c0, 0xc0679ea960})
	bazel-out/s390x-fastbuild/bin/pkg/kv/kvpb/kvpb_go_proto_/github.com/cockroachdb/cockroach/pkg/kv/kvpb/api.pb.go:11711 +0x102
github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.StreamServerInterceptor.func13({0x87565780, 0xc002462a88}, {0x885e95c0, 0xc0679ea960}, 0xc01810c300, 0x87ac6a18)
	pkg/util/tracing/grpcinterceptor/grpc_interceptor.go:107 +0x482
google.golang.org/grpc.getChainStreamHandler.func1({0x87565780, 0xc002462a88}, {0x885e95c0, 0xc0679ea960})
	external/org_golang_google_grpc/server.go:1504 +0xe2
github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func4({0x87565780, 0xc002462a88}, {0x885e95c0, 0xc0679ea960}, 0xc01810c300, 0xc01a9ba5c0)
	pkg/rpc/context.go:190 +0xa6
google.golang.org/grpc.getChainStreamHandler.func1({0x87565780, 0xc002462a88}, {0x885e95c0, 0xc0679ea960})
	external/org_golang_google_grpc/server.go:1504 +0xe2
github.com/cockroachdb/cockroach/pkg/rpc.kvAuth.streamInterceptor({0xc00ed2a000, {{0x1}, {0x88605dc0, 0xc00a453f20}}, 0x0}, {0x87565780, 0xc002462a88}, {0x885e95c0, 0xc0679ea960}, 0xc01810c300, ...)
	pkg/rpc/auth.go:193 +0x3d4
google.golang.org/grpc.getChainStreamHandler.func1({0x87565780, 0xc002462a88}, {0x885e95c0, 0xc0679ea960})
	external/org_golang_google_grpc/server.go:1504 +0xe2
github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func2.1({0x885b5370, 0xc026fe8c90})
	pkg/rpc/context.go:147 +0x4e
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr(0xc00cfdb0e0, {0x885b5370, 0xc026fe8c90}, {0xc06e134150, 0x27}, 0xc02d816aa8)
	pkg/util/stop/stopper.go:351 +0x118
github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func2({0x87565780, 0xc002462a88}, {0x885e95c0, 0xc0679ea960}, 0xc01810c300, 0xc01a9ba540)
	pkg/rpc/context.go:146 +0xc8
google.golang.org/grpc.NewServer.chainStreamServerInterceptors.chainStreamInterceptors.func2({0x87565780, 0xc002462a88}, {0x885e95c0, 0xc0679ea960}, 0xc01810c300, 0x87ac6a18)
	external/org_golang_google_grpc/server.go:1495 +0xb8
google.golang.org/grpc.(*Server).processStreamingRPC(0xc004ef5c20, {0x88607ec0, 0xc002a7ad00}, 0xc0352359e0, 0xc00888fd40, 0x8c226180, 0x0)
	external/org_golang_google_grpc/server.go:1659 +0x15d4
google.golang.org/grpc.(*Server).handleStream(0xc004ef5c20, {0x88607ec0, 0xc002a7ad00}, 0xc0352359e0, 0x0)
	external/org_golang_google_grpc/server.go:1739 +0xbbe
google.golang.org/grpc.(*Server).serveStreams.func1.1()
	external/org_golang_google_grpc/server.go:970 +0xe6
created by google.golang.org/grpc.(*Server).serveStreams.func1 in goroutine 45010
	external/org_golang_google_grpc/server.go:981 +0x198

goroutine 362036 [select]:
google.golang.org/grpc.newClientStreamWithParams.func4()
	external/org_golang_google_grpc/stream.go:383 +0xda
created by google.golang.org/grpc.newClientStreamWithParams in goroutine 362147
	external/org_golang_google_grpc/stream.go:382 +0xf8c

Help

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

This test on roachdash | Improve this report!