sql/importer: TestExportJoin failed #101612

cockroach-teamcity · 2023-04-16T14:36:47Z

sql/importer.TestExportJoin failed with artifacts on master @ e7cac13f62d69373bc3a025d38de03ea2a02ee35:

Fatal error:

panic: logging already active; first use:

Stack:

goroutine 5155563 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc000456b20, {{{0xc018e4bd40, 0x24}, {0x0, 0x0}, {0x60add4b, 0x1}, {0x60add4f, 0x1}}, 0x1756710a3cbc0e79, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x7622280, 0xc0183dd620}, 0x2, 0x1, 0x0, 0x0?, {0x6069108, 0x1c}, {0xc0384d5b20, 0x1, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.Infof(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:277
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processReady(0xc0044f2a80, 0x7622280?)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_raft.go:655 +0x337
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker(0xc005fa4480, {0x7622280, 0xc0156c8870}, {0x7605f00, 0xc0044f2a80}, 0xc0129d2000)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:392 +0x195
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2({0x7622280?, 0xc0156c8870?})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:299 +0x45
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b [recovered]
	panic: logging already active; first use:
goroutine 5155563 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc000456b20, {{{0xc018e4bd40, 0x24}, {0x0, 0x0}, {0x60add4b, 0x1}, {0x60add4f, 0x1}}, 0x1756710a3cbc0e79, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x7622280, 0xc0183dd620}, 0x2, 0x1, 0x0, 0x0?, {0x6069108, 0x1c}, {0xc0384d5b20, 0x1, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.Infof(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:277
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processReady(0xc0044f2a80, 0x7622280?)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_raft.go:655 +0x337
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker(0xc005fa4480, {0x7622280, 0xc0156c8870}, {0x7605f00, 0xc0044f2a80}, 0xc0129d2000)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:392 +0x195
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2({0x7622280?, 0xc0156c8870?})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:299 +0x45
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b

Log preceding fatal error

=== RUN   TestExportJoin
I230416 14:36:39.511580 5043010 kv/kvserver/store_raft.go:655  [T1,n3,s3,r31/5:/{Table/29-NamespaceTab…},raft] 38  raft ready handling: 0.74s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.74s], wrote [append-batch=12 B, ]; node might be overloaded
I230416 14:36:39.511709 5043178 kv/kvserver/store_raft.go:655  [T1,n3,s3,r27/5:/Table/2{5-6},raft] 40  raft ready handling: 0.82s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.82s], wrote [append-batch=12 B, ]; node might be overloaded
I230416 14:36:39.511967 5043035 kv/kvserver/store_raft.go:655  [T1,n3,s3,r1/3:/{Min-System/NodeL…},raft] 39  raft ready handling: 0.89s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.89s], wrote [append-batch=12 B, ]; node might be overloaded
W230416 14:36:39.514135 5156487 kv/kvserver/replica_gossip.go:157  [T1,n5,s5,r2/4:/System/NodeLiveness{-Max}] 42  could not acquire lease for range gossip: replica unavailable: (n5,s5):4 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, (n4,s4):5, next=6, gen=8]: closed timestamp: 1681655406.651898531,0 (2023-04-16 14:30:06); raft status: {"id":"4","term":83,"vote":"4","commit":283,"lead":"0","raftState":"StatePreCandidate","applied":283,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/System/NodeLiveness,/Min)
I230416 14:36:39.512265 5043203 kv/kvserver/store_raft.go:655  [T1,n3,s3,r51/3:/Table/5{0-1},raft] 41  raft ready handling: 1.10s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.10s], wrote [append-batch=12 B, ]; node might be overloaded
W230416 14:36:39.525875 8361238 2@rpc/clock_offset.go:276  [T1,n4,rnode=2,raddr=127.0.0.1:37135,class=system,rpc] 44  latency jump (prev avg 143.91ms, current 693.14ms)
I230416 14:36:39.510792 5043473 kv/kvserver/store_raft.go:655  [T1,n3,s3,r47/2:/Table/4{5-6},raft] 43  raft ready handling: 1.34s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.34s], wrote [append-batch=320 B, append-ent=219 B (1), ]; node might be overloaded
I230416 14:36:39.517931 5043228 kv/kvserver/store_raft.go:655  [T1,n3,s3,r21/3:/Table/{19-20},raft] 45  raft ready handling: 0.93s [append=0.00s, apply=0.61s, sync=0.00s, other=0.32s], wrote [append-batch=50 B, apply=219 B (1)]; node might be overloaded
I230416 14:36:39.525985 33596795 gossip/client.go:124  [T1,n3] 46  started gossip client to n0 (127.0.0.1:37135)
I230416 14:36:39.536996 5042913 kv/kvserver/store_raft.go:655  [T1,n3,s3,r36/4:/Table/3{4-5},raft] 47  raft ready handling: 1.17s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.17s], wrote [append-batch=49 B, ]; node might be overloaded
I230416 14:36:39.537285 5043397 kv/kvserver/store_raft.go:655  [T1,n3,s3,r64/2:/Table/106/1/{60-80},raft] 48  raft ready handling: 0.87s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.87s], wrote [append-batch=284 B, append-ent=221 B (1), ]; node might be overloaded
I230416 14:36:39.537720 5043102 kv/kvserver/store_raft.go:655  [T1,n3,s3,r44/3:/Table/4{2-3},raft] 49  raft ready handling: 0.69s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.69s], wrote [append-batch=12 B, ]; node might be overloaded
I230416 14:36:39.557256 5042918 kv/kvserver/store_raft.go:655  [T1,n3,s3,r66/2:/Table/106/1/{40-60},raft] 50  raft ready handling: 0.71s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.71s], wrote [append-batch=294 B, append-ent=231 B (1), ]; node might be overloaded
I230416 14:36:39.557995 4619357 kv/kvserver/store_raft.go:655  [T1,n1,s1,r56/1:/Table/5{5-6},raft] 51  raft ready handling: 1.12s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.12s], wrote [append-batch=50 B, ]; node might be overloaded
I230416 14:36:39.563377 4619090 kv/kvserver/store_raft.go:655  [T1,n1,s1,r24/1:/Table/2{2-3},raft] 53  raft ready handling: 1.33s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.33s], wrote [append-batch=296 B, append-ent=233 B (1), ]; node might be overloaded
I230416 14:36:39.568309 5043163 kv/kvserver/store_raft.go:655  [T1,n3,s3,r50/2:/Table/{48-50},raft] 52  raft ready handling: 1.18s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.18s], wrote [append-batch=12 B, ]; node might be overloaded
I230416 14:36:39.545804 5043058 kv/kvserver/store_raft.go:655  [T1,n3,s3,r14/5:/Table/1{2-3},raft] 54  raft ready handling: 0.74s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.74s], wrote [append-batch=12 B, ]; node might be overloaded
I230416 14:36:39.577424 4995840 kv/kvserver/store_raft.go:655  [T1,n2,s2,r35/3:/Table/3{3-4},raft] 58  raft ready handling: 0.65s [append=0.00s, apply=0.00s, , other=0.65s], wrote []; node might be overloaded
I230416 14:36:39.571352 4619510 kv/kvserver/store_raft.go:655  [T1,n1,s1,r39/1:/Table/3{7-8},raft] 55  raft ready handling: 1.40s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.40s], wrote [append-batch=12 B, ]; node might be overloaded
W230416 14:36:39.573073 4619805 kv/kvserver/replica_gossip.go:157  [T1,n1,s1,r1/1:/{Min-System/NodeL…}] 56  could not acquire lease for range gossip: replica unavailable: (n1,s1):1 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n4,s4):2, (n3,s3):3, (n2,s2):4, (n5,s5):5, next=6, gen=8]: closed timestamp: 1681655552.965342780,0 (2023-04-16 14:32:32); raft status: {"id":"1","term":62,"vote":"4","commit":1300,"lead":"0","raftState":"StateFollower","applied":1300,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Min,/Min)
I230416 14:36:39.582924 5043509 kv/kvserver/store_raft.go:655  [T1,n3,s3,r35/2:/Table/3{3-4},raft] 57  raft ready handling: 0.98s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.98s], wrote [append-batch=12 B, ]; node might be overloaded
I230416 14:36:39.634138 5099996 kv/kvserver/replica_rangefeed.go:711  [T1,n4,s4,r48/5:/Table/4{6-7}] 60  RangeFeed closed timestamp 1681655768.741370487,0 is behind by 30.892704602s
I230416 14:36:39.623211 5043297 kv/kvserver/store_raft.go:655  [T1,n3,s3,r22/4:/Table/2{0-1},raft] 61  raft ready handling: 0.83s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.83s], wrote [append-batch=382 B, append-ent=319 B (1), ]; node might be overloaded
I230416 14:36:39.615277 4619203 kv/kvserver/store_raft.go:655  [T1,n1,s1,r12/1:/Table/{8-11},raft] 59  raft ready handling: 1.34s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.34s], wrote [append-batch=12 B, ]; node might be overloaded
I230416 14:36:39.627787 4619238 kv/kvserver/store_raft.go:655  [T1,n1,s1,r1/1:/{Min-System/NodeL…},raft] 62  raft ready handling: 1.44s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.44s], wrote [append-batch=12 B, ]; node might be overloaded
I230416 14:36:39.652028 5155563 kv/kvserver/store_raft.go:655  [T1,n5,s5,r37/3:/Table/3{5-6},raft] 64  raft ready handling: 1.09s [append=0.00s, apply=0.00s, sync=0.00s, other=1.09s], wrote [append-batch=12 B, ]; node might be overloaded
I230416 14:36:39.714603 4995438 kv/kvserver/store_raft.go:655  [T1,n2,s2,r3/3:/System/{NodeLive…-tsd},raft] 66  raft ready handling: 0.81s [append=0.00s, apply=0.00s, , other=0.81s], wrote []; node might be overloaded
--- FAIL: TestExportJoin (0.17s)
W230416 14:36:39.649236 8368647 2@rpc/clock_offset.go:276  [T1,n3,rnode=2,raddr=127.0.0.1:37135,class=system,rpc] 65  latency jump (prev avg 147.19ms, current 238.70ms)

Parameters: TAGS=bazel,gss,deadlock

Help

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

/cc @cockroachdb/sql-queries _{This test on roachdash | Improve this report!

Jira issue: CRDB-27060
Epic CRDB-27234}

The text was updated successfully, but these errors were encountered:

cockroach-teamcity · 2023-04-18T14:18:52Z

sql/importer.TestExportJoin failed with artifacts on master @ 1de7ba85509d0305108ad6be0d273621fa700d19:

Fatal error:

panic: logging already active; first use:

Stack:

goroutine 4539073 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc000356c80, {{{0xc00c787b60, 0x24}, {0x0, 0x0}, {0x60b03ed, 0x1}, {0x60b03ed, 0x1}}, 0x17570d392a51f20e, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x76250e0, 0xc0098566c0}, 0x2, 0x1, 0x0, 0x88?, {0x610a120, 0x2d}, {0xc0090d0cd8, 0x2, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.Infof(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:277
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).handleClosedTimestampUpdateRaftMuLocked(0xc01cb7d900, {0x76250e0, 0xc0098566c0}, {0xc007cdce40?, 0x16836810?, 0xc0?})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:711 +0x26e
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).handleClosedTimestampUpdate(0xc01cb7d900, {0x7625038?, 0xc007cdce40?}, {0xbebc200?, 0x0?, 0x0?})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:687 +0xf7
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).startRangefeedUpdater.func1({0x76250e0?, 0xc01b0d8d80?})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store.go:2299 +0x58c
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b [recovered]
	panic: logging already active; first use:
goroutine 4539073 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc000356c80, {{{0xc00c787b60, 0x24}, {0x0, 0x0}, {0x60b03ed, 0x1}, {0x60b03ed, 0x1}}, 0x17570d392a51f20e, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x76250e0, 0xc0098566c0}, 0x2, 0x1, 0x0, 0x88?, {0x610a120, 0x2d}, {0xc0090d0cd8, 0x2, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.Infof(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:277
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).handleClosedTimestampUpdateRaftMuLocked(0xc01cb7d900, {0x76250e0, 0xc0098566c0}, {0xc007cdce40?, 0x16836810?, 0xc0?})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:711 +0x26e
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).handleClosedTimestampUpdate(0xc01cb7d900, {0x7625038?, 0xc007cdce40?}, {0xbebc200?, 0x0?, 0x0?})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:687 +0xf7
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).startRangefeedUpdater.func1({0x76250e0?, 0xc01b0d8d80?})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store.go:2299 +0x58c
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b

Log preceding fatal error

E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*replicaCircuitBreaker).tripSync
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_circuit_breaker.go:110
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*replicaCircuitBreaker).TripAsync.func1
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_circuit_breaker.go:104
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | 	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | runtime.goexit
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | 	GOROOT/src/runtime/asm_amd64.s:1594
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +Wraps: (8) closed timestamp: 1681826931.567596609,0 (2023-04-18 14:08:51); raft status: {"id":"5","term":31,"vote":"1","commit":135,"lead":"0","raftState":"StatePreCandidate","applied":135,"progress":{},"leadtransferee":"0"}
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +Wraps: (9)
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | (opaque error wrapper)
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | type name: github.com/cockroachdb/errors/withstack/*withstack.withStack
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | reportable 0:
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  |
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).refreshProposalsLocked
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_raft.go:1403
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).tick
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_raft.go:1266
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processTick
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_raft.go:674
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:386
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:299
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | 	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | runtime.goexit
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +  | 	GOROOT/src/runtime/asm_amd64.s:1594
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +Wraps: (10) have been waiting 60.50s for slow proposal RequestLease [/Table/3,/Min)
E230418 14:18:44.931441 4898870 jobs/job_scheduler.go:429  [T1,n1] 53 +Error types: (1) *secondary.withSecondaryError (2) *withstack.withStack (3) *errutil.withPrefix (4) *markers.withMark (5) *markers.withMark (6) *kvpb.ReplicaUnavailableError (7) *errbase.opaqueWrapper (8) *errutil.withPrefix (9) *errbase.opaqueWrapper (10) *errutil.leafError
I230418 14:18:44.932207 5076964 kv/kvserver/store_raft.go:655  [T1,n5,s5,r54/2:/Table/5{3-4},raft] 54  raft ready handling: 0.73s [append=0.00s, apply=0.00s, , other=0.73s], wrote []; node might be overloaded
I230418 14:18:44.988631 4913310 kv/kvserver/store_raft.go:655  [T1,n2,s2,r43/4:/Table/4{1-2},raft] 56  raft ready handling: 0.71s [append=0.00s, apply=0.00s, sync=0.00s, other=0.71s], wrote [append-batch=320 B, append-ent=219 B (1), ]; node might be overloaded
W230418 14:18:44.910300 4539612 kv/kvserver/liveness/liveness.go:810  [T1,n1,liveness-hb] 55  failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 5.447s (given timeout 3s): aborted during DistSender.Send: context deadline exceeded
W230418 14:18:44.910300 4539612 kv/kvserver/liveness/liveness.go:810  [T1,n1,liveness-hb] 55 +
W230418 14:18:44.910300 4539612 kv/kvserver/liveness/liveness.go:810  [T1,n1,liveness-hb] 55 +An inability to maintain liveness will prevent a node from participating in a
W230418 14:18:44.910300 4539612 kv/kvserver/liveness/liveness.go:810  [T1,n1,liveness-hb] 55 +cluster. If this problem persists, it may be a sign of resource starvation or
W230418 14:18:44.910300 4539612 kv/kvserver/liveness/liveness.go:810  [T1,n1,liveness-hb] 55 +of network connectivity problems. For help troubleshooting, visit:
W230418 14:18:44.910300 4539612 kv/kvserver/liveness/liveness.go:810  [T1,n1,liveness-hb] 55 +
W230418 14:18:44.910300 4539612 kv/kvserver/liveness/liveness.go:810  [T1,n1,liveness-hb] 55 +    https://www.cockroachlabs.com/docs/stable/cluster-setup-troubleshooting.html#node-liveness-issues
I230418 14:18:44.988860 4538434 kv/kvserver/store_raft.go:655  [T1,n1,s1,r19/1:/Table/1{7-8},raft] 57  raft ready handling: 1.12s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.12s], wrote [append-batch=12 B, ]; node might be overloaded
W230418 14:18:45.003444 5098650 2@rpc/clock_offset.go:276  [T1,n1,rnode=5,raddr=127.0.0.1:45403,class=default,rpc] 60  latency jump (prev avg 144.80ms, current 303.41ms)
W230418 14:18:45.020262 8376465 2@rpc/clock_offset.go:276  [T1,n4,rnode=3,raddr=127.0.0.1:44233,class=default,rpc] 61  latency jump (prev avg 144.17ms, current 220.39ms)
E230418 14:18:44.988037 4551827 jobs/registry.go:1060  [T1,n1] 58  error processing claimed jobs: could not query for claimed jobs: select-running/get-claimed-jobs: replica unavailable: (n3,s3):5 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n2,s2):2, (n5,s5):3, (n4,s4):4, (n3,s3):5, next=6, gen=8]: closed timestamp: 1681826931.567596609,0 (2023-04-18 14:08:51); raft status: {"id":"5","term":31,"vote":"1","commit":135,"lead":"0","raftState":"StatePreCandidate","applied":135,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/3,/Min)
I230418 14:18:45.000534 31508258 kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:77  [T1,n5,rangefeed=tenant-boundaries-watcher] 59  Establishing MuxRangeFeed (/Table/5{7-8}@1681826795.295300291,0...; 1 spans)
I230418 14:18:45.015819 4538474 kv/kvserver/store_raft.go:655  [T1,n1,s1,r7/1:/Table/{3-4},raft] 62  raft ready handling: 1.32s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.32s], wrote [append-batch=387 B, append-ent=324 B (1), ]; node might be overloaded
I230418 14:18:45.020480 4539073 kv/kvserver/replica_rangefeed.go:711  [T1,n1,s1,r7/1:/Table/{3-4}] 63  RangeFeed closed timestamp 1681827446.162766603,0 is behind by 1m18.851981623s
W230418 14:18:45.033325 8364573 2@rpc/clock_offset.go:276  [T1,n2,rnode=3,raddr=127.0.0.1:44233,class=default,rpc] 65  latency jump (prev avg 133.82ms, current 295.57ms)
I230418 14:18:45.022491 5013490 kv/kvserver/store_raft.go:655  [T1,n4,s4,r46/3:/Table/4{4-5},raft] 64  raft ready handling: 1.42s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.42s], wrote [append-batch=12 B, ]; node might be overloaded
W230418 14:18:45.018612 5095617 kv/kvclient/rangefeed/rangefeed.go:331  [T1,n5,rangefeed=system-config-cache] 66  rangefeed failed 5 times, restarting: replica unavailable: (n3,s3):5 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n2,s2):2, (n5,s5):3, (n4,s4):4, (n3,s3):5, next=6, gen=8]: closed timestamp: 1681827446.162766603,0 (2023-04-18 14:17:26); raft status: {"id":"5","term":44,"vote":"5","commit":181,"lead":"5","raftState":"StateLeader","applied":180,"progress":{"2":{"match":180,"next":183,"state":"StateReplicate"},"3":{"match":182,"next":183,"state":"StateReplicate"},"4":{"match":0,"next":179,"state":"StateProbe"},"5":{"match":181,"next":182,"state":"StateReplicate"},"1":{"match":182,"next":183,"state":"StateReplicate"}},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/3,/Min)
--- FAIL: TestExportJoin (0.13s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

_{This test on roachdash | Improve this report!}

yuzefovich · 2023-04-19T00:44:12Z

Both failures have "kv.expiration_leases_only.enabled" with value true, and I didn't find any other suspiciously looking commits from the last few days before the first SHA. cc @erikgrinaker

cockroach-teamcity · 2023-04-19T14:16:52Z

sql/importer.TestExportJoin failed with artifacts on master @ 8688fc98fca1a1ab64bcd913170eaf786ae0cd6f:

Fatal error:

panic: logging already active; first use:

Stack:

goroutine 8521828 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc0001ac8c0, {{{0xc015ccfe60, 0x24}, {0x0, 0x0}, {0x60b1a42, 0x1}, {0x60b1a46, 0x1}}, 0x17575bb1e299b964, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x7628100, 0xc00bb95a70}, 0x2, 0x2, 0x2, 0x40?, {0x611ae08, 0x2e}, {0xc020b8baa0, 0x2, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.loggerHealth.Warningf(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:1664
github.com/cockroachdb/cockroach/pkg/rpc.(*RemoteClockMonitor).UpdateOffset(0xc00bebc5b0, {0x7628100, 0xc00bb95a70}, 0x2, {0x7a505cadee?, 0x0?, 0x0?}, 0x280c4ac2)
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/clock_offset.go:276 +0x637
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).runHeartbeat.func2({0x7628100, 0xc00bb95a70})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2549 +0x552
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr(0xc014682200, {0x7628100, 0xc00bb95a70}, {0x0?, 0x12?}, 0xc020b8be30)
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:322 +0xd1
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).runHeartbeat(0xc007a8ce00, {0x7628100, 0xc00bb95a70}, 0xc00609de90, {0xc01121bd00?, 0xc001216ee8?})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2460 +0x4af
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).grpcDialNodeInternal.func1({0x7628100, 0xc00bb95a70})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2301 +0xc6
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b [recovered]
	panic: logging already active; first use:
goroutine 8521828 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc0001ac8c0, {{{0xc015ccfe60, 0x24}, {0x0, 0x0}, {0x60b1a42, 0x1}, {0x60b1a46, 0x1}}, 0x17575bb1e299b964, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x7628100, 0xc00bb95a70}, 0x2, 0x2, 0x2, 0x40?, {0x611ae08, 0x2e}, {0xc020b8baa0, 0x2, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.loggerHealth.Warningf(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:1664
github.com/cockroachdb/cockroach/pkg/rpc.(*RemoteClockMonitor).UpdateOffset(0xc00bebc5b0, {0x7628100, 0xc00bb95a70}, 0x2, {0x7a505cadee?, 0x0?, 0x0?}, 0x280c4ac2)
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/clock_offset.go:276 +0x637
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).runHeartbeat.func2({0x7628100, 0xc00bb95a70})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2549 +0x552
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr(0xc014682200, {0x7628100, 0xc00bb95a70}, {0x0?, 0x12?}, 0xc020b8be30)
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:322 +0xd1
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).runHeartbeat(0xc007a8ce00, {0x7628100, 0xc00bb95a70}, 0xc00609de90, {0xc01121bd00?, 0xc001216ee8?})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2460 +0x4af
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).grpcDialNodeInternal.func1({0x7628100, 0xc00bb95a70})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2301 +0xc6
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b

Log preceding fatal error

=== RUN   TestExportJoin
I230419 14:16:45.220330 5012919 kv/kvserver/store_raft.go:656  [T1,n2,s2,r3/4:/System/{NodeLive…-tsd},raft] 41  raft ready handling: 1.04s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.04s], wrote [append-batch=12 B, ]; node might be overloaded
I230419 14:16:45.220809 5012770 kv/kvserver/store_raft.go:656  [T1,n2,s2,r38/4:/Table/3{6-7},raft] 42  raft ready handling: 1.00s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.00s], wrote [append-batch=12 B, ]; node might be overloaded
I230419 14:16:45.244615 5114607 kv/kvserver/store_raft.go:656  [T1,n4,s4,r55/2:/Table/5{4-5},raft] 43  raft ready handling: 1.06s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.06s], wrote [append-batch=12 B, ]; node might be overloaded
I230419 14:16:45.265577 4632275 kv/kvserver/store_raft.go:656  [T1,n1,s1,r28/1:/Table/2{6-7},raft] 45  raft ready handling: 0.98s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.98s], wrote [append-batch=49 B, ]; node might be overloaded
I230419 14:16:45.241091 5172876 kv/kvserver/store_raft.go:656  [T1,n5,s5,r49/2:/Table/4{7-8},raft] 44  raft ready handling: 0.75s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.75s], wrote [append-batch=57 B, append-ent=0 B (1), ]; node might be overloaded
I230419 14:16:45.249639 4632312 kv/kvserver/store_raft.go:656  [T1,n1,s1,r29/1:/Table/2{7-8},raft] 46  raft ready handling: 0.57s [append=0.00s, apply=0.00s, , other=0.57s], wrote []; node might be overloaded
I230419 14:16:45.287273 22549322 kv/txn.go:875  [T1,n2] 47  async rollback failed: replica unavailable: (n4,s4):4 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n4,s4):4, (n5,s5):5, next=6, gen=8]: closed timestamp: 1681913430.076060569,0 (2023-04-19 14:10:30); raft status: {"id":"4","term":46,"vote":"1","commit":242,"lead":"0","raftState":"StatePreCandidate","applied":242,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/System/NodeLiveness,/Min): "unnamed" meta={id=a3861faa key=/System/NodeLiveness/2 iso=Serializable pri=0.00895169 epo=0 ts=1681913795.457652404,0 min=1681913795.457652404,0 seq=0} lock=true stat=PENDING rts=1681913795.457652404,0 wto=false gul=1681913795.957652404,0
I230419 14:16:45.267575 4631871 kv/kvserver/store_raft.go:656  [T1,n1,s1,r19/1:/Table/1{7-8},raft] 48  raft ready handling: 0.65s [append=0.00s, apply=0.00s, , other=0.65s], wrote []; node might be overloaded
I230419 14:16:45.254388 5174070 kv/kvserver/store_raft.go:656  [T1,n5,s5,r27/2:/Table/2{5-6},raft] 49  raft ready handling: 0.77s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.77s], wrote [append-batch=49 B, ]; node might be overloaded
I230419 14:16:45.302871 5115459 kv/kvserver/store_raft.go:656  [T1,n4,s4,r10/2:/Table/{6-7},raft] 50  raft ready handling: 0.75s [append=0.00s, apply=0.00s, , other=0.75s], wrote []; node might be overloaded
I230419 14:16:45.286685 5114462 kv/kvserver/store_raft.go:656  [T1,n4,s4,r66/3:/Table/106/1/{40-60},raft] 51  raft ready handling: 1.20s [append=0.00s, apply=0.66s, non-blocking-sync=0.00s, other=0.54s], wrote [append-batch=50 B, apply=305 B (1)]; node might be overloaded
I230419 14:16:45.311733 5012882 kv/kvserver/store_raft.go:656  [T1,n2,s2,r51/3:/Table/5{0-1},raft] 53  raft ready handling: 0.95s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.95s], wrote [append-batch=12 B, ]; node might be overloaded
I230419 14:16:45.308517 5114555 kv/kvserver/store_raft.go:656  [T1,n4,s4,r61/2:/Table/6{0-1},raft] 52  raft ready handling: 1.11s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.11s], wrote [append-batch=12 B, ]; node might be overloaded
I230419 14:16:45.321878 5114560 kv/kvserver/store_raft.go:656  [T1,n4,s4,r25/3:/Table/2{3-4},raft] 54  raft ready handling: 1.12s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.12s], wrote [append-batch=12 B, ]; node might be overloaded
I230419 14:16:45.336276 5012569 kv/kvserver/store_raft.go:656  [T1,n2,s2,r30/4:/Table/2{8-9},raft] 56  raft ready handling: 0.99s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.99s], wrote [append-batch=12 B, ]; node might be overloaded
W230419 14:16:45.337592 5063633 kv/kvclient/kvcoord/dist_sender.go:1694  [T1,n3,summaries] 55  slow range RPC: have been waiting 65.64s (3 attempts) for RPC Get [/System/StatusNode/3,/Min) to r3:/System/{NodeLivenessMax-tsd} [(n1,s1):1, (n4,s4):2, (n3,s3):3, (n2,s2):4, (n5,s5):5, next=6, gen=8]; resp: failed to send RPC: sending to all replicas failed; last error: [NotLeaseHolderError] lease acquisition canceled because context canceled; r3: replica (n2,s2):4 not lease holder; lease holder unknown
E230419 14:16:45.340865 22720618 kv/kvserver/queue.go:1142  [T1,n1,replicaGC,s1,r29/1:/Table/2{7-8}] 57  replica unavailable: (n3,s3):4 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n5,s5):2, (n2,s2):3, (n3,s3):4, (n4,s4):5, next=6, gen=8]: closed timestamp: 1681913441.290645414,0 (2023-04-19 14:10:41); raft status: {"id":"4","term":35,"vote":"4","commit":1186,"lead":"0","raftState":"StatePreCandidate","applied":1186,"progress":{},"leadtransferee":"0"}: operation "probe" timed out after 1m0.106s (given timeout 1m0s): result is ambiguous: after 60.08s of attempting command: context deadline exceeded
W230419 14:16:45.360980 8611170 2@rpc/clock_offset.go:276  [T1,n2,rnode=3,raddr=127.0.0.1:36005,class=system,rpc] 62  latency jump (prev avg 175.97ms, current 277.40ms)
W230419 14:16:45.349125 20127477 kv/kvclient/kvcoord/dist_sender.go:1694  [T1,n2,intExec=check-claim-session] 58  slow range RPC: have been waiting 79.45s (3 attempts) for RPC QueryIntent [/Table/15/1/858007467765891074/0,/Min), QueryIntent [/Table/15/1/858007467765891074/2/1,/Min), Scan [/Table/15/1/858007467765891074,/Table/15/1/858007467765891075), [txn: fbfe7cd8], [can-forward-ts] to r17:/Table/1{5-6} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n4,s4):4, (n5,s5):5, next=6, gen=8]; resp: failed to send RPC: sending to all replicas failed; last error: [NotLeaseHolderError] lease acquisition canceled because context canceled; r17: replica (n1,s1):1 not lease holder; lease holder unknown
I230419 14:16:45.352218 5115763 kv/kvserver/replica_rangefeed.go:711  [T1,n4,s4,r12/4:/Table/{8-11}] 59  RangeFeed closed timestamp 1681913763.920143626,0 is behind by 41.42400189s
I230419 14:16:45.339356 5057183 kv/kvserver/store_raft.go:656  [T1,n3,s3,r30/2:/Table/2{8-9},raft] 60  raft ready handling: 0.98s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.98s], wrote [append-batch=12 B, ]; node might be overloaded
I230419 14:16:45.348848 22757600 gossip/client.go:124  [T1,n3] 61  started gossip client to n0 (127.0.0.1:41829)
I230419 14:16:45.377284 5012956 kv/kvserver/store_raft.go:656  [T1,n2,s2,r52/4:/Table/5{1-2},raft] 63  raft ready handling: 0.89s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.89s], wrote [append-batch=283 B, append-ent=221 B (1), ]; node might be overloaded
W230419 14:16:45.380968 8467459 2@rpc/clock_offset.go:276  [T1,n3,rnode=5,raddr=127.0.0.1:44281,class=system,rpc] 65  latency jump (prev avg 167.58ms, current 286.25ms)
W230419 14:16:45.373342 5057884 kv/kvserver/replica_gossip.go:157  [T1,n3,s3,r1/4:/{Min-System/NodeL…}] 64  could not acquire lease for range gossip: replica unavailable: (n3,s3):4 unable to serve request to r1:/{Min-System/NodeLiveness} [(n1,s1):1, (n5,s5):2, (n2,s2):3, (n3,s3):4, (n4,s4):5, next=6, gen=8]: closed timestamp: 1681913441.290645414,0 (2023-04-19 14:10:41); raft status: {"id":"4","term":35,"vote":"4","commit":1186,"lead":"0","raftState":"StatePreCandidate","applied":1186,"progress":{},"leadtransferee":"0"}: operation "probe" timed out after 1m0.106s (given timeout 1m0s): result is ambiguous: after 60.08s of attempting command: context deadline exceeded
I230419 14:16:45.385115 5114518 kv/kvserver/store_raft.go:656  [T1,n4,s4,r36/3:/Table/3{4-5},raft] 66  raft ready handling: 0.81s [append=0.00s, apply=0.00s, , other=0.81s], wrote []; node might be overloaded
W230419 14:16:45.379205 5200342 2@rpc/clock_offset.go:276  [T1,n1,rnode=5,raddr=127.0.0.1:44281,class=default,rpc] 67  latency jump (prev avg 158.73ms, current 372.08ms)
I230419 14:16:45.396515 21239097 kv/kvserver/replica_circuit_breaker.go:151  [T1,n4,s4,r58/3:/Table/5{7-8}] 68  breaker: breaker reset
I230419 14:16:45.395914 5172599 kv/kvserver/store_raft.go:656  [T1,n5,s5,r6/3:/Table/{0-3},raft] 69  raft ready handling: 0.92s [append=0.00s, apply=0.75s, sync=0.00s, other=0.17s], wrote [append-batch=49 B, apply=223 B (1)]; node might be overloaded
I230419 14:16:45.388726 5013036 kv/kvserver/store_raft.go:656  [T1,n2,s2,r53/2:/Table/5{2-3},raft] 70  raft ready handling: 1.39s [append=0.00s, apply=0.88s, non-blocking-sync=0.00s, other=0.52s], wrote [append-batch=49 B, apply=317 B (1)]; node might be overloaded
W230419 14:16:45.412887 5058119 kv/kvserver/liveness/liveness.go:810  [T1,n3,liveness-hb] 71  failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 4.283s (given timeout 3s): aborted during DistSender.Send: context deadline exceeded
W230419 14:16:45.412887 5058119 kv/kvserver/liveness/liveness.go:810  [T1,n3,liveness-hb] 71 +
W230419 14:16:45.412887 5058119 kv/kvserver/liveness/liveness.go:810  [T1,n3,liveness-hb] 71 +An inability to maintain liveness will prevent a node from participating in a
W230419 14:16:45.412887 5058119 kv/kvserver/liveness/liveness.go:810  [T1,n3,liveness-hb] 71 +cluster. If this problem persists, it may be a sign of resource starvation or
W230419 14:16:45.412887 5058119 kv/kvserver/liveness/liveness.go:810  [T1,n3,liveness-hb] 71 +of network connectivity problems. For help troubleshooting, visit:
W230419 14:16:45.412887 5058119 kv/kvserver/liveness/liveness.go:810  [T1,n3,liveness-hb] 71 +
W230419 14:16:45.412887 5058119 kv/kvserver/liveness/liveness.go:810  [T1,n3,liveness-hb] 71 +    https://www.cockroachlabs.com/docs/stable/cluster-setup-troubleshooting.html#node-liveness-issues
W230419 14:16:45.415233 8521828 2@rpc/clock_offset.go:276  [T1,n5,rnode=2,raddr=127.0.0.1:43889,class=default,rpc] 73  latency jump (prev avg 164.56ms, current 671.89ms)
W230419 14:16:45.419687 5262630 2@rpc/clock_offset.go:276  [T1,n4,rnode=5,raddr=127.0.0.1:44281,class=system,rpc] 72  latency jump (prev avg 146.45ms, current 279.35ms)
I230419 14:16:45.448682 5013156 kv/kvserver/store_raft.go:656  [T1,n2,s2,r47/4:/Table/4{5-6},raft] 74  raft ready handling: 0.96s [append=0.00s, apply=0.00s, , other=0.96s], wrote []; node might be overloaded
I230419 14:16:45.468988 5057375 kv/kvserver/store_raft.go:656  [T1,n3,s3,r7/3:/Table/{3-4},raft] 75  raft ready handling: 0.81s [append=0.00s, apply=0.00s, sync=0.00s, other=0.81s], wrote [append-batch=49 B, ]; node might be overloaded
--- FAIL: TestExportJoin (0.17s)
I230419 14:16:45.432120 4632068 kv/kvserver/store_raft.go:656  [T1,n1,s1,r62/1:/Table/{61-106},raft] 76  raft ready handling: 1.25s [append=0.00s, apply=0.26s, non-blocking-sync=0.00s, other=0.98s], wrote [append-batch=12 B, apply=231 B (1)]; node might be overloaded

Parameters: TAGS=bazel,gss,deadlock

Help

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

_{This test on roachdash | Improve this report!}

cockroach-teamcity · 2023-04-21T14:02:38Z

sql/importer.TestExportJoin failed with artifacts on master @ 5957850444b4baafaee88332f93fd79e7703c6e8:

Fatal error:

panic: logging already active; first use:

Stack:

goroutine 6949397 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc000469360, {{{0xc015b8e090, 0x24}, {0x0, 0x0}, {0x60cd42e, 0x1}, {0x60cd42e, 0x1}}, 0x1757f813e69889ce, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x7650ec0, 0xc0097b40c0}, 0x2, 0x3, 0x0, 0xc0?, {0x6199c97, 0x38}, {0xc006a7b468, 0x2, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.Errorf(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:654
github.com/cockroachdb/cockroach/pkg/jobs/metricspoller.(*metricsPoller).Resume(0xc00524a680?, {0x7650ec0, 0xc0097b40c0}, {0x5d13da0?, 0xc0189b8190})
	github.com/cockroachdb/cockroach/pkg/jobs/metricspoller/poller.go:76 +0x3fc
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).stepThroughStateMachine.func2(0xc00524a680?, 0x0?, {0x76219d0?, 0xc015b92820?}, {0x7650ec0?, 0xc0201c6b40?}, {0x5d13da0?, 0xc0189b8190?}, 0xc006a7b840)
	github.com/cockroachdb/cockroach/pkg/jobs/registry.go:1624 +0xcc
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).stepThroughStateMachine(0xc002522000, {0x7650ec0, 0xc00d17def0}, {0x5d13da0, 0xc0189b8190}, {0x76219d0, 0xc015b92820}, 0xc00524a680, {0xc00d6468b8, 0x7}, ...)
	github.com/cockroachdb/cockroach/pkg/jobs/registry.go:1625 +0x8df
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).runJob(0xc002522000, {0x7650e18, 0xc000877700}, {0x76219d0, 0xc015b92820}, 0xc00524a680, {0xc00d6468b8, 0x7}, {0xc015231690, 0x7})
	github.com/cockroachdb/cockroach/pkg/jobs/adopt.go:474 +0x637
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).resumeJob.func2({0x7650ec0?, 0xc01a3f1740?})
	github.com/cockroachdb/cockroach/pkg/jobs/adopt.go:388 +0x146
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b [recovered]
	panic: logging already active; first use:
goroutine 6949397 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc000469360, {{{0xc015b8e090, 0x24}, {0x0, 0x0}, {0x60cd42e, 0x1}, {0x60cd42e, 0x1}}, 0x1757f813e69889ce, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x7650ec0, 0xc0097b40c0}, 0x2, 0x3, 0x0, 0xc0?, {0x6199c97, 0x38}, {0xc006a7b468, 0x2, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.Errorf(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:654
github.com/cockroachdb/cockroach/pkg/jobs/metricspoller.(*metricsPoller).Resume(0xc00524a680?, {0x7650ec0, 0xc0097b40c0}, {0x5d13da0?, 0xc0189b8190})
	github.com/cockroachdb/cockroach/pkg/jobs/metricspoller/poller.go:76 +0x3fc
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).stepThroughStateMachine.func2(0xc00524a680?, 0x0?, {0x76219d0?, 0xc015b92820?}, {0x7650ec0?, 0xc0201c6b40?}, {0x5d13da0?, 0xc0189b8190?}, 0xc006a7b840)
	github.com/cockroachdb/cockroach/pkg/jobs/registry.go:1624 +0xcc
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).stepThroughStateMachine(0xc002522000, {0x7650ec0, 0xc00d17def0}, {0x5d13da0, 0xc0189b8190}, {0x76219d0, 0xc015b92820}, 0xc00524a680, {0xc00d6468b8, 0x7}, ...)
	github.com/cockroachdb/cockroach/pkg/jobs/registry.go:1625 +0x8df
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).runJob(0xc002522000, {0x7650e18, 0xc000877700}, {0x76219d0, 0xc015b92820}, 0xc00524a680, {0xc00d6468b8, 0x7}, {0xc015231690, 0x7})
	github.com/cockroachdb/cockroach/pkg/jobs/adopt.go:474 +0x637
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).resumeJob.func2({0x7650ec0?, 0xc01a3f1740?})
	github.com/cockroachdb/cockroach/pkg/jobs/adopt.go:388 +0x146
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b

Log preceding fatal error

=== RUN   TestExportJoin
I230421 14:02:30.157520 5070408 kv/kvserver/store_raft.go:656  [T1,n3,s3,r47/5:/Table/4{5-6},raft] 49  raft ready handling: 1.77s [append=0.00s, apply=0.77s, non-blocking-sync=0.00s, other=1.00s], wrote [append-batch=49 B, apply=223 B (1)]; node might be overloaded
I230421 14:02:30.150602 24878099 kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:212  [T1,n3,rangefeed=system-config-cache] 51  MuxRangeFeed starting for range /Table/{3-4}@1682085311.511643491,0 (rangeID 7, attempt 0)
E230421 14:02:30.150612 4637462 jobs/registry.go:1033  [T1,n1] 50  error expiring job sessions: expire-sessions: replica unavailable: (n1,s1):1 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, (n4,s4):5, next=6, gen=8]: closed timestamp: 1682085311.511643491,0 (2023-04-21 13:55:11); raft status: {"id":"1","term":41,"vote":"1","commit":121,"lead":"0","raftState":"StateCandidate","applied":121,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/3,/Min)
I230421 14:02:30.170167 5070165 kv/kvserver/store_raft.go:656  [T1,n3,s3,r22/4:/Table/2{0-1},raft] 53  raft ready handling: 0.81s [append=0.00s, apply=0.00s, , other=0.81s], wrote []; node might be overloaded
W230421 14:02:30.189379 5284658 2@rpc/clock_offset.go:276  [T1,n4,rnode=5,raddr=127.0.0.1:37621,class=system,rpc] 56  latency jump (prev avg 159.37ms, current 666.84ms)
I230421 14:02:30.165230 5070491 kv/kvserver/replica_rangefeed.go:711  [T1,n3,s3,r48/3:/Table/4{6-7}] 52  RangeFeed closed timestamp 1682085595.684569691,0 is behind by 2m34.426232862s
I230421 14:02:30.155576 5070353 kv/kvserver/store_raft.go:656  [T1,n3,s3,r53/2:/Table/5{2-3},raft] 54  raft ready handling: 0.66s [append=0.00s, apply=0.00s, , other=0.66s], wrote []; node might be overloaded
I230421 14:02:30.180910 12463768 sql/catalog/lease/lease.go:1316  [T1,n2] 55  refreshing descriptor: 37 lease failed: replica unavailable: (n3,s3):3 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, (n4,s4):5, next=6, gen=8]: closed timestamp: 1682085311.511643491,0 (2023-04-21 13:55:11); raft status: {"id":"3","term":41,"vote":"5","commit":121,"lead":"0","raftState":"StatePreCandidate","applied":121,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/3,/Min)
I230421 14:02:30.191546 24881717 kv/kvclient/kvcoord/dist_sender_mux_rangefeed.go:471  [T1,n2,rangefeed=lease] 57  RangeFeed /Table/{3-4}@1682085311.511643491,0 disconnected with last checkpoint 467246h2m30.176481555s ago: retry rangefeed (REASON_NO_LEASEHOLDER)
W230421 14:02:30.191576 16549395 kv/kvclient/kvcoord/dist_sender.go:1705  [T1,n1,intExec=protectedts-GetMetadata] 58  slow RPC response: slow RPC finished after 254.43s (5 attempts)
I230421 14:02:30.196603 5126043 kv/kvserver/store_raft.go:656  [T1,n4,s4,r35/3:/Table/3{3-4},raft] 59  raft ready handling: 1.73s [append=0.00s, apply=0.96s, non-blocking-sync=0.00s, other=0.77s], wrote [append-batch=49 B, apply=219 B (1)]; node might be overloaded
I230421 14:02:30.198567 5023184 kv/kvserver/store_raft.go:656  [T1,n2,s2,r22/5:/Table/2{0-1},raft] 61  raft ready handling: 1.51s [append=0.00s, apply=0.91s, non-blocking-sync=0.00s, other=0.60s], wrote [append-batch=320 B, append-ent=219 B (1), apply=319 B (1)]; node might be overloaded
I230421 14:02:30.195267 4624474 kv/kvserver/store_raft.go:656  [T1,n1,s1,r19/1:/Table/1{7-8},raft] 60  raft ready handling: 0.79s [append=0.00s, apply=0.00s, , other=0.79s], wrote []; node might be overloaded
I230421 14:02:30.199941 5125235 kv/kvserver/store_raft.go:656  [T1,n4,s4,r7/5:/Table/{3-4},raft] 62  raft ready handling: 1.01s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.01s], wrote [append-batch=12 B, ]; node might be overloaded
E230421 14:02:30.202993 6949397 jobs/metricspoller/poller.go:76  [T1,n1,job=POLL JOBS STATS id=101,task=manage-pts] 63  Periodic stats collector task manage-pts completed with error failed to read metadata: protectedts-GetMetadata: replica unavailable: (n1,s1):1 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, (n4,s4):5, next=6, gen=8]: closed timestamp: 1682085311.511643491,0 (2023-04-21 13:55:11); raft status: {"id":"1","term":41,"vote":"1","commit":121,"lead":"0","raftState":"StateCandidate","applied":121,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/3,/Min)
--- FAIL: TestExportJoin (0.07s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

_{This test on roachdash | Improve this report!}

cockroach-teamcity · 2023-04-22T14:23:31Z

sql/importer.TestExportJoin failed with artifacts on master @ 0545913ede29a681dbeef9a6f1211d8b95395c5e:

Fatal error:

panic: logging already active; first use:

Stack:

goroutine 8510772 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc000121040, {{{0xc002fb2a20, 0x24}, {0x0, 0x0}, {0x60cd609, 0x1}, {0x60cd60c, 0x1}}, 0x175847cc8052a5ce, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x76510a0, 0xc014354720}, 0x2, 0x2, 0x2, 0xe0?, {0x6136cdd, 0x2e}, {0xc01d7e1aa0, 0x2, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.loggerHealth.Warningf(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:1664
github.com/cockroachdb/cockroach/pkg/rpc.(*RemoteClockMonitor).UpdateOffset(0xc00f5055e0, {0x76510a0, 0xc014354720}, 0x4, {0xe23dc69e38?, 0x0?, 0x0?}, 0x2e58f8e9)
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/clock_offset.go:276 +0x637
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).runHeartbeat.func2({0x76510a0, 0xc014354720})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2549 +0x552
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr(0xc00a4d8c00, {0x76510a0, 0xc014354720}, {0x0?, 0x12?}, 0xc01d7e1e30)
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:322 +0xd1
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).runHeartbeat(0xc00d7de200, {0x76510a0, 0xc014354720}, 0xc014340c30, {0xc00624dc20?, 0xc00903b6e8?})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2460 +0x4af
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).grpcDialNodeInternal.func1({0x76510a0, 0xc014354720})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2301 +0xc6
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b [recovered]
	panic: logging already active; first use:
goroutine 8510772 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc000121040, {{{0xc002fb2a20, 0x24}, {0x0, 0x0}, {0x60cd609, 0x1}, {0x60cd60c, 0x1}}, 0x175847cc8052a5ce, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x76510a0, 0xc014354720}, 0x2, 0x2, 0x2, 0xe0?, {0x6136cdd, 0x2e}, {0xc01d7e1aa0, 0x2, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.loggerHealth.Warningf(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:1664
github.com/cockroachdb/cockroach/pkg/rpc.(*RemoteClockMonitor).UpdateOffset(0xc00f5055e0, {0x76510a0, 0xc014354720}, 0x4, {0xe23dc69e38?, 0x0?, 0x0?}, 0x2e58f8e9)
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/clock_offset.go:276 +0x637
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).runHeartbeat.func2({0x76510a0, 0xc014354720})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2549 +0x552
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr(0xc00a4d8c00, {0x76510a0, 0xc014354720}, {0x0?, 0x12?}, 0xc01d7e1e30)
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:322 +0xd1
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).runHeartbeat(0xc00d7de200, {0x76510a0, 0xc014354720}, 0xc014340c30, {0xc00624dc20?, 0xc00903b6e8?})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2460 +0x4af
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).grpcDialNodeInternal.func1({0x76510a0, 0xc014354720})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2301 +0xc6
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b

Log preceding fatal error

=== RUN   TestExportJoin
I230422 14:23:24.276840 5237629 kv/kvserver/store_raft.go:656  [T1,n4,s4,r22/2:/Table/2{0-1},raft] 42  raft ready handling: 1.20s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.20s], wrote [append-batch=12 B, ]; node might be overloaded
I230422 14:23:24.281090 37701203 gossip/client.go:124  [T1,n2] 43  started gossip client to n0 (127.0.0.1:43207)
I230422 14:23:24.322989 5138819 kv/kvserver/store_raft.go:656  [T1,n2,s2,r9/5:/Table/{5-6},raft] 44  raft ready handling: 0.75s [append=0.00s, apply=0.00s, sync=0.00s, other=0.75s], wrote [append-batch=50 B, ]; node might be overloaded
I230422 14:23:24.287554 5296103 kv/kvserver/store_raft.go:656  [T1,n5,s5,r4/3:/System{/tsd-tse},raft] 45  raft ready handling: 0.87s [append=0.00s, apply=0.00s, , other=0.87s], wrote []; node might be overloaded
W230422 14:23:24.358649 8601851 2@rpc/clock_offset.go:276  [T1,n4,rnode=3,raddr=127.0.0.1:45699,class=system,rpc] 48  latency jump (prev avg 131.58ms, current 240.53ms)
I230422 14:23:24.357599 37704734 gossip/client.go:124  [T1,n4] 47  started gossip client to n0 (127.0.0.1:43207)
I230422 14:23:24.325751 5184359 kv/kvserver/store_raft.go:656  [T1,n3,s3,r37/4:/Table/3{5-6},raft] 46  raft ready handling: 0.92s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.92s], wrote [append-batch=50 B, ]; node might be overloaded
W230422 14:23:24.394598 8509705 2@rpc/clock_offset.go:276  [T1,n3,rnode=5,raddr=127.0.0.1:41365,class=default,rpc] 52  latency jump (prev avg 154.31ms, current 405.34ms)
I230422 14:23:24.347574 5184436 kv/kvserver/store_raft.go:656  [T1,n3,s3,r2/4:/System/NodeLiveness{-Max},raft] 50  raft ready handling: 0.92s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.92s], wrote [append-batch=12 B, ]; node might be overloaded
I230422 14:23:24.376123 37664968 gossip/client.go:129  [T1,n4] 49  closing client to n5 (127.0.0.1:41365): received forward from n5 to n3 (127.0.0.1:45699); already have active connection, skipping
I230422 14:23:24.306579 5184904 kv/kvserver/store_raft.go:656  [T1,n3,s3,r41/3:/Table/{39-40},raft] 51  raft ready handling: 1.06s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.06s], wrote [append-batch=50 B, ]; node might be overloaded
I230422 14:23:24.448447 5295404 kv/kvserver/store_raft.go:656  [T1,n5,s5,r6/4:/Table/{0-3},raft] 54  raft ready handling: 1.10s [append=0.00s, apply=0.86s, sync=0.00s, other=0.24s], wrote [append-batch=50 B, apply=233 B (1)]; node might be overloaded
W230422 14:23:24.401885 8602691 2@rpc/clock_offset.go:276  [T1,n5,rnode=3,raddr=127.0.0.1:45699,class=system,rpc] 53  latency jump (prev avg 166.72ms, current 648.98ms)
E230422 14:23:24.430524 15565824 sql/catalog/lease/descriptor_state.go:316  [T1,n1,intExec=select-running/get-claimed-jobs] 56  background lease renewal for id=15 name="jobs" failed: replica unavailable: (n5,s5):5 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n3,s3):2, (n4,s4):3, (n2,s2):4, (n5,s5):5, next=6, gen=8]: closed timestamp: 1682172577.339212512,0 (2023-04-22 14:09:37); raft status: {"id":"5","term":55,"vote":"1","commit":191,"lead":"0","raftState":"StateFollower","applied":191,"progress":{},"leadtransferee":"0"}: have been waiting 60.50s for slow proposal RequestLease [/Table/3,/Min)
I230422 14:23:24.449754 5184815 kv/kvserver/store_raft.go:656  [T1,n3,s3,r58/2:/Table/5{7-8},raft] 55  raft ready handling: 1.83s [append=0.00s, apply=1.03s, non-blocking-sync=0.00s, other=0.80s], wrote [append-batch=50 B, apply=231 B (1)]; node might be overloaded
I230422 14:23:24.461435 5236824 kv/kvserver/store_raft.go:656  [T1,n4,s4,r43/2:/Table/4{1-2},raft] 57  raft ready handling: 1.39s [append=0.00s, apply=1.15s, , other=0.24s], wrote [append-batch=50 B, apply=543 B (2 in 2 batches)]; node might be overloaded
I230422 14:23:24.470960 5184233 kv/kvserver/store_raft.go:656  [T1,n3,s3,r42/3:/Table/4{0-1},raft] 58  raft ready handling: 0.83s [append=0.00s, apply=0.60s, sync=0.00s, other=0.23s], wrote [append-batch=50 B, apply=223 B (1)]; node might be overloaded
W230422 14:23:24.474680 8510772 2@rpc/clock_offset.go:276  [T1,n4,rnode=4,raddr=127.0.0.1:38701,class=default,rpc] 59  latency jump (prev avg 117.90ms, current 777.58ms)
W230422 14:23:24.501047 8604182 2@rpc/clock_offset.go:276  [T1,n2,rnode=4,raddr=127.0.0.1:38701,class=system,rpc] 61  latency jump (prev avg 161.05ms, current 607.75ms)
W230422 14:23:24.502233 5238112 kv/kvserver/replica_gossip.go:157  [T1,n4,s4,r2/3:/System/NodeLiveness{-Max}] 60  could not acquire lease for range gossip: replica unavailable: (n4,s4):3 unable to serve request to r2:/System/NodeLiveness{-Max} [(n1,s1):1, (n5,s5):2, (n4,s4):3, (n3,s3):4, (n2,s2):5, next=6, gen=8]: closed timestamp: 1682172573.893690051,0 (2023-04-22 14:09:33); raft status: {"id":"3","term":82,"vote":"4","commit":297,"lead":"0","raftState":"StatePreCandidate","applied":297,"progress":{},"leadtransferee":"0"}: have been waiting 61.00s for slow proposal RequestLease [/System/NodeLiveness,/Min)
--- FAIL: TestExportJoin (0.11s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

_{This test on roachdash | Improve this report!}

blathers-crl · 2023-04-24T13:49:09Z

cc @cockroachdb/replication

cockroach-teamcity · 2023-04-24T14:48:29Z

sql/importer.TestExportJoin failed with artifacts on master @ 3c23346a6d1c91dfe8ed1c5285966f9b9e487601:

Fatal error:

panic: logging already active; first use:

Stack:

goroutine 19823892 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc0002b7020, {{{0xc00bc43710, 0x24}, {0x0, 0x0}, {0x60ce295, 0x1}, {0x60ce298, 0x1}}, 0x1758e65224a7b1d2, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x7651ee0, 0xc018ba4960}, 0x2, 0x2, 0x0, 0x16?, {0x605d4fd, 0x15}, {0xc009be75e8, 0x1, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.Warningf(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:463
github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).sendPartialBatch.func1({0xc000860000?, 0x931977?, 0x0?}, 0xc0000e0000?)
	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:1715 +0x11e
github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).sendPartialBatch(0xc00a1ce000, {0x7651ee0?, 0xc018ba4960}, 0xc00d34e480, {{0xc005a4ce68, 0x5, 0x8}, {0xc018dba738, 0x1, 0x8}}, ...)
	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:1815 +0x1277
github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).sendPartialBatchAsync.func1({0x7651ee0, 0xc018ba4960})
	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:1570 +0x174
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b [recovered]
	panic: logging already active; first use:
goroutine 19823892 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc0002b7020, {{{0xc00bc43710, 0x24}, {0x0, 0x0}, {0x60ce295, 0x1}, {0x60ce298, 0x1}}, 0x1758e65224a7b1d2, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x7651ee0, 0xc018ba4960}, 0x2, 0x2, 0x0, 0x16?, {0x605d4fd, 0x15}, {0xc009be75e8, 0x1, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.Warningf(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:463
github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).sendPartialBatch.func1({0xc000860000?, 0x931977?, 0x0?}, 0xc0000e0000?)
	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:1715 +0x11e
github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).sendPartialBatch(0xc00a1ce000, {0x7651ee0?, 0xc018ba4960}, 0xc00d34e480, {{0xc005a4ce68, 0x5, 0x8}, {0xc018dba738, 0x1, 0x8}}, ...)
	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:1815 +0x1277
github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord.(*DistSender).sendPartialBatchAsync.func1({0x7651ee0, 0xc018ba4960})
	github.com/cockroachdb/cockroach/pkg/kv/kvclient/kvcoord/dist_sender.go:1570 +0x174
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b

Log preceding fatal error

=== RUN   TestExportJoin
W230424 14:48:21.134790 8721115 2@rpc/clock_offset.go:276  [T1,n3,rnode=2,raddr=127.0.0.1:38365,class=system,rpc] 64  latency jump (prev avg 170.05ms, current 706.72ms)
E230424 14:48:21.127389 27605203 kv/kvserver/replica_circuit_breaker.go:176  [T1,n3,s3,r7/4:/Table/{3-4}] 63  breaker: tripped with error: replica unavailable: (n3,s3):4 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n5,s5):2, (n4,s4):3, (n3,s3):4, (n2,s2):5, next=6, gen=8]: closed timestamp: 1682347455.084261351,0 (2023-04-24 14:44:15); raft status: {"id":"4","term":48,"vote":"1","commit":154,"lead":"0","raftState":"StatePreCandidate","applied":154,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/3,/Min)
W230424 14:48:21.121646 5215952 kv/kvserver/liveness/liveness.go:810  [T1,n5,liveness-hb] 62  failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 4.474s (given timeout 3s): aborted during DistSender.Send: context deadline exceeded
W230424 14:48:21.121646 5215952 kv/kvserver/liveness/liveness.go:810  [T1,n5,liveness-hb] 62 +
W230424 14:48:21.121646 5215952 kv/kvserver/liveness/liveness.go:810  [T1,n5,liveness-hb] 62 +An inability to maintain liveness will prevent a node from participating in a
W230424 14:48:21.121646 5215952 kv/kvserver/liveness/liveness.go:810  [T1,n5,liveness-hb] 62 +cluster. If this problem persists, it may be a sign of resource starvation or
W230424 14:48:21.121646 5215952 kv/kvserver/liveness/liveness.go:810  [T1,n5,liveness-hb] 62 +of network connectivity problems. For help troubleshooting, visit:
W230424 14:48:21.121646 5215952 kv/kvserver/liveness/liveness.go:810  [T1,n5,liveness-hb] 62 +
W230424 14:48:21.121646 5215952 kv/kvserver/liveness/liveness.go:810  [T1,n5,liveness-hb] 62 +    https://www.cockroachlabs.com/docs/stable/cluster-setup-troubleshooting.html#node-liveness-issues
I230424 14:48:21.152395 5100096 kv/kvserver/store_raft.go:656  [T1,n3,s3,r10/3:/Table/{6-7},raft] 65  raft ready handling: 0.73s [append=0.00s, apply=0.00s, , other=0.73s], wrote []; node might be overloaded
I230424 14:48:21.134507 5058006 kv/kvserver/store_raft.go:656  [T1,n2,s2,r31/2:/{Table/29-NamespaceTab…},raft] 66  raft ready handling: 0.70s [append=0.00s, apply=0.00s, sync=0.00s, other=0.70s], wrote [append-batch=12 B, ]; node might be overloaded
I230424 14:48:21.154426 27610138 gossip/client.go:129  [T1,n4] 67  closing client to n3 (127.0.0.1:34511): stopping outgoing client to n3 (127.0.0.1:34511); already have incoming
W230424 14:48:21.192457 5314399 2@rpc/clock_offset.go:276  [T1,n2,rnode=5,raddr=127.0.0.1:45567,class=system,rpc] 69  latency jump (prev avg 164.62ms, current 249.62ms)
I230424 14:48:21.156532 5214230 kv/kvserver/store_raft.go:656  [T1,n5,s5,r14/2:/Table/1{2-3},raft] 68  raft ready handling: 0.85s [append=0.00s, apply=0.00s, sync=0.00s, other=0.85s], wrote [append-batch=334 B, append-ent=233 B (1), ]; node might be overloaded
I230424 14:48:21.197231 5156565 kv/kvserver/store_raft.go:656  [T1,n4,s4,r40/2:/Table/3{8-9},raft] 70  raft ready handling: 2.35s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=2.35s], wrote [append-batch=12 B, ]; node might be overloaded
W230424 14:48:21.226848 5110573 2@rpc/clock_offset.go:276  [T1,n1,rnode=3,raddr=127.0.0.1:34511,class=default,rpc] 72  latency jump (prev avg 177.84ms, current 575.57ms)
W230424 14:48:21.222186 21661984 kv/kvclient/kvcoord/dist_sender.go:1715  [T1,n4] 73  slow RPC response: slow RPC finished after 184.77s (4 attempts)
I230424 14:48:21.219801 25703479 kv/txn.go:875  [T1,n4] 71  async rollback failed: aborted during DistSender.Send: context deadline exceeded
I230424 14:48:21.242566 4655201 kv/kvserver/store_raft.go:656  [T1,n1,s1,r38/1:/Table/3{6-7},raft] 74  raft ready handling: 1.01s [append=0.00s, apply=0.95s, sync=0.00s, other=0.06s], wrote [append-batch=49 B, apply=324 B (1)]; node might be overloaded
I230424 14:48:21.217883 5100721 2@util/log/event_log.go:32  [T1,n3] 75 ={"Timestamp":1682347701217877666,"EventType":"runtime_stats","MemRSSBytes":1322172416,"GoroutineCount":3834,"MemStackSysBytes":69206016,"GoAllocBytes":678115376,"GoTotalBytes":1054308872,"GoStatsStaleness":0.003327627,"HeapFragmentBytes":123488208,"HeapReservedBytes":113123328,"HeapReleasedBytes":119169024,"CGoAllocBytes":214430080,"CGoTotalBytes":295473152,"CGoCallRate":0.5000313,"CPUUserPercent":194.8122,"CPUSysPercent":27.301708,"GCPausePercent":0.0036984915,"GCRunCount":176,"NetHostRecvBytes":10559403,"NetHostSendBytes":10559403}
I230424 14:48:21.242888 5156395 kv/kvserver/store_raft.go:656  [T1,n4,s4,r58/3:/Table/5{7-8},raft] 76  raft ready handling: 2.58s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=2.58s], wrote [append-batch=12 B, ]; node might be overloaded
W230424 14:48:21.252129 8633731 2@rpc/clock_offset.go:276  [T1,n5,rnode=3,raddr=127.0.0.1:34511,class=default,rpc] 77  latency jump (prev avg 172.31ms, current 293.48ms)
W230424 14:48:21.288438 8629000 2@rpc/clock_offset.go:276  [T1,n2,rnode=2,raddr=127.0.0.1:38365,class=default,rpc] 79  latency jump (prev avg 175.96ms, current 767.30ms)
I230424 14:48:21.249023 5155378 kv/kvserver/store_raft.go:656  [T1,n4,s4,r6/3:/Table/{0-3},raft] 78  raft ready handling: 0.85s [append=0.00s, apply=0.00s, , other=0.85s], wrote []; node might be overloaded
--- FAIL: TestExportJoin (0.11s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

_{This test on roachdash | Improve this report!}

cockroach-teamcity · 2023-04-25T14:45:24Z

sql/importer.TestExportJoin failed with artifacts on master @ a9ce55af2ff225264fcbdf4ffe0741a22858f605:

Fatal error:

panic: logging already active; first use:

Stack:

goroutine 5152413 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc0003e0bc0, {{{0xc00af52630, 0x24}, {0x0, 0x0}, {0x60c94ce, 0x1}, {0x60c94d0, 0x1}}, 0x175934bbe8041e09, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x7648918, 0xc01ad9a340}, 0x2, 0x3, 0x0, 0x0?, {0x609862c, 0x1e}, {0xc00a5c1eb0, 0x1, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.Errorf(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:654
github.com/cockroachdb/cockroach/pkg/jobs.(*jobScheduler).runDaemon.func1({0x76489c0?, 0xc007802930?})
	github.com/cockroachdb/cockroach/pkg/jobs/job_scheduler.go:429 +0x3dd
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b [recovered]
	panic: logging already active; first use:
goroutine 5152413 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc0003e0bc0, {{{0xc00af52630, 0x24}, {0x0, 0x0}, {0x60c94ce, 0x1}, {0x60c94d0, 0x1}}, 0x175934bbe8041e09, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x7648918, 0xc01ad9a340}, 0x2, 0x3, 0x0, 0x0?, {0x609862c, 0x1e}, {0xc00a5c1eb0, 0x1, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.Errorf(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:654
github.com/cockroachdb/cockroach/pkg/jobs.(*jobScheduler).runDaemon.func1({0x76489c0?, 0xc007802930?})
	github.com/cockroachdb/cockroach/pkg/jobs/job_scheduler.go:429 +0x3dd
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b

Log preceding fatal error

E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +Wraps: (5) forced error mark
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | "breaker open"
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | github.com/cockroachdb/errors/withstack/*withstack.withStack::
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +Wraps: (6) replica unavailable: (n1,s1):1 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n5,s5):2, (n3,s3):3, (n2,s2):4, (n4,s4):5, next=6, gen=8]: closed timestamp: 1682433291.631314873,0 (2023-04-25 14:34:51); raft status: {"id":"1","term":135,"vote":"1","commit":351,"lead":"1","raftState":"StateLeader","applied":350,"progress":{"1":{"match":350,"next":351,"state":"StateReplicate"},"2":{"match":351,"next":352,"state":"StateReplicate"},"3":{"match":351,"next":352,"state":"StateReplicate"},"4":{"match":351,"next":352,"state":"StateReplicate"},"5":{"match":0,"next":350,"state":"StateProbe"}},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/3,/Min)
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +Wraps: (7)
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | (opaque error wrapper)
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | type name: github.com/cockroachdb/errors/withstack/*withstack.withStack
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | reportable 0:
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  |
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.replicaUnavailableError
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_circuit_breaker.go:282
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).replicaUnavailableError
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_circuit_breaker.go:291
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*replicaCircuitBreaker).tripSync
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_circuit_breaker.go:110
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*replicaCircuitBreaker).TripAsync.func1
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_circuit_breaker.go:104
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | runtime.goexit
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	GOROOT/src/runtime/asm_amd64.s:1594
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +Wraps: (8) closed timestamp: 1682433291.631314873,0 (2023-04-25 14:34:51); raft status: {"id":"1","term":135,"vote":"1","commit":351,"lead":"1","raftState":"StateLeader","applied":350,"progress":{"1":{"match":350,"next":351,"state":"StateReplicate"},"2":{"match":351,"next":352,"state":"StateReplicate"},"3":{"match":351,"next":352,"state":"StateReplicate"},"4":{"match":351,"next":352,"state":"StateReplicate"},"5":{"match":0,"next":350,"state":"StateProbe"}},"leadtransferee":"0"}
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +Wraps: (9)
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | (opaque error wrapper)
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | type name: github.com/cockroachdb/errors/withstack/*withstack.withStack
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | reportable 0:
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  |
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).refreshProposalsLocked
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_raft.go:1412
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).tick
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_raft.go:1275
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processTick
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_raft.go:675
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:386
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:299
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | runtime.goexit
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +  | 	GOROOT/src/runtime/asm_amd64.s:1594
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +Wraps: (10) have been waiting 61.50s for slow proposal RequestLease [/Table/3,/Min)
E230425 14:45:17.455703 5152413 jobs/job_scheduler.go:429  [T1,n3] 63 +Error types: (1) *secondary.withSecondaryError (2) *withstack.withStack (3) *errutil.withPrefix (4) *markers.withMark (5) *markers.withMark (6) *kvpb.ReplicaUnavailableError (7) *errbase.opaqueWrapper (8) *errutil.withPrefix (9) *errbase.opaqueWrapper (10) *errutil.leafError
I230425 14:45:17.504649 5177910 kv/kvserver/store_raft.go:656  [T1,n4,s4,r84/3:/Table/106/1/1{60-80},raft] 65  raft ready handling: 0.66s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=0.66s], wrote [append-batch=12 B, ]; node might be overloaded
I230425 14:45:17.481757 5242014 kv/kvserver/store_raft.go:656  [T1,n5,s5,r28/2:/Table/2{6-7},raft] 66  raft ready handling: 1.03s [append=0.00s, apply=0.81s, sync=0.00s, other=0.22s], wrote [append-batch=50 B, apply=219 B (1)]; node might be overloaded
I230425 14:45:17.494582 41198999 sql/catalog/lease/lease.go:1316  [T1,n1] 67  refreshing descriptor: 105 lease failed: replica unavailable: (n1,s1):1 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n5,s5):2, (n3,s3):3, (n2,s2):4, (n4,s4):5, next=6, gen=8]: closed timestamp: 1682433291.631314873,0 (2023-04-25 14:34:51); raft status: {"id":"1","term":135,"vote":"1","commit":351,"lead":"1","raftState":"StateLeader","applied":350,"progress":{"1":{"match":350,"next":351,"state":"StateReplicate"},"2":{"match":351,"next":352,"state":"StateReplicate"},"3":{"match":351,"next":352,"state":"StateReplicate"},"4":{"match":351,"next":352,"state":"StateReplicate"},"5":{"match":0,"next":350,"state":"StateProbe"}},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/3,/Min)
I230425 14:45:17.484041 5178763 kv/kvserver/store_raft.go:656  [T1,n4,s4,r28/5:/Table/2{6-7},raft] 68  raft ready handling: 0.78s [append=0.00s, apply=0.62s, sync=0.00s, other=0.15s], wrote [append-batch=50 B, apply=219 B (1)]; node might be overloaded
W230425 14:45:17.481807 5257978 kv/kvclient/rangefeed/rangefeed.go:331  [T1,n5,rangefeed=lease] 69  rangefeed failed 2 times, restarting: replica unavailable: (n1,s1):1 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n5,s5):2, (n3,s3):3, (n2,s2):4, (n4,s4):5, next=6, gen=8]: closed timestamp: 1682433291.631314873,0 (2023-04-25 14:34:51); raft status: {"id":"1","term":135,"vote":"1","commit":351,"lead":"1","raftState":"StateLeader","applied":350,"progress":{"1":{"match":350,"next":351,"state":"StateReplicate"},"2":{"match":351,"next":352,"state":"StateReplicate"},"3":{"match":351,"next":352,"state":"StateReplicate"},"4":{"match":351,"next":352,"state":"StateReplicate"},"5":{"match":0,"next":350,"state":"StateProbe"}},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/3,/Min)
I230425 14:45:17.535374 5078059 kv/kvserver/store_raft.go:656  [T1,n2,s2,r19/2:/Table/1{7-8},raft] 70  raft ready handling: 0.71s [append=0.00s, apply=0.20s, non-blocking-sync=0.00s, other=0.52s], wrote [append-batch=334 B, append-ent=233 B (1), apply=233 B (1)]; node might be overloaded
--- FAIL: TestExportJoin (0.17s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

_{This test on roachdash | Improve this report!}

cockroach-teamcity · 2023-04-26T14:42:50Z

sql/importer.TestExportJoin failed with artifacts on master @ 9fb03ee9b365d656cc26728cc87f682a385d511b:

Fatal error:

panic: logging already active; first use:

Stack:

goroutine 8421048 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc0003d6f40, {{{0xc00b0fe6c0, 0x24}, {0x0, 0x0}, {0x60cb4e6, 0x1}, {0x60cb4e7, 0x1}}, 0x1759832c522c2120, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x764bcc0, 0xc010d68930}, 0x2, 0x2, 0x2, 0x0?, {0x613273b, 0x2e}, {0xc01b9cfaa0, 0x2, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.loggerHealth.Warningf(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:1664
github.com/cockroachdb/cockroach/pkg/rpc.(*RemoteClockMonitor).UpdateOffset(0xc00a5db490, {0x764bcc0, 0xc010d68930}, 0x4, {0xaee5c831d7?, 0x0?, 0x40?}, 0x18538c64)
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/clock_offset.go:276 +0x637
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).runHeartbeat.func2({0x764bcc0, 0xc010d68930})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2549 +0x552
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr(0xc002036200, {0x764bcc0, 0xc010d68930}, {0x0?, 0x12?}, 0xc01b9cfe30)
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:322 +0xd1
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).runHeartbeat(0xc001b6ca00, {0x764bcc0, 0xc010d68930}, 0xc014dfe510, {0xc00503c2d0?, 0xc0026d06e8?})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2460 +0x4af
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).grpcDialNodeInternal.func1({0x764bcc0, 0xc010d68930})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2301 +0xc6
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b [recovered]
	panic: logging already active; first use:
goroutine 8421048 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc0003d6f40, {{{0xc00b0fe6c0, 0x24}, {0x0, 0x0}, {0x60cb4e6, 0x1}, {0x60cb4e7, 0x1}}, 0x1759832c522c2120, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x764bcc0, 0xc010d68930}, 0x2, 0x2, 0x2, 0x0?, {0x613273b, 0x2e}, {0xc01b9cfaa0, 0x2, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.loggerHealth.Warningf(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:1664
github.com/cockroachdb/cockroach/pkg/rpc.(*RemoteClockMonitor).UpdateOffset(0xc00a5db490, {0x764bcc0, 0xc010d68930}, 0x4, {0xaee5c831d7?, 0x0?, 0x40?}, 0x18538c64)
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/clock_offset.go:276 +0x637
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).runHeartbeat.func2({0x764bcc0, 0xc010d68930})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2549 +0x552
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr(0xc002036200, {0x764bcc0, 0xc010d68930}, {0x0?, 0x12?}, 0xc01b9cfe30)
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:322 +0xd1
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).runHeartbeat(0xc001b6ca00, {0x764bcc0, 0xc010d68930}, 0xc014dfe510, {0xc00503c2d0?, 0xc0026d06e8?})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2460 +0x4af
github.com/cockroachdb/cockroach/pkg/rpc.(*Context).grpcDialNodeInternal.func1({0x764bcc0, 0xc010d68930})
	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:2301 +0xc6
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b

Log preceding fatal error

=== RUN   TestExportJoin
W230426 14:42:42.131380 5249025 2@rpc/clock_offset.go:276  [T1,n5,rnode=1,raddr=127.0.0.1:43753,class=default,rpc] 50  latency jump (prev avg 166.43ms, current 273.54ms)
I230426 14:42:42.127497 4686977 kv/kvserver/store_raft.go:656  [T1,n1,s1,r32/1:/NamespaceTable/{30-Max},raft] 49  raft ready handling: 1.20s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.20s], wrote [append-batch=12 B, ]; node might be overloaded
I230426 14:42:42.149068 5131205 kv/kvserver/store_raft.go:656  [T1,n3,s3,r15/2:/Table/1{3-4},raft] 51  raft ready handling: 2.17s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=2.17s], wrote [append-batch=50 B, ]; node might be overloaded
I230426 14:42:42.173123 4686896 kv/kvserver/store_raft.go:656  [T1,n1,s1,r13/1:/Table/1{1-2},raft] 52  raft ready handling: 2.11s [append=0.00s, apply=0.99s, non-blocking-sync=0.00s, other=1.13s], wrote [append-batch=50 B, apply=536 B (2 in 2 batches)]; node might be overloaded
I230426 14:42:42.173992 5244782 kv/kvserver/store_raft.go:656  [T1,n5,s5,r27/2:/Table/2{5-6},raft] 53  raft ready handling: 1.83s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.83s], wrote [append-batch=12 B, ]; node might be overloaded
W230426 14:42:42.180014 8421048 2@rpc/clock_offset.go:276  [T1,n2,rnode=4,raddr=127.0.0.1:39999,class=default,rpc] 55  latency jump (prev avg 163.33ms, current 408.13ms)
I230426 14:42:42.168137 5244627 kv/kvserver/store_raft.go:656  [T1,n5,s5,r2/3:/System/NodeLiveness{-Max},raft] 54  raft ready handling: 0.90s [append=0.00s, apply=0.00s, sync=0.00s, other=0.90s], wrote [append-batch=12 B, ]; node might be overloaded
W230426 14:42:42.186610 5164955 2@rpc/clock_offset.go:276  [T1,n1,rnode=2,raddr=127.0.0.1:42861,class=system,rpc] 57  latency jump (prev avg 153.41ms, current 580.86ms)
--- FAIL: TestExportJoin (0.06s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

_{This test on roachdash | Improve this report!}

cockroach-teamcity · 2023-04-27T14:30:55Z

sql/importer.TestExportJoin failed with artifacts on master @ e87549936f4b89e3d95a1822ca26ce6d2ad21f23:

Fatal error:

panic: logging already active; first use:

Stack:

goroutine 4530347 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc0003d6e00, {{{0xc00a23c270, 0x24}, {0x0, 0x0}, {0x60cac5e, 0x1}, {0x60cac5e, 0x1}}, 0x1759d11a485bb336, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x764afa0, 0xc00f861ad0}, 0x2, 0x1, 0x0, 0x0?, {0x608719d, 0x1c}, {0xc042e2fb20, 0x1, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.Infof(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:277
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processReady(0xc00a8b7500, 0x764afa0?)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_raft.go:656 +0x337
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker(0xc00ab14fc0, {0x764afa0, 0xc008a156b0}, {0x762eb30, 0xc00a8b7500}, 0xc017156900)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:392 +0x195
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2({0x764afa0?, 0xc008a156b0?})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:299 +0x45
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b [recovered]
	panic: logging already active; first use:
goroutine 4530347 [running]:
runtime/debug.Stack()
	GOROOT/src/runtime/debug/stack.go:24 +0x65
github.com/cockroachdb/cockroach/pkg/util/log.setActive()
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:418 +0xa7
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0xc0003d6e00, {{{0xc00a23c270, 0x24}, {0x0, 0x0}, {0x60cac5e, 0x1}, {0x60cac5e, 0x1}}, 0x1759d11a485bb336, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x764afa0, 0xc00f861ad0}, 0x2, 0x1, 0x0, 0x0?, {0x608719d, 0x1c}, {0xc042e2fb20, 0x1, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:106 +0x605
github.com/cockroachdb/cockroach/pkg/util/log.logfDepth(...)
	github.com/cockroachdb/cockroach/pkg/util/log/channels.go:39
github.com/cockroachdb/cockroach/pkg/util/log.Infof(...)
	github.com/cockroachdb/cockroach/bazel-out/k8-fastbuild/bin/pkg/util/log/log_channels_generated.go:277
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processReady(0xc00a8b7500, 0x764afa0?)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_raft.go:656 +0x337
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker(0xc00ab14fc0, {0x764afa0, 0xc008a156b0}, {0x762eb30, 0xc00a8b7500}, 0xc017156900)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:392 +0x195
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2({0x764afa0?, 0xc008a156b0?})
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:299 +0x45
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b

Log preceding fatal error

=== RUN   TestExportJoin
W230427 14:30:46.348462 5085368 kv/kvserver/replica_raft.go:1408  [T1,n5,s5,r32/3:/NamespaceTable/{30-Max},raft] 41  have been waiting 61.50s for slow proposal RequestLease [/NamespaceTable/30,/Min)
I230427 14:30:46.376168 5085450 kv/kvserver/store_raft.go:656  [T1,n5,s5,r43/2:/Table/4{1-2},raft] 42  raft ready handling: 1.06s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.06s], wrote [append-batch=296 B, append-ent=233 B (1), ]; node might be overloaded
I230427 14:30:46.463683 4530880 2@server/status/runtime_log.go:47  [T1,n1] 46  runtime stats: 1.8 GiB RSS, 3914 goroutines (stacks: 66 MiB), 816 MiB/1.5 GiB Go alloc/total(stale) (heap fragmentation: 382 MiB, heap reserved: 216 MiB, heap released: 12 MiB), 235 MiB/344 MiB CGO alloc/total (0.5 CGO/sec), 154.2/11.0 %(u/s)time, 0.0 %gc (201x), 18 MiB/18 MiB (r/w)net
E230427 14:30:46.439967 43179682 kv/kvserver/replica_circuit_breaker.go:176  [T1,n2,s2,r48/5:/Table/4{6-7}] 43  breaker: tripped with error: replica unavailable: (n2,s2):5 unable to serve request to r48:/Table/4{6-7} [(n1,s1):1, (n4,s4):2, (n5,s5):3, (n3,s3):4, (n2,s2):5, next=6, gen=8]: closed timestamp: 1682605502.852397711,0 (2023-04-27 14:25:02); raft status: {"id":"5","term":70,"vote":"4","commit":219,"lead":"0","raftState":"StateFollower","applied":219,"progress":{},"leadtransferee":"0"}: have been waiting 62.50s for slow proposal RequestLease [/Table/46,/Min)
I230427 14:30:46.452446 4529922 kv/kvserver/store_raft.go:656  [T1,n1,s1,r48/1:/Table/4{6-7},raft] 44  raft ready handling: 1.60s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.60s], wrote [append-batch=50 B, ]; node might be overloaded
I230427 14:30:46.449085 4530322 kv/kvserver/store_raft.go:656  [T1,n1,s1,r3/1:/System/{NodeLive…-tsd},raft] 45  raft ready handling: 1.60s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.60s], wrote [append-batch=12 B, ]; node might be overloaded
I230427 14:30:46.471660 5027097 kv/kvserver/store_raft.go:656  [T1,n4,s4,r41/2:/Table/{39-40},raft] 47  raft ready handling: 1.24s [append=0.00s, apply=0.00s, sync=0.00s, other=1.24s], wrote [append-batch=397 B, append-ent=334 B (1), ]; node might be overloaded
I230427 14:30:46.486811 4530337 kv/kvserver/store_raft.go:656  [T1,n1,s1,r22/1:/Table/2{0-1},raft] 48  raft ready handling: 1.83s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.83s], wrote [append-batch=286 B, append-ent=223 B (1), ]; node might be overloaded
I230427 14:30:46.500562 4530158 kv/kvserver/store_raft.go:656  [T1,n1,s1,r2/1:/System/NodeLiveness{-Max},raft] 50  raft ready handling: 0.81s [append=0.00s, apply=0.00s, sync=0.00s, other=0.81s], wrote [append-batch=12 B, ]; node might be overloaded
I230427 14:30:46.464872 5085556 kv/kvserver/store_raft.go:656  [T1,n5,s5,r31/5:/{Table/29-NamespaceTab…},raft] 49  raft ready handling: 1.24s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.24s], wrote [append-batch=12 B, ]; node might be overloaded
I230427 14:30:46.492576 4931164 kv/kvserver/store_raft.go:656  [T1,n2,s2,r40/3:/Table/3{8-9},raft] 51  raft ready handling: 1.12s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.12s], wrote [append-batch=12 B, ]; node might be overloaded
W230427 14:30:46.504046 8347500 2@rpc/clock_offset.go:276  [T1,n5,rnode=2,raddr=127.0.0.1:36571,class=default,rpc] 52  latency jump (prev avg 99.98ms, current 195.79ms)
I230427 14:30:46.514808 43184203 gossip/client.go:124  [T1,n5] 53  started gossip client to n0 (127.0.0.1:34805)
W230427 14:30:46.510989 5127375 2@rpc/clock_offset.go:276  [T1,n1,rnode=5,raddr=127.0.0.1:36965,class=system,rpc] 54  latency jump (prev avg 124.27ms, current 591.62ms)
W230427 14:30:46.515905 8345342 2@rpc/clock_offset.go:276  [T1,n4,rnode=5,raddr=127.0.0.1:36965,class=default,rpc] 55  latency jump (prev avg 117.39ms, current 246.82ms)
I230427 14:30:46.533133 4930604 kv/kvserver/store_raft.go:656  [T1,n2,s2,r30/4:/Table/2{8-9},raft] 56  raft ready handling: 1.18s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.18s], wrote [append-batch=50 B, ]; node might be overloaded
W230427 14:30:46.534600 8314625 2@rpc/clock_offset.go:276  [T1,n3,rnode=5,raddr=127.0.0.1:36965,class=default,rpc] 57  latency jump (prev avg 83.40ms, current 311.83ms)
I230427 14:30:46.567740 5085571 kv/kvserver/store_raft.go:656  [T1,n5,s5,r7/3:/Table/{3-4},raft] 58  raft ready handling: 1.31s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.31s], wrote [append-batch=12 B, ]; node might be overloaded
W230427 14:30:46.549140 8429289 2@rpc/clock_offset.go:276  [T1,n2,rnode=4,raddr=127.0.0.1:40897,class=system,rpc] 60  latency jump (prev avg 139.93ms, current 252.99ms)
I230427 14:30:46.551106 4530240 kv/kvserver/store_raft.go:656  [T1,n1,s1,r63/1:/Table/{62-106},raft] 59  raft ready handling: 1.77s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.77s], wrote [append-batch=50 B, ]; node might be overloaded
I230427 14:30:46.551759 5026136 kv/kvserver/store_raft.go:656  [T1,n4,s4,r66/5:/Table/106/1/{60-80},raft] 61  raft ready handling: 1.92s [append=0.00s, apply=1.20s, non-blocking-sync=0.00s, other=0.72s], wrote [append-batch=50 B, apply=231 B (2 in 2 batches)]; node might be overloaded
I230427 14:30:46.558222 4931236 kv/kvserver/store_raft.go:656  [T1,n2,s2,r59/5:/Table/5{8-9},raft] 62  raft ready handling: 1.15s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.15s], wrote [append-batch=12 B, ]; node might be overloaded
I230427 14:30:46.567263 4530078 kv/kvserver/store_raft.go:656  [T1,n1,s1,r31/1:/{Table/29-NamespaceTab…},raft] 63  raft ready handling: 1.56s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.56s], wrote [append-batch=12 B, ]; node might be overloaded
I230427 14:30:46.583048 4530107 kv/kvserver/store_raft.go:656  [T1,n1,s1,r38/1:/Table/3{6-7},raft] 64  raft ready handling: 1.92s [append=0.00s, apply=1.00s, non-blocking-sync=0.00s, other=0.92s], wrote [append-batch=50 B, apply=233 B (1)]; node might be overloaded
I230427 14:30:46.586302 43180081 gossip/client.go:129  [T1,n3] 65  closing client to n2 (127.0.0.1:36571): stopping outgoing client to n2 (127.0.0.1:36571); already have incoming
I230427 14:30:46.603765 4930763 kv/kvserver/store_raft.go:656  [T1,n2,s2,r49/2:/Table/4{7-8},raft] 67  raft ready handling: 1.20s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.20s], wrote [append-batch=12 B, ]; node might be overloaded
I230427 14:30:46.589883 43181109 gossip/client.go:129  [T1,n2] 66  closing client to n1 (127.0.0.1:39473): stopping outgoing client to n1 (127.0.0.1:39473); already have incoming
W230427 14:30:46.614467 8320103 2@rpc/clock_offset.go:276  [T1,n5,rnode=3,raddr=127.0.0.1:34805,class=system,rpc] 70  latency jump (prev avg 116.05ms, current 204.03ms)
I230427 14:30:46.606686 43021721 kv/kvserver/replica_rangefeed.go:738  [n1,s1,r22/1:/Table/2{0-1}] 68  RangeFeed failed to nudge: retry rangefeed (REASON_NO_LEASEHOLDER)
W230427 14:30:46.611868 5030425 2@rpc/clock_offset.go:276  [T1,n4,rnode=1,raddr=127.0.0.1:39473,class=default,rpc] 69  latency jump (prev avg 130.74ms, current 274.92ms)
I230427 14:30:46.618142 5085339 kv/kvserver/store_raft.go:656  [T1,n5,s5,r60/5:/Table/{59-60},raft] 71  raft ready handling: 1.13s [append=0.00s, apply=1.08s, sync=0.00s, other=0.05s], wrote [append-batch=332 B, append-ent=231 B (1), apply=693 B (4 in 4 batches)]; node might be overloaded
I230427 14:30:46.612914 4530347 kv/kvserver/store_raft.go:656  [T1,n1,s1,r64/6:/Table/106/1/1{00-20},raft] 72  raft ready handling: 1.70s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.70s], wrote [append-batch=12 B, ]; node might be overloaded
E230427 14:30:46.631034 43188518 kv/kvserver/replica_circuit_breaker.go:176  [T1,n5,s5,r32/3:/NamespaceTable/{30-Max}] 74  breaker: tripped with error: replica unavailable: (n5,s5):3 unable to serve request to r32:/NamespaceTable/{30-Max} [(n1,s1):1, (n3,s3):2, (n5,s5):3, (n4,s4):4, (n2,s2):5, next=6, gen=8]: closed timestamp: 1682605722.356002311,0 (2023-04-27 14:28:42); raft status: {"id":"3","term":63,"vote":"4","commit":218,"lead":"0","raftState":"StatePreCandidate","applied":218,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/NamespaceTable/30,/Min)
I230427 14:30:46.632640 5026744 kv/kvserver/store_raft.go:656  [T1,n4,s4,r3/4:/System/{NodeLive…-tsd},raft] 75  raft ready handling: 1.13s [append=0.00s, apply=0.00s, , other=1.13s], wrote []; node might be overloaded
W230427 14:30:46.626872 5027910 kv/kvserver/liveness/liveness.go:908  [T1,n4,liveness-hb] 73  slow heartbeat took 4.107735515s; err=aborted during DistSender.Send: context deadline exceeded
I230427 14:30:46.642780 4530551 kv/kvserver/store_raft.go:656  [T1,n1,s1,r17/1:/Table/1{5-6},raft] 76  raft ready handling: 1.84s [append=0.00s, apply=0.25s, non-blocking-sync=0.00s, other=1.58s], wrote [append-batch=50 B, apply=334 B (1)]; node might be overloaded
--- FAIL: TestExportJoin (0.19s)

Parameters: TAGS=bazel,gss,deadlock

Help

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

_{This test on roachdash | Improve this report!}

erikgrinaker · 2023-04-28T12:59:53Z

Opened #102588 to track the log panic here.

knz · 2023-08-17T15:49:28Z

IMHO there's something specific to this test that's "interesting" - it should not flake with this reason.

knz · 2023-08-17T15:49:36Z

now owned by obs inf though

Santamaura · 2023-08-21T18:03:14Z

Spent a bit of time looking at this in the morning, it doesn't reproduce locally for me under stress and race. The errors seemed to be happening almost daily prior to #102591, are we sure that didn't resolve it or we keeping this open to find out some underlying reason why it was failing?

knz · 2023-08-23T15:25:17Z

good call. I agree #102591 is the likely culprit. Let's close this.

cockroach-teamcity added branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Apr 16, 2023

cockroach-teamcity added this to the 23.1 milestone Apr 16, 2023

blathers-crl bot added the T-sql-queries SQL Queries Team label Apr 16, 2023

erikgrinaker self-assigned this Apr 19, 2023

blathers-crl bot added the T-kv KV Team label Apr 19, 2023

exalate-issue-sync bot removed the T-sql-queries SQL Queries Team label Apr 24, 2023

erikgrinaker added T-kv-replication and removed T-kv KV Team labels Apr 24, 2023

This was referenced Apr 28, 2023

util/log: panic: logging already active #102588

Closed

sql/importer: skip tests under deadlock/stressrace #102589

Closed

erikgrinaker mentioned this issue Apr 28, 2023

kvserver: disable kv.expiration_leases_only.enabled metamorphism under deadlock #102591

Merged

craig bot closed this as completed in f8523ec Apr 28, 2023

knz reopened this Aug 17, 2023

knz unassigned erikgrinaker Aug 17, 2023

knz added T-observability-inf and removed T-kv-replication labels Aug 17, 2023

blathers-crl bot added the A-observability-inf label Aug 17, 2023

exalate-issue-sync bot assigned Santamaura Aug 21, 2023

knz closed this as completed Aug 23, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

sql/importer: TestExportJoin failed #101612

sql/importer: TestExportJoin failed #101612

cockroach-teamcity commented Apr 16, 2023 •

edited by exalate-issue-sync bot

Loading

cockroach-teamcity commented Apr 18, 2023

yuzefovich commented Apr 19, 2023 •

edited

Loading

cockroach-teamcity commented Apr 19, 2023

cockroach-teamcity commented Apr 21, 2023

cockroach-teamcity commented Apr 22, 2023

blathers-crl bot commented Apr 24, 2023

cockroach-teamcity commented Apr 24, 2023

cockroach-teamcity commented Apr 25, 2023

cockroach-teamcity commented Apr 26, 2023

cockroach-teamcity commented Apr 27, 2023

erikgrinaker commented Apr 28, 2023

knz commented Aug 17, 2023

knz commented Aug 17, 2023

Santamaura commented Aug 21, 2023

knz commented Aug 23, 2023

sql/importer: TestExportJoin failed #101612

sql/importer: TestExportJoin failed #101612

Comments

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

cockroach-teamcity commented Apr 18, 2023

yuzefovich commented Apr 19, 2023 • edited Loading

cockroach-teamcity commented Apr 19, 2023

cockroach-teamcity commented Apr 21, 2023

cockroach-teamcity commented Apr 22, 2023

blathers-crl bot commented Apr 24, 2023

cockroach-teamcity commented Apr 24, 2023

cockroach-teamcity commented Apr 25, 2023

cockroach-teamcity commented Apr 26, 2023

cockroach-teamcity commented Apr 27, 2023

erikgrinaker commented Apr 28, 2023

knz commented Aug 17, 2023

knz commented Aug 17, 2023

Santamaura commented Aug 21, 2023

knz commented Aug 23, 2023

cockroach-teamcity commented Apr 16, 2023 •

edited by exalate-issue-sync bot

Loading

yuzefovich commented Apr 19, 2023 •

edited

Loading