server: TestListenerFileCreation failed #43949
Description
(server).TestListenerFileCreation failed on master@3d98dae853edbde083cc23b60ad6696958909849:
Fatal error:
F200114 03:18:16.212253 70735 sqlmigrations/migrations.go:531 [n1] not enough time left on migration lease, terminating for safety
Stack:
goroutine 70735 [running]:
github.com/cockroachdb/cockroach/pkg/util/log.getStacks(0x6285c01, 0xed5af29f8, 0x0, 0xc000875ec0)
/go/src/github.com/cockroachdb/cockroach/pkg/util/log/get_stacks.go:25 +0xb8
github.com/cockroachdb/cockroach/pkg/util/log.(*loggerT).outputLogEntry(0x6282c40, 0xc000000004, 0x5c52d33, 0x1b, 0x213, 0xc002f2fcc0, 0x44)
/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:211 +0xa0c
github.com/cockroachdb/cockroach/pkg/util/log.addStructured(0x41367c0, 0xc002a07f50, 0x4, 0x2, 0x0, 0x0, 0xc000875e28, 0x1, 0x1)
/go/src/github.com/cockroachdb/cockroach/pkg/util/log/structured.go:66 +0x2c9
github.com/cockroachdb/cockroach/pkg/util/log.logDepth(0x41367c0, 0xc002a07f50, 0x1, 0xc000000004, 0x0, 0x0, 0xc000875e28, 0x1, 0x1)
/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:44 +0x8c
github.com/cockroachdb/cockroach/pkg/util/log.Fatal(...)
/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:164
github.com/cockroachdb/cockroach/pkg/sqlmigrations.(*Manager).EnsureMigrations.func2(0x41367c0, 0xc002a07f50)
/go/src/github.com/cockroachdb/cockroach/pkg/sqlmigrations/migrations.go:531 +0x284
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1(0xc004d6c120, 0x41367c0, 0xc002a07f50, 0xc00142a6f0, 0x29, 0x0, 0x0, 0xc0003e7da0)
/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:322 +0x152
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask
/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:317 +0x131
Log preceding fatal error
Sum 0/0 0.00 KB 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.00 0.00 0 0.000 0 0
Int 0/0 0.00 KB 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.00 0.00 0 0.000 0 0
** Compaction Stats [default] **
Priority Files Size Score Read(GB) Rn(GB) Rnp1(GB) Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) Comp(sec) CompMergeCPU(sec) Comp(cnt) Avg(sec) KeyIn KeyDrop
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Uptime(secs): 141.2 total, 14.2 interval
Flush(GB): cumulative 0.000, interval 0.000
AddFile(GB): cumulative 0.000, interval 0.000
AddFile(Total Files): cumulative 0, interval 0
AddFile(L0 Files): cumulative 0, interval 0
AddFile(Keys): cumulative 0, interval 0
Cumulative compaction: 0.00 GB write, 0.00 MB/s write, 0.00 GB read, 0.00 MB/s read, 0.0 seconds
Interval compaction: 0.00 GB write, 0.00 MB/s write, 0.00 GB read, 0.00 MB/s read, 0.0 seconds
Stalls(count): 0 level0_slowdown, 0 level0_slowdown_with_compaction, 0 level0_numfiles, 0 level0_numfiles_with_compaction, 0 stop for pending_compaction_bytes, 0 slowdown for pending_compaction_bytes, 0 memtable_compaction, 0 memtable_slowdown, interval 0 total count
estimated_pending_compaction_bytes: 0 B
W200114 03:17:52.827670 70535 storage/node_liveness.go:544 [n1,liveness-hb] slow heartbeat took 4.5s
W200114 03:17:52.827727 70535 storage/node_liveness.go:469 [n1,liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 4.5s
W200114 03:17:57.327946 70535 storage/node_liveness.go:544 [n1,liveness-hb] slow heartbeat took 4.5s
W200114 03:17:57.328010 70535 storage/node_liveness.go:469 [n1,liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 4.5s
I200114 03:17:59.140054 70509 gossip/gossip.go:566 [n1] gossip status (stalled, 1 node)
gossip client (0/3 cur/max conns)
gossip server (0/3 cur/max conns, infos 0/0 sent/received, bytes 0B/0B sent/received)
I200114 03:17:59.151121 70513 server/status/runtime.go:498 [n1] runtime stats: 263 MiB RSS, 183 goroutines, 46 MiB/131 MiB/92 MiB GO alloc/idle/total, 16 MiB/52 MiB CGO alloc/total, 10.0 CGO/sec, 0.6/0.1 %(u/s)time, 0.0 %gc (0x), 4.0 MiB/4.0 MiB (r/w)net
W200114 03:18:01.607831 70439 storage/store_raft.go:496 [n1,s1,r2/1:/System/NodeLiveness{-Max}] handle raft ready: 16.3s [applied=1, batches=1, state_assertions=0]
W200114 03:18:01.607891 70443 storage/store_raft.go:496 [n1,s1,r4/1:/System{/tsd-tse}] handle raft ready: 16.3s [applied=1, batches=1, state_assertions=1]
W200114 03:18:01.608026 70468 storage/store_raft.go:496 [n1,s1,r1/1:/{Min-System/NodeL…}] handle raft ready: 16.3s [applied=1, batches=1, state_assertions=0]
W200114 03:18:01.828264 70535 storage/node_liveness.go:544 [n1,liveness-hb] slow heartbeat took 4.5s
W200114 03:18:01.828323 70535 storage/node_liveness.go:469 [n1,liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 4.5s
W200114 03:18:05.072647 70225 storage/store_raft.go:496 [n1,s1,r2/1:/System/NodeLiveness{-Max}] handle raft ready: 3.4s [applied=1, batches=1, state_assertions=1]
W200114 03:18:05.561053 70458 storage/store_raft.go:496 [n1,s1,r1/1:/{Min-System/NodeL…}] handle raft ready: 3.9s [applied=1, batches=1, state_assertions=1]
W200114 03:18:05.581830 70442 storage/store_raft.go:496 [n1,s1,r2/1:/System/NodeLiveness{-Max}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W200114 03:18:05.582129 71882 storage/node_liveness.go:544 [n1,s1,r15/1:/Table/{19-20}] slow heartbeat took 20.3s
W200114 03:18:05.582301 71804 storage/node_liveness.go:544 [n1,s1,r6/1:/Table/{SystemCon…-11}] slow heartbeat took 20.2s
E200114 03:18:05.582329 71804 storage/replica_range_lease.go:339 [n1,s1,r6/1:/Table/{SystemCon…-11}] heartbeat failed on epoch increment
W200114 03:18:05.582392 71805 storage/node_liveness.go:544 [n1,s1,r8/1:/Table/1{2-3}] slow heartbeat took 20.2s
E200114 03:18:05.582406 71805 storage/replica_range_lease.go:339 [n1,s1,r8/1:/Table/1{2-3}] heartbeat failed on epoch increment
W200114 03:18:05.582564 71884 storage/node_liveness.go:544 [n1,s1,r3/1:/System/{NodeLive…-tsd}] slow heartbeat took 20.2s
E200114 03:18:05.582582 71884 storage/replica_range_lease.go:339 [n1,s1,r3/1:/System/{NodeLive…-tsd}] heartbeat failed on epoch increment
W200114 03:18:05.582741 72107 storage/node_liveness.go:544 [n1,s1,r4/1:/System{/tsd-tse}] slow heartbeat took 4.0s
E200114 03:18:05.582763 72107 storage/replica_range_lease.go:339 [n1,s1,r4/1:/System{/tsd-tse}] heartbeat failed on epoch increment
W200114 03:18:05.582820 70535 storage/node_liveness.go:544 [n1,liveness-hb] slow heartbeat took 3.8s
I200114 03:18:05.582833 70535 storage/node_liveness.go:459 [n1,liveness-hb] heartbeat failed on epoch increment; retrying
I200114 03:18:05.597058 70423 gossip/gossip.go:1531 [n1] node has connected to cluster via gossip
W200114 03:18:08.134792 70464 storage/store_raft.go:496 [n1,s1,r4/1:/System{/tsd-tse}] handle raft ready: 2.5s [applied=1, batches=1, state_assertions=0]
I200114 03:18:09.151757 70513 server/status/runtime.go:498 [n1] runtime stats: 263 MiB RSS, 176 goroutines, 51 MiB/126 MiB/92 MiB GO alloc/idle/total, 16 MiB/52 MiB CGO alloc/total, 56.2 CGO/sec, 0.9/0.1 %(u/s)time, 0.0 %gc (0x), 7.1 MiB/7.1 MiB (r/w)net
W200114 03:18:16.000469 70506 storage/store_rebalancer.go:223 [n1,s1,store-rebalancer] StorePool missing descriptor for local store
W200114 03:18:16.211328 70492 storage/store_raft.go:496 [n1,s1,r6/1:/Table/{SystemCon…-11}] handle raft ready: 10.5s [applied=1, batches=1, state_assertions=0]
W200114 03:18:16.211564 70446 storage/store_raft.go:496 [n1,s1,r3/1:/System/{NodeLive…-tsd}] handle raft ready: 10.4s [applied=1, batches=1, state_assertions=0]
W200114 03:18:16.212122 70486 storage/store_raft.go:496 [n1,s1,r1/1:/{Min-System/NodeL…}] handle raft ready: 8.8s [applied=1, batches=1, state_assertions=1]
Repro
Parameters:
- GOFLAGS=-json
make stressrace TESTS=TestListenerFileCreation PKG=./pkg/server TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1
powered by pkg/cmd/internal/issues