cockroachdb / cockroachdb/cockroach
the server is terminating due to a fatal error
- Dominant language
- Go
- Stars
- 32.5k
- Forks
- 4.1k
- PR merge metrics
- PR metrics pending
Description
OS: Fedora Linux 38 (Workstation Edition) x86_64
Kernel: 6.3.7-200.fc38.x86_64
Cockroach Version: v23.1.3.linux-amd64
supervisor conf:
```
[program:cockroach_node1]
command=/data/cockroach/current/cockroach start --certs-dir=certs --store=/data/cockroach/cockroach-data/node1 --listen-addr=localhost:26257 --sql-addr=localhost:36257 --http-addr=localhost:38081 --join=localhost:26257,localhost:26258,localhost:26259 --unencrypted-localhost-http
directory=/data/cockroach
autostart=true
[program:cockroach_node2]
command=/data/cockroach/current/cockroach start --certs-dir=certs --store=/data/cockroach/cockroach-data/node2 --listen-addr=localhost:26258 --sql-addr=localhost:36258 --http-addr=localhost:38082 --join=localhost:26257,localhost:26258,localhost:26259 --unencrypted-localhost-http
directory=/data/cockroach
autostart=true
command=/data/cockroach/current/cockroach start --certs-dir=certs --store=/data/cockroach/cockroach-data/node3 --listen-addr=localhost:26259 --sql-addr=localhost:36259 --http-addr=localhost:38083 --join=localhost:26257,localhost:26258,localhost:26259 --unencrypted-localhost-http
directory=/data/cockroach
autostart=true
```
log:
```
I230620 04:00:00.625520 568 kv/kvserver/replica_raft.go:1531 ⋮ [T1,n1,s1,r31/1:‹/{Table/29-NamespaceTab…}›,raft] 1567 slow non-blocking raft commit: commit-wait 766.62258ms sem 379ns
I230620 04:00:01.600379 568 kv/kvserver/replica_raft.go:1531 ⋮ [T1,n1,s1,r57/1:‹/Table/5{6-7}›,raft] 1568 slow non-blocking raft commit: commit-wait 511.349809ms sem 241ns
I230620 04:00:06.000239 568 kv/kvserver/replica_raft.go:1531 ⋮ [T1,n1,s1,r1/1:‹/{Min-System/NodeL…}›,raft] 1569 slow non-blocking raft commit: commit-wait 1.026425686s sem 326ns
W230620 04:00:06.217018 655 kv/kvserver/liveness/liveness.go:908 ⋮ [T1,n1,liveness-hb] 1570 slow heartbeat took 1.243741185s; err=
I230620 04:00:09.623788 568 kv/kvserver/replica_raft.go:1531 ⋮ [T1,n1,s1,r94/1:‹/System{/tsd/cr.n…-tse}›,raft] 1571 slow non-blocking raft commit: commit-wait 1.985339693s sem 396ns
I230620 04:00:09.623971 535 kv/kvserver/store_raft.go:656 ⋮ [T1,n1,s1,r4/1:‹/System/tsd{-/cr.nod…}›,raft] 1572 raft ready handling: 1.55s [append=0.00s, apply=0.00s, commit-batch-non-blocking-sync=1.55s, other=0.00s], wrote 138 KiB sync(non-blocking) [append-ent=138 KiB (1), ]; node might be overloaded
I230620 04:00:09.623986 557 kv/kvserver/store_raft.go:656 ⋮ [T1,n1,s1,r95/1:‹/System/tsd/cr.node.{re…-sq…}›,raft] 1573 raft ready handling: 1.42s [append=0.00s, apply=0.00s, commit-batch-non-blocking-sync=1.42s, other=0.00s], wrote 136 B sync(non-blocking) [append-ent=76 B (1), ]; node might be overloaded
I230620 04:00:09.624047 542 kv/kvserver/store_raft.go:656 ⋮ [T1,n1,s1,r94/1:‹/System{/tsd/cr.n…-tse}›,raft] 1574 raft ready handling: 1.42s [append=0.00s, apply=0.00s, commit-batch-non-blocking-sync=1.42s, other=0.00s], wrote 140 B sync(non-blocking) [append-ent=79 B (1), ]; node might be overloaded
I230620 04:00:09.624144 498 kv/kvserver/store_raft.go:656 ⋮ [T1,n1,s1,r1/1:‹/{Min-System/NodeL…}›,raft] 1575 raft ready handling: 1.20s [append=0.00s, apply=0.00s, commit-batch-non-blocking-sync=1.20s, other=0.00s], wrote 51 B sync(non-blocking) []; node might be overloaded
I230620 04:00:09.624202 473 kv/kvserver/store_raft.go:656 ⋮ [T1,n1,s1,r37/1:‹/Table/3{5-6}›,raft] 1576 raft ready handling: 1.06s [append=0.00s, apply=0.00s, commit-batch-non-blocking-sync=1.06s, other=0.00s], wrote 507 B sync(non-blocking) [append-ent=398 B (2), ]; node might be overloaded
I230620 04:00:09.624296 511 kv/kvserver/store_raft.go:656 ⋮ [T1,n1,s1,r2/1:‹/System/NodeLiveness{-Max}›,raft] 1577 raft ready handling: 1.39s [append=0.00s, apply=0.00s, commit-batch-non-blocking-sync=1.39s, other=0.00s], wrote 187 B sync(non-blocking) [append-ent=124 B (1), ]; node might be overloaded
I230620 04:00:09.624400 560 kv/kvserver/store_raft.go:656 ⋮ [T1,n1,s1,r53/1:‹/Table/5{2-3}›,raft] 1578 raft ready handling: 1.39s [append=0.00s, apply=0.00s, commit-batch=1.39s, other=0.00s], wrote 50 B [apply=357 B (1)] pebble stats: [commit-wait 71ns sem 571ns]; node might be overloaded
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 +__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp__val-bl
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + WAL 1 49 M - 3.2 G - - - - 3.2 G - - - 1.0
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + 0 0 0 B 0.00 3.2 G 0 B 0 0 B 0 222 M 158 0 B 0 0.1 0 B
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + 5 14 36 M 0.71 222 M 0 B 0 215 K 1 1.7 G 534 1.7 G 1 8.0 17 K
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + 6 52 330 M - 212 M 0 B 0 15 K 1 433 M 69 463 M 1 2.0 940 K
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + total 66 366 M - 3.2 G 0 B 0 230 K 2 5.6 G 761 2.2 G 2 1.7 958 K
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + flush 61 0 B 0 0 (ingest = tables-ingested, move = ingested-as-flushable)
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 +compact 183 0 B 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress)
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + ctype 181 0 0 2 0 0 0 (default, delete, elision, move, read, rewrite, multi-level)
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + memtbl 1 64 M
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 +zmemtbl 0 0 B
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + ztbl 0 0 B
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + bcache 3.5 K 49 M 88.2% (score == hit-rate)
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + tcache 57 40 K 100.0% (score == hit-rate)
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + snaps 0 - 0 (score == earliest seq num)
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + titers 0
I230620 04:00:09.974366 643 kv/kvserver/store.go:3299 ⋮ [T1,n1] 1579 + filter - - 98.5% (score == utility)
I230620 04:00:12.599096 568 kv/kvserver/replica_raft.go:1531 ⋮ [T1,n1,s1,r4/1:‹/System/tsd{-/cr.nod…}›,raft] 1580 slow non-blocking raft commit: commit-wait 2.756649604s wal-q 1.551084007s sem 363ns
I230620 04:00:12.599136 568 kv/kvserver/replica_raft.go:1531 ⋮ [T1,n1,s1,r95/1:‹/System/tsd/cr.node.{re…-sq…}›,raft] 1581 slow non-blocking raft commit: commit-wait 174ns sem 1.134µs
I230620 04:00:12.599146 568 kv/kvserver/replica_raft.go:1531 ⋮ [T1,n1,s1,r94/1:‹/System{/tsd/cr.n…-tse}›,raft] 1582 slow non-blocking raft commit: commit-wait 188ns sem 345ns
I230620 04:00:12.599214 568 kv/kvserver/replica_raft.go:1531 ⋮ [T1,n1,s1,r1/1:‹/{Min-System/NodeL…}›,raft] 1583 slow non-blocking raft commit: commit-wait 130ns sem 444ns
I230620 04:00:12.599246 568 kv/kvserver/replica_raft.go:1531 ⋮ [T1,n1,s1,r37/1:‹/Table/3{5-6}›,raft] 1584 slow non-blocking raft commit: commit-wait 106ns sem 383ns
I230620 04:00:12.599261 568 kv/kvserver/replica_raft.go:1531 ⋮ [T1,n1,s1,r2/1:‹/System/NodeLiveness{-Max}›,raft] 1585 slow non-blocking raft commit: commit-wait 151.326µs sem 240ns
W230620 04:00:12.653886 655 kv/kvserver/liveness/liveness.go:908 ⋮ [T1,n1,liveness-hb] 1586 slow heartbeat took 4.680613173s; err=
W230620 04:00:12.987598 346979 kv/kvserver/liveness/liveness.go:908 ⋮ [T1,n1,s1,r66/1:‹/Table/110{-/1/8754…}›] 1587 slow heartbeat took 3.282238401s; err=
W230620 04:00:18.313636 655 kv/kvserver/liveness/liveness.go:908 ⋮ [T1,n1,liveness-hb] 1588 slow heartbeat took 1.339651294s; err=
W230620 04:00:25.973696 655 kv/kvserver/liveness/liveness.go:908 ⋮ [T1,n1,liveness-hb] 1589 slow heartbeat took 3.000252694s; err=disk write failed while updating node liveness: interrupted during singleflight ‹engine sync:0›: context deadline exceeded
W230620 04:00:25.973745 655 kv/kvserver/liveness/liveness.go:810 ⋮ [T1,n1,liveness-hb] 1590 failed node liveness heartbeat: operation ‹"node liveness heartbeat"› timed out after 3s (given timeout 3s): disk write failed while updating node liveness: interrupted during singleflight ‹engine sync:0›: context deadline exceeded
W230620 04:00:25.973745 655 kv/kvserver/liveness/liveness.go:810 ⋮ [T1,n1,liveness-hb] 1590 +
W230620 04:00:25.973745 655 kv/kvserver/liveness/liveness.go:810 ⋮ [T1,n1,liveness-hb] 1590 +An inability to maintain liveness will prevent a node from participating in a
W230620 04:00:25.973745 655 kv/kvserver/liveness/liveness.go:810 ⋮ [T1,n1,liveness-hb] 1590 +cluster. If this problem persists, it may be a sign of resource starvation or
W230620 04:00:25.973745 655 kv/kvserver/liveness/liveness.go:810 ⋮ [T1,n1,liveness-hb] 1590 +of network connectivity problems. For help troubleshooting, visit:
W230620 04:00:25.973745 655 kv/kvserver/liveness/liveness.go:810 ⋮ [T1,n1,liveness-hb] 1590 +
W230620 04:00:25.973745 655 kv/kvserver/liveness/liveness.go:810 ⋮ [T1,n1,liveness-hb] 1590 + https://www.cockroachlabs.com/docs/stable/cluster-setup-troubleshooting.html#node-liveness-issues
W230620 04:00:26.827176 833 server/node.go:1075 ⋮ [T1,n1,summaries] 1591 health alerts detected: {Alerts:[{StoreID:0 Category:‹METRICS› Description:‹liveness.heartbeatfailures› Value:1}]}
I230620 04:00:27.040338 568 kv/kvserver/replica_raft.go:1531 ⋮ [T1,n1,s1,r2/1:‹/System/NodeLiveness{-Max}›,raft] 1592 slow non-blocking raft commit: commit-wait 4.149644868s sem 167ns
I230620 04:00:35.774789 570 kv/kvserver/store_gossip.go:134 ⋮ [T1,n1,s1,r1/1:‹/{Min-System/NodeL…}›] 1593 could not gossip first range descriptor: [NotLeaseHolderError] ‹lease acquisition canceled because context canceled›; r1: replica (n1,s1):1 not lease holder; lease holder unknown
W230620 04:00:41.858325 748 kv/kvserver/store_raft.go:316 ⋮ [-] 1594 raft receive queue for r44 is full
W230620 04:00:41.984680 575 13@kv/kvserver/store_rebalancer.go:323 ⋮ [T1,n1,s1,store-rebalancer,obj=‹cpu›] 1595 StorePool missing descriptor for local store with ID 1, store list ‹ candidate: avg-ranges=66.00 avg-leases=25.00 avg-disk-usage=1.4 GiB avg-queries-per-second=12.86 avg-store-cpu-per-second=10ms›
W230620 04:00:41.984680 575 13@kv/kvserver/store_rebalancer.go:323 ⋮ [T1,n1,s1,store-rebalancer,obj=‹cpu›] 1595 +‹ 2: ranges=66 leases=25 disk-usage=1.4 GiB queries-per-second=11.27 store-cpu-per-second=9ms io-overload=0.00›
W230620 04:00:41.984680 575 13@kv/kvserver/store_rebalancer.go:323 ⋮ [T1,n1,s1,store-rebalancer,obj=‹cpu›] 1595 +‹ 3: ranges=66 leases=25 disk-usage=1.4 GiB queries-per-second=14.46 store-cpu-per-second=11ms io-overload=0.00›
W230620 04:00:42.231078 575 13@kv/kvserver/store_rebalancer.go:431 ⋮ [T1,n1,s1,store-rebalancer,obj=‹cpu›] 1596 no rebalance context given, bailing out of rebalancing store, will try again later
W230620 04:00:42.858581 748 kv/kvserver/store_raft.go:316 ⋮ [-] 1597 raft receive queue for r44 is full
W230620 04:00:44.858976 748 kv/kvserver/store_raft.go:316 ⋮ [-] 1598 raft receive queue for r44 is full
W230620 04:00:46.858709 748 kv/kvserver/store_raft.go:316 ⋮ [-] 1599 raft receive queue for r44 is full
W230620 04:00:47.593111 1722 kv/kvserver/closedts/sidetransport/receiver.go:139 ⋮ [n1] 1600 closed timestamps side-transport connection dropped from node: 3
W230620 04:00:47.593157 1898 kv/kvserver/closedts/sidetransport/receiver.go:139 ⋮ [n1] 1601 closed timestamps side-transport connection dropped from node: 2
W230620 04:00:47.593152 641 kv/kvserver/raft_transport.go:605 ⋮ [T1,n1] 1602 while processing outgoing Raft queue to node 3: recv msg error: grpc: ‹error reading from server: EOF› [code 14/Unavailable]:
W230620 04:00:47.593157 60 kv/kvserver/raft_transport.go:605 ⋮ [T1,n1] 1603 while processing outgoing Raft queue to node 2: recv msg error: grpc: ‹error reading from server: EOF› [code 14/Unavailable]:
W230620 04:00:47.593182 493 kv/kvserver/raft_transport.go:605 ⋮ [T1,n1] 1604 while processing outgoing Raft queue to node 3: recv msg error: grpc: ‹error reading from server: EOF› [code 14/Unavailable]:
W230620 04:00:47.593201 55 2@gossip/gossip.go:1406 ⋮ [T1,n1] 1605 no incoming or outgoing connections
W230620 04:00:47.593231 347874 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1606 ‹[core]›‹[Server #1] grpc: Server.processUnaryRPC failed to write status: connection error: desc = "transport is closing"›
W230620 04:00:47.593235 347861 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1607 ‹[core]›‹[Server #1] grpc: Server.processUnaryRPC failed to write status: connection error: desc = "transport is closing"›
W230620 04:00:47.593240 724 kv/kvserver/raft_transport.go:605 ⋮ [T1,n1] 1608 while processing outgoing Raft queue to node 2: recv msg error: grpc: ‹error reading from server: EOF› [code 14/Unavailable]:
W230620 04:00:47.593382 347895 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1609 ‹[core]›‹[Channel #9 SubChannel #11] grpc: addrConn.createTransport failed to connect to {›
W230620 04:00:47.593382 347895 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1609 +‹ "Addr": "localhost:26258",›
W230620 04:00:47.593382 347895 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1609 +‹ "ServerName": "localhost:26258",›
W230620 04:00:47.593382 347895 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1609 +‹ "Attributes": null,›
W230620 04:00:47.593382 347895 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1609 +‹ "BalancerAttributes": null,›
W230620 04:00:47.593382 347895 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1609 +‹ "Type": 0,›
W230620 04:00:47.593382 347895 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1609 +‹ "Metadata": null›
W230620 04:00:47.593382 347895 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1609 +‹}. Err: connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"›
E230620 04:00:47.593447 350 2@rpc/context.go:2399 ⋮ [T1,n1,rnode=?,raddr=‹localhost:26258›,class=system,rpc] 1610 closing connection after: grpc: ‹connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"› [code 14/Unavailable]
I230620 04:00:47.593478 350 rpc/context.go:2313 ⋮ [T1,n1,rnode=?,raddr=‹localhost:26258›,class=system,rpc] 1611 connection heartbeat loop ended with err: grpc: ‹connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"› [code 14/Unavailable]
I230620 04:00:47.593477 347894 1@circuitbreaker/circuitbreaker.go:322 ⋮ [T1,n1] 1612 circuitbreaker: ‹gossip 127.0.0.1:26257->localhost:26258› tripped: grpc: ‹connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"› [code 14/Unavailable]
I230620 04:00:47.593530 347894 1@circuitbreaker/circuitbreaker.go:447 ⋮ [T1,n1] 1613 circuitbreaker: ‹gossip 127.0.0.1:26257->localhost:26258› event: ‹BreakerTripped›
W230620 04:00:47.593540 347894 gossip/client.go:118 ⋮ [T1,n1] 1614 failed to start gossip client to ‹localhost:26258›: grpc: ‹connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"› [code 14/Unavailable]
E230620 04:00:47.593798 342480 util/log/logcrash/crash_reporting.go:373 ⋮ [T1,n1] 1615 Queued as error ‹86a1698254d94f4ca9cfb6aa93fff494›
W230620 04:00:47.725793 346430 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1616 ‹[core]›‹[Channel #41 SubChannel #42] grpc: addrConn.createTransport failed to connect to {›
W230620 04:00:47.725793 346430 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1616 +‹ "Addr": "localhost:26259",›
W230620 04:00:47.725793 346430 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1616 +‹ "ServerName": "localhost:26259",›
W230620 04:00:47.725793 346430 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1616 +‹ "Attributes": null,›
W230620 04:00:47.725793 346430 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1616 +‹ "BalancerAttributes": null,›
W230620 04:00:47.725793 346430 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1616 +‹ "Type": 0,›
W230620 04:00:47.725793 346430 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1616 +‹ "Metadata": null›
W230620 04:00:47.725793 346430 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1616 +‹}. Err: connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"›
E230620 04:00:47.725890 725 2@rpc/context.go:2399 ⋮ [T1,n1,rnode=2,raddr=‹localhost:26259›,class=default,rpc] 1617 closing connection after: grpc: ‹connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"› [code 14/Unavailable]
I230620 04:00:47.725944 725 rpc/context.go:2313 ⋮ [T1,n1,rnode=2,raddr=‹localhost:26259›,class=default,rpc] 1618 connection heartbeat loop ended with err: grpc: ‹connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"› [code 14/Unavailable]
W230620 04:00:47.761236 1616 kv/kvserver/closedts/sidetransport/sender.go:825 ⋮ [T1,n1,ctstream=2] 1619 failed to send closed timestamp message 57056 to n2: send msg error: ‹EOF›
W230620 04:00:47.761236 1617 kv/kvserver/closedts/sidetransport/sender.go:825 ⋮ [T1,n1,ctstream=3] 1620 failed to send closed timestamp message 57056 to n3: send msg error: ‹EOF›
W230620 04:00:47.927606 347897 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1621 ‹[core]›‹[Channel #27 SubChannel #29] grpc: addrConn.createTransport failed to connect to {›
W230620 04:00:47.927606 347897 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1621 +‹ "Addr": "localhost:26258",›
W230620 04:00:47.927606 347897 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1621 +‹ "ServerName": "localhost:26258",›
W230620 04:00:47.927606 347897 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1621 +‹ "Attributes": null,›
W230620 04:00:47.927606 347897 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1621 +‹ "BalancerAttributes": null,›
W230620 04:00:47.927606 347897 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1621 +‹ "Type": 0,›
W230620 04:00:47.927606 347897 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1621 +‹ "Metadata": null›
W230620 04:00:47.927606 347897 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1621 +‹}. Err: connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"›
W230620 04:00:47.927606 346494 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1622 ‹[core]›‹[Channel #34 SubChannel #35] grpc: addrConn.createTransport failed to connect to {›
W230620 04:00:47.927606 346494 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1622 +‹ "Addr": "localhost:26259",›
W230620 04:00:47.927606 346494 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1622 +‹ "ServerName": "localhost:26259",›
W230620 04:00:47.927606 346494 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1622 +‹ "Attributes": null,›
W230620 04:00:47.927606 346494 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1622 +‹ "BalancerAttributes": null,›
W230620 04:00:47.927606 346494 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1622 +‹ "Type": 0,›
W230620 04:00:47.927606 346494 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1622 +‹ "Metadata": null›
W230620 04:00:47.927606 346494 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1622 +‹}. Err: connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"›
W230620 04:00:47.927606 347987 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1623 ‹[core]›‹[Channel #26 SubChannel #28] grpc: addrConn.createTransport failed to connect to {›
W230620 04:00:47.927606 347987 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1623 +‹ "Addr": "localhost:26259",›
W230620 04:00:47.927606 347987 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1623 +‹ "ServerName": "localhost:26259",›
W230620 04:00:47.927606 347987 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1623 +‹ "Attributes": null,›
W230620 04:00:47.927606 347987 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1623 +‹ "BalancerAttributes": null,›
W230620 04:00:47.927606 347987 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1623 +‹ "Type": 0,›
W230620 04:00:47.927606 347987 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1623 +‹ "Metadata": null›
W230620 04:00:47.927606 347987 google.golang.org/grpc/grpclog/component.go:41 ⋮ [-] 1623 +‹}. Err: connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"›
E230620 04:00:47.927679 661 2@rpc/context.go:2399 ⋮ [T1,n1,rnode=?,raddr=‹localhost:26259›,class=system,rpc] 1625 closing connection after: grpc: ‹connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"› [code 14/Unavailable]
E230620 04:00:47.927679 582 2@rpc/context.go:2399 ⋮ [T1,n1,rnode=3,raddr=‹localhost:26258›,class=system,rpc] 1624 closing connection after: grpc: ‹connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"› [code 14/Unavailable]
E230620 04:00:47.927680 62 2@rpc/context.go:2399 ⋮ [T1,n1,rnode=2,raddr=‹localhost:26259›,class=system,rpc] 1626 closing connection after: grpc: ‹connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"› [code 14/Unavailable]
I230620 04:00:47.927705 661 rpc/context.go:2313 ⋮ [T1,n1,rnode=?,raddr=‹localhost:26259›,class=system,rpc] 1627 connection heartbeat loop ended with err: grpc: ‹connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"› [code 14/Unavailable]
I230620 04:00:47.927706 582 rpc/context.go:2313 ⋮ [T1,n1,rnode=3,raddr=‹localhost:26258›,class=system,rpc] 1628 connection heartbeat loop ended with err: grpc: ‹connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"› [code 14/Unavailable]
I230620 04:00:47.927707 62 rpc/context.go:2313 ⋮ [T1,n1,rnode=2,raddr=‹localhost:26259›,class=system,rpc] 1629 connection heartbeat loop ended with err: grpc: ‹connection error: desc = "transport: error while dialing: connection interrupted (did the remote node shut down or are there networking issues?)"› [code 14/Unavailable]
E230620 04:00:48.027941 347961 2@rpc/context.go:2399 ⋮ [T1,n1,rnode=2,raddr=‹localhost:26259›,class=system,rpc] 1630 unable to connect (is the peer up and reachable?): initial connection heartbeat failed: grpc: ‹connection error: desc = "transport: error while dialing: dial tcp [::1]:26257: connect: connection refused"› [code 2/Unknown]
I230620 04:00:48.027969 347961 rpc/context.go:2313 ⋮ [T1,n1,rnode=2,raddr=‹localhost:26259›,class=system,rpc] 1631 connection heartbeat loop ended with err: initial connection heartbeat failed: grpc: ‹connection error: desc = "transport: error while dialing: dial tcp [::1]:26257: connect: connection refused"› [code 2/Unknown]
I230620 04:00:48.028016 346589 1@circuitbreaker/circuitbreaker.go:322 ⋮ [T1,n1] 1632 circuitbreaker: ‹rpc 127.0.0.1:26257 [n2]› tripped: failed to connect to n2 at ‹localhost:26259›: initial connection heartbeat failed: grpc: ‹connection error: desc = "transport: error while dialing: dial tcp [::1]:26257: connect: connection refused"› [code 2/Unknown]
I230620 04:00:48.028054 346589 1@circuitbreaker/circuitbreaker.go:447 ⋮ [T1,n1] 1633 circuitbreaker: ‹rpc 127.0.0.1:26257 [n2]› event: ‹BreakerTripped›
W230620 04:00:48.028061 346589 2@rpc/nodedialer/nodedialer.go:196 ⋮ [T1,n1] 1634 unable to connect to n2: failed to connect to n2 at ‹localhost:26259›: initial connection heartbeat failed: grpc: ‹connection error: desc = "transport: error while dialing: dial tcp [::1]:26257: connect: connection refused"› [code 2/Unknown]
I230620 04:00:48.029362 346591 rpc/context.go:2313 ⋮ [T1,n1,rnode=3,raddr=‹localhost:26258›,class=system,rpc] 1635 connection heartbeat loop ended with err: initial connection heartbeat failed: grpc: ‹connection error: desc = "transport: error while dialing: dial tcp [::1]:26257: connect: connection refused"› [code 2/Unknown]
I230620 04:00:48.029405 346590 1@circuitbreaker/circuitbreaker.go:322 ⋮ [T1,n1] 1636 circuitbreaker: ‹rpc 127.0.0.1:26257 [n3]› tripped: failed to connect to n3 at ‹localhost:26258›: initial connection heartbeat failed: grpc: ‹connection error: desc = "transport: error while dialing: dial tcp [::1]:26257: connect: connection refused"› [code 2/Unknown]
I230620 04:00:48.029436 346590 1@circuitbreaker/circuitbreaker.go:447 ⋮ [T1,n1] 1637 circuitbreaker: ‹rpc 127.0.0.1:26257 [n3]› event: ‹BreakerTripped›
W230620 04:00:48.029443 346590 2@rpc/nodedialer/nodedialer.go:196 ⋮ [T1,n1] 1638 unable to connect to n3: failed to connect to n3 at ‹localhost:26258›: initial connection heartbeat failed: grpc: ‹connection error: desc = "transport: error while dialing: dial tcp [::1]:26257: connect: connection refused"› [code 2/Unknown]
I230620 04:00:48.100776 342480 1@storage/pebble.go:1268 ⋮ [T1,n1] 1639 the server is terminating due to a fatal error (see the DEV channel for details)
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 file write stall detected: disk slowness detected: syncdata on file 005315.log (0 bytes) has been ongoing for 20.4s
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !goroutine 342480 [running]:
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !runtime/debug.Stack()
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! GOROOT/src/runtime/debug/stack.go:24 +0x65
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc00130d460, {{{0xc007d80bd0, 0x24}, {0x5d8c9db, 0x1}, {0x5d8c9db, 0x1}, {0x5d8c9db, 0x1}}, 0x176a421048227da4, ...})
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! github.com/cockroachdb/cockroach/pkg/util/log/clog.go:261 +0xb8
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x72a32f0, 0xc000da2cf0}, 0x2, 0x4, 0x0, 0x0?, {0x5d563a6, 0x1d}, {0xc00180ddc8, 0x1, ...})
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x645
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !github.com/cockroachdb/cockroach/pkg/util/log.Fatalf(...)
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! github.com/cockroachdb/cockroach/bazel-out/k8-opt/bin/pkg/util/log/log_channels_generated.go:848
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !github.com/cockroachdb/cockroach/pkg/storage.(*Pebble).makeMetricEtcEventListener.func4({{0xc0096c6ed0, 0x2f}, 0x3, 0x0, 0x4bd7c719b})
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! github.com/cockroachdb/cockroach/pkg/storage/pebble.go:1268 +0x215
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !github.com/cockroachdb/pebble.TeeEventListener.func4({{0xc0096c6ed0, 0x2f}, 0x3, 0x0, 0x4bd7c719b})
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! github.com/cockroachdb/pebble/external/com_github_cockroachdb_pebble/event.go:672 +0x4d
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !github.com/cockroachdb/cockroach/pkg/storage.wrapFilesystemMiddleware.func1({{0xc0096c6ed0, 0x2f}, 0x3, 0x0, 0x4bd7c719b})
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! github.com/cockroachdb/cockroach/pkg/storage/pebble.go:668 +0x97
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !github.com/cockroachdb/pebble/vfs.(*diskHealthCheckingFS).ReuseForWrite.func2(0x3e?, 0xa6f8b542846?, 0xb5572c0?)
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! github.com/cockroachdb/pebble/vfs/external/com_github_cockroachdb_pebble/vfs/disk_health.go:754 +0x6b
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !github.com/cockroachdb/pebble/vfs.(*diskHealthCheckingFile).startTicker.func1()
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! github.com/cockroachdb/pebble/vfs/external/com_github_cockroachdb_pebble/vfs/disk_health.go:187 +0x1cf
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !created by github.com/cockroachdb/pebble/vfs.(*diskHealthCheckingFile).startTicker
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! github.com/cockroachdb/pebble/vfs/external/com_github_cockroachdb_pebble/vfs/disk_health.go:167 +0x5d
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !For more context, check log files in: /data/cockroach/cockroach-data/node1/logs
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !****************************************************************************
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !This node experienced a fatal error (printed above), and as a result the
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !process is terminating.
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !Fatal errors can occur due to faulty hardware (disks, memory, clocks) or a
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !problem in CockroachDB. With your help, the support team at Cockroach Labs
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !will try to determine the root cause, recommend next steps, and we can
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !improve CockroachDB based on your report.
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !Please submit a crash report by following the instructions here:
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! https://github.com/cockroachdb/cockroach/issues/new/choose
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !If you would rather not post publicly, please contact us directly at:
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 ! support@cockroachlabs.com
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !
F230620 04:00:48.100801 342480 storage/pebble.go:1268 ⋮ [T1,n1] 1640 !The Cockroach Labs team appreciates your feedback.
```
code:
```go
package main
import (
"context"
"log"
"math/rand"
"time"
"github.com/jmoiron/sqlx"
_ "github.com/lib/pq"
"github.com/samber/lo"
)
type Person struct {
ID int64 `db:"_id"`
RealName string `db:"real_name"`
NickName string `db:"nick_name"`
Sex string `db:"sex"`
Birthday time.Time `db:"birthday"`
Height int32 `db:"height"`
Weight int32 `db:"weight"`
City string `db:"city"`
Deleted bool `db:"deleted"`
CreateTime time.Time `db:"create_time"`
UpdateTime time.Time `db:"update_time"`
}
func main() {
dsn := "postgresql://test@localhost:36256/test?sslmode=verify-full&sslrootcert=/data/cockroach/certs/node.crt&sslcert=/data/cockroach/certs/client.test.crt&sslkey=/data/cockroach/certs/client.test.key"
db, err := sqlx.Open("postgres", dsn)
if err != nil {
log.Fatalln(err)
return
}
defer db.Close()
ctx := context.Background()
err = db.PingContext(ctx)
if err != nil {
log.Println(err)
return
}
var now string
err = db.GetContext(ctx, &now, "SELECT now() AT TIME ZONE 'Asia/Shanghai';")
if err != nil {
log.Fatalln(err)
return
}
log.Println(now)
err = insert(ctx, db, 5000000)
if err != nil {
log.Println(err)
return
}
err = query_by_city(ctx, db, 100)
if err != nil {
log.Println(err)
return
}
log.Println("finished.")
}
func insert(ctx context.Context, db *sqlx.DB, number int) error {
log.Println("start inserting. number:", number)
var total int64
for l := 0; l < number/500; l++ {
persons := make([]*Person, 0, 500)
for idx := 0; idx < 500; idx++ {
person := &Person{
RealName: lo.Sample(firstNames) + lo.Sample(lastNames),
NickName: lo.Sample(firstNames) + lo.Sample(lastNames),
Sex: lo.Sample([]string{"male", "female"}),
Birthday: time.Date(
rand.Intn(100)+1920,
time.Month(rand.Intn(12)+1),
rand.Intn(30),
0,
0,
0,
0,
time.Local,
),
Height: int32(rand.Intn(20) + 160),
Weight: int32(rand.Intn(30) + 50),
City: lo.Sample(cityList),
}
persons = append(persons, person)
}
log.Println("preared.")
_, err := db.NamedExecContext(ctx, `INSERT INTO person
(real_name, nick_name, sex, birthday, height, weight, city)
VALUES(:real_name, :nick_name, :sex, :birthday, :height, :weight, :city)`, persons)
if err != nil {
return err
}
total += int64(len(persons))
log.Println("inserted:", total)
}
log.Println("complete insertion.")
return nil
}
func query_by_city(ctx context.Context, db *sqlx.DB, number int) error {
log.Println("start quering. condition: city. number:", number)
for idx := 0; idx < number; idx++ {
city := lo.Sample(cityList)
var rows []*Person
err := db.SelectContext(
ctx,
&rows,
`SELECT _id, real_name, nick_name, sex, birthday, height, weight, city, deleted, create_time, update_time
FROM person
WHERE city = $1`,
city,
)
if err != nil {
return err
}
}
log.Println("complete querion.")
return nil
}
```
Jira issue: CRDB-28904
Contributor guide
Assessment
This issue has not been assessed yet.