Closed cockroach-teamcity closed 6 years ago
The following tests appear to have failed:
#676177:
--- FAIL: testrace/TestBackupRestoreNegativePrimaryKey (51.110s) sql_runner.go:41: error executing 'CREATE INDEX balance_idx ON data.bank (balance)': pq: log-job: internal/client/txn.go:883: attempting to use transaction with wrong status or finalized: COMMITTED true ------- Stdout: ------- I180523 22:51:56.691217 16537 server/server.go:784 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled I180523 22:51:56.729572 16537 server/config.go:539 [n?] 1 storage engine initialized I180523 22:51:56.729850 16537 server/config.go:542 [n?] RocksDB cache size: 128 MiB I180523 22:51:56.729955 16537 server/config.go:542 [n?] store 0: in-memory, size 0 B I180523 22:51:56.986130 16537 server/node.go:376 [n?] **** cluster 1136c89f-fbf2-46b3-8efd-5671ecb805a4 has been created I180523 22:51:56.986353 16537 server/server.go:1358 [n?] **** add additional nodes by specifying --join=127.0.0.1:43857 I180523 22:51:57.054686 16537 storage/store.go:1450 [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available I180523 22:51:57.055588 16537 server/node.go:506 [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=1, writes=0.00, bytesPerReplica={p10=7043.00 p25=7043.00 p50=7043.00 p75=7043.00 p90=7043.00 pMax=7043.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00} I180523 22:51:57.066862 16537 server/node.go:354 [n1] node ID 1 initialized I180523 22:51:57.065651 16441 kv/dist_sender.go:368 [n1] unable to determine this node's attributes for replica selection; node is most likely bootstrapping I180523 22:51:57.067523 16537 gossip/gossip.go:333 [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:43857" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:5 > I180523 22:51:57.069064 16537 storage/stores.go:222 [n1] read 0 node addresses from persistent storage I180523 22:51:57.070215 16537 server/node.go:647 [n1] connecting to gossip network to verify cluster ID... I180523 22:51:57.070539 16537 server/node.go:672 [n1] node connected via gossip and verified as part of cluster "1136c89f-fbf2-46b3-8efd-5671ecb805a4" I180523 22:51:57.070997 16537 server/node.go:440 [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes [] I180523 22:51:57.076181 16537 server/server.go:1485 [n1] starting https server at 127.0.0.1:40491 I180523 22:51:57.098667 16537 server/server.go:1486 [n1] starting grpc/postgres server at 127.0.0.1:43857 I180523 22:51:57.100379 16537 server/server.go:1487 [n1] advertising CockroachDB node at 127.0.0.1:43857 W180523 22:51:57.106470 16537 sql/jobs/registry.go:287 [n1] unable to get node liveness: node not in the liveness table I180523 22:51:57.205665 16655 storage/replica_command.go:863 [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2] I180523 22:51:57.986765 16809 storage/replica_command.go:863 [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3] W180523 22:51:58.025512 16462 storage/intent_resolver.go:320 [n1,s1] failed to push during intent resolution: failed to push "sql txn" id=08daa941 key=/Table/SystemConfigSpan/Start rw=true pri=0.01897975 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527115917.202982706,0 orig=1527115917.202982706,0 max=1527115917.202982706,0 wto=false rop=false seq=7 I180523 22:51:58.158990 16819 sql/event_log.go:126 [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root} I180523 22:51:58.275993 16445 storage/replica_command.go:863 [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4] I180523 22:51:58.620957 16851 storage/replica_command.go:863 [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5] W180523 22:51:58.812106 16874 storage/intent_resolver.go:320 [n1,s1] failed to push during intent resolution: failed to push "split" id=ac8c23c0 key=/Local/Range/System/NodeLivenessMax/RangeDescriptor rw=true pri=0.01557162 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527115918.621222166,0 orig=1527115918.621222166,0 max=1527115918.621222166,0 wto=false rop=false seq=3 I180523 22:51:58.824637 16465 sql/event_log.go:126 [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root} I180523 22:51:58.880924 16882 storage/replica_command.go:863 [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6] I180523 22:51:59.114790 16883 storage/replica_command.go:863 [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7] W180523 22:51:59.200087 16900 storage/intent_resolver.go:320 [n1,s1] failed to push during intent resolution: failed to push "sql txn" id=9f6088d9 key=/Table/SystemConfigSpan/Start rw=true pri=0.07033171 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527115918.850703916,0 orig=1527115918.850703916,0 max=1527115918.850703916,0 wto=false rop=false seq=7 I180523 22:51:59.336361 16446 sql/event_log.go:126 [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root} I180523 22:51:59.418098 16877 storage/replica_command.go:863 [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8] W180523 22:51:59.597738 16930 storage/intent_resolver.go:320 [n1,s1] failed to push during intent resolution: failed to push "split" id=14acc710 key=/Local/Range/Table/SystemConfigSpan/Start/RangeDescriptor rw=true pri=0.00614976 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527115919.418337534,0 orig=1527115919.418337534,0 max=1527115919.418337534,0 wto=false rop=false seq=3 I180523 22:51:59.642654 16921 storage/replica_command.go:863 [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9] I180523 22:51:59.902748 16962 storage/replica_command.go:863 [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10] I180523 22:52:00.175140 16983 storage/replica_command.go:863 [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11] I180523 22:52:00.358833 16939 sql/event_log.go:126 [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:root} I180523 22:52:00.411228 16986 storage/replica_command.go:863 [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12] I180523 22:52:00.554836 16988 storage/replica_command.go:863 [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13] I180523 22:52:00.686240 17011 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} W180523 22:52:00.722494 17006 storage/intent_resolver.go:320 [n1,s1] failed to push during intent resolution: failed to push "split" id=58f24cd7 key=/Local/Range/Table/15/RangeDescriptor rw=true pri=0.02981457 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527115920.564232893,0 orig=1527115920.564232893,0 max=1527115920.564232893,0 wto=false rop=false seq=3 I180523 22:52:00.817090 17042 storage/replica_command.go:863 [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14] I180523 22:52:00.880515 17004 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} I180523 22:52:00.907065 16537 server/server.go:1564 [n1] done ensuring all necessary migrations have run I180523 22:52:00.913620 16537 server/server.go:1567 [n1] serving sql connections I180523 22:52:01.008778 17043 server/server_update.go:66 [n1] no need to upgrade, cluster already at the newest version I180523 22:52:01.089046 17045 sql/event_log.go:126 [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:43857} Attrs: Locality: ServerVersion:2.0-5} ClusterID:1136c89f-fbf2-46b3-8efd-5671ecb805a4 StartedAt:1527115917070631401 LastUp:1527115917070631401} I180523 22:52:01.165335 16897 storage/replica_command.go:863 [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15] I180523 22:52:01.318739 16972 storage/replica_command.go:863 [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16] I180523 22:52:01.500660 17124 storage/replica_command.go:863 [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17] I180523 22:52:01.754475 17102 storage/replica_command.go:863 [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18] I180523 22:52:01.955159 17110 storage/replica_command.go:863 [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19] I180523 22:52:02.124017 17141 storage/replica_command.go:863 [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20] W180523 22:52:02.330479 17149 storage/intent_resolver.go:320 [n1,s1] failed to push during intent resolution: failed to push "split" id=3edf7a08 key=/Local/Range/Table/22/RangeDescriptor rw=true pri=0.02834690 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527115922.124275163,0 orig=1527115922.124275163,0 max=1527115922.124275163,0 wto=false rop=false seq=3 I180523 22:52:02.413238 17154 storage/replica_command.go:863 [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21] I180523 22:52:02.615514 17131 storage/replica_command.go:863 [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22] I180523 22:52:03.722136 16537 server/server.go:784 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled I180523 22:52:03.767930 16537 server/config.go:539 [n?] 1 storage engine initialized I180523 22:52:03.768218 16537 server/config.go:542 [n?] RocksDB cache size: 128 MiB I180523 22:52:03.768306 16537 server/config.go:542 [n?] store 0: in-memory, size 0 B W180523 22:52:03.768978 16537 gossip/gossip.go:1293 [n?] no incoming or outgoing connections I180523 22:52:03.769731 16537 server/server.go:1360 [n?] no stores bootstrapped and --join flag specified, awaiting init command. I180523 22:52:03.973324 17246 gossip/client.go:129 [n?] started gossip client to 127.0.0.1:43857 I180523 22:52:03.976641 17253 gossip/server.go:219 [n1] received initial cluster-verification connection from {tcp 127.0.0.1:39393} I180523 22:52:03.989577 16537 storage/stores.go:222 [n?] read 0 node addresses from persistent storage I180523 22:52:03.990022 16537 storage/stores.go:241 [n?] wrote 1 node addresses to persistent storage I180523 22:52:03.990084 16537 server/node.go:647 [n?] connecting to gossip network to verify cluster ID... I180523 22:52:03.990356 16537 server/node.go:672 [n?] node connected via gossip and verified as part of cluster "1136c89f-fbf2-46b3-8efd-5671ecb805a4" I180523 22:52:04.023039 16537 kv/dist_sender.go:368 [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping I180523 22:52:04.036285 16537 server/node.go:347 [n?] new node allocated ID 2 I180523 22:52:04.037025 16537 gossip/gossip.go:333 [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:39393" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:5 > I180523 22:52:04.038077 16537 server/node.go:421 [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>] I180523 22:52:04.038743 16537 server/node.go:440 [n2] node=2: started with [] engine(s) and attributes [] I180523 22:52:04.041796 16537 server/server.go:1485 [n2] starting https server at 127.0.0.1:42187 I180523 22:52:04.042024 16537 server/server.go:1486 [n2] starting grpc/postgres server at 127.0.0.1:39393 I180523 22:52:04.042103 16537 server/server.go:1487 [n2] advertising CockroachDB node at 127.0.0.1:39393 W180523 22:52:04.042480 16537 sql/jobs/registry.go:287 [n2] unable to get node liveness: node not in the liveness table I180523 22:52:04.085065 17200 storage/stores.go:241 [n1] wrote 1 node addresses to persistent storage I180523 22:52:04.087241 16537 server/server.go:1564 [n2] done ensuring all necessary migrations have run I180523 22:52:04.087536 16537 server/server.go:1567 [n2] serving sql connections I180523 22:52:04.368494 17299 server/node.go:628 [n2] bootstrapped store [n2,s2] I180523 22:52:04.578376 17269 sql/event_log.go:126 [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:39393} Attrs: Locality: ServerVersion:2.0-5} ClusterID:1136c89f-fbf2-46b3-8efd-5671ecb805a4 StartedAt:1527115924038404794 LastUp:1527115924038404794} I180523 22:52:04.674758 17267 server/server_update.go:66 [n2] no need to upgrade, cluster already at the newest version I180523 22:52:04.791563 16537 server/server.go:784 [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled I180523 22:52:04.828370 16537 server/config.go:539 [n?] 1 storage engine initialized I180523 22:52:04.828677 16537 server/config.go:542 [n?] RocksDB cache size: 128 MiB I180523 22:52:04.828767 16537 server/config.go:542 [n?] store 0: in-memory, size 0 B W180523 22:52:04.829457 16537 gossip/gossip.go:1293 [n?] no incoming or outgoing connections I180523 22:52:04.830528 16537 server/server.go:1360 [n?] no stores bootstrapped and --join flag specified, awaiting init command. I180523 22:52:05.025001 17505 gossip/server.go:219 [n1] received initial cluster-verification connection from {tcp 127.0.0.1:34973} I180523 22:52:05.027363 17356 gossip/client.go:129 [n?] started gossip client to 127.0.0.1:43857 I180523 22:52:05.042926 16537 storage/stores.go:222 [n?] read 0 node addresses from persistent storage I180523 22:52:05.043451 16537 storage/stores.go:241 [n?] wrote 2 node addresses to persistent storage I180523 22:52:05.043604 16537 server/node.go:647 [n?] connecting to gossip network to verify cluster ID... I180523 22:52:05.043889 16537 server/node.go:672 [n?] node connected via gossip and verified as part of cluster "1136c89f-fbf2-46b3-8efd-5671ecb805a4" I180523 22:52:05.062260 16537 kv/dist_sender.go:368 [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping I180523 22:52:05.072541 16537 server/node.go:347 [n?] new node allocated ID 3 I180523 22:52:05.073369 16537 gossip/gossip.go:333 [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:34973" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:5 > I180523 22:52:05.079285 16537 server/node.go:421 [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>] I180523 22:52:05.080106 16537 server/node.go:440 [n3] node=3: started with [] engine(s) and attributes [] I180523 22:52:05.083593 16537 server/server.go:1485 [n3] starting https server at 127.0.0.1:44871 I180523 22:52:05.083841 16537 server/server.go:1486 [n3] starting grpc/postgres server at 127.0.0.1:34973 I180523 22:52:05.083977 16537 server/server.go:1487 [n3] advertising CockroachDB node at 127.0.0.1:34973 I180523 22:52:05.096865 16537 server/server.go:1564 [n3] done ensuring all necessary migrations have run I180523 22:52:05.097095 16537 server/server.go:1567 [n3] serving sql connections I180523 22:52:05.107873 17451 storage/stores.go:241 [n1] wrote 2 node addresses to persistent storage I180523 22:52:05.116803 17576 storage/stores.go:241 [n2] wrote 2 node addresses to persistent storage I180523 22:52:05.272192 17531 server/node.go:628 [n3] bootstrapped store [n3,s3] I180523 22:52:05.292549 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 469f3504 at index 71 I180523 22:52:05.299272 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:05.315966 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:05.343841 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:05.426661 17574 sql/event_log.go:126 [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:34973} Attrs: Locality: ServerVersion:2.0-5} ClusterID:1136c89f-fbf2-46b3-8efd-5671ecb805a4 StartedAt:1527115925079664165 LastUp:1527115925079664165} I180523 22:52:05.449899 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:05.475297 17572 server/server_update.go:66 [n3] no need to upgrade, cluster already at the newest version I180523 22:52:05.538945 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:05.594323 16759 storage/replica_proposal.go:202 [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115925.587768433,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:05.631256 16769 storage/replica_proposal.go:202 [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115925.589217671,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:05.676864 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:05.762018 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 54, log entries: 44, rate-limit: 8.0 MiB/sec, 118ms I180523 22:52:05.766371 17694 storage/replica_raftstorage.go:730 [n2,s2,r1/?:{-}] applying preemptive snapshot at index 71 (id=469f3504, encoded size=65436, 1 rocksdb batches, 44 log entries) I180523 22:52:05.781755 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:05.795618 16758 storage/replica_proposal.go:202 [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115925.790620543,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:05.853346 17694 storage/replica_raftstorage.go:736 [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 87ms [clear=0ms batch=0ms entries=81ms commit=5ms] I180523 22:52:05.863390 16712 storage/replica_command.go:1777 [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] I180523 22:52:05.893101 16775 storage/replica_proposal.go:202 [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115925.881751785,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:05.899550 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:05.967069 16785 storage/replica_proposal.go:202 [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115925.958431862,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:05.997516 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:06.052489 16712 storage/replica.go:3320 [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3 I180523 22:52:06.083512 17780 storage/raft_transport.go:459 [n2] raft transport stream to node 1 established I180523 22:52:06.085225 16783 storage/replica_proposal.go:202 [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115926.065749812,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:06.091639 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot 17e8f347 at index 18 I180523 22:52:06.192653 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:06.199991 16584 storage/replica_proposal.go:202 [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115926.195504070,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:06.214770 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 29ms I180523 22:52:06.218678 17599 storage/replica_raftstorage.go:730 [n2,s2,r17/?:{-}] applying preemptive snapshot at index 18 (id=17e8f347, encoded size=2417, 1 rocksdb batches, 8 log entries) I180523 22:52:06.232867 17599 storage/replica_raftstorage.go:736 [n2,s2,r17/?:/Table/2{0-1}] applied preemptive snapshot in 14ms [clear=0ms batch=0ms entries=3ms commit=1ms] I180523 22:52:06.243936 16712 storage/replica_command.go:1777 [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, next=2] I180523 22:52:06.311020 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:06.403037 16744 storage/replica_proposal.go:202 [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115926.397333192,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:06.417556 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:06.460367 16712 storage/replica.go:3320 [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3 I180523 22:52:06.475615 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot ebf54aec at index 22 I180523 22:52:06.496988 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 12, rate-limit: 8.0 MiB/sec, 19ms I180523 22:52:06.502620 17844 storage/replica_raftstorage.go:730 [n2,s2,r2/?:{-}] applying preemptive snapshot at index 22 (id=ebf54aec, encoded size=5333, 1 rocksdb batches, 12 log entries) I180523 22:52:06.507725 17844 storage/replica_raftstorage.go:736 [n2,s2,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=3ms commit=1ms] I180523 22:52:06.534637 16712 storage/replica_command.go:1777 [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] I180523 22:52:06.575095 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:06.606749 16760 storage/replica_proposal.go:202 [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115926.602422939,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:06.699902 16712 storage/replica.go:3320 [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3 I180523 22:52:06.706488 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:06.727597 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot f6671a4e at index 26 I180523 22:52:06.811597 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:06.907048 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 16, rate-limit: 8.0 MiB/sec, 5ms I180523 22:52:06.916184 17805 storage/replica_raftstorage.go:730 [n3,s3,r3/?:{-}] applying preemptive snapshot at index 26 (id=f6671a4e, encoded size=5392, 1 rocksdb batches, 16 log entries) I180523 22:52:06.921377 17805 storage/replica_raftstorage.go:736 [n3,s3,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=3ms commit=1ms] I180523 22:52:06.927999 16712 storage/replica_command.go:1777 [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] I180523 22:52:06.940545 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:07.038976 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:07.059880 16712 storage/replica.go:3320 [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3 I180523 22:52:07.091717 16745 storage/replica_proposal.go:202 [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115927.069508643,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:07.100114 16568 server/status/runtime.go:219 [n1] runtime stats: 1.4 GiB RSS, 550 goroutines, 43 MiB/90 MiB/161 MiB GO alloc/idle/total, 80 MiB/112 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (86x) I180523 22:52:07.112275 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 71bfe4f2 at index 44 I180523 22:52:07.137004 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:07.142052 17892 storage/raft_transport.go:459 [n3] raft transport stream to node 1 established I180523 22:52:07.149145 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 37, log entries: 34, rate-limit: 8.0 MiB/sec, 35ms I180523 22:52:07.175554 17837 storage/replica_raftstorage.go:730 [n3,s3,r4/?:{-}] applying preemptive snapshot at index 44 (id=71bfe4f2, encoded size=114425, 1 rocksdb batches, 34 log entries) I180523 22:52:07.205345 17837 storage/replica_raftstorage.go:736 [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 29ms [clear=0ms batch=0ms entries=26ms commit=1ms] I180523 22:52:07.210619 16712 storage/replica_command.go:1777 [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, next=2] I180523 22:52:07.243696 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:07.260189 16712 storage/replica.go:3320 [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3 I180523 22:52:07.280592 16768 storage/replica_proposal.go:202 [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115927.271914494,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:07.298609 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot 2c94f223 at index 18 I180523 22:52:07.318349 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 8ms I180523 22:52:07.322159 17791 storage/replica_raftstorage.go:730 [n3,s3,r12/?:{-}] applying preemptive snapshot at index 18 (id=2c94f223, encoded size=2417, 1 rocksdb batches, 8 log entries) I180523 22:52:07.343562 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:07.348368 17791 storage/replica_raftstorage.go:736 [n3,s3,r12/?:/Table/1{5-6}] applied preemptive snapshot in 21ms [clear=0ms batch=0ms entries=2ms commit=9ms] I180523 22:52:07.353270 16712 storage/replica_command.go:1777 [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] I180523 22:52:07.431055 16712 storage/replica.go:3320 [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3 I180523 22:52:07.447638 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot ba81d197 at index 18 I180523 22:52:07.453832 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 5ms I180523 22:52:07.472308 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:07.499578 17841 storage/replica_raftstorage.go:730 [n3,s3,r14/?:{-}] applying preemptive snapshot at index 18 (id=ba81d197, encoded size=2586, 1 rocksdb batches, 8 log entries) I180523 22:52:07.507415 17841 storage/replica_raftstorage.go:736 [n3,s3,r14/?:/Table/1{7-8}] applied preemptive snapshot in 7ms [clear=0ms batch=0ms entries=1ms commit=1ms] I180523 22:52:07.529615 16712 storage/replica_command.go:1777 [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, next=2] I180523 22:52:07.589692 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:07.701880 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges W180523 22:52:07.739875 16570 server/node.go:802 [n1,summaries] health alerts detected: {Alerts:[{StoreID:1 Category:METRICS Description:queue.replicate.process.failure Value:311} {StoreID:1 Category:METRICS Description:ranges.underreplicated Value:22}]} I180523 22:52:07.740099 16712 storage/replica.go:3320 [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3 I180523 22:52:07.765936 16583 storage/replica_proposal.go:202 [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115927.752038103,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:07.788654 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot deaed0ee at index 32 I180523 22:52:07.812108 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 53, log entries: 22, rate-limit: 8.0 MiB/sec, 22ms I180523 22:52:07.817991 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:07.818352 17865 storage/replica_raftstorage.go:730 [n2,s2,r9/?:{-}] applying preemptive snapshot at index 32 (id=deaed0ee, encoded size=17250, 1 rocksdb batches, 22 log entries) I180523 22:52:07.829506 17865 storage/replica_raftstorage.go:736 [n2,s2,r9/?:/Table/1{2-3}] applied preemptive snapshot in 11ms [clear=0ms batch=0ms entries=8ms commit=1ms] I180523 22:52:07.834600 16712 storage/replica_command.go:1777 [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] I180523 22:52:07.895343 16712 storage/replica.go:3320 [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3 I180523 22:52:07.952700 16763 storage/replica_proposal.go:202 [n1,s1,r20/1:/Table/{23-50}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115927.930872335,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:07.960748 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r20/1:/Table/{23-50}] generated preemptive snapshot 40e9fcbb at index 18 I180523 22:52:07.965079 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:07.982722 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r20/1:/Table/{23-50}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 8, rate-limit: 8.0 MiB/sec, 21ms I180523 22:52:07.985975 17970 storage/replica_raftstorage.go:730 [n2,s2,r20/?:{-}] applying preemptive snapshot at index 18 (id=40e9fcbb, encoded size=2549, 1 rocksdb batches, 8 log entries) I180523 22:52:07.989617 17970 storage/replica_raftstorage.go:736 [n2,s2,r20/?:/Table/{23-50}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=1ms] I180523 22:52:07.994571 16712 storage/replica_command.go:1777 [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] I180523 22:52:08.066178 16772 storage/replica_proposal.go:202 [n1,s1,r22/1:/{Table/51-Max}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115928.020922585,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:08.088016 16784 storage/replica_proposal.go:202 [n1,s1,r21/1:/Table/5{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115928.083716907,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:08.114947 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:08.143367 16712 storage/replica.go:3320 [n1,s1,r20/1:/Table/{23-50}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3 I180523 22:52:08.171573 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot 3d174b23 at index 18 I180523 22:52:08.178556 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 6ms I180523 22:52:08.197166 17936 storage/replica_raftstorage.go:730 [n3,s3,r15/?:{-}] applying preemptive snapshot at index 18 (id=3d174b23, encoded size=2586, 1 rocksdb batches, 8 log entries) I180523 22:52:08.200972 17936 storage/replica_raftstorage.go:736 [n3,s3,r15/?:/Table/1{8-9}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=1ms] I180523 22:52:08.207969 16712 storage/replica_command.go:1777 [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, next=2] I180523 22:52:08.259445 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:08.367645 16712 storage/replica.go:3320 [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3 I180523 22:52:08.399998 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot 60612174 at index 18 I180523 22:52:08.425491 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 24ms I180523 22:52:08.431653 17958 storage/replica_raftstorage.go:730 [n3,s3,r19/?:{-}] applying preemptive snapshot at index 18 (id=60612174, encoded size=2417, 1 rocksdb batches, 8 log entries) I180523 22:52:08.448400 17958 storage/replica_raftstorage.go:736 [n3,s3,r19/?:/Table/2{2-3}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=2ms commit=1ms] I180523 22:52:08.459907 16712 storage/replica_command.go:1777 [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] I180523 22:52:08.509095 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:08.572113 16712 storage/replica.go:3320 [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3 I180523 22:52:08.586529 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot fc2cbf66 at index 30 I180523 22:52:08.598446 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 57, log entries: 20, rate-limit: 8.0 MiB/sec, 5ms I180523 22:52:08.622748 17974 storage/replica_raftstorage.go:730 [n2,s2,r7/?:{-}] applying preemptive snapshot at index 30 (id=fc2cbf66, encoded size=14743, 1 rocksdb batches, 20 log entries) I180523 22:52:08.625406 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:08.657661 17974 storage/replica_raftstorage.go:736 [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 34ms [clear=0ms batch=6ms entries=20ms commit=7ms] I180523 22:52:08.666909 16712 storage/replica_command.go:1777 [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] I180523 22:52:08.740088 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:08.743736 16712 storage/replica.go:3320 [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3 I180523 22:52:08.769003 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot e8b4eb5b at index 18 I180523 22:52:08.803542 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 18ms I180523 22:52:08.807758 18034 storage/replica_raftstorage.go:730 [n2,s2,r16/?:{-}] applying preemptive snapshot at index 18 (id=e8b4eb5b, encoded size=2421, 1 rocksdb batches, 8 log entries) I180523 22:52:08.812311 18034 storage/replica_raftstorage.go:736 [n2,s2,r16/?:/Table/{19-20}] applied preemptive snapshot in 4ms [clear=1ms batch=0ms entries=1ms commit=1ms] I180523 22:52:08.827884 16712 storage/replica_command.go:1777 [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] I180523 22:52:08.864441 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:08.932473 16712 storage/replica.go:3320 [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3 I180523 22:52:08.953973 16743 storage/replica_proposal.go:202 [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115928.941552597,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:08.977855 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:08.984189 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot 49fa318f at index 18 I180523 22:52:09.016663 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 31ms I180523 22:52:09.055233 17947 storage/replica_raftstorage.go:730 [n3,s3,r18/?:{-}] applying preemptive snapshot at index 18 (id=49fa318f, encoded size=2417, 1 rocksdb batches, 8 log entries) I180523 22:52:09.059287 17947 storage/replica_raftstorage.go:736 [n3,s3,r18/?:/Table/2{1-2}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=2ms commit=1ms] I180523 22:52:09.066395 16712 storage/replica_command.go:1777 [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] I180523 22:52:09.092595 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:09.185626 16712 storage/replica.go:3320 [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3 I180523 22:52:09.189851 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:09.194701 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 86a3c62c at index 25 I180523 22:52:09.306538 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:09.341952 18039 storage/replica_raftstorage.go:730 [n2,s2,r5/?:{-}] applying preemptive snapshot at index 25 (id=86a3c62c, encoded size=190644, 1 rocksdb batches, 4 log entries) I180523 22:52:09.350163 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 966, log entries: 4, rate-limit: 8.0 MiB/sec, 145ms I180523 22:52:09.397581 18039 storage/replica_raftstorage.go:736 [n2,s2,r5/?:/System/ts{d-e}] applied preemptive snapshot in 55ms [clear=0ms batch=1ms entries=30ms commit=22ms] I180523 22:52:09.403792 16712 storage/replica_command.go:1777 [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, next=2] I180523 22:52:09.414865 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:09.502460 16712 storage/replica.go:3320 [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3 I180523 22:52:09.543578 16777 storage/replica_proposal.go:202 [n1,s1,r6/1:/{System/tse-Table/System…}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115929.539252815,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:09.553886 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot d68cb336 at index 22 I180523 22:52:09.566429 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:09.569333 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 12, rate-limit: 8.0 MiB/sec, 7ms I180523 22:52:09.572786 17949 storage/replica_raftstorage.go:730 [n3,s3,r6/?:{-}] applying preemptive snapshot at index 22 (id=d68cb336, encoded size=5224, 1 rocksdb batches, 12 log entries) I180523 22:52:09.616217 17949 storage/replica_raftstorage.go:736 [n3,s3,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 36ms [clear=7ms batch=0ms entries=15ms commit=13ms] I180523 22:52:09.621265 16712 storage/replica_command.go:1777 [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] I180523 22:52:09.673765 16712 storage/replica.go:3320 [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3 I180523 22:52:09.684092 16591 storage/replica_proposal.go:202 [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115929.679322345,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:09.698592 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:09.701222 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot a655dbaf at index 18 I180523 22:52:09.725029 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 23ms I180523 22:52:09.733674 17995 storage/replica_raftstorage.go:730 [n3,s3,r11/?:{-}] applying preemptive snapshot at index 18 (id=a655dbaf, encoded size=2417, 1 rocksdb batches, 8 log entries) I180523 22:52:09.774581 17995 storage/replica_raftstorage.go:736 [n3,s3,r11/?:/Table/1{4-5}] applied preemptive snapshot in 40ms [clear=0ms batch=0ms entries=3ms commit=18ms] I180523 22:52:09.779891 16712 storage/replica_command.go:1777 [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] I180523 22:52:09.809936 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:09.860750 16712 storage/replica.go:3320 [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3 I180523 22:52:09.877839 16769 storage/replica_proposal.go:202 [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1527115916.991477413,0 epo=1 pro=1527115929.868070740,0 following repl=(n1,s1):1 seq=2 start=1527115916.991477413,0 exp=1527115926.023474078,0 pro=1527115917.023544471,0 I180523 22:52:09.900075 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot 8ee6e2d4 at index 19 I180523 22:52:09.910802 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 7ms I180523 22:52:09.914769 18013 storage/replica_raftstorage.go:730 [n3,s3,r8/?:{-}] applying preemptive snapshot at index 19 (id=8ee6e2d4, encoded size=3649, 1 rocksdb batches, 9 log entries) I180523 22:52:09.919278 18013 storage/replica_raftstorage.go:736 [n3,s3,r8/?:/Table/1{1-2}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=2ms commit=1ms] I180523 22:52:09.939977 16712 storage/replica_command.go:1777 [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] I180523 22:52:09.943552 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:10.024748 16712 storage/replica.go:3320 [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3 I180523 22:52:10.043962 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r22/1:/{Table/51-Max}] generated preemptive snapshot 29d13abe at index 14 I180523 22:52:10.057118 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r22/1:/{Table/51-Max}] streamed snapshot to (n2,s2):?: kv pairs: 7, log entries: 4, rate-limit: 8.0 MiB/sec, 12ms I180523 22:52:10.075798 18115 storage/replica_raftstorage.go:730 [n2,s2,r22/?:{-}] applying preemptive snapshot at index 14 (id=29d13abe, encoded size=772, 1 rocksdb batches, 4 log entries) I180523 22:52:10.103471 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:10.109491 18115 storage/replica_raftstorage.go:736 [n2,s2,r22/?:/{Table/51-Max}] applied preemptive snapshot in 33ms [clear=0ms batch=0ms entries=1ms commit=1ms] I180523 22:52:10.125905 16712 storage/replica_command.go:1777 [replicate,n1,s1,r22/1:/{Table/51-Max}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r22:/{Table/51-Max} [(n1,s1):1, next=2] I180523 22:52:10.228288 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:10.246780 16712 storage/replica.go:3320 [n1,s1,r22/1:/{Table/51-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3 I180523 22:52:10.255674 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot eff5e2e7 at index 18 I180523 22:52:10.281940 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 25ms I180523 22:52:10.294013 18087 storage/replica_raftstorage.go:730 [n2,s2,r13/?:{-}] applying preemptive snapshot at index 18 (id=eff5e2e7, encoded size=2582, 1 rocksdb batches, 8 log entries) I180523 22:52:10.297984 18087 storage/replica_raftstorage.go:736 [n2,s2,r13/?:/Table/1{6-7}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=2ms commit=1ms] I180523 22:52:10.322218 16712 storage/replica_command.go:1777 [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] I180523 22:52:10.338830 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:10.445428 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:10.448846 16712 storage/replica.go:3320 [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3 I180523 22:52:10.506552 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot 55e67306 at index 80 I180523 22:52:10.519632 16712 storage/store_snapshot.go:605 [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 239, log entries: 70, rate-limit: 8.0 MiB/sec, 10ms I180523 22:52:10.524744 17998 storage/replica_raftstorage.go:730 [n2,s2,r10/?:{-}] applying preemptive snapshot at index 80 (id=55e67306, encoded size=72740, 1 rocksdb batches, 70 log entries) I180523 22:52:10.554321 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:10.607607 17998 storage/replica_raftstorage.go:736 [n2,s2,r10/?:/Table/1{3-4}] applied preemptive snapshot in 82ms [clear=0ms batch=0ms entries=70ms commit=10ms] I180523 22:52:10.613273 16712 storage/replica_command.go:1777 [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, next=2] I180523 22:52:10.653049 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:10.767490 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:10.799900 16712 storage/replica.go:3320 [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3 I180523 22:52:10.820776 16712 storage/replica_raftstorage.go:520 [replicate,n1,s1,r21/1:/Table/5{0-1}] generated preemptive snapshot 513b56d8 at index 18 I180523 22:52:10.845066 16712 storage/store_snapshot.go:605 [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, 16ms I180523 22:52:10.848742 18062 storage/replica_raftstorage.go:730 [n3,s3,r21/?:{-}] applying preemptive snapshot at index 18 (id=513b56d8, encoded size=2390, 1 rocksdb batches, 8 log entries) I180523 22:52:10.852560 18062 storage/replica_raftstorage.go:736 [n3,s3,r21/?:/Table/5{0-1}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=1ms] I180523 22:52:10.857673 16712 storage/replica_command.go:1777 [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] I180523 22:52:10.893109 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:10.968390 16712 storage/replica.go:3320 [n1,s1,r21/1:/Table/5{0-1}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3 I180523 22:52:10.974797 16712 storage/queue.go:864 [n1,replicate] purgatory is now empty I180523 22:52:11.010646 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:11.026249 18130 storage/replica_raftstorage.go:520 [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot f1f6119f at index 119 I180523 22:52:11.046833 18130 storage/store_snapshot.go:605 [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n3,s3):?: kv pairs: 78, log entries: 41, rate-limit: 8.0 MiB/sec, 19ms I180523 22:52:11.076910 18108 storage/replica_raftstorage.go:730 [n3,s3,r1/?:{-}] applying preemptive snapshot at index 119 (id=f1f6119f, encoded size=9751, 1 rocksdb batches, 41 log entries) I180523 22:52:11.118146 18108 storage/replica_raftstorage.go:736 [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 27ms [clear=0ms batch=0ms entries=19ms commit=6ms] I180523 22:52:11.134416 18130 storage/replica_command.go:1777 [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] I180523 22:52:11.137022 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 22 underreplicated ranges I180523 22:52:11.218328 18147 storage/replica.go:3320 [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4 I180523 22:52:11.253968 18149 storage/replica_raftstorage.go:520 [replicate,n1,s1,r21/1:/Table/5{0-1}] generated preemptive snapshot 1b3a88ab at index 21 I180523 22:52:11.257453 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 21 underreplicated ranges I180523 22:52:11.266743 18149 storage/store_snapshot.go:605 [replicate,n1,s1,r21/1:/Table/5{0-1}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 11ms I180523 22:52:11.271190 18072 storage/replica_raftstorage.go:730 [n2,s2,r21/?:{-}] applying preemptive snapshot at index 21 (id=1b3a88ab, encoded size=3418, 1 rocksdb batches, 11 log entries) I180523 22:52:11.275695 18072 storage/replica_raftstorage.go:736 [n2,s2,r21/?:/Table/5{0-1}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=2ms commit=1ms] I180523 22:52:11.291977 18149 storage/replica_command.go:1777 [replicate,n1,s1,r21/1:/Table/5{0-1}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r21:/Table/5{0-1} [(n1,s1):1, (n3,s3):2, next=3] I180523 22:52:11.367467 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 21 underreplicated ranges I180523 22:52:11.385077 18149 storage/replica.go:3320 [n1,s1,r21/1:/Table/5{0-1}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4 I180523 22:52:11.420851 18162 storage/replica_raftstorage.go:520 [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot ccbf22d1 at index 21 I180523 22:52:11.472565 18162 storage/store_snapshot.go:605 [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 48ms I180523 22:52:11.472859 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 20 underreplicated ranges I180523 22:52:11.477216 18164 storage/replica_raftstorage.go:730 [n3,s3,r17/?:{-}] applying preemptive snapshot at index 21 (id=ccbf22d1, encoded size=3445, 1 rocksdb batches, 11 log entries) I180523 22:52:11.488467 18164 storage/replica_raftstorage.go:736 [n3,s3,r17/?:/Table/2{0-1}] applied preemptive snapshot in 11ms [clear=4ms batch=0ms entries=2ms commit=1ms] I180523 22:52:11.494349 18162 storage/replica_command.go:1777 [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, (n2,s2):2, next=3] I180523 22:52:11.592357 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 20 underreplicated ranges I180523 22:52:11.631123 18162 storage/replica.go:3320 [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4 I180523 22:52:11.681407 18137 storage/replica_raftstorage.go:520 [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 46e90ebd at index 32 I180523 22:52:11.694178 18137 storage/store_snapshot.go:605 [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 17, log entries: 22, rate-limit: 8.0 MiB/sec, 9ms I180523 22:52:11.698715 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 19 underreplicated ranges I180523 22:52:11.716087 18153 storage/replica_raftstorage.go:730 [n2,s2,r3/?:{-}] applying preemptive snapshot at index 32 (id=46e90ebd, encoded size=7121, 1 rocksdb batches, 22 log entries) I180523 22:52:11.728504 18153 storage/replica_raftstorage.go:736 [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 12ms [clear=0ms batch=0ms entries=10ms commit=1ms] I180523 22:52:11.733961 18137 storage/replica_command.go:1777 [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] I180523 22:52:11.817317 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 19 underreplicated ranges I180523 22:52:11.857772 18137 storage/replica.go:3320 [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 I180523 22:52:11.938768 18178 storage/replica_raftstorage.go:520 [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 33907bc4 at index 35 I180523 22:52:11.968601 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 18 underreplicated ranges I180523 22:52:11.970772 18178 storage/store_snapshot.go:605 [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 54, log entries: 25, rate-limit: 8.0 MiB/sec, 30ms I180523 22:52:11.981145 18194 storage/replica_raftstorage.go:730 [n3,s3,r9/?:{-}] applying preemptive snapshot at index 35 (id=33907bc4, encoded size=18278, 1 rocksdb batches, 25 log entries) I180523 22:52:11.990246 18194 storage/replica_raftstorage.go:736 [n3,s3,r9/?:/Table/1{2-3}] applied preemptive snapshot in 9ms [clear=0ms batch=0ms entries=6ms commit=1ms] I180523 22:52:11.995620 18178 storage/replica_command.go:1777 [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, (n2,s2):2, next=3] I180523 22:52:12.071127 16537 testutils/testcluster/testcluster.go:536 [n1,s1] has 18 underreplicated ranges I180523 22:52:12.125068 18178 storage/replica.go:3320 [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4 I180523 22:52:12.149445 18095 storage/replica_raftstorage.go:520 [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 6fda0e40 at index 25 I180523 22:52:12.155623 18095 storage/store_snapshot.go:605 [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 15, rate-limit: 8.0 MiB/sec, 5ms I180523 22:52:12.159965 18143 storage/replica_raftstorage.go:730 [n2,s2,r6/?:{-}] applying preemptive snapshot at index 25 (id=6fda0e40, encoded size=6291, 1 rocksdb batches, 15 log entries) I180523 22:52:12.165412 18143 storage/replica_raf
Please assign, take a look and update the issue accordingly.
andreimatei
commented
6 years ago andreimatei
commented
6 years ago
The following tests appear to have failed:
#676177:
Please assign, take a look and update the issue accordingly.