sql/importer: TestExportJoin failed

[cockroach-teamcity]

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

Fatal error:

panic: logging already active; first use:

Stack:

goroutine 5050247 [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(0xc0001b0860, {{{0xc0139e1e30, 0x24}, {0x0, 0x0}, {0x60e6ea4, 0x1}, {0x60e6ea8, 0x1}}, 0x175a22f3aabf090f, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x7669040, 0xc00f860390}, 0x2, 0x1, 0x0, 0x0?, {0x60a326f, 0x1c}, {0xc008f31b20, 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(0xc002144000, 0x7669040?)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_raft.go:656 +0x337
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker(0xc00491b9e0, {0x7669040, 0xc0183056e0}, {0x764cbd0, 0xc002144000}, 0xc014f16900)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:392 +0x195
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2({0x7669040?, 0xc0183056e0?})
	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 5050247 [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(0xc0001b0860, {{{0xc0139e1e30, 0x24}, {0x0, 0x0}, {0x60e6ea4, 0x1}, {0x60e6ea8, 0x1}}, 0x175a22f3aabf090f, ...})
	github.com/cockroachdb/cockroach/pkg/util/log/clog.go:250 +0x50
github.com/cockroachdb/cockroach/pkg/util/log.logfDepthInternal({0x7669040, 0xc00f860390}, 0x2, 0x1, 0x0, 0x0?, {0x60a326f, 0x1c}, {0xc008f31b20, 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(0xc002144000, 0x7669040?)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_raft.go:656 +0x337
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker(0xc00491b9e0, {0x7669040, 0xc0183056e0}, {0x764cbd0, 0xc002144000}, 0xc014f16900)
	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:392 +0x195
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2({0x7669040?, 0xc0183056e0?})
	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
I230428 15:30:40.635475 4895832 kv/kvserver/store_raft.go:656  [T1,n2,s2,r21/3:/Table/{19-20},raft] 31  raft ready handling: 0.98s [append=0.00s, apply=0.91s, sync=0.00s, other=0.07s], wrote [append-batch=50 B, apply=223 B (1)]; node might be overloaded
I230428 15:30:40.633868 4896030 kv/kvserver/store_raft.go:656  [T1,n2,s2,r46/2:/Table/4{4-5},raft] 32  raft ready handling: 0.97s [append=0.00s, apply=0.00s, sync=0.00s, other=0.97s], wrote [append-batch=12 B, ]; node might be overloaded
I230428 15:30:40.640253 32104407 gossip/server.go:277  [T1,n3] 33  refusing gossip from n5 (max 3 conns); forwarding to n1 (127.0.0.1:42767)
I230428 15:30:40.648100 4493975 kv/kvserver/store_raft.go:656  [T1,n1,s1,r66/1:/Table/106/1/{60-80},raft] 34  raft ready handling: 0.97s [append=0.00s, apply=0.53s, non-blocking-sync=0.00s, other=0.44s], wrote [append-batch=332 B, append-ent=231 B (1), apply=217 B (1)]; node might be overloaded
I230428 15:30:40.648885 5049717 kv/kvserver/store_raft.go:656  [T1,n5,s5,r24/4:/Table/2{2-3},raft] 35  raft ready handling: 0.80s [append=0.00s, apply=0.00s, sync=0.00s, other=0.80s], wrote [append-batch=282 B, append-ent=219 B (1), ]; node might be overloaded
I230428 15:30:40.642377 4994081 kv/kvserver/store_raft.go:656  [T1,n4,s4,r52/5:/Table/5{1-2},raft] 36  raft ready handling: 1.04s [append=0.00s, apply=0.00s, sync=0.00s, other=1.04s], wrote [append-batch=332 B, append-ent=231 B (1), ]; node might be overloaded
I230428 15:30:40.658074 4494550 kv/kvserver/store_raft.go:656  [T1,n1,s1,r41/1:/Table/{39-40},raft] 37  raft ready handling: 0.59s [append=0.00s, apply=0.00s, sync=0.00s, other=0.59s], wrote [append-batch=12 B, ]; node might be overloaded
W230428 15:30:40.666909 4994668 kv/kvserver/replica_gossip.go:157  [T1,n4,s4,r2/4:/System/NodeLiveness{-Max}] 38  could not acquire lease for range gossip: 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: 1682695132.257750340,0 (2023-04-28 15:18:52); raft status: {"id":"4","term":76,"vote":"5","commit":249,"lead":"0","raftState":"StateFollower","applied":249,"progress":{},"leadtransferee":"0"}: operation "probe" timed out after 1m0.055s (given timeout 1m0s): result is ambiguous: after 60.00s of attempting command: context deadline exceeded
I230428 15:30:40.667583 4993540 kv/kvserver/store_raft.go:656  [T1,n4,s4,r44/3:/Table/4{2-3},raft] 39  raft ready handling: 1.01s [append=0.00s, apply=0.98s, , other=0.03s], wrote [append-batch=50 B, apply=223 B (1)]; node might be overloaded
I230428 15:30:40.663680 4895415 kv/kvserver/store_raft.go:656  [T1,n2,s2,r13/3:/Table/1{1-2},raft] 40  raft ready handling: 0.92s [append=0.00s, apply=0.79s, sync=0.00s, other=0.13s], wrote [append-batch=50 B, apply=223 B (2 in 2 batches)]; node might be overloaded
I230428 15:30:40.663753 4940737 kv/kvserver/store_raft.go:656  [T1,n3,s3,r19/5:/Table/1{7-8},raft] 41  raft ready handling: 1.75s [append=0.00s, apply=0.00s, non-blocking-sync=0.00s, other=1.75s], wrote [append-batch=282 B, append-ent=219 B (1), ]; node might be overloaded
E230428 15:30:40.675684 4494992 kv/kvserver/protectedts/ptcache/cache.go:205  [T1,n1] 42  failed to refresh protected timestamps: failed to fetch protectedts metadata: failed to read metadata: protectedts-GetMetadata: replica unavailable: (n2,s2):3 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n4,s4):2, (n2,s2):3, (n5,s5):4, (n3,s3):5, next=6, gen=8]: closed timestamp: 1682695494.873171824,0 (2023-04-28 15:24:54); raft status: {"id":"3","term":60,"vote":"4","commit":161,"lead":"0","raftState":"StateFollower","applied":161,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/3,/Min)
I230428 15:30:40.680747 4895776 kv/kvserver/store_raft.go:656  [T1,n2,s2,r45/5:/Table/4{3-4},raft] 43  raft ready handling: 1.00s [append=0.00s, apply=0.00s, , other=1.00s], wrote []; node might be overloaded
E230428 15:30:40.685560 6972748 jobs/metricspoller/poller.go:76  [T1,n1,job=POLL JOBS STATS id=101,task=paused-jobs] 44  Periodic stats collector task paused-jobs completed with error could not query jobs table: poll-jobs-metrics-job: replica unavailable: (n2,s2):3 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n4,s4):2, (n2,s2):3, (n5,s5):4, (n3,s3):5, next=6, gen=8]: closed timestamp: 1682695494.873171824,0 (2023-04-28 15:24:54); raft status: {"id":"3","term":60,"vote":"4","commit":161,"lead":"0","raftState":"StateFollower","applied":161,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/3,/Min)
W230428 15:30:40.689860 4951642 2@rpc/clock_offset.go:276  [T1,n1,rnode=3,raddr=127.0.0.1:45243,class=default,rpc] 46  latency jump (prev avg 134.72ms, current 592.73ms)
I230428 15:30:40.700634 4895525 kv/kvserver/store_raft.go:656  [T1,n2,s2,r56/2:/Table/5{5-6},raft] 45  raft ready handling: 1.03s [append=0.00s, apply=0.92s, sync=0.00s, other=0.11s], wrote [append-batch=50 B, apply=295 B (2 in 2 batches)]; node might be overloaded
I230428 15:30:40.697776 5050265 kv/kvserver/store_raft.go:656  [T1,n5,s5,r63/4:/Table/{62-106},raft] 47  raft ready handling: 0.66s [append=0.00s, apply=0.00s, , other=0.66s], wrote []; node might be overloaded
I230428 15:30:40.701602 4940812 kv/kvserver/store_raft.go:656  [T1,n3,s3,r26/2:/Table/2{4-5},raft] 48  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
I230428 15:30:40.696072 4494459 kv/kvserver/store_raft.go:656  [T1,n1,s1,r58/1:/Table/5{7-8},raft] 49  raft ready handling: 1.33s [append=0.00s, apply=0.80s, non-blocking-sync=0.00s, other=0.53s], wrote [append-batch=50 B, apply=217 B (1)]; node might be overloaded
I230428 15:30:40.713345 5050247 kv/kvserver/store_raft.go:656  [T1,n5,s5,r15/3:/Table/1{3-4},raft] 50  raft ready handling: 0.61s [append=0.00s, apply=0.00s, , other=0.61s], wrote []; node might be overloaded
E230428 15:30:40.711591 4507353 jobs/registry.go:1102  [T1,n1] 51  error processing claimed jobs: could not query for claimed jobs: select-running/get-claimed-jobs: replica unavailable: (n2,s2):3 unable to serve request to r7:/Table/{3-4} [(n1,s1):1, (n4,s4):2, (n2,s2):3, (n5,s5):4, (n3,s3):5, next=6, gen=8]: closed timestamp: 1682695494.873171824,0 (2023-04-28 15:24:54); raft status: {"id":"3","term":60,"vote":"4","commit":161,"lead":"0","raftState":"StateFollower","applied":161,"progress":{},"leadtransferee":"0"}: have been waiting 61.50s for slow proposal RequestLease [/Table/3,/Min)
I230428 15:30:40.704210 4494168 kv/kvserver/store_raft.go:656  [T1,n1,s1,r31/1:/{Table/29-NamespaceTab…},raft] 52  raft ready handling: 1.03s [append=0.00s, apply=0.60s, , other=0.43s], wrote [append-batch=49 B, apply=319 B (1)]; node might be overloaded
--- FAIL: TestExportJoin (0.12s)

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-27558

[yuzefovich]

mitigated by #102591 and tracked in #102588