TestMergeQueue/non-collocated
...orage.go:829  [s2,r10/?:{b-c}] applied PREEMPTIVE snapshot in 320ms [clear=0ms batch=229ms entries=0ms commit=90ms]
I190807 19:00:07.904950 157073 storage/replica_command.go:1188  [s1,r10/1:{b-c}] change replicas (ADD_REPLICA (n2,s2):2): existing descriptor r10:{b-c} [(n1,s1):1, next=2, gen=15]
I190807 19:00:07.915726 157073 storage/replica_raft.go:290  [s1,r10/1:{b-c},txn=93480a64] proposing ADD_REPLICA((n2,s2):2): updated=(n1,s1):1,(n2,s2):2 next=3
I190807 19:00:08.332247 157073 storage/replica_command.go:1188  [s2,r10/2:{b-c}] change replicas (REMOVE_REPLICA (n1,s1):1): existing descriptor r10:{b-c} [(n1,s1):1, (n2,s2):2, next=3, gen=16]
I190807 19:00:08.360906 157073 storage/replica_raft.go:290  [s2,r10/2:{b-c},txn=f9bde25a] proposing REMOVE_REPLICA((n1,s1):1): updated=(n2,s2):2 next=3
I190807 19:00:08.414632 170862 storage/store.go:2530  [replicaGC,s1,r10/1:{b-c}] removing replica r10/1
I190807 19:00:08.416044 170862 storage/replica_destroy.go:146  [replicaGC,s1,r10/1:{b-c}] removed 6 (1+5) keys in 1ms [clear=0ms commit=0ms]
W190807 19:00:08.416810 170888 storage/replica_command.go:1725  [merge,s2,r10/2:{b-c}] while adding target n1,s1: snapshot failed: (n1,s1):?: remote couldn't accept PREEMPTIVE snapshot a0c5420f at applied index 21 with error: [n1,s1],r10: cannot apply snapshot: snapshot intersects existing range; initiated GC: [n1,s1,r10/1:{b-c}] (incoming {b-c})
E190807 19:00:08.425903 170713 storage/queue.go:1027  [replicate,s2,r10/2:{b-c}] 1 matching stores are currently throttled: [[n1,s1],r10: cannot apply snapshot: snapshot intersects existing range; initiated GC: [n1,s1,r10/1:{b-c}] (incoming {b-c})]
I190807 19:00:08.426036 170713 storage/queue.go:1127  [replicate] purgatory is now empty
I190807 19:00:08.426725 170888 storage/store_snapshot.go:775  [merge,s2,r10/2:{b-c}] sending PREEMPTIVE snapshot 5a6de673 at applied index 21
I190807 19:00:08.427752 170888 storage/store_snapshot.go:818  [merge,s2,r10/2:{b-c}] streamed snapshot to (n1,s1):?: kv pairs: 21, log entries: 0, rate-limit: 8.0 MiB/sec, 0.00s
I190807 19:00:08.430891 170882 storage/replica_raftstorage.go:823  [s1,r10/?:{-}] applying PREEMPTIVE snapshot at index 21 (id=5a6de673, encoded size=1102, 1 rocksdb batches, 0 log entries)
I190807 19:00:08.432871 170882 storage/replica_raftstorage.go:829  [s1,r10/?:{b-c}] applied PREEMPTIVE snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I190807 19:00:08.442618 170888 storage/replica_command.go:1188  [merge,s2,r10/2:{b-c}] change replicas (ADD_REPLICA (n1,s1):3): existing descriptor r10:{b-c} [(n2,s2):2, next=3, gen=17]
I190807 19:00:08.460010 170888 storage/replica_raft.go:290  [merge,s2,r10/2:{b-c},txn=4cb784e3] proposing ADD_REPLICA((n1,s1):3): updated=(n2,s2):2,(n1,s1):3 next=4
I190807 19:00:08.495173 170888 storage/replica_command.go:1188  [merge,s1,r10/3:{b-c}] change replicas (REMOVE_REPLICA (n2,s2):2): existing descriptor r10:{b-c} [(n2,s2):2, (n1,s1):3, next=4, gen=18]
I190807 19:00:08.510995 170888 storage/replica_raft.go:290  [merge,s1,r10/3:{b-c},txn=647f6935] proposing REMOVE_REPLICA((n2,s2):2): updated=(n1,s1):3 next=4
I190807 19:00:08.526619 170888 storage/replica_command.go:597  [merge,s1,r2/1:{a-b}] initiating a merge of r10:{b-c} [(n1,s1):3, next=4, gen=19] into this range (lhs+rhs has (size=0 B+0 B qps=0.00+0.00 --> 0.00qps) below threshold (size=0 B, qps=0.00))
I190807 19:00:08.538611 171003 storage/store.go:2530  [replicaGC,s2,r10/2:{b-c}] removing replica r10/2
I190807 19:00:08.540067 171003 storage/replica_destroy.go:146  [replicaGC,s2,r10/2:{b-c}] removed 7 (0+7) keys in 1ms [clear=0ms commit=0ms]
I190807 19:00:08.689040 170888 storage/replica_command.go:597  [merge,s1,r2/1:{a-b}] initiating a merge of r10:{b-c} [(n1,s1):3, next=4, gen=19] into this range (lhs+rhs has (size=0 B+0 B qps=0.00+0.00 --> 0.00qps) below threshold (size=0 B, qps=0.00))
I190807 19:00:08.877603 85667 storage/store.go:2530  [merge,s1,r2/1:{a-b},txn=bac592ef] removing replica r10/3



TestMergeQueue
--- FAIL: testrace/TestMergeQueue (0.000s)
Test ended in panic.

------- Stdout: -------
I190807 18:57:01.616659 85583 gossip/gossip.go:394  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:39043" > attrs:<> locality:<> ServerVersion:<major_val:0 minor_val:0 patch:0 unstable:0 > build_tag:"" started_at:0 cluster_name:"" 
W190807 18:57:01.710337 85583 gossip/gossip.go:1498  [n2] no incoming or outgoing connections
I190807 18:57:01.711139 85583 gossip/gossip.go:394  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:33469" > attrs:<> locality:<> ServerVersion:<major_val:0 minor_val:0 patch:0 unstable:0 > build_tag:"" started_at:0 cluster_name:"" 
I190807 18:57:01.730521 85876 gossip/client.go:124  [n2] started gossip client to 127.0.0.1:39043
I190807 18:57:01.795336 85583 storage/client_test.go:495  gossip network initialized
I190807 18:57:01.803889 85583 storage/replica_command.go:283  [s1,r1/1:/M{in-ax}] initiating a split of this range at key "a" [r2] (manual)
I190807 18:57:01.850586 85583 storage/replica_command.go:283  [s1,r2/1:{a-/Max}] initiating a split of this range at key "b" [r3] (manual)
I190807 18:57:01.899827 85583 storage/replica_command.go:283  [s1,r3/1:{b-/Max}] initiating a split of this range at key "c" [r4] (manual)
I190807 18:57:03.850154 85892 gossip/gossip.go:1512  [n2] node has connected to cluster via gossip



TestMergeQueue/lhs-undersize
--- FAIL: testrace/TestMergeQueue/lhs-undersize (0.000s)
Test ended in panic.

------- Stdout: -------
W190807 18:59:08.782829 85658 storage/store.go:3618  [s1,r1/1:{/Min-a}] handle raft ready: 0.7s [applied=1, batches=1, state_assertions=0]
I190807 18:59:08.807560 85596 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:59:08.808047 85596 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
I190807 18:59:08.843036 85893 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:59:08.847447 85893 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
W190807 18:59:09.705064 85686 storage/store.go:3618  [s1,r2/1:{a-c}] handle raft ready: 10.1s [applied=1, batches=1, state_assertions=0]
I190807 18:59:11.884279 85724 storage/compactor/compactor.go:325  [s1,compactor] purging suggested compaction for range "a" - "b" that contains live data
I190807 18:59:11.886797 85724 storage/compactor/compactor.go:370  [s1,compactor] processing compaction #1/1 ("b"-"c") for 16 MiB (reasons: size=false used=true avail=false)
I190807 18:59:11.887846 85724 storage/compactor/compactor.go:386  [s1,compactor] processed compaction #1/1 ("b"-"c") for 16 MiB in 0.0s
W190807 18:59:23.526013 85698 storage/store.go:3618  [s1,r2/1:{a-c}] handle raft ready: 11.0s [applied=1, batches=1, state_assertions=0]
I190807 18:59:23.529053 134859 storage/replica_command.go:283  [s1,r2/1:{a-c}] initiating a split of this range at key "b" [r8] (manual)
I190807 18:59:25.341106 134859 storage/replica_command.go:597  [merge,s1,r2/1:{a-b}] initiating a merge of r8:{b-c} [(n1,s1):1, next=2, gen=11] into this range (lhs+rhs has (size=16 MiB+16 MiB qps=4.62+0.00 --> 4.62qps) below threshold (size=32 MiB, qps=4.62))
I190807 18:59:25.537883 85653 storage/store.go:2530  [merge,s1,r2/1:{a-b},txn=f8f4916e] removing replica r8/1



TestMergeQueue/combined-threshold
--- FAIL: testrace/TestMergeQueue/combined-threshold (0.000s)
Test ended in panic.

------- Stdout: -------
W190807 18:59:36.625896 85676 storage/store.go:3618  [s1,r2/1:{a-c}] handle raft ready: 9.2s [applied=1, batches=1, state_assertions=0]
I190807 18:59:40.539715 85724 storage/compactor/compactor.go:325  [s1,compactor] purging suggested compaction for range "a" - "b" that contains live data
I190807 18:59:40.540850 85724 storage/compactor/compactor.go:370  [s1,compactor] processing compaction #1/1 ("b"-"c") for 32 MiB (reasons: size=false used=true avail=false)
I190807 18:59:40.541589 85724 storage/compactor/compactor.go:386  [s1,compactor] processed compaction #1/1 ("b"-"c") for 32 MiB in 0.0s
W190807 18:59:45.926124 85710 storage/store.go:3618  [s1,r2/1:{a-c}] handle raft ready: 7.1s [applied=1, batches=1, state_assertions=0]
I190807 18:59:45.932898 147186 storage/replica_command.go:283  [s1,r2/1:{a-c}] initiating a split of this range at key "b" [r9] (manual)
I190807 18:59:46.913641 156969 storage/replica_command.go:597  [merge,s1,r2/1:{a-b}] initiating a merge of r9:{b-c} [(n1,s1):1, next=2, gen=13] into this range (lhs+rhs has (size=16 MiB+16 MiB qps=0.00+0.00 --> 0.00qps) below threshold (size=32 MiB, qps=0.00))
I190807 18:59:47.128755 85651 storage/store.go:2530  [merge,s1,r2/1:{a-b},txn=3ac231da] removing replica r9/1



TestMergeQueue/sticky-bit
...heduler).Start.func2(0x5778e20, 0xc001f28660)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:161 +0x56
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc000345e10, 0xc000dc55e0, 0xc000345e00)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:196 +0x160
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:189 +0xc4

goroutine 85697 [sync.Cond.Wait]:
runtime.goparkunlock(...)
	/usr/local/go/src/runtime/proc.go:307
sync.runtime_notifyListWait(0xc0023d8290, 0xc000000a9c)
	/usr/local/go/src/runtime/sema.go:510 +0xf9
sync.(*Cond).Wait(0xc0023d8280)
	/usr/local/go/src/sync/cond.go:56 +0x8e
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc001140ab0, 0x5778e20, 0xc00193a1b0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:192 +0x9c
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2(0x5778e20, 0xc00193a1b0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:161 +0x56
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc0025a63a0, 0xc000dc55e0, 0xc0025a6390)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:196 +0x160
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:189 +0xc4

goroutine 171028 [select]:
github.com/cockroachdb/cockroach/pkg/internal/client/requestbatcher.(*RequestBatcher).Send(0xc0003acfc0, 0x5778da0, 0xc0000de010, 0xa, 0x57d9da0, 0xc000795200, 0x0, 0x1, 0x0, 0xc00038bcc0)
	/go/src/github.com/cockroachdb/cockroach/pkg/internal/client/requestbatcher/batcher.go:240 +0x251
github.com/cockroachdb/cockroach/pkg/storage/intentresolver.(*IntentResolver).gcTxnRecord(0xc0003acd20, 0x5778da0, 0xc0000de010, 0xa, 0xc0016c7560, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/intentresolver/intent_resolver.go:772 +0x571
github.com/cockroachdb/cockroach/pkg/storage/intentresolver.(*IntentResolver).cleanupFinishedTxnIntents.func2(0x5778da0, 0xc0000de010)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/intentresolver/intent_resolver.go:812 +0x91
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1(0xc0011b6aa0, 0x5778da0, 0xc0000de010, 0xc000496880, 0x33, 0x0, 0x0, 0xc002cd4f60)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:321 +0xf4
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:316 +0x14b

goroutine 85736 [select]:
github.com/cockroachdb/cockroach/pkg/storage.(*baseQueue).processLoop.func1(0x5778e20, 0xc001f29c80)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:748 +0x1ef
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc0002faf00, 0xc000dc55e0, 0xc000416f40)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:196 +0x160
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:189 +0xc4


****************************************************************************

This node experienced a fatal error (printed above), and as a result the
process is terminating.

Fatal errors can occur due to faulty hardware (disks, memory, clocks) or a
problem in CockroachDB. With your help, the support team at Cockroach Labs
will try to determine the root cause, recommend next steps, and we can
improve CockroachDB based on your report.

Please submit a crash report by following the instructions here:

    https://github.com/cockroachdb/cockroach/issues/new/choose

If you would rather not post publicly, please contact us directly at:

    support@cockroachlabs.com

The Cockroach Labs team appreciates your feedback.



TestMergeQueue/sanity
...269] removing replica r5/1
I190807 18:57:56.238789 85596 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:57:56.239373 85596 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
I190807 18:57:58.884367 85596 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:57:58.885544 85596 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
I190807 18:57:59.419582 85596 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:57:59.420066 85596 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
I190807 18:58:08.237228 85893 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:58:08.237968 85893 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
I190807 18:58:08.416758 85596 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:58:08.417527 85596 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
I190807 18:58:09.061599 85893 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:58:09.062161 85893 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
I190807 18:58:09.064319 85596 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:58:09.064742 85596 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
I190807 18:58:09.540987 85724 storage/compactor/compactor.go:370  [s1,compactor] processing compaction #1-2/2 ("a"-"c") for 32 MiB (reasons: size=false used=true avail=false)
W190807 18:58:11.103858 85661 storage/store.go:3618  [s1,r1/1:{/Min-a}] handle raft ready: 0.5s [applied=1, batches=1, state_assertions=0]
W190807 18:58:11.560338 85686 storage/store.go:3618  [s1,r2/1:{a-c}] handle raft ready: 13.6s [applied=1, batches=1, state_assertions=0]
I190807 18:58:11.562378 85893 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:58:11.562787 85893 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
I190807 18:58:11.584071 85596 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:58:11.584547 85596 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
I190807 18:58:11.894549 85724 storage/compactor/compactor.go:386  [s1,compactor] processed compaction #1-2/2 ("a"-"c") for 32 MiB in 2.4s
W190807 18:58:25.326862 85705 storage/store.go:3618  [s1,r2/1:{a-c}] handle raft ready: 10.8s [applied=1, batches=1, state_assertions=0]
I190807 18:58:25.331543 96953 storage/replica_command.go:283  [s1,r2/1:{a-c}] initiating a split of this range at key "b" [r6] (manual)



TestMergeQueue/both-empty
--- FAIL: testrace/TestMergeQueue/both-empty (0.000s)
Test ended in panic.

------- Stdout: -------
I190807 18:58:27.185018 122024 storage/replica_command.go:597  [merge,s1,r2/1:{a-b}] initiating a merge of r6:{b-c} [(n1,s1):1, next=2, gen=7] into this range (lhs+rhs has (size=0 B+0 B qps=4.82+0.00 --> 4.82qps) below threshold (size=0 B, qps=4.82))
I190807 18:58:27.790959 85705 storage/store.go:2530  [merge,s1,r2/1:{a-b},txn=7ac14de8] removing replica r6/1
W190807 18:58:38.204739 85668 storage/store.go:3618  [s1,r1/1:{/Min-a}] handle raft ready: 0.7s [applied=1, batches=1, state_assertions=0]
I190807 18:58:38.213803 85893 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:58:38.214397 85893 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
I190807 18:58:38.266936 85596 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:58:38.269692 85596 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
I190807 18:58:39.805151 85596 storage/node_liveness.go:836  [liveness-hb] retrying liveness update after storage.errRetryLiveness: result is ambiguous (context deadline exceeded)
W190807 18:58:39.805623 85596 storage/node_liveness.go:484  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 450ms
W190807 18:58:39.807038 85676 storage/store.go:3618  [s1,r2/1:{a-c}] handle raft ready: 10.7s [applied=1, batches=1, state_assertions=0]
I190807 18:58:41.885436 85724 storage/compactor/compactor.go:325  [s1,compactor] purging suggested compaction for range "a" - "b" that contains live data
I190807 18:58:41.888047 85724 storage/compactor/compactor.go:370  [s1,compactor] processing compaction #1/1 ("b"-"c") for 16 MiB (reasons: size=false used=true avail=false)
I190807 18:58:41.890478 85724 storage/compactor/compactor.go:386  [s1,compactor] processed compaction #1/1 ("b"-"c") for 16 MiB in 0.0s
W190807 18:58:54.874866 85670 storage/store.go:3618  [s1,r2/1:{a-c}] handle raft ready: 11.7s [applied=1, batches=1, state_assertions=0]
I190807 18:58:54.877563 122008 storage/replica_command.go:283  [s1,r2/1:{a-c}] initiating a split of this range at key "b" [r7] (manual)
I190807 18:58:56.925560 134529 storage/replica_command.go:597  [merge,s1,r2/1:{a-b}] initiating a merge of r7:{b-c} [(n1,s1):1, next=2, gen=9] into this range (lhs+rhs has (size=0 B+0 B qps=3.95+0.00 --> 3.95qps) below threshold (size=0 B, qps=3.95))
I190807 18:58:57.181493 85682 storage/store.go:2530  [merge,s1,r2/1:{a-b},txn=42f7db6a] removing replica r7/1