--- FAIL: test/TestImportPgDump (0.000s)
Test ended in panic.

------- Stdout: -------
W180827 20:41:52.746991 50862 server/status/runtime.go:294  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180827 20:41:52.757923 50862 server/server.go:830  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180827 20:41:52.758132 50862 base/addr_validation.go:260  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180827 20:41:52.758156 50862 base/addr_validation.go:300  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180827 20:41:52.761168 50862 server/config.go:496  [n?] 1 storage engine initialized
I180827 20:41:52.761191 50862 server/config.go:499  [n?] RocksDB cache size: 128 MiB
I180827 20:41:52.761204 50862 server/config.go:499  [n?] store 0: in-memory, size 0 B
I180827 20:41:52.767725 50862 server/node.go:373  [n?] **** cluster d5e53e69-a109-4eb6-91bf-29e74ae744ba has been created
I180827 20:41:52.767752 50862 server/server.go:1401  [n?] **** add additional nodes by specifying --join=127.0.0.1:41477
I180827 20:41:52.767936 50862 gossip/gossip.go:382  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:41477" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:12 > build_tag:"v2.1.0-alpha.20180702-2025-gf1e7bb1" started_at:1535402512767856449 
I180827 20:41:52.770338 50862 storage/store.go:1541  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180827 20:41:52.770546 50862 server/node.go:476  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=1, queries=0.00, writes=0.00, bytesPerReplica={p10=7103.00 p25=7103.00 p50=7103.00 p75=7103.00 p90=7103.00 pMax=7103.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180827 20:41:52.770626 50862 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I180827 20:41:52.770721 50862 server/node.go:697  [n1] connecting to gossip network to verify cluster ID...
I180827 20:41:52.770760 50862 server/node.go:722  [n1] node connected via gossip and verified as part of cluster "d5e53e69-a109-4eb6-91bf-29e74ae744ba"
I180827 20:41:52.770788 50862 server/node.go:546  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180827 20:41:52.771023 50862 server/status/recorder.go:652  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180827 20:41:52.771066 50862 server/server.go:1807  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180827 20:41:52.771159 50862 server/server.go:1538  [n1] starting https server at 127.0.0.1:42563 (use: 127.0.0.1:42563)
I180827 20:41:52.771188 50862 server/server.go:1540  [n1] starting grpc/postgres server at 127.0.0.1:41477
I180827 20:41:52.771209 50862 server/server.go:1541  [n1] advertising CockroachDB node at 127.0.0.1:41477
I180827 20:41:52.775258 51089 server/status/recorder.go:652  [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180827 20:41:52.776337 50925 storage/replica_command.go:298  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180827 20:41:52.788832 51094 storage/replica_command.go:298  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180827 20:41:52.790188 51128 storage/intent_resolver.go:668  [n1,s1] failed to push during intent resolution: failed to push "unnamed" id=ec083bbe key=/Table/SystemConfigSpan/Start rw=true pri=0.01126188 iso=SERIALIZABLE stat=PENDING epo=0 ts=1535402512.772758792,0 orig=1535402512.772758792,0 max=1535402512.772758792,0 wto=false rop=false seq=6
I180827 20:41:52.790695 51118 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180827 20:41:52.795125 51100 storage/replica_command.go:298  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180827 20:41:52.800783 51143 storage/replica_command.go:298  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180827 20:41:52.807906 51165 storage/replica_command.go:298  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180827 20:41:52.811784 51141 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:2.0-12 User:root}
I180827 20:41:52.818164 50799 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180827 20:41:52.821094 51188 storage/replica_command.go:298  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180827 20:41:52.830709 51176 storage/replica_command.go:298  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180827 20:41:52.839374 51187 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:045a1c98-219f-445b-bd6b-d481f04d6b0d User:root}
I180827 20:41:52.849534 51154 storage/replica_command.go:298  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180827 20:41:52.855898 51218 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I180827 20:41:52.861462 51240 storage/replica_command.go:298  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180827 20:41:52.868342 51268 storage/replica_command.go:298  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180827 20:41:52.872706 51256 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I180827 20:41:52.874819 51264 storage/replica_command.go:298  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180827 20:41:52.876403 50862 server/server.go:1594  [n1] done ensuring all necessary migrations have run
I180827 20:41:52.876433 50862 server/server.go:1597  [n1] serving sql connections
I180827 20:41:52.879108 51233 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
I180827 20:41:52.879639 51235 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:41477} Attrs: Locality: ServerVersion:2.0-12 BuildTag:v2.1.0-alpha.20180702-2025-gf1e7bb1 StartedAt:1535402512767856449 LocalityAddress:[]} ClusterID:d5e53e69-a109-4eb6-91bf-29e74ae744ba StartedAt:1535402512767856449 LastUp:1535402512767856449}
I180827 20:41:52.880318 51302 storage/replica_command.go:298  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180827 20:41:52.927701 50819 storage/replica_command.go:298  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180827 20:41:52.940165 51323 storage/replica_command.go:298  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180827 20:41:52.948539 51355 storage/replica_command.go:298  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180827 20:41:52.953658 51380 storage/replica_command.go:298  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180827 20:41:52.961237 51137 storage/replica_command.go:298  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180827 20:41:52.966548 50832 storage/replica_command.go:298  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180827 20:41:52.977113 51362 storage/replica_command.go:298  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180827 20:41:53.041315 51440 storage/replica_command.go:298  [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
I180827 20:41:53.047478 51414 storage/replica_command.go:298  [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
W180827 20:41:53.081214 50862 server/status/runtime.go:294  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180827 20:41:53.089127 50862 server/server.go:830  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180827 20:41:53.089322 50862 base/addr_validation.go:260  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180827 20:41:53.089338 50862 base/addr_validation.go:300  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180827 20:41:53.102793 50862 server/config.go:496  [n?] 1 storage engine initialized
I180827 20:41:53.102863 50862 server/config.go:499  [n?] RocksDB cache size: 128 MiB
I180827 20:41:53.102878 50862 server/config.go:499  [n?] store 0: in-memory, size 0 B
W180827 20:41:53.102953 50862 gossip/gossip.go:1371  [n?] no incoming or outgoing connections
I180827 20:41:53.103001 50862 server/server.go:1403  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180827 20:41:53.115344 51458 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:41477
I180827 20:41:53.125579 51530 gossip/server.go:217  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:36113}
I180827 20:41:53.127987 50862 server/node.go:697  [n?] connecting to gossip network to verify cluster ID...
I180827 20:41:53.128034 50862 server/node.go:722  [n?] node connected via gossip and verified as part of cluster "d5e53e69-a109-4eb6-91bf-29e74ae744ba"
I180827 20:41:53.128397 51575 kv/dist_sender.go:345  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180827 20:41:53.134920 51574 kv/dist_sender.go:345  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180827 20:41:53.135628 50862 kv/dist_sender.go:345  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180827 20:41:53.136461 50862 server/node.go:428  [n?] new node allocated ID 2
I180827 20:41:53.136541 50862 gossip/gossip.go:382  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:36113" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:12 > build_tag:"v2.1.0-alpha.20180702-2025-gf1e7bb1" started_at:1535402513136479434 
I180827 20:41:53.136591 50862 storage/stores.go:242  [n2] read 0 node addresses from persistent storage
I180827 20:41:53.136624 50862 storage/stores.go:261  [n2] wrote 1 node addresses to persistent storage
I180827 20:41:53.137485 51552 storage/stores.go:261  [n1] wrote 1 node addresses to persistent storage
I180827 20:41:53.139442 50862 server/node.go:672  [n2] bootstrapped store [n2,s2]
I180827 20:41:53.139577 50862 server/node.go:546  [n2] node=2: started with [] engine(s) and attributes []
I180827 20:41:53.140140 50862 server/status/recorder.go:652  [n2] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180827 20:41:53.140166 50862 server/server.go:1807  [n2] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180827 20:41:53.140233 50862 server/server.go:1538  [n2] starting https server at 127.0.0.1:39947 (use: 127.0.0.1:39947)
I180827 20:41:53.140246 50862 server/server.go:1540  [n2] starting grpc/postgres server at 127.0.0.1:36113
I180827 20:41:53.140256 50862 server/server.go:1541  [n2] advertising CockroachDB node at 127.0.0.1:36113
I180827 20:41:53.140624 51685 server/status/recorder.go:652  [n2,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180827 20:41:53.153945 50862 server/server.go:1594  [n2] done ensuring all necessary migrations have run
I180827 20:41:53.153974 50862 server/server.go:1597  [n2] serving sql connections
W180827 20:41:53.165268 50862 server/status/runtime.go:294  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180827 20:41:53.185802 51467 server/server_update.go:67  [n2] no need to upgrade, cluster already at the newest version
I180827 20:41:53.186848 51469 sql/event_log.go:126  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:36113} Attrs: Locality: ServerVersion:2.0-12 BuildTag:v2.1.0-alpha.20180702-2025-gf1e7bb1 StartedAt:1535402513136479434 LocalityAddress:[]} ClusterID:d5e53e69-a109-4eb6-91bf-29e74ae744ba StartedAt:1535402513136479434 LastUp:1535402513136479434}
I180827 20:41:53.189622 50862 server/server.go:830  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180827 20:41:53.189776 50862 base/addr_validation.go:260  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180827 20:41:53.189808 50862 base/addr_validation.go:300  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I180827 20:41:53.207782 50862 server/config.go:496  [n?] 1 storage engine initialized
I180827 20:41:53.207807 50862 server/config.go:499  [n?] RocksDB cache size: 128 MiB
I180827 20:41:53.207815 50862 server/config.go:499  [n?] store 0: in-memory, size 0 B
W180827 20:41:53.207911 50862 gossip/gossip.go:1371  [n?] no incoming or outgoing connections
I180827 20:41:53.207947 50862 server/server.go:1403  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180827 20:41:53.211471 51475 rpc/nodedialer/nodedialer.go:92  [ct-client] connection to n2 established
I180827 20:41:53.223653 51740 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:41477
I180827 20:41:53.223954 51816 gossip/server.go:217  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:46463}
I180827 20:41:53.224401 50862 server/node.go:697  [n?] connecting to gossip network to verify cluster ID...
I180827 20:41:53.224432 50862 server/node.go:722  [n?] node connected via gossip and verified as part of cluster "d5e53e69-a109-4eb6-91bf-29e74ae744ba"
I180827 20:41:53.224690 51837 kv/dist_sender.go:345  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180827 20:41:53.225445 51836 kv/dist_sender.go:345  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180827 20:41:53.226030 50862 kv/dist_sender.go:345  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180827 20:41:53.226699 50862 server/node.go:428  [n?] new node allocated ID 3
I180827 20:41:53.226763 50862 gossip/gossip.go:382  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:46463" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:12 > build_tag:"v2.1.0-alpha.20180702-2025-gf1e7bb1" started_at:1535402513226706701 
I180827 20:41:53.226805 50862 storage/stores.go:242  [n3] read 0 node addresses from persistent storage
I180827 20:41:53.226851 50862 storage/stores.go:261  [n3] wrote 2 node addresses to persistent storage
I180827 20:41:53.227563 51809 storage/stores.go:261  [n1] wrote 2 node addresses to persistent storage
I180827 20:41:53.227869 51810 storage/stores.go:261  [n2] wrote 2 node addresses to persistent storage
I180827 20:41:53.228504 50862 server/node.go:672  [n3] bootstrapped store [n3,s3]
I180827 20:41:53.229044 50862 server/node.go:546  [n3] node=3: started with [] engine(s) and attributes []
I180827 20:41:53.229696 50862 server/status/recorder.go:652  [n3] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180827 20:41:53.229749 50862 server/server.go:1807  [n3] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180827 20:41:53.235251 50862 server/server.go:1538  [n3] starting https server at 127.0.0.1:43307 (use: 127.0.0.1:43307)
I180827 20:41:53.235271 50862 server/server.go:1540  [n3] starting grpc/postgres server at 127.0.0.1:46463
I180827 20:41:53.235283 50862 server/server.go:1541  [n3] advertising CockroachDB node at 127.0.0.1:46463
I180827 20:41:53.240284 50862 server/server.go:1594  [n3] done ensuring all necessary migrations have run
I180827 20:41:53.240307 50862 server/server.go:1597  [n3] serving sql connections
I180827 20:41:53.243124 51945 server/status/recorder.go:652  [n3,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180827 20:41:53.248117 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r20/1:/Table/{23-50}] sending preemptive snapshot 59e1afc9 at applied index 16
I180827 20:41:53.249136 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180827 20:41:53.251012 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r20/1:/Table/{23-50}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 6, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.251369 51983 storage/replica_raftstorage.go:784  [n2,s2,r20/?:{-}] applying preemptive snapshot at index 16 (id=59e1afc9, encoded size=2241, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.254056 51839 server/server_update.go:67  [n3] no need to upgrade, cluster already at the newest version
I180827 20:41:53.255122 51841 sql/event_log.go:126  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:46463} Attrs: Locality: ServerVersion:2.0-12 BuildTag:v2.1.0-alpha.20180702-2025-gf1e7bb1 StartedAt:1535402513226706701 LocalityAddress:[]} ClusterID:d5e53e69-a109-4eb6-91bf-29e74ae744ba StartedAt:1535402513226706701 LastUp:1535402513226706701}
I180827 20:41:53.256061 51983 storage/replica_raftstorage.go:790  [n2,s2,r20/?:/Table/{23-50}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180827 20:41:53.256605 50930 storage/replica_command.go:812  [replicate,n1,s1,r20/1:/Table/{23-50}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r20:/Table/{23-50} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.259565 50930 storage/replica.go:3743  [n1,s1,r20/1:/Table/{23-50}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.261627 51625 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180827 20:41:53.264544 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180827 20:41:53.286630 50930 rpc/nodedialer/nodedialer.go:92  [replicate,n1,s1,r21/1:/Table/5{0-1}] connection to n3 established
I180827 20:41:53.287245 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180827 20:41:53.287799 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r21/1:/Table/5{0-1}] sending preemptive snapshot de08568a at applied index 18
I180827 20:41:53.288157 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r21/1:/Table/5{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.288623 51959 storage/replica_raftstorage.go:784  [n3,s3,r21/?:{-}] applying preemptive snapshot at index 18 (id=de08568a, encoded size=2646, 1 rocksdb batches, 8 log entries)
I180827 20:41:53.289814 51959 storage/replica_raftstorage.go:790  [n3,s3,r21/?:/Table/5{0-1}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180827 20:41:53.290329 50930 storage/replica_command.go:812  [replicate,n1,s1,r21/1:/Table/5{0-1}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r21:/Table/5{0-1} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.293678 50930 storage/replica.go:3743  [n1,s1,r21/1:/Table/5{0-1}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.294953 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r22/1:/{Table/51-Max}] sending preemptive snapshot a84e7278 at applied index 12
I180827 20:41:53.295229 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r22/1:/{Table/51-Max}] streamed snapshot to (n3,s3):?: kv pairs: 7, log entries: 2, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.295441 51883 rpc/nodedialer/nodedialer.go:92  [n3] connection to n1 established
I180827 20:41:53.295585 51953 storage/replica_raftstorage.go:784  [n3,s3,r22/?:{-}] applying preemptive snapshot at index 12 (id=a84e7278, encoded size=386, 1 rocksdb batches, 2 log entries)
I180827 20:41:53.295717 51953 storage/replica_raftstorage.go:790  [n3,s3,r22/?:/{Table/51-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.295955 50930 storage/replica_command.go:812  [replicate,n1,s1,r22/1:/{Table/51-Max}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r22:/{Table/51-Max} [(n1,s1):1, next=2, gen=0]
I180827 20:41:53.298097 50930 storage/replica.go:3743  [n1,s1,r22/1:/{Table/51-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.301122 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r8/1:/Table/1{1-2}] sending preemptive snapshot 201bdccc at applied index 18
I180827 20:41:53.301565 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 8, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.306578 52088 storage/replica_raftstorage.go:784  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 18 (id=201bdccc, encoded size=4352, 1 rocksdb batches, 8 log entries)
I180827 20:41:53.306868 52088 storage/replica_raftstorage.go:790  [n3,s3,r8/?:/Table/1{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.307601 50930 storage/replica_command.go:812  [replicate,n1,s1,r8/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.311873 50930 storage/replica.go:3743  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.314134 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r17/1:/Table/2{0-1}] sending preemptive snapshot 53116eb2 at applied index 16
I180827 20:41:53.314317 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.314683 52103 storage/replica_raftstorage.go:784  [n3,s3,r17/?:{-}] applying preemptive snapshot at index 16 (id=53116eb2, encoded size=2105, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.314887 52103 storage/replica_raftstorage.go:790  [n3,s3,r17/?:/Table/2{0-1}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.315401 50930 storage/replica_command.go:812  [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.318398 50930 storage/replica.go:3743  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.319436 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r16/1:/Table/{19-20}] sending preemptive snapshot e0be8540 at applied index 16
I180827 20:41:53.319691 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.320127 52072 storage/replica_raftstorage.go:784  [n2,s2,r16/?:{-}] applying preemptive snapshot at index 16 (id=e0be8540, encoded size=2109, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.320339 52072 storage/replica_raftstorage.go:790  [n2,s2,r16/?:/Table/{19-20}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.320816 50930 storage/replica_command.go:812  [replicate,n1,s1,r16/1:/Table/{19-20}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r16:/Table/{19-20} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.323849 50930 storage/replica.go:3743  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.326208 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r15/1:/Table/1{8-9}] sending preemptive snapshot d259ae5c at applied index 16
I180827 20:41:53.326404 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.326731 52116 storage/replica_raftstorage.go:784  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 16 (id=d259ae5c, encoded size=2276, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.326923 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180827 20:41:53.326953 52116 storage/replica_raftstorage.go:790  [n2,s2,r15/?:/Table/1{8-9}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.334514 50930 storage/replica_command.go:812  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.337656 50930 storage/replica.go:3743  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.338767 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r14/1:/Table/1{7-8}] sending preemptive snapshot 9d0058d5 at applied index 16
I180827 20:41:53.339034 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.339612 52090 storage/replica_raftstorage.go:784  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 16 (id=9d0058d5, encoded size=2276, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.339831 52090 storage/replica_raftstorage.go:790  [n2,s2,r14/?:/Table/1{7-8}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.340173 50930 storage/replica_command.go:812  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.343121 50930 storage/replica.go:3743  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.345432 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r9/1:/Table/1{2-3}] sending preemptive snapshot 0eea2d20 at applied index 26
I180827 20:41:53.345859 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 53, log entries: 16, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.347137 52066 storage/replica_raftstorage.go:784  [n2,s2,r9/?:{-}] applying preemptive snapshot at index 26 (id=0eea2d20, encoded size=15139, 1 rocksdb batches, 16 log entries)
I180827 20:41:53.347467 52066 storage/replica_raftstorage.go:790  [n2,s2,r9/?:/Table/1{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.348208 50930 storage/replica_command.go:812  [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.352166 50930 storage/replica.go:3743  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.353188 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] sending preemptive snapshot 0cdee511 at applied index 39
I180827 20:41:53.353765 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n2,s2):?: kv pairs: 36, log entries: 29, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.354286 51723 storage/replica_raftstorage.go:784  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 39 (id=0cdee511, encoded size=98384, 1 rocksdb batches, 29 log entries)
I180827 20:41:53.354994 51723 storage/replica_raftstorage.go:790  [n2,s2,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.355529 50930 storage/replica_command.go:812  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.358523 50930 storage/replica.go:3743  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.360250 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] sending preemptive snapshot 965d58b1 at applied index 19
I180827 20:41:53.360436 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 9, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.360789 52150 storage/replica_raftstorage.go:784  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 19 (id=965d58b1, encoded size=4003, 1 rocksdb batches, 9 log entries)
I180827 20:41:53.361043 52150 storage/replica_raftstorage.go:790  [n3,s3,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.361522 50930 storage/replica_command.go:812  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.364392 50930 storage/replica.go:3743  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.366422 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r12/1:/Table/1{5-6}] sending preemptive snapshot 811af376 at applied index 16
I180827 20:41:53.366638 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.367089 52137 storage/replica_raftstorage.go:784  [n3,s3,r12/?:{-}] applying preemptive snapshot at index 16 (id=811af376, encoded size=2276, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.367359 52137 storage/replica_raftstorage.go:790  [n3,s3,r12/?:/Table/1{5-6}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.368127 50930 storage/replica_command.go:812  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.371691 50930 storage/replica.go:3743  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.374563 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r19/1:/Table/2{2-3}] sending preemptive snapshot 9cd02555 at applied index 16
I180827 20:41:53.374760 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.375252 52080 storage/replica_raftstorage.go:784  [n3,s3,r19/?:{-}] applying preemptive snapshot at index 16 (id=9cd02555, encoded size=2276, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.375582 52080 storage/replica_raftstorage.go:790  [n3,s3,r19/?:/Table/2{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.375950 50930 storage/replica_command.go:812  [replicate,n1,s1,r19/1:/Table/2{2-3}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.381819 50930 storage/replica.go:3743  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.386461 52091 rpc/nodedialer/nodedialer.go:92  [ct-client] connection to n3 established
I180827 20:41:53.386637 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r10/1:/Table/1{3-4}] sending preemptive snapshot a16f4b15 at applied index 64
I180827 20:41:53.388005 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 204, log entries: 54, rate-limit: 8.0 MiB/sec, 4ms
I180827 20:41:53.388536 52181 storage/replica_raftstorage.go:784  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 64 (id=a16f4b15, encoded size=62836, 1 rocksdb batches, 54 log entries)
I180827 20:41:53.389154 52181 storage/replica_raftstorage.go:790  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.389513 50930 storage/replica_command.go:812  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.392649 50930 storage/replica.go:3743  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.394122 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] sending preemptive snapshot 69adabc1 at applied index 23
I180827 20:41:53.394365 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n2,s2):?: kv pairs: 7, log entries: 13, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.394729 52213 storage/replica_raftstorage.go:784  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 23 (id=69adabc1, encoded size=6277, 1 rocksdb batches, 13 log entries)
I180827 20:41:53.394981 52213 storage/replica_raftstorage.go:790  [n2,s2,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.395465 50930 storage/replica_command.go:812  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.398757 50930 storage/replica.go:3743  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.399709 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r18/1:/Table/2{1-2}] sending preemptive snapshot e9df2a4a at applied index 16
I180827 20:41:53.400036 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.400391 52185 storage/replica_raftstorage.go:784  [n3,s3,r18/?:{-}] applying preemptive snapshot at index 16 (id=e9df2a4a, encoded size=2272, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.400594 52185 storage/replica_raftstorage.go:790  [n3,s3,r18/?:/Table/2{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.400882 50930 storage/replica_command.go:812  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.407636 50930 storage/replica.go:3743  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.408861 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r13/1:/Table/1{6-7}] sending preemptive snapshot 6f914d55 at applied index 16
I180827 20:41:53.409071 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.409426 52218 storage/replica_raftstorage.go:784  [n2,s2,r13/?:{-}] applying preemptive snapshot at index 16 (id=6f914d55, encoded size=2276, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.409616 52218 storage/replica_raftstorage.go:790  [n2,s2,r13/?:/Table/1{6-7}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.409970 50930 storage/replica_command.go:812  [replicate,n1,s1,r13/1:/Table/1{6-7}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.411262 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180827 20:41:53.412831 50930 storage/replica.go:3743  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.414081 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r11/1:/Table/1{4-5}] sending preemptive snapshot cca961c1 at applied index 16
I180827 20:41:53.414277 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.414576 52199 storage/replica_raftstorage.go:784  [n3,s3,r11/?:{-}] applying preemptive snapshot at index 16 (id=cca961c1, encoded size=2272, 1 rocksdb batches, 6 log entries)
I180827 20:41:53.414816 52199 storage/replica_raftstorage.go:790  [n3,s3,r11/?:/Table/1{4-5}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.415293 50930 storage/replica_command.go:812  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.418111 50930 storage/replica.go:3743  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.419054 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r5/1:/System/ts{d-e}] sending preemptive snapshot 3c3a015f at applied index 27
I180827 20:41:53.423022 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n3,s3):?: kv pairs: 1391, log entries: 2, rate-limit: 8.0 MiB/sec, 4ms
I180827 20:41:53.423893 52201 storage/replica_raftstorage.go:784  [n3,s3,r5/?:{-}] applying preemptive snapshot at index 27 (id=3c3a015f, encoded size=194658, 1 rocksdb batches, 2 log entries)
I180827 20:41:53.429501 52201 storage/replica_raftstorage.go:790  [n3,s3,r5/?:/System/ts{d-e}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=2ms commit=4ms]
I180827 20:41:53.433500 50930 storage/replica_command.go:812  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.437580 50930 storage/replica.go:3743  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.440575 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] sending preemptive snapshot cbd412df at applied index 21
I180827 20:41:53.440794 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 11, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.441181 52260 storage/replica_raftstorage.go:784  [n3,s3,r6/?:{-}] applying preemptive snapshot at index 21 (id=cbd412df, encoded size=4339, 1 rocksdb batches, 11 log entries)
I180827 20:41:53.441400 52260 storage/replica_raftstorage.go:790  [n3,s3,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.441676 50930 storage/replica_command.go:812  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.448564 52224 rpc/nodedialer/nodedialer.go:92  [ct-client] connection to n2 established
I180827 20:41:53.461587 50930 storage/replica.go:3743  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180827 20:41:53.463345 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] sending preemptive snapshot 114f4385 at applied index 29
I180827 20:41:53.464896 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 59, log entries: 19, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.465343 52280 storage/replica_raftstorage.go:784  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 29 (id=114f4385, encoded size=16646, 1 rocksdb batches, 19 log entries)
I180827 20:41:53.465821 52280 storage/replica_raftstorage.go:790  [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.466988 50930 storage/replica_command.go:812  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.472743 50930 storage/replica.go:3743  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.474632 50930 storage/store_snapshot.go:615  [replicate,n1,s1,r1/1:/{Min-System/}] sending preemptive snapshot 0a244018 at applied index 114
I180827 20:41:53.475250 50930 storage/store_snapshot.go:657  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 73, log entries: 90, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.475827 52267 storage/replica_raftstorage.go:784  [n2,s2,r1/?:{-}] applying preemptive snapshot at index 114 (id=0a244018, encoded size=40271, 1 rocksdb batches, 90 log entries)
I180827 20:41:53.476525 52267 storage/replica_raftstorage.go:790  [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.476869 50930 storage/replica_command.go:812  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r1:/{Min-System/} [(n1,s1):1, next=2, gen=1]
I180827 20:41:53.482912 50930 storage/replica.go:3743  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180827 20:41:53.483281 50930 storage/queue.go:873  [n1,replicate] purgatory is now empty
I180827 20:41:53.485684 52286 storage/store_snapshot.go:615  [replicate,n1,s1,r20/1:/Table/{23-50}] sending preemptive snapshot f1426c69 at applied index 19
I180827 20:41:53.487316 52286 storage/store_snapshot.go:657  [replicate,n1,s1,r20/1:/Table/{23-50}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 9, rate-limit: 8.0 MiB/sec, 4ms
I180827 20:41:53.487681 52252 storage/replica_raftstorage.go:784  [n3,s3,r20/?:{-}] applying preemptive snapshot at index 19 (id=f1426c69, encoded size=3273, 1 rocksdb batches, 9 log entries)
I180827 20:41:53.487932 52252 storage/replica_raftstorage.go:790  [n3,s3,r20/?:/Table/{23-50}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.488311 52286 storage/replica_command.go:812  [replicate,n1,s1,r20/1:/Table/{23-50}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r20:/Table/{23-50} [(n1,s1):1, (n2,s2):2, next=3, gen=1]
I180827 20:41:53.503580 52286 storage/replica.go:3743  [n1,s1,r20/1:/Table/{23-50}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180827 20:41:53.505707 52235 storage/store_snapshot.go:615  [replicate,n1,s1,r1/1:/{Min-System/}] sending preemptive snapshot 99036b07 at applied index 119
I180827 20:41:53.506514 52235 storage/store_snapshot.go:657  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n3,s3):?: kv pairs: 78, log entries: 95, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.507282 52188 storage/replica_raftstorage.go:784  [n3,s3,r1/?:{-}] applying preemptive snapshot at index 119 (id=99036b07, encoded size=42101, 1 rocksdb batches, 95 log entries)
I180827 20:41:53.508109 52188 storage/replica_raftstorage.go:790  [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.508641 52235 storage/replica_command.go:812  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r1:/{Min-System/} [(n1,s1):1, (n2,s2):2, next=3, gen=1]
I180827 20:41:53.512524 52235 storage/replica.go:3743  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180827 20:41:53.513999 52209 storage/store_snapshot.go:615  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] sending preemptive snapshot bb53109c at applied index 32
I180827 20:41:53.514379 52209 storage/store_snapshot.go:657  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):?: kv pairs: 60, log entries: 22, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.514821 52292 storage/replica_raftstorage.go:784  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 32 (id=bb53109c, encoded size=17687, 1 rocksdb batches, 22 log entries)
I180827 20:41:53.515905 52292 storage/replica_raftstorage.go:790  [n3,s3,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 1ms [clear=1ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.516367 52209 storage/replica_command.go:812  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n2,s2):2, next=3, gen=1]
I180827 20:41:53.520158 52209 storage/replica.go:3743  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180827 20:41:53.521958 52312 storage/store_snapshot.go:615  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] sending preemptive snapshot 2ca43612 at applied index 24
I180827 20:41:53.522776 52312 storage/store_snapshot.go:657  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 14, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.523128 52239 storage/replica_raftstorage.go:784  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 24 (id=2ca43612, encoded size=5410, 1 rocksdb batches, 14 log entries)
I180827 20:41:53.523377 52239 storage/replica_raftstorage.go:790  [n2,s2,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.523701 52312 storage/replica_command.go:812  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I180827 20:41:53.525176 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 19 underreplicated ranges
I180827 20:41:53.527482 52312 storage/replica.go:3743  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.528875 52327 storage/store_snapshot.go:615  [replicate,n1,s1,r5/1:/System/ts{d-e}] sending preemptive snapshot 731be2ae at applied index 30
I180827 20:41:53.532860 52327 storage/store_snapshot.go:657  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 1392, log entries: 5, rate-limit: 8.0 MiB/sec, 4ms
I180827 20:41:53.533361 52316 storage/replica_raftstorage.go:784  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 30 (id=731be2ae, encoded size=195741, 1 rocksdb batches, 5 log entries)
I180827 20:41:53.535834 52316 storage/replica_raftstorage.go:790  [n2,s2,r5/?:/System/ts{d-e}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=2ms]
I180827 20:41:53.536253 52327 storage/replica_command.go:812  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I180827 20:41:53.540576 52327 storage/replica.go:3743  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.545804 52341 storage/store_snapshot.go:615  [replicate,n1,s1,r11/1:/Table/1{4-5}] sending preemptive snapshot 7497a95f at applied index 19
I180827 20:41:53.546108 52341 storage/store_snapshot.go:657  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 9, rate-limit: 8.0 MiB/sec, 4ms
I180827 20:41:53.546590 52275 storage/replica_raftstorage.go:784  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 19 (id=7497a95f, encoded size=3304, 1 rocksdb batches, 9 log entries)
I180827 20:41:53.546960 52275 storage/replica_raftstorage.go:790  [n2,s2,r11/?:/Table/1{4-5}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.547386 52341 storage/replica_command.go:812  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I180827 20:41:53.551568 52341 storage/replica.go:3743  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.554959 52323 storage/store_snapshot.go:615  [replicate,n1,s1,r13/1:/Table/1{6-7}] sending preemptive snapshot 5932a5bd at applied index 19
I180827 20:41:53.555353 52323 storage/store_snapshot.go:657  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 9, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.555743 52329 storage/replica_raftstorage.go:784  [n3,s3,r13/?:{-}] applying preemptive snapshot at index 19 (id=5932a5bd, encoded size=3308, 1 rocksdb batches, 9 log entries)
I180827 20:41:53.556103 52329 storage/replica_raftstorage.go:790  [n3,s3,r13/?:/Table/1{6-7}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.556489 52323 storage/replica_command.go:812  [replicate,n1,s1,r13/1:/Table/1{6-7}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, (n2,s2):2, next=3, gen=1]
I180827 20:41:53.563494 52323 storage/replica.go:3743  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180827 20:41:53.566866 52362 storage/store_snapshot.go:615  [replicate,n1,s1,r18/1:/Table/2{1-2}] sending preemptive snapshot c74baa54 at applied index 19
I180827 20:41:53.568042 52362 storage/store_snapshot.go:657  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 9, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.568417 52366 storage/replica_raftstorage.go:784  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 19 (id=c74baa54, encoded size=3304, 1 rocksdb batches, 9 log entries)
I180827 20:41:53.568651 52366 storage/replica_raftstorage.go:790  [n2,s2,r18/?:/Table/2{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.568954 52362 storage/replica_command.go:812  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I180827 20:41:53.572711 52362 storage/replica.go:3743  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.574655 52190 storage/store_snapshot.go:615  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] sending preemptive snapshot d4c499ea at applied index 26
I180827 20:41:53.574962 52190 storage/store_snapshot.go:657  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 16, rate-limit: 8.0 MiB/sec, 1ms
I180827 20:41:53.575725 52299 storage/replica_raftstorage.go:784  [n3,s3,r2/?:{-}] applying preemptive snapshot at index 26 (id=d4c499ea, encoded size=7349, 1 rocksdb batches, 16 log entries)
I180827 20:41:53.576022 52299 storage/replica_raftstorage.go:790  [n3,s3,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.576405 52190 storage/replica_command.go:812  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, (n2,s2):2, next=3, gen=1]
I180827 20:41:53.579762 52190 storage/replica.go:3743  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180827 20:41:53.583103 52372 storage/store_snapshot.go:615  [replicate,n1,s1,r10/1:/Table/1{3-4}] sending preemptive snapshot dbe83d06 at applied index 103
I180827 20:41:53.583765 52372 storage/store_snapshot.go:657  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 295, log entries: 10, rate-limit: 8.0 MiB/sec, 2ms
I180827 20:41:53.584214 52369 storage/replica_raftstorage.go:784  [n2,s2,r10/?:{-}] applying preemptive snapshot at index 103 (id=dbe83d06, encoded size=38018, 1 rocksdb batches, 10 log entries)
I180827 20:41:53.584577 52369 storage/replica_raftstorage.go:790  [n2,s2,r10/?:/Table/1{3-4}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.584963 52372 storage/replica_command.go:812  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I180827 20:41:53.588661 52372 storage/replica.go:3743  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.590522 52331 storage/store_snapshot.go:615  [replicate,n1,s1,r19/1:/Table/2{2-3}] sending preemptive snapshot ba0de389 at applied index 19
I180827 20:41:53.596120 52331 storage/store_snapshot.go:657  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 9, rate-limit: 8.0 MiB/sec, 6ms
I180827 20:41:53.597215 52259 storage/replica_raftstorage.go:784  [n2,s2,r19/?:{-}] applying preemptive snapshot at index 19 (id=ba0de389, encoded size=3308, 1 rocksdb batches, 9 log entries)
I180827 20:41:53.597484 52259 storage/replica_raftstorage.go:790  [n2,s2,r19/?:/Table/2{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.597898 52331 storage/replica_command.go:812  [replicate,n1,s1,r19/1:/Table/2{2-3}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I180827 20:41:53.601937 52331 storage/replica.go:3743  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.604379 52303 storage/store_snapshot.go:615  [replicate,n1,s1,r12/1:/Table/1{5-6}] sending preemptive snapshot 60969a90 at applied index 19
I180827 20:41:53.606558 52303 storage/store_snapshot.go:657  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 9, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.606975 52307 storage/replica_raftstorage.go:784  [n2,s2,r12/?:{-}] applying preemptive snapshot at index 19 (id=60969a90, encoded size=3308, 1 rocksdb batches, 9 log entries)
I180827 20:41:53.607211 52307 storage/replica_raftstorage.go:790  [n2,s2,r12/?:/Table/1{5-6}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.608276 52303 storage/replica_command.go:812  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I180827 20:41:53.612795 52303 storage/replica.go:3743  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.615927 52392 storage/store_snapshot.go:615  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] sending preemptive snapshot 3d427041 at applied index 22
I180827 20:41:53.617153 52392 storage/store_snapshot.go:657  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 12, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.618565 52405 storage/replica_raftstorage.go:784  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 22 (id=3d427041, encoded size=5215, 1 rocksdb batches, 12 log entries)
I180827 20:41:53.619140 52405 storage/replica_raftstorage.go:790  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.621854 50862 testutils/testcluster/testcluster.go:536  [n1,s1] has 10 underreplicated ranges
I180827 20:41:53.635001 52392 storage/replica_command.go:812  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I180827 20:41:53.638726 52392 storage/replica.go:3743  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180827 20:41:53.643490 52420 storage/store_snapshot.go:615  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] sending preemptive snapshot a2505d74 at applied index 42
I180827 20:41:53.644245 52420 storage/store_snapshot.go:657  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 37, log entries: 32, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.644709 52436 storage/replica_raftstorage.go:784  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 42 (id=a2505d74, encoded size=99568, 1 rocksdb batches, 32 log entries)
I180827 20:41:53.645176 52436 storage/replica_raftstorage.go:790  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180827 20:41:53.645567 52420 storage/replica_command.go:812  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, (n2,s2):2, next=3, gen=1]
I180827 20:41:53.649433 52420 storage/replica.go:3743  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180827 20:41:53.652117 52398 storage/store_snapshot.go:615  [replicate,n1,s1,r9/1:/Table/1{2-3}] sending preemptive snapshot 6dc7ffcb at applied index 29
I180827 20:41:53.653729 52398 storage/store_snapshot.go:657  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 54, log entries: 19, rate-limit: 8.0 MiB/sec, 3ms
I180827 20:41:53.654216 52402 storage/replica_raftstorage.go:784  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 29 (id=6dc7ffcb, encoded size=16171, 1 ro