Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

: TestStoreRangeDownReplicate failed under stress #10428

Closed
cockroach-teamcity opened this issue Nov 3, 2016 · 1 comment
Closed

: TestStoreRangeDownReplicate failed under stress #10428

cockroach-teamcity opened this issue Nov 3, 2016 · 1 comment
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.

Comments

@cockroach-teamcity
Copy link
Member

SHA: https://github.com/cockroachdb/cockroach/commits/f2042dfdb404c4f1938c92a55e3f39a2bba50c4e

Stress build found a failed test:

I161103 07:34:00.211261 14239 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161103 07:34:00.212871 14239 gossip/gossip.go:237  [n?] initial resolvers: []
W161103 07:34:00.213292 14239 gossip/gossip.go:1055  [n?] no resolvers found; use --join to specify a connected node
I161103 07:34:00.216579 14239 base/node_id.go:62  NodeID set to 1
I161103 07:34:00.243767 14239 storage/store.go:1172  [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I161103 07:34:00.244099 14239 gossip/gossip.go:280  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:51280" > attrs:<> locality:<> 
I161103 07:34:00.261247 14255 storage/replica_proposal.go:292  [s1,r1/1:/M{in-ax}] new range lease replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC 900.000124ms following replica {0 0 0} 1970-01-01 00:00:00 +0000 UTC 0s [physicalTime=1970-01-01 00:00:00.000000123 +0000 UTC]
I161103 07:34:00.286775 14239 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161103 07:34:00.288296 14239 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:51280]
W161103 07:34:00.288759 14239 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161103 07:34:00.289131 14239 base/node_id.go:62  NodeID set to 2
I161103 07:34:00.312257 14239 storage/store.go:1172  [n2,s2]: failed initial metrics computation: [n2,s2]: system config not yet available
I161103 07:34:00.312652 14239 gossip/gossip.go:280  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:35404" > attrs:<> locality:<> 
I161103 07:34:00.315029 14239 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161103 07:34:00.316539 14239 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:51280]
W161103 07:34:00.316962 14239 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161103 07:34:00.317280 14239 base/node_id.go:62  NodeID set to 3
I161103 07:34:00.350064 14204 gossip/client.go:126  [n2] node 2: started gossip client to 127.0.0.1:51280
I161103 07:34:00.360114 14239 storage/store.go:1172  [n3,s3]: failed initial metrics computation: [n3,s3]: system config not yet available
I161103 07:34:00.361746 14239 gossip/gossip.go:280  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:34569" > attrs:<> locality:<> 
I161103 07:34:00.363854 13953 gossip/client.go:126  [n3] node 3: started gossip client to 127.0.0.1:51280
I161103 07:34:00.369504 14239 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161103 07:34:00.383804 14239 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:51280]
W161103 07:34:00.384233 14239 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161103 07:34:00.414845 14239 base/node_id.go:62  NodeID set to 4
I161103 07:34:00.447267 14399 gossip/client.go:126  [n4] node 4: started gossip client to 127.0.0.1:51280
I161103 07:34:00.447526 14239 storage/store.go:1172  [n4,s4]: failed initial metrics computation: [n4,s4]: system config not yet available
I161103 07:34:00.447888 14239 gossip/gossip.go:280  [n4] NodeDescriptor set to node_id:4 address:<network_field:"tcp" address_field:"127.0.0.1:41792" > attrs:<> locality:<> 
I161103 07:34:00.456417 14239 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161103 07:34:00.485676 14239 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:51280]
W161103 07:34:00.486154 14239 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161103 07:34:00.486734 14239 base/node_id.go:62  NodeID set to 5
I161103 07:34:00.576850 14239 storage/store.go:1172  [n5,s5]: failed initial metrics computation: [n5,s5]: system config not yet available
I161103 07:34:00.577204 14239 gossip/gossip.go:280  [n5] NodeDescriptor set to node_id:5 address:<network_field:"tcp" address_field:"127.0.0.1:45884" > attrs:<> locality:<> 
I161103 07:34:00.592988 14279 gossip/client.go:126  [n5] node 5: started gossip client to 127.0.0.1:51280
I161103 07:34:00.599651 14535 gossip/server.go:263  [n1] refusing gossip from node 5 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:34569})
I161103 07:34:00.600077 14535 gossip/server.go:263  [n1] refusing gossip from node 5 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:34569})
I161103 07:34:00.609157 14279 gossip/client.go:131  [n5] node 5: closing client to node 1 (127.0.0.1:51280): received forward from node 1 to 3 (127.0.0.1:34569)
I161103 07:34:00.612138 14280 gossip/client.go:126  [n5] node 5: started gossip client to 127.0.0.1:34569
I161103 07:34:00.717179 14239 storage/client_test.go:419  gossip network initialized
I161103 07:34:00.733784 14239 storage/replica_raftstorage.go:446  [s1,r1/1:/M{in-ax}] generated snapshot dba44fb7 for range 1 at index 22 in 101.903µs.
I161103 07:34:00.736906 14239 storage/store.go:3084  streamed snapshot: kv pairs: 41, log entries: 12
I161103 07:34:00.747712 14709 storage/replica_raftstorage.go:574  [s2] [n2,s2,r1/?:{-}]: with replicaID [?], applying preemptive snapshot at index 22 (id=dba44fb7, encoded size=16, 1 rocksdb batches, 12 log entries)
I161103 07:34:00.752134 14709 storage/replica_raftstorage.go:577  [s2] [n2,s2,r1/?:/M{in-ax}]: with replicaID [?], applied preemptive snapshot in 0.004s
I161103 07:34:00.772883 14239 storage/replica_command.go:3240  change replicas: read existing descriptor range_id:1 start_key:"" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
I161103 07:34:00.812551 14741 storage/replica.go:1895  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:2} for range 1: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I161103 07:34:00.845656 14702 storage/raft_transport.go:431  raft transport stream to node 1 established
I161103 07:34:00.854569 14239 storage/replica_raftstorage.go:446  [s1,r1/1:/M{in-ax}] generated snapshot 6e68c6c6 for range 1 at index 27 in 93.203µs.
I161103 07:34:00.875503 14239 storage/store.go:3084  streamed snapshot: kv pairs: 47, log entries: 17
I161103 07:34:00.896182 14744 storage/replica_raftstorage.go:574  [s3] [n3,s3,r1/?:{-}]: with replicaID [?], applying preemptive snapshot at index 27 (id=6e68c6c6, encoded size=16, 1 rocksdb batches, 17 log entries)
I161103 07:34:00.905169 14744 storage/replica_raftstorage.go:577  [s3] [n3,s3,r1/?:/M{in-ax}]: with replicaID [?], applied preemptive snapshot in 0.009s
I161103 07:34:00.923470 14239 storage/replica_command.go:3240  change replicas: read existing descriptor range_id:1 start_key:"" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I161103 07:34:01.139493 14790 storage/replica.go:1895  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:3} for range 1: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3}]
W161103 07:34:01.421761 14364 storage/store.go:770  storeMu: mutex held by github.com/cockroachdb/cockroach/pkg/storage.(*Store).processRequestQueue for 103.282677ms (>100ms):
goroutine 14364 [running]:
runtime/debug.Stack(0x1bece80, 0x1becec0, 0x49)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x79
github.com/cockroachdb/cockroach/pkg/util/syncutil.ThresholdLogger.func1(0x627f7f5)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/syncutil/timedmutex.go:65 +0xe1
github.com/cockroachdb/cockroach/pkg/util/syncutil.(*TimedMutex).Unlock(0xc4299e69b8)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/syncutil/timedmutex.go:92 +0x80
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processRequestQueue(0xc4299e6700, 0x1)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:3120 +0xca
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc4274fe820, 0xc429188510)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:241 +0x267
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2()
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:181 +0x33
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc429188510, 0xc42939d740)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:196 +0x7d
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:197 +0x66
I161103 07:34:01.446384 14871 storage/raft_transport.go:431  raft transport stream to node 1 established
I161103 07:34:01.468586 14239 storage/replica_command.go:2363  initiating a split of this range at key "m" [r2]
I161103 07:34:02.167321 14239 storage/replica_raftstorage.go:446  [s1,r2/1:{"m"-/Max}] generated snapshot 87b54bce for range 2 at index 10 in 118.104µs.
I161103 07:34:02.171006 14239 storage/store.go:3084  streamed snapshot: kv pairs: 28, log entries: 0
I161103 07:34:02.172805 14957 storage/replica_raftstorage.go:574  [s4] [n4,s4,r2/?:{-}]: with replicaID [?], applying preemptive snapshot at index 10 (id=87b54bce, encoded size=16, 1 rocksdb batches, 0 log entries)
I161103 07:34:02.196147 14957 storage/replica_raftstorage.go:577  [s4] [n4,s4,r2/?:{"m"-/Max}]: with replicaID [?], applied preemptive snapshot in 0.023s
I161103 07:34:02.219916 14239 storage/replica_command.go:3240  change replicas: read existing descriptor range_id:2 start_key:"m" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > replicas:<node_id:3 store_id:3 replica_id:3 > next_replica_id:4 
W161103 07:34:02.603243 14984 storage/stores.go:218  range not contained in one range: [/Meta2/Max,"m\x00"), but have [/Min,"m")
I161103 07:34:02.848626 14928 storage/replica.go:1895  [s1,r2/1:{"m"-/Max}] proposing ADD_REPLICA {NodeID:4 StoreID:4 ReplicaID:4} for range 2: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3} {NodeID:4 StoreID:4 ReplicaID:4}]
I161103 07:34:02.981259 14239 storage/replica_raftstorage.go:446  [s1,r2/1:{"m"-/Max}] generated snapshot 6ecfca73 for range 2 at index 14 in 97.903µs.
I161103 07:34:02.993943 14239 storage/store.go:3084  streamed snapshot: kv pairs: 30, log entries: 4
I161103 07:34:03.033543 15042 storage/replica_raftstorage.go:574  [s5] [n5,s5,r2/?:{-}]: with replicaID [?], applying preemptive snapshot at index 14 (id=6ecfca73, encoded size=16, 1 rocksdb batches, 4 log entries)
I161103 07:34:03.080037 15042 storage/replica_raftstorage.go:577  [s5] [n5,s5,r2/?:{"m"-/Max}]: with replicaID [?], applied preemptive snapshot in 0.046s
I161103 07:34:03.086991 15045 storage/raft_transport.go:431  raft transport stream to node 1 established
I161103 07:34:03.173415 14239 storage/replica_command.go:3240  change replicas: read existing descriptor range_id:2 start_key:"m" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > replicas:<node_id:3 store_id:3 replica_id:3 > replicas:<node_id:4 store_id:4 replica_id:4 > next_replica_id:5 
I161103 07:34:03.880710 15071 storage/replica.go:1895  [s1,r2/1:{"m"-/Max}] proposing ADD_REPLICA {NodeID:5 StoreID:5 ReplicaID:5} for range 2: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5}]
I161103 07:34:04.071863 15125 storage/raft_transport.go:431  raft transport stream to node 1 established
I161103 07:34:05.614857 14422 storage/replica_proposal.go:292  [s3,r1/3:{/Min-"m"}] new range lease replica {3 3 3} 1970-01-01 00:00:02.700000126 +0000 UTC 1.800000002s following replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC 2.700000126s [physicalTime=1970-01-01 00:00:09.000000133 +0000 UTC]
I161103 07:34:05.847710 14256 storage/replica_proposal.go:292  [s1,r1/1:{/Min-"m"}] new range lease replica {1 1 1} 1970-01-01 00:00:04.500000128 +0000 UTC 3.600000004s following replica {3 3 3} 1970-01-01 00:00:02.700000126 +0000 UTC 1.800000002s [physicalTime=1970-01-01 00:00:09.000000133 +0000 UTC]
I161103 07:34:06.653779 14358 storage/replica.go:1943  [s2,r2/2:{"m"-/Max}] not quiescing: 1 pending commands
I161103 07:34:07.418565 14366 storage/replica.go:1943  [s2,r2/2:{"m"-/Max}] not quiescing: 1 pending commands
E161103 07:34:07.587700 14278 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
W161103 07:34:07.606481 15252 storage/store.go:770  storeMu: mutex held by github.com/cockroachdb/cockroach/pkg/storage.(*Store).LookupReplica for 149.062857ms (>100ms):
goroutine 15252 [running]:
runtime/debug.Stack(0x1be9e30, 0x1be9e70, 0x43)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x79
github.com/cockroachdb/cockroach/pkg/util/syncutil.ThresholdLogger.func1(0x8e284c9)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/syncutil/timedmutex.go:65 +0xe1
github.com/cockroachdb/cockroach/pkg/util/syncutil.(*TimedMutex).Unlock(0xc42675f7b8)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/syncutil/timedmutex.go:92 +0x80
github.com/cockroachdb/cockroach/pkg/storage.(*Store).LookupReplica(0xc42675f500, 0xc426f5719a, 0x2, 0x2, 0x0, 0x0, 0x0, 0xc427b57180)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:1465 +0x1f6
github.com/cockroachdb/cockroach/pkg/storage.(*Stores).LookupReplica(0xc426866c00, 0xc426f5719a, 0x2, 0x2, 0xc422a876f5, 0x3, 0x3, 0x0, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/stores.go:209 +0x1a6
github.com/cockroachdb/cockroach/pkg/storage.(*Stores).Send(0xc426866c00, 0x7f6e6e387198, 0xc425ed7140, 0x0, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/stores.go:152 +0x131
github.com/cockroachdb/cockroach/pkg/storage_test.(*multiTestContextKVTransport).SendNext.func1(0x7f6e6e387198, 0xc425ed7140)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/client_test.go:476 +0x136
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask.func1(0xc4241aa510, 0x2080070, 0x16, 0x1fa, 0x0, 0x0, 0xc427d0c1a0, 0x7f6e6e387198, 0xc425ed7140)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:264 +0xdf
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTask
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:265 +0x234
E161103 07:34:07.617199 14200 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
E161103 07:34:07.637710 14345 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
E161103 07:34:07.662732 14514 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
E161103 07:34:07.688222 14436 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
I161103 07:34:08.116507 15282 storage/raft_transport.go:431  raft transport stream to node 2 established
I161103 07:34:08.140695 15137 storage/raft_transport.go:431  raft transport stream to node 5 established
I161103 07:34:08.146213 15136 storage/raft_transport.go:431  raft transport stream to node 4 established
I161103 07:34:08.594844 15289 storage/raft_transport.go:431  raft transport stream to node 4 established
I161103 07:34:08.595518 15288 storage/raft_transport.go:431  raft transport stream to node 3 established
I161103 07:34:08.596015 15290 storage/raft_transport.go:431  raft transport stream to node 2 established
I161103 07:34:08.658220 15322 storage/raft_transport.go:431  raft transport stream to node 5 established
I161103 07:34:08.680195 15355 storage/raft_transport.go:431  raft transport stream to node 3 established
I161103 07:34:08.716646 15297 storage/raft_transport.go:431  raft transport stream to node 5 established
I161103 07:34:08.717392 15359 storage/raft_transport.go:431  raft transport stream to node 3 established
I161103 07:34:10.230862 14359 storage/replica_proposal.go:292  [s2,r1/2:{/Min-"m"}] new range lease replica {2 2 2} 1970-01-01 00:00:45.900000174 +0000 UTC 9.00000001s following replica {1 1 1} 1970-01-01 00:00:04.500000128 +0000 UTC 41.400000046s [physicalTime=1970-01-01 00:00:54.000000183 +0000 UTC]
I161103 07:34:10.520326 14411 storage/replica.go:1943  [s3,r1/3:{/Min-"m"}] not quiescing: 1 pending commands
I161103 07:34:10.548023 15329 storage/raft_transport.go:431  raft transport stream to node 2 established
I161103 07:34:10.583708 15429 storage/raft_transport.go:431  raft transport stream to node 4 established
I161103 07:34:10.801551 14419 storage/replica_proposal.go:292  [s3,r1/3:{/Min-"m"}] new range lease replica {3 3 3} 1970-01-01 00:00:54.900000184 +0000 UTC 1.800000002s following replica {2 2 2} 1970-01-01 00:00:45.900000174 +0000 UTC 9.00000001s [physicalTime=1970-01-01 00:01:06.600000197 +0000 UTC]
I161103 07:34:10.848927 14491 storage/replica_proposal.go:292  [s4,r2/4:{"m"-/Max}] new range lease replica {4 4 4} 1970-01-01 00:00:35.100000162 +0000 UTC 32.400000036s following replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC 35.100000162s [physicalTime=1970-01-01 00:01:06.600000197 +0000 UTC]
I161103 07:34:11.023059 14356 storage/replica_proposal.go:292  [s2,r1/2:{/Min-"m"}] new range lease replica {2 2 2} 1970-01-01 00:00:56.700000186 +0000 UTC 10.800000012s following replica {3 3 3} 1970-01-01 00:00:54.900000184 +0000 UTC 1.800000002s [physicalTime=1970-01-01 00:01:06.600000197 +0000 UTC]
E161103 07:34:11.209005 14200 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
E161103 07:34:11.211156 14514 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
E161103 07:34:11.213312 14436 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
I161103 07:34:11.230763 14239 storage/replica_command.go:3240  [replicate,s4,r2/4:{"m"-/Max}] change replicas: read existing descriptor range_id:2 start_key:"m" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > replicas:<node_id:3 store_id:3 replica_id:3 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > next_replica_id:6 
W161103 07:34:11.542840 14365 storage/store.go:770  storeMu: mutex held by github.com/cockroachdb/cockroach/pkg/storage.(*Store).processReady for 104.303933ms (>100ms):
goroutine 14365 [running]:
runtime/debug.Stack(0x1becf70, 0x1becfb0, 0x42)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x79
github.com/cockroachdb/cockroach/pkg/util/syncutil.ThresholdLogger.func1(0x6378d3d)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/syncutil/timedmutex.go:65 +0xe1
github.com/cockroachdb/cockroach/pkg/util/syncutil.(*TimedMutex).Unlock(0xc4299e69b8)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/syncutil/timedmutex.go:92 +0x80
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processReady(0xc4299e6700, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:3141 +0xe6
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc4274fe820, 0xc429188510)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:230 +0x28c
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2()
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:181 +0x33
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc429188510, 0xc42939d760)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:196 +0x7d
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:197 +0x66
W161103 07:34:12.284695 14595 storage/store.go:770  storeMu: mutex held by github.com/cockroachdb/cockroach/pkg/storage.(*Store).processRequestQueue for 121.629727ms (>100ms):
goroutine 14595 [running]:
runtime/debug.Stack(0x1bece80, 0x1becec0, 0x49)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x79
github.com/cockroachdb/cockroach/pkg/util/syncutil.ThresholdLogger.func1(0x73fec1f)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/syncutil/timedmutex.go:65 +0xe1
github.com/cockroachdb/cockroach/pkg/util/syncutil.(*TimedMutex).Unlock(0xc4278ac638)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/syncutil/timedmutex.go:92 +0x80
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processRequestQueue(0xc4278ac380, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:3120 +0xca
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc42481da40, 0xc4241ab7a0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:241 +0x267
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2()
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:181 +0x33
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc4241ab7a0, 0xc4254151a0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:196 +0x7d
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:197 +0x66
E161103 07:34:13.648845 14345 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
I161103 07:34:14.105179 15492 storage/replica.go:1895  [s4,r2/4:{"m"-/Max}] proposing REMOVE_REPLICA {NodeID:1 StoreID:1 ReplicaID:1} for range 2: [{NodeID:5 StoreID:5 ReplicaID:5} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3} {NodeID:4 StoreID:4 ReplicaID:4}]
I161103 07:34:14.267733 15022 storage/store.go:2941  [s1] [n1,s1,r2/1:{"m"-/Max}]: added to replica GC queue (peer suggestion)
I161103 07:34:14.415922 14250 storage/replica_proposal.go:292  [s1,r1/1:{/Min-"m"}] new range lease replica {1 1 1} 1970-01-01 00:01:21.900000214 +0000 UTC 10.800000012s following replica {2 2 2} 1970-01-01 00:00:56.700000186 +0000 UTC 25.200000028s [physicalTime=1970-01-01 00:01:37.200000231 +0000 UTC]
I161103 07:34:14.480686 14413 storage/replica_proposal.go:292  [s3,r1/3:{/Min-"m"}] new range lease replica {3 3 3} 1970-01-01 00:01:32.700000226 +0000 UTC 5.400000006s following replica {1 1 1} 1970-01-01 00:01:21.900000214 +0000 UTC 10.800000012s [physicalTime=1970-01-01 00:01:37.200000231 +0000 UTC]
E161103 07:34:14.597492 14278 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
I161103 07:34:15.235664 14239 storage/replica_command.go:3240  [replicate,s4,r2/4:{"m"-/Max}] change replicas: read existing descriptor range_id:2 start_key:"m" end_key:"\377\377" replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:2 store_id:2 replica_id:2 > replicas:<node_id:3 store_id:3 replica_id:3 > replicas:<node_id:4 store_id:4 replica_id:4 > next_replica_id:6 
I161103 07:34:15.315710 14255 storage/replica_proposal.go:292  [s1,r1/1:{/Min-"m"}] new range lease replica {1 1 1} 1970-01-01 00:01:39.900000234 +0000 UTC 1.800000002s following replica {3 3 3} 1970-01-01 00:01:32.700000226 +0000 UTC 7.200000008s [physicalTime=1970-01-01 00:01:40.800000235 +0000 UTC]
I161103 07:34:15.320356 14418 storage/replica_proposal.go:341  [s3,r1/3:{/Min-"m"}] range [n3,s3,r1/3:{/Min-"m"}]: transferring raft leadership to replica ID 1
I161103 07:34:16.413129 14411 storage/replica_proposal.go:341  [s3,r1/3:{/Min-"m"}] range [n3,s3,r1/3:{/Min-"m"}]: transferring raft leadership to replica ID 1
E161103 07:34:16.494471 14436 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
I161103 07:34:16.631949 14490 storage/replica_proposal.go:341  [s4,r2/4:{"m"-/Max}] range [n4,s4,r2/4:{"m"-/Max}]: transferring raft leadership to replica ID 3
I161103 07:34:16.702266 14411 storage/replica_proposal.go:292  [s3,r2/3:{"m"-/Max}] new range lease replica {3 3 3} 1970-01-01 00:01:41.700000236 +0000 UTC 1.800000002s following replica {4 4 4} 1970-01-01 00:00:35.100000162 +0000 UTC 1m6.600000074s [physicalTime=1970-01-01 00:01:42.600000237 +0000 UTC]
I161103 07:34:18.377527 15738 storage/replica.go:1895  [s3,r2/3:{"m"-/Max}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:3} for range 2: [{NodeID:5 StoreID:5 ReplicaID:5} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:4 StoreID:4 ReplicaID:4}]
I161103 07:34:18.496794 15628 util/stop/stopper.go:468  quiescing; tasks left:
11     storage/client_test.go:506
1      storage/queue.go:477
I161103 07:34:18.497821 15630 util/stop/stopper.go:468  quiescing; tasks left:
1      storage/queue.go:477
1      storage/intent_resolver.go:383
1      storage/intent_resolver.go:317
I161103 07:34:18.500912 15628 util/stop/stopper.go:468  quiescing; tasks left:
10     storage/client_test.go:506
1      storage/queue.go:477
E161103 07:34:18.502087 14436 storage/node_liveness.go:141  [hb] failed liveness heartbeat: node unavailable; try another peer
I161103 07:34:18.503303 15249 storage/store.go:2941  [s3] [n3,s3,r2/3:{"m"-/Max}]: added to replica GC queue (peer suggestion)
I161103 07:34:18.504322 15629 util/stop/stopper.go:468  quiescing; tasks left:
1      storage/intent_resolver.go:317
W161103 07:34:18.508746 15735 storage/replica.go:1729  [s1,r1/1:{/Min-"m"}] shutdown cancellation of command [txn: 1674b0ec], BeginTransaction [/System/NodeLiveness/4,/Min), ConditionalPut [/System/NodeLiveness/4,/Min), EndTransaction [/System/NodeLiveness/4,/Min)
W161103 07:34:18.509541 15697 storage/replica.go:1729  [s1,r1/1:{/Min-"m"}] shutdown cancellation of command [txn: 7badad07], BeginTransaction [/System/NodeLiveness/2,/Min), ConditionalPut [/System/NodeLiveness/2,/Min), EndTransaction [/System/NodeLiveness/2,/Min)
E161103 07:34:18.515127 14514 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
E161103 07:34:18.516278 14514 storage/node_liveness.go:141  [hb] failed liveness heartbeat: node unavailable; try another peer
I161103 07:34:18.533929 15628 util/stop/stopper.go:468  quiescing; tasks left:
9      storage/client_test.go:506
1      storage/queue.go:477
I161103 07:34:18.534171 15628 util/stop/stopper.go:468  quiescing; tasks left:
8      storage/client_test.go:506
1      storage/queue.go:477
W161103 07:34:18.534712 15613 storage/replica.go:1729  [s1,r1/1:{/Min-"m"}] shutdown cancellation of command ResolveIntent [/Meta2/Max,/Min)
I161103 07:34:18.535154 15628 util/stop/stopper.go:468  quiescing; tasks left:
7      storage/client_test.go:506
1      storage/queue.go:477
W161103 07:34:18.538050 15707 storage/replica.go:1729  [s1,r1/1:{/Min-"m"}] shutdown cancellation of command [txn: 6937e4af], BeginTransaction [/System/NodeLiveness/5,/Min), ConditionalPut [/System/NodeLiveness/5,/Min), EndTransaction [/System/NodeLiveness/5,/Min)
E161103 07:34:18.538770 14200 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
E161103 07:34:18.539621 14200 storage/node_liveness.go:141  [hb] failed liveness heartbeat: node unavailable; try another peer
W161103 07:34:18.539871 15609 storage/intent_resolver.go:310  [n3,s3,r1/3:{/Min-"m"}]: failed to resolve intents: result is ambiguous
I161103 07:34:18.540529 15628 util/stop/stopper.go:468  quiescing; tasks left:
6      storage/client_test.go:506
1      storage/queue.go:477
W161103 07:34:18.541114 15672 storage/replica.go:1729  [s1,r1/1:{/Min-"m"}] shutdown cancellation of command [txn: f546ae1f], BeginTransaction [/System/NodeLiveness/1,/Min), ConditionalPut [/System/NodeLiveness/1,/Min), EndTransaction [/System/NodeLiveness/1,/Min)
I161103 07:34:18.541486 15628 util/stop/stopper.go:468  quiescing; tasks left:
5      storage/client_test.go:506
1      storage/queue.go:477
I161103 07:34:18.558489 15630 util/stop/stopper.go:468  quiescing; tasks left:
1      storage/queue.go:477
1      storage/intent_resolver.go:383
E161103 07:34:18.563378 14278 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
E161103 07:34:18.564239 14278 storage/node_liveness.go:141  [hb] failed liveness heartbeat: node unavailable; try another peer
E161103 07:34:18.565103 14436 storage/node_liveness.go:141  [hb] failed liveness heartbeat: node unavailable; try another peer
I161103 07:34:18.571540 15628 util/stop/stopper.go:468  quiescing; tasks left:
4      storage/client_test.go:506
1      storage/queue.go:477
E161103 07:34:18.572822 14458 storage/queue.go:568  [replicaGC] on [n3,s3,r2/3:{"m"-/Max}]: failed to send RPC: sending to all 3 replicas failed; last error: failed to send RPC: store is stopped
I161103 07:34:18.582036 15630 util/stop/stopper.go:468  quiescing; tasks left:
1      storage/intent_resolver.go:383
W161103 07:34:18.585756 15657 storage/replica.go:1729  [s1,r1/1:{/Min-"m"}] shutdown cancellation of command ResolveIntent [/Meta2/Max,/Min)
I161103 07:34:18.586209 15628 util/stop/stopper.go:468  quiescing; tasks left:
3      storage/client_test.go:506
1      storage/queue.go:477
E161103 07:34:18.589431 14278 storage/node_liveness.go:141  [hb] failed liveness heartbeat: node unavailable; try another peer
E161103 07:34:18.589711 14345 storage/node_liveness.go:141  [hb] failed liveness heartbeat: result is ambiguous
E161103 07:34:18.590551 14345 storage/node_liveness.go:141  [hb] failed liveness heartbeat: node unavailable; try another peer
W161103 07:34:18.590991 15518 storage/intent_resolver.go:101  [s1] asynchronous resolveIntents failed: result is ambiguous
I161103 07:34:18.598820 15628 util/stop/stopper.go:468  quiescing; tasks left:
2      storage/client_test.go:506
1      storage/queue.go:477
W161103 07:34:18.616018 15553 storage/replica.go:1729  [s1,r1/1:{/Min-"m"}] shutdown cancellation of command ResolveIntent [/Meta2/Max,/Min)
W161103 07:34:18.616951 15615 storage/intent_resolver.go:310  [n2,s2,r1/2:{/Min-"m"}]: failed to resolve intents: result is ambiguous
I161103 07:34:18.617128 15628 util/stop/stopper.go:468  quiescing; tasks left:
2      storage/client_test.go:506
I161103 07:34:18.617347 15628 util/stop/stopper.go:468  quiescing; tasks left:
1      storage/client_test.go:506
E161103 07:34:18.628120 15249 storage/store.go:2939  [s3] [n3,s3,r2/3:{"m"-/Max}]: unable to add to replica GC queue: queue stopped
E161103 07:34:18.638751 14514 storage/node_liveness.go:141  [hb] failed liveness heartbeat: node unavailable; try another peer
E161103 07:34:18.690336 14345 storage/node_liveness.go:141  [hb] failed liveness heartbeat: node unavailable; try another peer
E161103 07:34:18.711287 14200 storage/node_liveness.go:141  [hb] failed liveness heartbeat: node unavailable; try another peer
W161103 07:34:18.711561 15743 storage/replica.go:1729  [s1,r1/1:{/Min-"m"}] shutdown cancellation of command ResolveIntent [/Meta2/Max,/Min)
W161103 07:34:18.719002 15673 storage/intent_resolver.go:337  [n3,s3,r2/3:{"m"-/Max}]: failed to resolve intents: result is ambiguous
I161103 07:34:18.719249 15627 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
W161103 07:34:18.724263 14827 storage/store.go:2945  [s3] got error from range 0, replica {1 1 0}: storage/raft_transport.go:257: unable to accept Raft message from {NodeID:3 StoreID:3 ReplicaID:0}: no handler registered for {NodeID:1 StoreID:1 ReplicaID:0}
I161103 07:34:18.730140 15627 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
E161103 07:34:18.757905 14436 storage/node_liveness.go:141  [hb] failed liveness heartbeat: node unavailable; try another peer
W161103 07:34:18.758123 14704 storage/raft_transport.go:471  no handler found for store 2 in response range_id:1 from_replica:<node_id:1 store_id:1 replica_id:1 > to_replica:<node_id:2 store_id:2 replica_id:2 > union:<error:<message:"storage/raft_transport.go:257: unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:1 StoreID:1 ReplicaID:1}" transaction_restart:NONE origin_node:0 now:<wall_time:0 logical:0 > > > 
W161103 07:34:18.758388 14704 storage/raft_transport.go:471  no handler found for store 2 in response range_id:1 from_replica:<node_id:1 store_id:1 replica_id:1 > to_replica:<node_id:2 store_id:2 replica_id:2 > union:<error:<message:"storage/raft_transport.go:257: unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:1 StoreID:1 ReplicaID:1}" transaction_restart:NONE origin_node:0 now:<wall_time:0 logical:0 > > > 
W161103 07:34:18.760971 14704 storage/raft_transport.go:471  no handler found for store 2 in response range_id:1 from_replica:<node_id:1 store_id:1 replica_id:1 > to_replica:<node_id:2 store_id:2 replica_id:2 > union:<error:<message:"storage/raft_transport.go:257: unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:1 StoreID:1 ReplicaID:1}" transaction_restart:NONE origin_node:0 now:<wall_time:0 logical:0 > > > 
W161103 07:34:18.762219 14704 storage/raft_transport.go:471  no handler found for store 2 in response range_id:1 from_replica:<node_id:1 store_id:1 replica_id:1 > to_replica:<node_id:2 store_id:2 replica_id:2 > union:<error:<message:"storage/raft_transport.go:257: unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:1 StoreID:1 ReplicaID:1}" transaction_restart:NONE origin_node:0 now:<wall_time:0 logical:0 > > > 
W161103 07:34:18.762423 14704 storage/raft_transport.go:471  no handler found for store 2 in response range_id:1 from_replica:<node_id:1 store_id:1 replica_id:1 > to_replica:<node_id:2 store_id:2 replica_id:2 > union:<error:<message:"storage/raft_transport.go:257: unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:1 StoreID:1 ReplicaID:1}" transaction_restart:NONE origin_node:0 now:<wall_time:0 logical:0 > > > 
W161103 07:34:18.762630 14704 storage/raft_transport.go:471  no handler found for store 2 in response range_id:1 from_replica:<node_id:1 store_id:1 replica_id:1 > to_replica:<node_id:2 store_id:2 replica_id:2 > union:<error:<message:"storage/raft_transport.go:257: unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:1 StoreID:1 ReplicaID:1}" transaction_restart:NONE origin_node:0 now:<wall_time:0 logical:0 > > > 
W161103 07:34:18.762829 14704 storage/raft_transport.go:471  no handler found for store 2 in response range_id:1 from_replica:<node_id:1 store_id:1 replica_id:1 > to_replica:<node_id:2 store_id:2 replica_id:2 > union:<error:<message:"storage/raft_transport.go:257: unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:1 StoreID:1 ReplicaID:1}" transaction_restart:NONE origin_node:0 now:<wall_time:0 logical:0 > > > 
W161103 07:34:18.763026 14704 storage/raft_transport.go:471  no handler found for store 2 in response range_id:1 from_replica:<node_id:1 store_id:1 replica_id:1 > to_replica:<node_id:2 store_id:2 replica_id:2 > union:<error:<message:"storage/raft_transport.go:257: unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:1 StoreID:1 ReplicaID:1}" transaction_restart:NONE origin_node:0 now:<wall_time:0 logical:0 > > > 
I161103 07:34:18.764498 15627 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
W161103 07:34:18.767801 15249 storage/raft_transport.go:471  no handler found for store 3 in response range_id:2 from_replica:<node_id:4 store_id:4 replica_id:4 > to_replica:<node_id:3 store_id:3 replica_id:3 > union:<error:<message:"sender replica too old, discarding message" transaction_restart:NONE origin_node:0 detail:<replica_too_old:<> > now:<wall_time:0 logical:0 > > > 
W161103 07:34:18.768192 15315 storage/raft_transport.go:471  no handler found for store 3 in response range_id:2 from_replica:<node_id:5 store_id:5 replica_id:5 > to_replica:<node_id:3 store_id:3 replica_id:3 > union:<error:<message:"sender replica too old, discarding message" transaction_restart:NONE origin_node:0 detail:<replica_too_old:<> > now:<wall_time:0 logical:0 > > > 
W161103 07:34:18.770196 15284 storage/raft_transport.go:471  no handler found for store 3 in response range_id:0 from_replica:<node_id:2 store_id:2 replica_id:0 > to_replica:<node_id:3 store_id:3 replica_id:0 > union:<error:<message:"storage/raft_transport.go:257: unable to accept Raft message from {NodeID:3 StoreID:3 ReplicaID:0}: no handler registered for {NodeID:2 StoreID:2 ReplicaID:0}" transaction_restart:NONE origin_node:0 now:<wall_time:0 logical:0 > > > 
E161103 07:34:18.771102 14278 storage/node_liveness.go:141  [hb] failed liveness heartbeat: node unavailable; try another peer
I161103 07:34:18.771593 15627 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
I161103 07:34:18.773633 15627 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
I161103 07:34:18.775848 15627 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
I161103 07:34:18.776864 14549 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:45884->127.0.0.1:37871: use of closed network connection
I161103 07:34:18.777235 14475 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:41792->127.0.0.1:40230: use of closed network connection
I161103 07:34:18.777619 14316 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:35404->127.0.0.1:50356: use of closed network connection
I161103 07:34:18.777942 14276 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:51280->127.0.0.1:51338: use of closed network connection
I161103 07:34:18.778390 13949 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:34569->127.0.0.1:38823: use of closed network connection
W161103 07:34:18.779051 15429 storage/raft_transport.go:436  raft transport stream to node 4 failed: rpc error: code = 13 desc = transport is closing
W161103 07:34:18.779506 14717 storage/raft_transport.go:436  raft transport stream to node 2 failed: rpc error: code = 13 desc = transport is closing
W161103 07:34:18.779936 15125 storage/raft_transport.go:436  raft transport stream to node 1 failed: rpc error: code = 13 desc = transport is closing
W161103 07:34:18.780172 15322 storage/raft_transport.go:436  raft transport stream to node 5 failed: rpc error: code = 13 desc = transport is closing
W161103 07:34:18.780438 15289 storage/raft_transport.go:436  raft transport stream to node 4 failed: rpc error: code = 13 desc = transport is closing
W161103 07:34:18.780768 15040 storage/raft_transport.go:436  raft transport stream to node 5 failed: rpc error: code = 13 desc = transport is closing
I161103 07:34:18.781704 15627 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
I161103 07:34:18.782098 15627 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
I161103 07:34:18.782477 15627 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
I161103 07:34:18.782862 15627 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
I161103 07:34:18.783249 15627 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
	client_raft_test.go:1056: Failed to achieve proper replication within 10 seconds
@cockroach-teamcity cockroach-teamcity added O-robot Originated from a bot. C-test-failure Broken test (automatically or manually discovered). labels Nov 3, 2016
@vivekmenezes
Copy link
Contributor

same as #10171

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@vivekmenezes @cockroach-teamcity