test.log

go list -tags '' -f \
'go test -v  -tags '\'''\'' -ldflags '\'''\'' -i -c {{.ImportPath}} -o {{.Dir}}/stress.test && (cd {{.Dir}} && if [ -f stress.test ]; then stress -stderr -maxfails 1 ./stress.test -test.run '\''TestRaftRemoveRace'\'' -test.timeout 10m --vmodule=raft=4,raft_log_queue=1; fi)' ./pkg/storage | \
/bin/bash
github.com/cockroachdb/cockroach/pkg/storage
github.com/cockroachdb/cockroach/pkg/storage_test
testmain
48 runs so far, 0 failures, over 5s
98 runs so far, 0 failures, over 10s
152 runs so far, 0 failures, over 15s
208 runs so far, 0 failures, over 20s
262 runs so far, 0 failures, over 25s
316 runs so far, 0 failures, over 30s
370 runs so far, 0 failures, over 35s
425 runs so far, 0 failures, over 40s
481 runs so far, 0 failures, over 45s
534 runs so far, 0 failures, over 50s
587 runs so far, 0 failures, over 55s
642 runs so far, 0 failures, over 1m0s
697 runs so far, 0 failures, over 1m5s
751 runs so far, 0 failures, over 1m10s
803 runs so far, 0 failures, over 1m15s
857 runs so far, 0 failures, over 1m20s
911 runs so far, 0 failures, over 1m25s
963 runs so far, 0 failures, over 1m30s
1018 runs so far, 0 failures, over 1m35s
1073 runs so far, 0 failures, over 1m40s
1124 runs so far, 0 failures, over 1m45s
1178 runs so far, 0 failures, over 1m50s

I161113 02:50:57.092130 1 rand.go:76  Random seed: -1176200230820898875
I161113 02:50:57.094894 37 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161113 02:50:57.119695 37 gossip/gossip.go:237  [n?] initial resolvers: []
W161113 02:50:57.119721 37 gossip/gossip.go:1055  [n?] no resolvers found; use --join to specify a connected node
I161113 02:50:57.119775 37 base/node_id.go:62  NodeID set to 1
I161113 02:50:57.150199 163 raft/raft.go:568  [s1,r1/1:/M{in-ax}] 1 became follower at term 5
I161113 02:50:57.150291 163 raft/raft.go:316  [s1,r1/1:/M{in-ax}] newRaft 1 [peers: [1], term: 5, commit: 10, applied: 10, lastindex: 10, lastterm: 5]
I161113 02:50:57.150320 163 raft/raft.go:750  [s1,r1/1:/M{in-ax}] 1 is starting a new election at term 5
I161113 02:50:57.150347 163 raft/raft.go:581  [s1,r1/1:/M{in-ax}] 1 became candidate at term 6
I161113 02:50:57.150375 163 raft/raft.go:665  [s1,r1/1:/M{in-ax}] 1 received MsgVoteResp from 1 at term 6
I161113 02:50:57.150408 163 raft/raft.go:622  [s1,r1/1:/M{in-ax}] 1 became leader at term 6
I161113 02:50:57.151540 103 storage/replica_proposal.go:328  [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]
I161113 02:50:57.152639 37 storage/store.go:1188  [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I161113 02:50:57.152790 37 gossip/gossip.go:280  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:35658" > attrs:<> locality:<> 
I161113 02:50:57.152883 37 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161113 02:50:57.158284 37 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:35658]
W161113 02:50:57.158325 37 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161113 02:50:57.158378 37 base/node_id.go:62  NodeID set to 2
I161113 02:50:57.160452 27 gossip/client.go:125  [n2] started gossip client to 127.0.0.1:35658
I161113 02:50:57.170121 37 gossip/gossip.go:280  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:43668" > attrs:<> locality:<> 
I161113 02:50:57.170211 37 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161113 02:50:57.173779 37 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:35658]
W161113 02:50:57.173815 37 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161113 02:50:57.173885 37 base/node_id.go:62  NodeID set to 3
I161113 02:50:57.185825 37 storage/store.go:1188  [n3,s3]: failed initial metrics computation: [n3,s3]: system config not yet available
I161113 02:50:57.185884 37 gossip/gossip.go:280  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:33891" > attrs:<> locality:<> 
I161113 02:50:57.186412 349 gossip/client.go:125  [n3] started gossip client to 127.0.0.1:35658
I161113 02:50:57.186753 37 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161113 02:50:57.187585 37 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:35658]
W161113 02:50:57.187608 37 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161113 02:50:57.187654 37 base/node_id.go:62  NodeID set to 4
I161113 02:50:57.190818 37 storage/store.go:1188  [n4,s4]: failed initial metrics computation: [n4,s4]: system config not yet available
I161113 02:50:57.190885 37 gossip/gossip.go:280  [n4] NodeDescriptor set to node_id:4 address:<network_field:"tcp" address_field:"127.0.0.1:42744" > attrs:<> locality:<> 
I161113 02:50:57.191666 37 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161113 02:50:57.194352 450 gossip/client.go:125  [n4] started gossip client to 127.0.0.1:35658
I161113 02:50:57.243852 37 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:35658]
W161113 02:50:57.243897 37 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161113 02:50:57.243980 37 base/node_id.go:62  NodeID set to 5
I161113 02:50:57.245686 37 storage/store.go:1188  [n5,s5]: failed initial metrics computation: [n5,s5]: system config not yet available
I161113 02:50:57.245754 37 gossip/gossip.go:280  [n5] NodeDescriptor set to node_id:5 address:<network_field:"tcp" address_field:"127.0.0.1:42185" > attrs:<> locality:<> 
I161113 02:50:57.329447 37 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161113 02:50:57.330507 55 gossip/client.go:125  [n5] started gossip client to 127.0.0.1:35658
I161113 02:50:57.331022 37 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:35658]
W161113 02:50:57.331051 37 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161113 02:50:57.331104 37 base/node_id.go:62  NodeID set to 6
I161113 02:50:57.332537 448 gossip/server.go:263  [n1] refusing gossip from node 5 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:33891})
I161113 02:50:57.332668 448 gossip/server.go:263  [n1] refusing gossip from node 5 (max 3 conns); forwarding to 2 ({tcp 127.0.0.1:43668})
I161113 02:50:57.385557 37 storage/store.go:1188  [n6,s6]: failed initial metrics computation: [n6,s6]: system config not yet available
I161113 02:50:57.385618 37 gossip/gossip.go:280  [n6] NodeDescriptor set to node_id:6 address:<network_field:"tcp" address_field:"127.0.0.1:37881" > attrs:<> locality:<> 
I161113 02:50:57.385974 681 gossip/client.go:125  [n6] started gossip client to 127.0.0.1:35658
I161113 02:50:57.386411 37 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161113 02:50:57.387318 37 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:35658]
W161113 02:50:57.387340 37 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161113 02:50:57.387426 37 base/node_id.go:62  NodeID set to 7
I161113 02:50:57.389098 37 storage/store.go:1188  [n7,s7]: failed initial metrics computation: [n7,s7]: system config not yet available
I161113 02:50:57.389143 37 gossip/gossip.go:280  [n7] NodeDescriptor set to node_id:7 address:<network_field:"tcp" address_field:"127.0.0.1:33897" > attrs:<> locality:<> 
I161113 02:50:57.389541 763 gossip/client.go:125  [n7] started gossip client to 127.0.0.1:35658
I161113 02:50:57.389854 37 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161113 02:50:57.390534 37 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:35658]
W161113 02:50:57.390554 37 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161113 02:50:57.390589 37 base/node_id.go:62  NodeID set to 8
I161113 02:50:57.391797 503 gossip/server.go:263  [n1] refusing gossip from node 7 (max 3 conns); forwarding to 2 ({tcp 127.0.0.1:43668})
I161113 02:50:57.392068 504 gossip/server.go:263  [n1] refusing gossip from node 6 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:33891})
I161113 02:50:57.392161 504 gossip/server.go:263  [n1] refusing gossip from node 6 (max 3 conns); forwarding to 2 ({tcp 127.0.0.1:43668})
I161113 02:50:57.393473 37 storage/store.go:1188  [n8,s8]: failed initial metrics computation: [n8,s8]: system config not yet available
I161113 02:50:57.393533 37 gossip/gossip.go:280  [n8] NodeDescriptor set to node_id:8 address:<network_field:"tcp" address_field:"127.0.0.1:42090" > attrs:<> locality:<> 
I161113 02:50:57.393867 844 gossip/client.go:125  [n8] started gossip client to 127.0.0.1:35658
I161113 02:50:57.394163 37 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161113 02:50:57.394886 37 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:35658]
W161113 02:50:57.394907 37 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161113 02:50:57.394956 37 base/node_id.go:62  NodeID set to 9
I161113 02:50:57.406705 37 storage/store.go:1188  [n9,s9]: failed initial metrics computation: [n9,s9]: system config not yet available
I161113 02:50:57.406808 37 gossip/gossip.go:280  [n9] NodeDescriptor set to node_id:9 address:<network_field:"tcp" address_field:"127.0.0.1:36899" > attrs:<> locality:<> 
I161113 02:50:57.407204 516 gossip/server.go:263  [n1] refusing gossip from node 8 (max 3 conns); forwarding to 2 ({tcp 127.0.0.1:43668})
I161113 02:50:57.412573 37 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161113 02:50:57.413451 37 gossip/gossip.go:237  [n?] initial resolvers: [127.0.0.1:35658]
W161113 02:50:57.413484 37 gossip/gossip.go:1057  [n?] no incoming or outgoing connections
I161113 02:50:57.413561 37 base/node_id.go:62  NodeID set to 10
I161113 02:50:57.416447 516 gossip/server.go:263  [n1] refusing gossip from node 8 (max 3 conns); forwarding to 2 ({tcp 127.0.0.1:43668})
I161113 02:50:57.448736 503 gossip/server.go:263  [n1] refusing gossip from node 7 (max 3 conns); forwarding to 4 ({tcp 127.0.0.1:42744})
I161113 02:50:57.449635 852 gossip/client.go:125  [n9] started gossip client to 127.0.0.1:35658
I161113 02:50:57.455798 65 gossip/server.go:263  [n1] refusing gossip from node 9 (max 3 conns); forwarding to 4 ({tcp 127.0.0.1:42744})
I161113 02:50:57.456000 65 gossip/server.go:263  [n1] refusing gossip from node 9 (max 3 conns); forwarding to 2 ({tcp 127.0.0.1:43668})
I161113 02:50:57.469262 852 gossip/client.go:130  [n9] closing client to node 1 (127.0.0.1:35658): received forward from node 1 to 4 (127.0.0.1:42744)
I161113 02:50:57.469485 1009 gossip/client.go:125  [n9] started gossip client to 127.0.0.1:42744
I161113 02:50:57.471922 681 gossip/client.go:130  [n6] closing client to node 1 (127.0.0.1:35658): received forward from node 1 to 3 (127.0.0.1:33891)
I161113 02:50:57.472101 1054 gossip/client.go:125  [n6] started gossip client to 127.0.0.1:33891
I161113 02:50:57.510083 55 gossip/client.go:130  [n5] closing client to node 1 (127.0.0.1:35658): received forward from node 1 to 3 (127.0.0.1:33891)
I161113 02:50:57.510296 1140 gossip/client.go:125  [n5] started gossip client to 127.0.0.1:33891
I161113 02:50:57.511424 763 gossip/client.go:130  [n7] closing client to node 1 (127.0.0.1:35658): received forward from node 1 to 2 (127.0.0.1:43668)
I161113 02:50:57.511633 1158 gossip/client.go:125  [n7] started gossip client to 127.0.0.1:43668
I161113 02:50:57.515175 844 gossip/client.go:130  [n8] closing client to node 1 (127.0.0.1:35658): received forward from node 1 to 2 (127.0.0.1:43668)
I161113 02:50:57.515353 1238 gossip/client.go:125  [n8] started gossip client to 127.0.0.1:43668
I161113 02:50:57.518437 37 storage/store.go:1188  [n10,s10]: failed initial metrics computation: [n10,s10]: system config not yet available
I161113 02:50:57.518509 37 gossip/gossip.go:280  [n10] NodeDescriptor set to node_id:10 address:<network_field:"tcp" address_field:"127.0.0.1:41421" > attrs:<> locality:<> 
I161113 02:50:57.518765 1336 gossip/client.go:125  [n10] started gossip client to 127.0.0.1:35658
I161113 02:50:57.521939 1110 gossip/server.go:263  [n1] refusing gossip from node 10 (max 3 conns); forwarding to 4 ({tcp 127.0.0.1:42744})
I161113 02:50:57.522046 1110 gossip/server.go:263  [n1] refusing gossip from node 10 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:33891})
I161113 02:50:57.524208 1336 gossip/client.go:130  [n10] closing client to node 1 (127.0.0.1:35658): received forward from node 1 to 4 (127.0.0.1:42744)
I161113 02:50:57.524416 1411 gossip/client.go:125  [n10] started gossip client to 127.0.0.1:42744
I161113 02:50:57.526319 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 8d28181e at index 26 in 51.73µs.
I161113 02:50:57.527620 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 45, log entries: 16
I161113 02:50:57.527867 1197 raft/raft.go:568  [s2,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:57.527947 1197 raft/raft.go:316  [s2,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:57.527979 1197 raft/raft.go:568  [s2,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:57.528020 1197 raft/raft.go:710  [s2,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:57.528049 1197 raft/raft.go:568  [s2,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:57.528126 1197 raft/raft.go:1125  [s2,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 26, term: 6]
I161113 02:50:57.569065 1197 raft/log.go:288  [s2,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 26, term: 6]
I161113 02:50:57.571652 1197 raft/raft.go:1135  [s2,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 27, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.571683 1197 raft/raft.go:1102  [s2,r1/?:{-}] ffffffffffffffff [commit: 26] restored snapshot [index: 26, term: 6]
I161113 02:50:57.571712 1197 storage/replica_raftstorage.go:589  [s2,r1/?:{-}] applying preemptive snapshot at index 26 (id=8d28181e, encoded size=16, 1 rocksdb batches, 16 log entries)
I161113 02:50:57.572461 1197 storage/replica_raftstorage.go:592  [s2,r1/?:/M{in-ax}] applied preemptive snapshot in 0.001s
I161113 02:50:57.574256 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 
I161113 02:50:57.575317 1545 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:2}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I161113 02:50:57.578729 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 3cc69924 at index 32 in 48.716µs.
I161113 02:50:57.579855 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 52, log entries: 22
I161113 02:50:57.580165 1530 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:57.580270 1530 raft/raft.go:316  [s3,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:57.580304 1530 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:57.580340 1530 raft/raft.go:710  [s3,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:57.580366 1530 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:57.580435 1530 raft/raft.go:1125  [s3,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 32, term: 6]
I161113 02:50:57.580465 1530 raft/log.go:288  [s3,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 32, term: 6]
I161113 02:50:57.580496 1530 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 33, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.580525 1530 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 33, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.580556 1530 raft/raft.go:1102  [s3,r1/?:{-}] ffffffffffffffff [commit: 32] restored snapshot [index: 32, term: 6]
I161113 02:50:57.580592 1530 storage/replica_raftstorage.go:589  [s3,r1/?:{-}] applying preemptive snapshot at index 32 (id=3cc69924, encoded size=16, 1 rocksdb batches, 22 log entries)
I161113 02:50:57.581350 1530 storage/replica_raftstorage.go:592  [s3,r1/?:/M{in-ax}] applied preemptive snapshot in 0.001s
I161113 02:50:57.582021 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 
I161113 02:50:57.582944 188 raft/raft.go:568  [s2,r1/?:/M{in-ax}] 2 became follower at term 6
I161113 02:50:57.583067 188 raft/raft.go:316  [s2,r1/?:/M{in-ax}] newRaft 2 [peers: [1], term: 6, commit: 26, applied: 26, lastindex: 26, lastterm: 6]
I161113 02:50:57.583114 188 raft/raft.go:1088  [s2,r1/?:/M{in-ax}] 2 [logterm: 0, index: 32] rejected msgApp [logterm: 6, index: 32] from 1
I161113 02:50:57.583446 1586 storage/raft_transport.go:436  raft transport stream to node 1 established
I161113 02:50:57.619251 127 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 26) from 2 for index 32
I161113 02:50:57.619317 127 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of 2 to [next = 27, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.624669 1602 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3}]
I161113 02:50:57.635689 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 947ac5bf at index 39 in 71.099µs.
I161113 02:50:57.637150 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 60, log entries: 29
I161113 02:50:57.637397 1623 raft/raft.go:568  [s4,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:57.637504 1623 raft/raft.go:316  [s4,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:57.637536 1623 raft/raft.go:568  [s4,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:57.637571 1623 raft/raft.go:710  [s4,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:57.637598 1623 raft/raft.go:568  [s4,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:57.637659 1623 raft/raft.go:1125  [s4,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 39, term: 6]
I161113 02:50:57.637688 1623 raft/log.go:288  [s4,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 39, term: 6]
I161113 02:50:57.637720 1623 raft/raft.go:1135  [s4,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 40, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.637748 1623 raft/raft.go:1135  [s4,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 40, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.637775 1623 raft/raft.go:1135  [s4,r1/?:{-}] ffffffffffffffff restored progress of 3 [next = 40, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.637797 1623 raft/raft.go:1102  [s4,r1/?:{-}] ffffffffffffffff [commit: 39] restored snapshot [index: 39, term: 6]
I161113 02:50:57.637831 1623 storage/replica_raftstorage.go:589  [s4,r1/?:{-}] applying preemptive snapshot at index 39 (id=947ac5bf, encoded size=16, 1 rocksdb batches, 29 log entries)
I161113 02:50:57.638632 1623 storage/replica_raftstorage.go:592  [s4,r1/?:/M{in-ax}] applied preemptive snapshot in 0.001s
I161113 02:50:57.639352 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:3 store_id:3 replica_id:3 > next_replica_id:4 
I161113 02:50:57.640493 292 raft/raft.go:568  [s3,r1/?:/M{in-ax}] 3 became follower at term 6
I161113 02:50:57.640605 292 raft/raft.go:316  [s3,r1/?:/M{in-ax}] newRaft 3 [peers: [1,2], term: 6, commit: 32, applied: 32, lastindex: 32, lastterm: 6]
I161113 02:50:57.640633 292 raft/raft.go:1088  [s3,r1/?:/M{in-ax}] 3 [logterm: 0, index: 39] rejected msgApp [logterm: 6, index: 39] from 1
I161113 02:50:57.640806 1687 storage/raft_transport.go:436  raft transport stream to node 1 established
I161113 02:50:57.641062 134 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 32) from 3 for index 39
I161113 02:50:57.641085 134 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of 3 to [next = 33, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.642012 1693 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:4 StoreID:4 ReplicaID:4}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3} {NodeID:4 StoreID:4 ReplicaID:4}]
I161113 02:50:57.643695 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 3c0f778d at index 41 in 47.014µs.
I161113 02:50:57.644580 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 63, log entries: 31
I161113 02:50:57.645363 1548 raft/raft.go:568  [s5,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:57.645482 1548 raft/raft.go:316  [s5,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:57.645503 1548 raft/raft.go:568  [s5,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:57.645527 1548 raft/raft.go:710  [s5,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:57.645539 1548 raft/raft.go:568  [s5,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:57.645595 1548 raft/raft.go:1125  [s5,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 41, term: 6]
I161113 02:50:57.645614 1548 raft/log.go:288  [s5,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 41, term: 6]
I161113 02:50:57.645634 1548 raft/raft.go:1135  [s5,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 42, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.645650 1548 raft/raft.go:1135  [s5,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 42, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.645670 1548 raft/raft.go:1135  [s5,r1/?:{-}] ffffffffffffffff restored progress of 3 [next = 42, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.645689 1548 raft/raft.go:1135  [s5,r1/?:{-}] ffffffffffffffff restored progress of 4 [next = 42, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.645703 1548 raft/raft.go:1102  [s5,r1/?:{-}] ffffffffffffffff [commit: 41] restored snapshot [index: 41, term: 6]
I161113 02:50:57.645721 1548 storage/replica_raftstorage.go:589  [s5,r1/?:{-}] applying preemptive snapshot at index 41 (id=3c0f778d, encoded size=16, 1 rocksdb batches, 31 log entries)
I161113 02:50:57.647107 1548 storage/replica_raftstorage.go:592  [s5,r1/?:/M{in-ax}] applied preemptive snapshot in 0.001s
I161113 02:50:57.652976 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:3 store_id:3 replica_id:3 > replicas:<node_id:4 store_id:4 replica_id:4 > next_replica_id:5 
I161113 02:50:57.654658 412 raft/raft.go:568  [s4,r1/?:/M{in-ax}] 4 became follower at term 6
I161113 02:50:57.654787 412 raft/raft.go:316  [s4,r1/?:/M{in-ax}] newRaft 4 [peers: [1,2,3], term: 6, commit: 39, applied: 39, lastindex: 39, lastterm: 6]
I161113 02:50:57.654824 412 raft/raft.go:1088  [s4,r1/?:/M{in-ax}] 4 [logterm: 0, index: 41] rejected msgApp [logterm: 6, index: 41] from 1
I161113 02:50:57.655780 1501 storage/raft_transport.go:436  raft transport stream to node 1 established
I161113 02:50:57.656131 101 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 39) from 4 for index 41
I161113 02:50:57.656202 101 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of 4 to [next = 40, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.657334 1615 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:5 StoreID:5 ReplicaID:5}: [{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}]
I161113 02:50:57.731869 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 7c1b9ec6 at index 43 in 53.942µs.
I161113 02:50:57.732555 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 66, log entries: 33
I161113 02:50:57.732822 1779 raft/raft.go:568  [s6,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:57.732882 1779 raft/raft.go:316  [s6,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:57.732891 1779 raft/raft.go:568  [s6,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:57.732905 1779 raft/raft.go:710  [s6,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:57.732912 1779 raft/raft.go:568  [s6,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:57.732949 1779 raft/raft.go:1125  [s6,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 43, term: 6]
I161113 02:50:57.732966 1779 raft/log.go:288  [s6,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 43, term: 6]
I161113 02:50:57.732986 1779 raft/raft.go:1135  [s6,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 44, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.733002 1779 raft/raft.go:1135  [s6,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 44, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.733018 1779 raft/raft.go:1135  [s6,r1/?:{-}] ffffffffffffffff restored progress of 3 [next = 44, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.733031 1779 raft/raft.go:1135  [s6,r1/?:{-}] ffffffffffffffff restored progress of 4 [next = 44, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.733043 1779 raft/raft.go:1135  [s6,r1/?:{-}] ffffffffffffffff restored progress of 5 [next = 44, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.733054 1779 raft/raft.go:1102  [s6,r1/?:{-}] ffffffffffffffff [commit: 43] restored snapshot [index: 43, term: 6]
I161113 02:50:57.733069 1779 storage/replica_raftstorage.go:589  [s6,r1/?:{-}] applying preemptive snapshot at index 43 (id=7c1b9ec6, encoded size=16, 1 rocksdb batches, 33 log entries)
I161113 02:50:57.734421 1779 storage/replica_raftstorage.go:592  [s6,r1/?:/M{in-ax}] applied preemptive snapshot in 0.001s
I161113 02:50:57.735293 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > 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 
I161113 02:50:57.737681 557 raft/raft.go:568  [s5,r1/?:/M{in-ax}] 5 became follower at term 6
I161113 02:50:57.737786 557 raft/raft.go:316  [s5,r1/?:/M{in-ax}] newRaft 5 [peers: [1,2,3,4], term: 6, commit: 41, applied: 41, lastindex: 41, lastterm: 6]
I161113 02:50:57.737810 557 raft/raft.go:1088  [s5,r1/?:/M{in-ax}] 5 [logterm: 0, index: 43] rejected msgApp [logterm: 6, index: 43] from 1
I161113 02:50:57.738034 1749 storage/raft_transport.go:436  raft transport stream to node 1 established
I161113 02:50:57.738322 123 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 41) from 5 for index 43
I161113 02:50:57.738348 123 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of 5 to [next = 42, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.742094 1755 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:6 StoreID:6 ReplicaID:6}: [{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} {NodeID:6 StoreID:6 ReplicaID:6}]
I161113 02:50:57.802782 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot a4a8fb50 at index 50 in 52.299µs.
I161113 02:50:57.803365 480 raft/raft.go:568  [s6,r1/?:/M{in-ax}] 6 became follower at term 6
I161113 02:50:57.803481 480 raft/raft.go:316  [s6,r1/?:/M{in-ax}] newRaft 6 [peers: [1,2,3,4,5], term: 6, commit: 43, applied: 43, lastindex: 43, lastterm: 6]
I161113 02:50:57.803503 480 raft/raft.go:1088  [s6,r1/?:/M{in-ax}] 6 [logterm: 0, index: 51] rejected msgApp [logterm: 6, index: 51] from 1
I161113 02:50:57.803720 1706 storage/raft_transport.go:436  raft transport stream to node 1 established
I161113 02:50:57.804786 104 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 43) from 6 for index 51
I161113 02:50:57.804833 104 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of 6 to [next = 44, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.805055 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 74, log entries: 40
I161113 02:50:57.809061 1861 raft/raft.go:568  [s7,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:57.809176 1861 raft/raft.go:316  [s7,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:57.809204 1861 raft/raft.go:568  [s7,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:57.809237 1861 raft/raft.go:710  [s7,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:57.809259 1861 raft/raft.go:568  [s7,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:57.809318 1861 raft/raft.go:1125  [s7,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 50, term: 6]
I161113 02:50:57.809351 1861 raft/log.go:288  [s7,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 50, term: 6]
I161113 02:50:57.809385 1861 raft/raft.go:1135  [s7,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 51, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.809416 1861 raft/raft.go:1135  [s7,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 51, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.809443 1861 raft/raft.go:1135  [s7,r1/?:{-}] ffffffffffffffff restored progress of 3 [next = 51, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.809480 1861 raft/raft.go:1135  [s7,r1/?:{-}] ffffffffffffffff restored progress of 4 [next = 51, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.809507 1861 raft/raft.go:1135  [s7,r1/?:{-}] ffffffffffffffff restored progress of 5 [next = 51, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.809534 1861 raft/raft.go:1135  [s7,r1/?:{-}] ffffffffffffffff restored progress of 6 [next = 51, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.809598 1861 raft/raft.go:1102  [s7,r1/?:{-}] ffffffffffffffff [commit: 50] restored snapshot [index: 50, term: 6]
I161113 02:50:57.809626 1861 storage/replica_raftstorage.go:589  [s7,r1/?:{-}] applying preemptive snapshot at index 50 (id=a4a8fb50, encoded size=16, 1 rocksdb batches, 40 log entries)
I161113 02:50:57.810979 1861 storage/replica_raftstorage.go:592  [s7,r1/?:/M{in-ax}] applied preemptive snapshot in 0.001s
I161113 02:50:57.811653 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > 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 > replicas:<node_id:6 store_id:6 replica_id:6 > next_replica_id:7 
I161113 02:50:57.814047 1804 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:7 StoreID:7 ReplicaID:7}: [{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} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7}]
I161113 02:50:57.818168 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 3999115e at index 57 in 111.98µs.
I161113 02:50:57.819046 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 82, log entries: 47
I161113 02:50:57.819582 1914 raft/raft.go:568  [s8,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:57.819682 1914 raft/raft.go:316  [s8,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:57.819704 1914 raft/raft.go:568  [s8,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:57.819734 1914 raft/raft.go:710  [s8,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:57.819752 1914 raft/raft.go:568  [s8,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:57.819799 1914 raft/raft.go:1125  [s8,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 57, term: 6]
I161113 02:50:57.819819 1914 raft/log.go:288  [s8,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 57, term: 6]
I161113 02:50:57.819839 1914 raft/raft.go:1135  [s8,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 58, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.819854 1914 raft/raft.go:1135  [s8,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 58, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.819870 1914 raft/raft.go:1135  [s8,r1/?:{-}] ffffffffffffffff restored progress of 3 [next = 58, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.819910 1914 raft/raft.go:1135  [s8,r1/?:{-}] ffffffffffffffff restored progress of 4 [next = 58, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.819934 1914 raft/raft.go:1135  [s8,r1/?:{-}] ffffffffffffffff restored progress of 5 [next = 58, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.819948 1914 raft/raft.go:1135  [s8,r1/?:{-}] ffffffffffffffff restored progress of 6 [next = 58, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.819974 1914 raft/raft.go:1135  [s8,r1/?:{-}] ffffffffffffffff restored progress of 7 [next = 58, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.819993 1914 raft/raft.go:1102  [s8,r1/?:{-}] ffffffffffffffff [commit: 57] restored snapshot [index: 57, term: 6]
I161113 02:50:57.820015 1914 storage/replica_raftstorage.go:589  [s8,r1/?:{-}] applying preemptive snapshot at index 57 (id=3999115e, encoded size=16, 1 rocksdb batches, 47 log entries)
I161113 02:50:57.821596 1914 storage/replica_raftstorage.go:592  [s8,r1/?:/M{in-ax}] applied preemptive snapshot in 0.002s
I161113 02:50:57.822918 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > 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 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > next_replica_id:8 
I161113 02:50:57.824584 705 raft/raft.go:568  [s7,r1/?:/M{in-ax}] 7 became follower at term 6
I161113 02:50:57.824695 705 raft/raft.go:316  [s7,r1/?:/M{in-ax}] newRaft 7 [peers: [1,2,3,4,5,6], term: 6, commit: 50, applied: 50, lastindex: 50, lastterm: 6]
I161113 02:50:57.824731 705 raft/raft.go:1088  [s7,r1/?:/M{in-ax}] 7 [logterm: 0, index: 57] rejected msgApp [logterm: 6, index: 57] from 1
I161113 02:50:57.824920 1866 storage/raft_transport.go:436  raft transport stream to node 1 established
I161113 02:50:57.825622 1870 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:8 StoreID:8 ReplicaID:8}: [{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} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8}]
I161113 02:50:57.826097 101 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 50) from 7 for index 57
I161113 02:50:57.826525 101 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of 7 to [next = 51, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.831769 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot dbc83cba at index 59 in 55.836µs.
I161113 02:50:57.833932 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 85, log entries: 49
I161113 02:50:57.834225 1453 raft/raft.go:568  [s9,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:57.834328 1453 raft/raft.go:316  [s9,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:57.834349 1453 raft/raft.go:568  [s9,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:57.834373 1453 raft/raft.go:710  [s9,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:57.834388 1453 raft/raft.go:568  [s9,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:57.834440 1453 raft/raft.go:1125  [s9,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 59, term: 6]
I161113 02:50:57.834470 1453 raft/log.go:288  [s9,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 59, term: 6]
I161113 02:50:57.834504 1453 raft/raft.go:1135  [s9,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 60, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.834521 1453 raft/raft.go:1135  [s9,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 60, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.834539 1453 raft/raft.go:1135  [s9,r1/?:{-}] ffffffffffffffff restored progress of 3 [next = 60, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.834582 1453 raft/raft.go:1135  [s9,r1/?:{-}] ffffffffffffffff restored progress of 4 [next = 60, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.834612 1453 raft/raft.go:1135  [s9,r1/?:{-}] ffffffffffffffff restored progress of 5 [next = 60, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.834664 1453 raft/raft.go:1135  [s9,r1/?:{-}] ffffffffffffffff restored progress of 6 [next = 60, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.834695 1453 raft/raft.go:1135  [s9,r1/?:{-}] ffffffffffffffff restored progress of 7 [next = 60, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.834745 1453 raft/raft.go:1135  [s9,r1/?:{-}] ffffffffffffffff restored progress of 8 [next = 60, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.834771 1453 raft/raft.go:1102  [s9,r1/?:{-}] ffffffffffffffff [commit: 59] restored snapshot [index: 59, term: 6]
I161113 02:50:57.834802 1453 storage/replica_raftstorage.go:589  [s9,r1/?:{-}] applying preemptive snapshot at index 59 (id=dbc83cba, encoded size=16, 1 rocksdb batches, 49 log entries)
I161113 02:50:57.836110 1453 storage/replica_raftstorage.go:592  [s9,r1/?:/M{in-ax}] applied preemptive snapshot in 0.001s
I161113 02:50:57.836876 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > 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 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > next_replica_id:9 
I161113 02:50:57.838784 786 raft/raft.go:568  [s8,r1/?:/M{in-ax}] 8 became follower at term 6
I161113 02:50:57.838901 786 raft/raft.go:316  [s8,r1/?:/M{in-ax}] newRaft 8 [peers: [1,2,3,4,5,6,7], term: 6, commit: 57, applied: 57, lastindex: 57, lastterm: 6]
I161113 02:50:57.838922 786 raft/raft.go:1088  [s8,r1/?:/M{in-ax}] 8 [logterm: 0, index: 59] rejected msgApp [logterm: 6, index: 59] from 1
I161113 02:50:57.839128 1961 storage/raft_transport.go:436  raft transport stream to node 1 established
I161113 02:50:57.839782 120 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 57) from 8 for index 59
I161113 02:50:57.839809 120 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of 8 to [next = 58, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.840764 1966 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:9 StoreID:9 ReplicaID:9}: [{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} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9}]
I161113 02:50:57.871103 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 946b81f6 at index 61 in 61.836µs.
I161113 02:50:57.873164 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 88, log entries: 51
I161113 02:50:57.873614 1979 raft/raft.go:568  [s10,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:57.873728 1979 raft/raft.go:316  [s10,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:57.873760 1979 raft/raft.go:568  [s10,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:57.873796 1979 raft/raft.go:710  [s10,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:57.873819 1979 raft/raft.go:568  [s10,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:57.873874 1979 raft/raft.go:1125  [s10,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 61, term: 6]
I161113 02:50:57.873906 1979 raft/log.go:288  [s10,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 61, term: 6]
I161113 02:50:57.873937 1979 raft/raft.go:1135  [s10,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 62, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.873966 1979 raft/raft.go:1135  [s10,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 62, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.873992 1979 raft/raft.go:1135  [s10,r1/?:{-}] ffffffffffffffff restored progress of 3 [next = 62, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.874017 1979 raft/raft.go:1135  [s10,r1/?:{-}] ffffffffffffffff restored progress of 4 [next = 62, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.874033 1979 raft/raft.go:1135  [s10,r1/?:{-}] ffffffffffffffff restored progress of 5 [next = 62, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.874056 1979 raft/raft.go:1135  [s10,r1/?:{-}] ffffffffffffffff restored progress of 6 [next = 62, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.874075 1979 raft/raft.go:1135  [s10,r1/?:{-}] ffffffffffffffff restored progress of 7 [next = 62, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.874106 1979 raft/raft.go:1135  [s10,r1/?:{-}] ffffffffffffffff restored progress of 8 [next = 62, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.874135 1979 raft/raft.go:1135  [s10,r1/?:{-}] ffffffffffffffff restored progress of 9 [next = 62, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.874161 1979 raft/raft.go:1102  [s10,r1/?:{-}] ffffffffffffffff [commit: 61] restored snapshot [index: 61, term: 6]
I161113 02:50:57.874191 1979 storage/replica_raftstorage.go:589  [s10,r1/?:{-}] applying preemptive snapshot at index 61 (id=946b81f6, encoded size=16, 1 rocksdb batches, 51 log entries)
I161113 02:50:57.875799 1979 storage/replica_raftstorage.go:592  [s10,r1/?:/M{in-ax}] applied preemptive snapshot in 0.002s
I161113 02:50:57.876632 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > 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 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > next_replica_id:10 
I161113 02:50:57.879049 911 raft/raft.go:568  [s9,r1/?:/M{in-ax}] 9 became follower at term 6
I161113 02:50:57.879154 911 raft/raft.go:316  [s9,r1/?:/M{in-ax}] newRaft 9 [peers: [1,2,3,4,5,6,7,8], term: 6, commit: 59, applied: 59, lastindex: 59, lastterm: 6]
I161113 02:50:57.879177 911 raft/raft.go:1088  [s9,r1/?:/M{in-ax}] 9 [logterm: 0, index: 61] rejected msgApp [logterm: 6, index: 61] from 1
I161113 02:50:57.879353 2022 storage/raft_transport.go:436  raft transport stream to node 1 established
I161113 02:50:57.879621 135 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 59) from 9 for index 61
I161113 02:50:57.879648 135 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of 9 to [next = 60, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.880837 2028 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:10 StoreID:10 ReplicaID:10}: [{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} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9} {NodeID:10 StoreID:10 ReplicaID:10}]
I161113 02:50:57.889506 1278 raft/raft.go:568  [s10,r1/?:/M{in-ax}] a became follower at term 6
I161113 02:50:57.889612 1278 raft/raft.go:316  [s10,r1/?:/M{in-ax}] newRaft a [peers: [1,2,3,4,5,6,7,8,9], term: 6, commit: 61, applied: 61, lastindex: 61, lastterm: 6]
I161113 02:50:57.890049 1087 storage/raft_transport.go:436  raft transport stream to node 1 established
I161113 02:50:57.890440 1280 raft/raft.go:1088  [s10,r1/?:/M{in-ax}] a [logterm: 0, index: 63] rejected msgApp [logterm: 6, index: 63] from 1
I161113 02:50:57.890616 133 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 61) from a for index 63
I161113 02:50:57.890651 133 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of a to [next = 62, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:57.921811 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > 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 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > replicas:<node_id:10 store_id:10 replica_id:10 > next_replica_id:11 
I161113 02:50:57.971151 2195 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9}]
I161113 02:50:58.077537 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot a7f38208 at index 75 in 56.095µs.
W161113 02:50:58.080478 1684 storage/store.go:2986  [s1] got error from range 1, replica {3 3 3}: raft group deleted
I161113 02:50:58.089280 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 104, log entries: 65
I161113 02:50:58.089621 2285 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:58.089743 2285 raft/raft.go:316  [s3,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:58.089760 2285 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:58.089781 2285 raft/raft.go:710  [s3,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:58.089793 2285 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:58.089855 2285 raft/raft.go:1125  [s3,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 75, term: 6]
I161113 02:50:58.089883 2285 raft/log.go:288  [s3,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 75, term: 6]
I161113 02:50:58.089906 2285 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 76, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.089923 2285 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 76, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.089941 2285 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of a [next = 76, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.089956 2285 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 4 [next = 76, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.089971 2285 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 5 [next = 76, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.089986 2285 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 6 [next = 76, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.090001 2285 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 7 [next = 76, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.090017 2285 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 8 [next = 76, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.090034 2285 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 9 [next = 76, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.090047 2285 raft/raft.go:1102  [s3,r1/?:{-}] ffffffffffffffff [commit: 75] restored snapshot [index: 75, term: 6]
I161113 02:50:58.090065 2285 storage/replica_raftstorage.go:589  [s3,r1/?:{-}] applying preemptive snapshot at index 75 (id=a7f38208, encoded size=16, 1 rocksdb batches, 65 log entries)
I161113 02:50:58.091698 2285 storage/replica_raftstorage.go:592  [s3,r1/?:/M{in-ax}] applied preemptive snapshot in 0.002s
I161113 02:50:58.092787 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > next_replica_id:11 
I161113 02:50:58.097632 2038 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:11}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9} {NodeID:3 StoreID:3 ReplicaID:11}]
I161113 02:50:58.111214 321 raft/raft.go:568  [s3,r1/?:/M{in-ax}] b became follower at term 6
I161113 02:50:58.111268 321 raft/raft.go:316  [s3,r1/?:/M{in-ax}] newRaft b [peers: [1,2,4,5,6,7,8,9,a], term: 6, commit: 75, applied: 75, lastindex: 75, lastterm: 6]
I161113 02:50:58.111316 321 raft/raft.go:1088  [s3,r1/?:/M{in-ax}] b [logterm: 0, index: 82] rejected msgApp [logterm: 6, index: 82] from 1
I161113 02:50:58.112434 112 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 75) from b for index 82
I161113 02:50:58.112536 112 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of b to [next = 76, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.128676 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > replicas:<node_id:3 store_id:3 replica_id:11 > next_replica_id:12 
I161113 02:50:58.131255 2301 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:11}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9}]
I161113 02:50:58.135956 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 2a6a9a7c at index 88 in 63.358µs.
I161113 02:50:58.136909 1689 storage/store.go:2982  [s3,r1/11:/M{in-ax}] added to replica GC queue (peer suggestion)
I161113 02:50:58.138008 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 119, log entries: 78
I161113 02:50:58.138445 2455 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:58.138570 2455 raft/raft.go:316  [s3,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:58.138605 2455 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:58.138633 2455 raft/raft.go:710  [s3,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:58.138667 2455 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:58.138747 2455 raft/raft.go:1125  [s3,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 88, term: 6]
I161113 02:50:58.138773 2455 raft/log.go:288  [s3,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 88, term: 6]
I161113 02:50:58.138793 2455 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 89, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.138818 2455 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 89, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.138833 2455 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of a [next = 89, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.138847 2455 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 4 [next = 89, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.138860 2455 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 5 [next = 89, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.138891 2455 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 6 [next = 89, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.138907 2455 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 7 [next = 89, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.138921 2455 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 8 [next = 89, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.138940 2455 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 9 [next = 89, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.138952 2455 raft/raft.go:1102  [s3,r1/?:{-}] ffffffffffffffff [commit: 88] restored snapshot [index: 88, term: 6]
I161113 02:50:58.138970 2455 storage/replica_raftstorage.go:589  [s3,r1/?:{-}] applying preemptive snapshot at index 88 (id=2a6a9a7c, encoded size=16, 1 rocksdb batches, 78 log entries)
I161113 02:50:58.140850 2455 storage/replica_raftstorage.go:592  [s3,r1/?:/M{in-ax}] applied preemptive snapshot in 0.002s
I161113 02:50:58.145693 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > next_replica_id:12 
I161113 02:50:58.161889 2108 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:12}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9} {NodeID:3 StoreID:3 ReplicaID:12}]
I161113 02:50:58.232602 338 raft/raft.go:568  [s3,r1/?:/M{in-ax}] c became follower at term 6
I161113 02:50:58.232655 338 raft/raft.go:316  [s3,r1/?:/M{in-ax}] newRaft c [peers: [1,2,4,5,6,7,8,9,a], term: 6, commit: 88, applied: 88, lastindex: 88, lastterm: 6]
I161113 02:50:58.232710 338 raft/raft.go:1088  [s3,r1/?:/M{in-ax}] c [logterm: 0, index: 91] rejected msgApp [logterm: 6, index: 91] from 1
I161113 02:50:58.233902 115 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 88) from c for index 91
I161113 02:50:58.233946 115 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of c to [next = 89, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.256843 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > replicas:<node_id:3 store_id:3 replica_id:12 > next_replica_id:13 
I161113 02:50:58.259337 2548 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:12}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9}]
I161113 02:50:58.264908 1689 storage/store.go:2982  [s3,r1/12:/M{in-ax}] added to replica GC queue (peer suggestion)
I161113 02:50:58.265703 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot aec02889 at index 97 in 58.436µs.
I161113 02:50:58.269307 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 130, log entries: 87
I161113 02:50:58.269605 2598 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:58.269833 2598 raft/raft.go:316  [s3,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:58.269865 2598 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:58.269942 2598 raft/raft.go:710  [s3,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:58.269971 2598 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:58.270082 2598 raft/raft.go:1125  [s3,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 97, term: 6]
I161113 02:50:58.270116 2598 raft/log.go:288  [s3,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 97, term: 6]
I161113 02:50:58.270148 2598 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 98, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.270179 2598 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 98, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.270210 2598 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of a [next = 98, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.270324 2598 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 4 [next = 98, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.270356 2598 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 5 [next = 98, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.270387 2598 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 6 [next = 98, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.270424 2598 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 7 [next = 98, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.270453 2598 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 8 [next = 98, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.270481 2598 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 9 [next = 98, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.270504 2598 raft/raft.go:1102  [s3,r1/?:{-}] ffffffffffffffff [commit: 97] restored snapshot [index: 97, term: 6]
I161113 02:50:58.270533 2598 storage/replica_raftstorage.go:589  [s3,r1/?:{-}] applying preemptive snapshot at index 97 (id=aec02889, encoded size=16, 1 rocksdb batches, 87 log entries)
I161113 02:50:58.276724 2598 storage/replica_raftstorage.go:592  [s3,r1/?:/M{in-ax}] applied preemptive snapshot in 0.006s
I161113 02:50:58.277499 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > next_replica_id:13 
I161113 02:50:58.292693 2584 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:13}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9} {NodeID:3 StoreID:3 ReplicaID:13}]
I161113 02:50:58.303234 314 raft/raft.go:568  [s3,r1/?:/M{in-ax}] d became follower at term 6
I161113 02:50:58.303918 314 raft/raft.go:316  [s3,r1/?:/M{in-ax}] newRaft d [peers: [1,2,4,5,6,7,8,9,a], term: 6, commit: 97, applied: 97, lastindex: 97, lastterm: 6]
I161113 02:50:58.303988 314 raft/raft.go:1088  [s3,r1/?:/M{in-ax}] d [logterm: 0, index: 102] rejected msgApp [logterm: 6, index: 102] from 1
W161113 02:50:58.305001 1684 storage/store.go:2986  [s1] got error from range 1, replica {3 3 12}: replicaID cannot move backwards from 13 to 12
I161113 02:50:58.305583 118 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 97) from d for index 102
I161113 02:50:58.305664 118 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of d to [next = 98, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.315593 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > replicas:<node_id:3 store_id:3 replica_id:13 > next_replica_id:14 
I161113 02:50:58.337520 2477 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:13}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9}]
I161113 02:50:58.376430 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot d08b35a9 at index 107 in 55.08µs.
I161113 02:50:58.381426 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 142, log entries: 97
I161113 02:50:58.381889 2387 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:58.382089 2387 raft/raft.go:316  [s3,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:58.382107 2387 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:58.382131 2387 raft/raft.go:710  [s3,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:58.382145 2387 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:58.382255 2387 raft/raft.go:1125  [s3,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 107, term: 6]
I161113 02:50:58.382276 2387 raft/log.go:288  [s3,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 107, term: 6]
I161113 02:50:58.382297 2387 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 108, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.382313 2387 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 108, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.382339 2387 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of a [next = 108, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.382361 2387 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 4 [next = 108, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.382379 2387 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 5 [next = 108, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.382394 2387 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 6 [next = 108, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.382409 2387 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 7 [next = 108, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.382424 2387 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 8 [next = 108, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.382441 2387 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 9 [next = 108, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.382463 2387 raft/raft.go:1102  [s3,r1/?:{-}] ffffffffffffffff [commit: 107] restored snapshot [index: 107, term: 6]
I161113 02:50:58.382492 2387 storage/replica_raftstorage.go:589  [s3,r1/?:{-}] applying preemptive snapshot at index 107 (id=d08b35a9, encoded size=16, 1 rocksdb batches, 97 log entries)
I161113 02:50:58.384917 2387 storage/replica_raftstorage.go:592  [s3,r1/?:/M{in-ax}] applied preemptive snapshot in 0.002s
I161113 02:50:58.385948 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > next_replica_id:14 
I161113 02:50:58.388988 2706 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:14}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9} {NodeID:3 StoreID:3 ReplicaID:14}]
I161113 02:50:58.399942 334 raft/raft.go:568  [s3,r1/?:/M{in-ax}] d became follower at term 6
I161113 02:50:58.400009 334 raft/raft.go:316  [s3,r1/?:/M{in-ax}] newRaft d [peers: [1,2,4,5,6,7,8,9,a], term: 6, commit: 107, applied: 107, lastindex: 107, lastterm: 6]
I161113 02:50:58.413262 337 raft/raft.go:568  [s3,r1/?:/M{in-ax}] e became follower at term 6
I161113 02:50:58.413331 337 raft/raft.go:316  [s3,r1/?:/M{in-ax}] newRaft e [peers: [1,2,4,5,6,7,8,9,a], term: 6, commit: 107, applied: 107, lastindex: 107, lastterm: 6]
I161113 02:50:58.413391 337 raft/raft.go:1088  [s3,r1/?:/M{in-ax}] e [logterm: 0, index: 109] rejected msgApp [logterm: 6, index: 109] from 1
I161113 02:50:58.414195 123 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 107) from e for index 109
I161113 02:50:58.414228 123 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of e to [next = 108, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.418403 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > replicas:<node_id:3 store_id:3 replica_id:14 > next_replica_id:15 
I161113 02:50:58.431089 2638 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:14}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9}]
I161113 02:50:58.435342 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot df9b41c7 at index 114 in 58.667µs.
I161113 02:50:58.439486 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 151, log entries: 104
I161113 02:50:58.441306 2646 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:58.441592 2646 raft/raft.go:316  [s3,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:58.441608 2646 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:58.441628 2646 raft/raft.go:710  [s3,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:58.441640 2646 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:58.441840 2646 raft/raft.go:1125  [s3,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 114, term: 6]
I161113 02:50:58.441857 2646 raft/log.go:288  [s3,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 114, term: 6]
I161113 02:50:58.441879 2646 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 115, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.441893 2646 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 115, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.441907 2646 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of a [next = 115, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.441920 2646 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 4 [next = 115, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.441933 2646 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 5 [next = 115, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.441947 2646 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 6 [next = 115, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.441962 2646 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 7 [next = 115, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.441977 2646 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 8 [next = 115, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.442001 2646 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 9 [next = 115, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.442014 2646 raft/raft.go:1102  [s3,r1/?:{-}] ffffffffffffffff [commit: 114] restored snapshot [index: 114, term: 6]
I161113 02:50:58.442032 2646 storage/replica_raftstorage.go:589  [s3,r1/?:{-}] applying preemptive snapshot at index 114 (id=df9b41c7, encoded size=16, 1 rocksdb batches, 104 log entries)
I161113 02:50:58.444643 2646 storage/replica_raftstorage.go:592  [s3,r1/?:/M{in-ax}] applied preemptive snapshot in 0.003s
I161113 02:50:58.445175 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > next_replica_id:15 
I161113 02:50:58.451505 1689 storage/store.go:2982  [s3,r1/?:/M{in-ax}] added to replica GC queue (peer suggestion)
I161113 02:50:58.454384 2763 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:15}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9} {NodeID:3 StoreID:3 ReplicaID:15}]
I161113 02:50:58.486214 304 raft/raft.go:568  [s3,r1/15:{-}] f became follower at term 0
I161113 02:50:58.486659 304 raft/raft.go:316  [s3,r1/15:{-}] newRaft f [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:58.486695 304 raft/raft.go:568  [s3,r1/15:{-}] f became follower at term 1
I161113 02:50:58.486734 304 raft/raft.go:710  [s3,r1/15:{-}] f [term: 1] received a MsgApp message with higher term from 1 [term: 6]
I161113 02:50:58.486761 304 raft/raft.go:568  [s3,r1/15:{-}] f became follower at term 6
I161113 02:50:58.486793 304 raft/raft.go:1088  [s3,r1/15:{-}] f [logterm: 0, index: 119] rejected msgApp [logterm: 6, index: 119] from 1
I161113 02:50:58.498176 307 raft/raft.go:1088  [s3,r1/15:{-}] f [logterm: 0, index: 119] rejected msgApp [logterm: 6, index: 119] from 1
I161113 02:50:58.502892 134 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 0) from f for index 119
I161113 02:50:58.502938 134 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of f to [next = 1, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.503059 134 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot cfbaccc2 at index 119 in 70.842µs.
I161113 02:50:58.503108 134 raft/raft.go:400  [s1,r1/1:/M{in-ax}] 1 [firstindex: 11, commit: 119] sent snapshot[index: 119, term: 6] to f [next = 1, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.503134 134 raft/raft.go:402  [s1,r1/1:/M{in-ax}] 1 paused sending replication messages to f [next = 1, match = 0, state = ProgressStateSnapshot, waiting = true, pendingSnapshot = 119]
I161113 02:50:58.505192 2144 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 157, log entries: 109
I161113 02:50:58.506419 2851 raft/raft.go:1125  [s3,r1/15:{-}] f [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 119, term: 6]
I161113 02:50:58.506448 2851 raft/log.go:288  [s3,r1/15:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 119, term: 6]
I161113 02:50:58.506469 2851 raft/raft.go:1135  [s3,r1/15:{-}] f restored progress of 1 [next = 120, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.506483 2851 raft/raft.go:1135  [s3,r1/15:{-}] f restored progress of 2 [next = 120, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.506497 2851 raft/raft.go:1135  [s3,r1/15:{-}] f restored progress of a [next = 120, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.506511 2851 raft/raft.go:1135  [s3,r1/15:{-}] f restored progress of 4 [next = 120, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.506524 2851 raft/raft.go:1135  [s3,r1/15:{-}] f restored progress of 5 [next = 120, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.506539 2851 raft/raft.go:1135  [s3,r1/15:{-}] f restored progress of 6 [next = 120, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.506554 2851 raft/raft.go:1135  [s3,r1/15:{-}] f restored progress of 7 [next = 120, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.506568 2851 raft/raft.go:1135  [s3,r1/15:{-}] f restored progress of 8 [next = 120, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.506584 2851 raft/raft.go:1135  [s3,r1/15:{-}] f restored progress of 9 [next = 120, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.506598 2851 raft/raft.go:1135  [s3,r1/15:{-}] f restored progress of f [next = 120, match = 119, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.506609 2851 raft/raft.go:1102  [s3,r1/15:{-}] f [commit: 119] restored snapshot [index: 119, term: 6]
I161113 02:50:58.506635 2851 storage/replica_raftstorage.go:589  [s3,r1/15:{-}] applying Raft snapshot at index 119 (id=cfbaccc2, encoded size=16, 1 rocksdb batches, 109 log entries)
I161113 02:50:58.509976 2851 storage/replica_raftstorage.go:592  [s3,r1/15:/M{in-ax}] applied Raft snapshot in 0.003s
I161113 02:50:58.512521 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > replicas:<node_id:3 store_id:3 replica_id:15 > next_replica_id:16 
I161113 02:50:58.514201 102 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 0) from f for index 119
I161113 02:50:58.514433 2144 raft/raft.go:933  [s1,r1/1:/M{in-ax}] 1 snapshot succeeded, resumed sending replication messages to f [next = 120, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.532211 2687 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:15}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9}]
I161113 02:50:58.537000 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 99b1ea79 at index 125 in 69.331µs.
I161113 02:50:58.539583 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 164, log entries: 115
I161113 02:50:58.539998 1689 storage/store.go:2982  [s3,r1/15:/M{in-ax}] added to replica GC queue (peer suggestion)
I161113 02:50:58.540457 2934 raft/raft.go:568  [s3,r1/15:/M{in-ax}] ffffffffffffffff became follower at term 6
I161113 02:50:58.540500 2934 raft/raft.go:316  [s3,r1/15:/M{in-ax}] newRaft ffffffffffffffff [peers: [1,2,4,5,6,7,8,9,a], term: 6, commit: 125, applied: 125, lastindex: 125, lastterm: 6]
I161113 02:50:58.540560 2934 raft/raft.go:1106  [s3,r1/15:/M{in-ax}] ffffffffffffffff [commit: 125] ignored snapshot [index: 125, term: 6]
I161113 02:50:58.541244 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > next_replica_id:16 
I161113 02:50:58.543809 2830 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:16}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9} {NodeID:3 StoreID:3 ReplicaID:16}]
I161113 02:50:58.595620 315 raft/raft.go:568  [s3,r1/16:{-}] 10 became follower at term 0
I161113 02:50:58.596093 315 raft/raft.go:316  [s3,r1/16:{-}] newRaft 10 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:58.596110 315 raft/raft.go:568  [s3,r1/16:{-}] 10 became follower at term 1
I161113 02:50:58.596135 315 raft/raft.go:710  [s3,r1/16:{-}] 10 [term: 1] received a MsgApp message with higher term from 1 [term: 6]
I161113 02:50:58.596147 315 raft/raft.go:568  [s3,r1/16:{-}] 10 became follower at term 6
I161113 02:50:58.596164 315 raft/raft.go:1088  [s3,r1/16:{-}] 10 [logterm: 0, index: 127] rejected msgApp [logterm: 6, index: 127] from 1
I161113 02:50:58.597966 105 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 0) from 10 for index 127
I161113 02:50:58.598009 105 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of 10 to [next = 1, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.598125 105 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 49cd2698 at index 129 in 59.411µs.
I161113 02:50:58.598171 105 raft/raft.go:400  [s1,r1/1:/M{in-ax}] 1 [firstindex: 11, commit: 129] sent snapshot[index: 129, term: 6] to 10 [next = 1, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.598199 105 raft/raft.go:402  [s1,r1/1:/M{in-ax}] 1 paused sending replication messages to 10 [next = 1, match = 0, state = ProgressStateSnapshot, waiting = true, pendingSnapshot = 129]
I161113 02:50:58.600769 2983 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 169, log entries: 119
I161113 02:50:58.601383 2809 raft/raft.go:1125  [s3,r1/16:{-}] 10 [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 129, term: 6]
I161113 02:50:58.601411 2809 raft/log.go:288  [s3,r1/16:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 129, term: 6]
I161113 02:50:58.601432 2809 raft/raft.go:1135  [s3,r1/16:{-}] 10 restored progress of 1 [next = 130, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.601450 2809 raft/raft.go:1135  [s3,r1/16:{-}] 10 restored progress of 2 [next = 130, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.601466 2809 raft/raft.go:1135  [s3,r1/16:{-}] 10 restored progress of a [next = 130, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.601481 2809 raft/raft.go:1135  [s3,r1/16:{-}] 10 restored progress of 4 [next = 130, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.601496 2809 raft/raft.go:1135  [s3,r1/16:{-}] 10 restored progress of 5 [next = 130, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.601511 2809 raft/raft.go:1135  [s3,r1/16:{-}] 10 restored progress of 6 [next = 130, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.601527 2809 raft/raft.go:1135  [s3,r1/16:{-}] 10 restored progress of 7 [next = 130, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.601542 2809 raft/raft.go:1135  [s3,r1/16:{-}] 10 restored progress of 8 [next = 130, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.601558 2809 raft/raft.go:1135  [s3,r1/16:{-}] 10 restored progress of 9 [next = 130, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.601572 2809 raft/raft.go:1135  [s3,r1/16:{-}] 10 restored progress of 10 [next = 130, match = 129, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.601585 2809 raft/raft.go:1102  [s3,r1/16:{-}] 10 [commit: 129] restored snapshot [index: 129, term: 6]
I161113 02:50:58.601609 2809 storage/replica_raftstorage.go:589  [s3,r1/16:{-}] applying Raft snapshot at index 129 (id=49cd2698, encoded size=16, 1 rocksdb batches, 119 log entries)
I161113 02:50:58.608888 2809 storage/replica_raftstorage.go:592  [s3,r1/16:/M{in-ax}] applied Raft snapshot in 0.007s
I161113 02:50:58.609184 2983 raft/raft.go:933  [s1,r1/1:/M{in-ax}] 1 snapshot succeeded, resumed sending replication messages to 10 [next = 130, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.630057 25 storage/raft_log_queue.go:219  [raftlog,s1,r1/1:/M{in-ax}] truncating raft log 11-131
I161113 02:50:58.632927 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > replicas:<node_id:3 store_id:3 replica_id:16 > next_replica_id:17 
I161113 02:50:58.704536 2845 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:16}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9}]
I161113 02:50:58.715917 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 7cf2c5f0 at index 139 in 54.003µs.
I161113 02:50:58.716694 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 179, log entries: 9
I161113 02:50:58.722464 2874 raft/raft.go:568  [s3,r1/16:/M{in-ax}] ffffffffffffffff became follower at term 6
I161113 02:50:58.722838 2874 raft/raft.go:316  [s3,r1/16:/M{in-ax}] newRaft ffffffffffffffff [peers: [1,2,4,5,6,7,8,9,a], term: 6, commit: 138, applied: 138, lastindex: 139, lastterm: 6]
I161113 02:50:58.722966 2874 raft/raft.go:1119  [s3,r1/16:/M{in-ax}] ffffffffffffffff [commit: 138, lastindex: 139, lastterm: 6] fast-forwarded commit to snapshot [index: 139, term: 6]
I161113 02:50:58.722998 2874 raft/raft.go:1106  [s3,r1/16:/M{in-ax}] ffffffffffffffff [commit: 139] ignored snapshot [index: 139, term: 6]
I161113 02:50:58.730062 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > next_replica_id:17 
I161113 02:50:58.733049 3126 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:17}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9} {NodeID:3 StoreID:3 ReplicaID:17}]
I161113 02:50:58.773932 333 raft/raft.go:568  [s3,r1/17:{-}] 11 became follower at term 0
I161113 02:50:58.774409 333 raft/raft.go:316  [s3,r1/17:{-}] newRaft 11 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:58.774433 333 raft/raft.go:568  [s3,r1/17:{-}] 11 became follower at term 1
I161113 02:50:58.774458 333 raft/raft.go:710  [s3,r1/17:{-}] 11 [term: 1] received a MsgApp message with higher term from 1 [term: 6]
I161113 02:50:58.774471 333 raft/raft.go:568  [s3,r1/17:{-}] 11 became follower at term 6
I161113 02:50:58.774488 333 raft/raft.go:1088  [s3,r1/17:{-}] 11 [logterm: 0, index: 142] rejected msgApp [logterm: 6, index: 142] from 1
I161113 02:50:58.774984 113 raft/raft.go:863  [s1,r1/1:/M{in-ax}] 1 received msgApp rejection(lastindex: 0) from 11 for index 142
I161113 02:50:58.775012 113 raft/raft.go:865  [s1,r1/1:/M{in-ax}] 1 decreased progress of 11 to [next = 1, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.775109 113 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 89f30d3e at index 143 in 53.865µs.
I161113 02:50:58.775216 113 raft/raft.go:400  [s1,r1/1:/M{in-ax}] 1 [firstindex: 131, commit: 143] sent snapshot[index: 143, term: 6] to 11 [next = 1, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.775247 113 raft/raft.go:402  [s1,r1/1:/M{in-ax}] 1 paused sending replication messages to 11 [next = 1, match = 0, state = ProgressStateSnapshot, waiting = true, pendingSnapshot = 143]
I161113 02:50:58.776918 3150 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 184, log entries: 13
I161113 02:50:58.777430 3153 raft/raft.go:1125  [s3,r1/17:{-}] 11 [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 143, term: 6]
I161113 02:50:58.777456 3153 raft/log.go:288  [s3,r1/17:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 143, term: 6]
I161113 02:50:58.777476 3153 raft/raft.go:1135  [s3,r1/17:{-}] 11 restored progress of 1 [next = 144, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.777491 3153 raft/raft.go:1135  [s3,r1/17:{-}] 11 restored progress of 2 [next = 144, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.777505 3153 raft/raft.go:1135  [s3,r1/17:{-}] 11 restored progress of a [next = 144, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.777519 3153 raft/raft.go:1135  [s3,r1/17:{-}] 11 restored progress of 4 [next = 144, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.777533 3153 raft/raft.go:1135  [s3,r1/17:{-}] 11 restored progress of 5 [next = 144, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.777548 3153 raft/raft.go:1135  [s3,r1/17:{-}] 11 restored progress of 6 [next = 144, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.777563 3153 raft/raft.go:1135  [s3,r1/17:{-}] 11 restored progress of 7 [next = 144, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.777584 3153 raft/raft.go:1135  [s3,r1/17:{-}] 11 restored progress of 8 [next = 144, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.777601 3153 raft/raft.go:1135  [s3,r1/17:{-}] 11 restored progress of 9 [next = 144, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.777614 3153 raft/raft.go:1135  [s3,r1/17:{-}] 11 restored progress of 11 [next = 144, match = 143, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.777626 3153 raft/raft.go:1102  [s3,r1/17:{-}] 11 [commit: 143] restored snapshot [index: 143, term: 6]
I161113 02:50:58.777652 3153 storage/replica_raftstorage.go:589  [s3,r1/17:{-}] applying Raft snapshot at index 143 (id=89f30d3e, encoded size=16, 1 rocksdb batches, 13 log entries)
I161113 02:50:58.779361 3153 storage/replica_raftstorage.go:592  [s3,r1/17:/M{in-ax}] applied Raft snapshot in 0.002s
I161113 02:50:58.779682 3150 raft/raft.go:933  [s1,r1/1:/M{in-ax}] 1 snapshot succeeded, resumed sending replication messages to 11 [next = 144, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.781392 37 storage/replica_command.go:3245  [s1,r1/1:/M{in-ax}] 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 > replicas:<node_id:10 store_id:10 replica_id:10 > replicas:<node_id:4 store_id:4 replica_id:4 > replicas:<node_id:5 store_id:5 replica_id:5 > replicas:<node_id:6 store_id:6 replica_id:6 > replicas:<node_id:7 store_id:7 replica_id:7 > replicas:<node_id:8 store_id:8 replica_id:8 > replicas:<node_id:9 store_id:9 replica_id:9 > replicas:<node_id:3 store_id:3 replica_id:17 > next_replica_id:18 
I161113 02:50:58.801045 3251 storage/replica.go:2055  [s1,r1/1:/M{in-ax}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:17}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:10 StoreID:10 ReplicaID:10} {NodeID:4 StoreID:4 ReplicaID:4} {NodeID:5 StoreID:5 ReplicaID:5} {NodeID:6 StoreID:6 ReplicaID:6} {NodeID:7 StoreID:7 ReplicaID:7} {NodeID:8 StoreID:8 ReplicaID:8} {NodeID:9 StoreID:9 ReplicaID:9}]
I161113 02:50:58.913539 37 storage/replica_raftstorage.go:445  [s1,r1/1:/M{in-ax}] generated snapshot 9703cdb9 at index 147 in 52.248µs.
I161113 02:50:58.918895 37 storage/store.go:3125  [s1,r1/1:/M{in-ax}] streamed snapshot: kv pairs: 189, log entries: 17
I161113 02:50:58.925241 3274 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 0
I161113 02:50:58.925614 3274 raft/raft.go:316  [s3,r1/?:{-}] newRaft ffffffffffffffff [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I161113 02:50:58.925643 3274 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 1
I161113 02:50:58.925672 3274 raft/raft.go:710  [s3,r1/?:{-}] ffffffffffffffff [term: 1] received a MsgSnap message with higher term from 1 [term: 6]
I161113 02:50:58.925692 3274 raft/raft.go:568  [s3,r1/?:{-}] ffffffffffffffff became follower at term 6
I161113 02:50:58.926927 3274 raft/raft.go:1125  [s3,r1/?:{-}] ffffffffffffffff [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 147, term: 6]
I161113 02:50:58.926967 3274 raft/log.go:288  [s3,r1/?:{-}] log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 147, term: 6]
I161113 02:50:58.927003 3274 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 1 [next = 148, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.927035 3274 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 2 [next = 148, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.927062 3274 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of a [next = 148, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.927090 3274 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 4 [next = 148, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.927128 3274 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 5 [next = 148, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.927156 3274 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 6 [next = 148, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.927202 3274 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 7 [next = 148, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.927237 3274 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 8 [next = 148, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.927266 3274 raft/raft.go:1135  [s3,r1/?:{-}] ffffffffffffffff restored progress of 9 [next = 148, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I161113 02:50:58.927291 3274 raft/raft.go:1102  [s3,r1/?:{-}] ffffffffffffffff [commit: 147] restored snapshot [index: 147, term: 6]
I161113 02:50:58.927322 3274 storage/replica_raftstorage.go:589  [s3,r1/?:{-}] applying preemptive snapshot at index 147 (id=9703cdb9, encoded size=16, 1 rocksdb batches, 17 log entries)
I161113 02:50:58.928833 3274 storage/replica_raftstorage.go:592  [s3,r1/?:/M{in-ax}] applied preemptive snapshot in 0.001s
I161113 02:50:58.940306 1689 storage/store.go:2982  [s3,r1/?:/M{in-ax}] added to replica GC queue (peer suggestion)
I161113 02:50:58.942317 1689 storage/store.go:2982  [s3,r1/?:/M{in-ax}] added to replica GC queue (peer suggestion)
I161113 02:50:58.952575 305 raft/raft.go:568  [s3,r1/?:/M{in-ax}] 11 became follower at term 6
I161113 02:50:58.952681 305 raft/raft.go:316  [s3,r1/?:/M{in-ax}] newRaft 11 [peers: [1,2,4,5,6,7,8,9,a], term: 6, commit: 147, applied: 147, lastindex: 147, lastterm: 6]
E161113 02:50:58.952754 305 raft/log.go:191  [s3,r1/?:/M{in-ax}] tocommit(151) is out of range [lastIndex(147)]. Was the raft log corrupted, truncated, or lost?
panic: tocommit(151) is out of range [lastIndex(147)]. Was the raft log corrupted, truncated, or lost? [recovered]
	panic: tocommit(151) is out of range [lastIndex(147)]. Was the raft log corrupted, truncated, or lost?

goroutine 305 [running]:
panic(0x16fc0a0, 0xc42117a710)
	/home/tamird/goroot/src/runtime/panic.go:500 +0x1a1
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).Recover(0xc42019f440)
	/home/tamird/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:185 +0x6e
panic(0x16fc0a0, 0xc42117a710)
	/home/tamird/goroot/src/runtime/panic.go:458 +0x243
github.com/cockroachdb/cockroach/pkg/storage.(*raftLogger).Panicf(0xc420d9eff0, 0x192e2b2, 0x5d, 0xc4213dc7e0, 0x2, 0x2)
	/home/tamird/go/src/github.com/cockroachdb/cockroach/pkg/storage/raft.go:111 +0x107
github.com/coreos/etcd/raft.(*raftLog).commitTo(0xc4204bcd90, 0x97)
	/home/tamird/go/src/github.com/coreos/etcd/raft/log.go:191 +0x166
github.com/coreos/etcd/raft.(*raft).handleHeartbeat(0xc421ee8c30, 0x8, 0x11, 0x1, 0x6, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/home/tamird/go/src/github.com/coreos/etcd/raft/raft.go:1094 +0x54
github.com/coreos/etcd/raft.stepFollower(0xc421ee8c30, 0x8, 0x11, 0x1, 0x6, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/home/tamird/go/src/github.com/coreos/etcd/raft/raft.go:1040 +0x31f
github.com/coreos/etcd/raft.(*raft).Step(0xc421ee8c30, 0x8, 0x11, 0x1, 0x6, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/home/tamird/go/src/github.com/coreos/etcd/raft/raft.go:779 +0x11ef
github.com/coreos/etcd/raft.(*RawNode).Step(0xc420e94100, 0x8, 0x11, 0x1, 0x6, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/home/tamird/go/src/github.com/coreos/etcd/raft/rawnode.go:195 +0xc9
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processRaftRequest.func4(0xc420e94100, 0x0, 0x0, 0x0)
	/home/tamird/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:2942 +0x89
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).withRaftGroupLocked(0xc421e9bc00, 0x1ab4c00, 0xc420ec7848, 0x69085b, 0xc421e9bcd8)
	/home/tamird/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:509 +0x139
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).withRaftGroup(0xc421e9bc00, 0xc420ec7848, 0x0, 0x0)
	/home/tamird/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:526 +0x92
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processRaftRequest(0xc42008c380, 0x7ff3dd94d5f8, 0xc421686a50, 0xc4217b4780, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/home/tamird/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:2943 +0xb94
github.com/cockroachdb/cockroach/pkg/storage.(*Store).processRequestQueue(0xc42008c380, 0x1)
	/home/tamird/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:3171 +0x180
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).worker(0xc4201823c0, 0xc42019f440)
	/home/tamird/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:241 +0x267
github.com/cockroachdb/cockroach/pkg/storage.(*raftScheduler).Start.func2()
	/home/tamird/go/src/github.com/cockroachdb/cockroach/pkg/storage/scheduler.go:181 +0x33
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc42019f440, 0xc420200480)
	/home/tamird/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:196 +0x7d
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker
	/home/tamird/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:197 +0x66


ERROR: exit status 2

1230 runs completed, 1 failures, over 1m55s
FAIL
Makefile:128: recipe for target 'stress' failed
make: *** [stress] Error 1