Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

teamcity: failed tests on master: testrace/TestBackupRestoreControlJob, test/TestBackupRestoreControlJob #24614

Closed
cockroach-teamcity opened this issue Apr 9, 2018 · 1 comment
Closed

teamcity: failed tests on master: testrace/TestBackupRestoreControlJob, test/TestBackupRestoreControlJob #24614

cockroach-teamcity opened this issue Apr 9, 2018 · 1 comment
Assignees
@dt
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone
2.1

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed:

#594739:

--- FAIL: testrace/TestBackupRestoreControlJob (178.790s)

------- Stdout: -------
W180409 20:21:27.598371 48722 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180409 20:21:27.774180 48722 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180409 20:21:27.806722 48722 server/config.go:538  [n?] 1 storage engine initialized
I180409 20:21:27.806926 48722 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180409 20:21:27.806994 48722 server/config.go:541  [n?] store 0: in-memory, size 0 B
I180409 20:21:27.941592 48722 server/node.go:374  [n?] **** cluster 741eb73d-daa0-4f5f-be6c-39921aff7551 has been created
I180409 20:21:27.941811 48722 server/server.go:1305  [n?] **** add additional nodes by specifying --join=127.0.0.1:41233
I180409 20:21:27.978784 48722 storage/store.go:1399  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180409 20:21:27.980696 48722 server/node.go:512  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=4.9 KiB), ranges=1, leases=0, writes=0.00, bytesPerReplica={p10=5043.00 p25=5043.00 p50=5043.00 p75=5043.00 p90=5043.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00}
I180409 20:21:27.981177 48722 server/node.go:352  [n1] node ID 1 initialized
I180409 20:21:27.981593 48722 gossip/gossip.go:332  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:41233" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180409 20:21:27.983107 48722 storage/stores.go:309  [n1] read 0 node addresses from persistent storage
I180409 20:21:27.983769 48722 server/node.go:653  [n1] connecting to gossip network to verify cluster ID...
I180409 20:21:27.993970 48722 server/node.go:678  [n1] node connected via gossip and verified as part of cluster "741eb73d-daa0-4f5f-be6c-39921aff7551"
I180409 20:21:27.999089 48722 server/node.go:446  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180409 20:21:28.018277 48722 server/server.go:1431  [n1] starting https server at 127.0.0.1:33751
I180409 20:21:28.020872 48722 server/server.go:1432  [n1] starting grpc/postgres server at 127.0.0.1:41233
I180409 20:21:28.020998 48722 server/server.go:1433  [n1] advertising CockroachDB node at 127.0.0.1:41233
W180409 20:21:28.030786 48722 sql/jobs/registry.go:286  [n1] unable to get node liveness: node not in the liveness table
I180409 20:21:28.142841 48801 storage/replica_command.go:862  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180409 20:21:28.655852 48962 storage/replica_command.go:862  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180409 20:21:28.719357 48893 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=4989b7b5 key=/Table/SystemConfigSpan/Start rw=true pri=0.02995236 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523305288.194873406,0 orig=1523305288.194873406,0 max=1523305288.194873406,0 wto=false rop=false seq=7
I180409 20:21:28.784120 48722 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}
I180409 20:21:29.033922 48876 storage/replica_command.go:862  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180409 20:21:29.312720 48980 storage/replica_command.go:862  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180409 20:21:29.454022 48641 storage/replica_command.go:862  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180409 20:21:29.538625 48722 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:node}
I180409 20:21:29.680787 48969 storage/replica_command.go:862  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
W180409 20:21:29.696482 48953 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=a0527ee7 key=/Table/SystemConfigSpan/Start rw=true pri=0.00911630 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523305289.564658786,0 orig=1523305289.564658786,0 max=1523305289.564658786,0 wto=false rop=false seq=7
I180409 20:21:29.808362 48722 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}
I180409 20:21:29.891798 48981 storage/replica_command.go:862  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
W180409 20:21:30.019063 48973 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=13865d1c key=/Local/Range/Table/SystemConfigSpan/Start/RangeDescriptor rw=true pri=0.01815567 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523305289.892048587,0 orig=1523305289.892048587,0 max=1523305289.892048587,0 wto=false rop=false seq=2
I180409 20:21:30.035892 48985 storage/replica_command.go:862  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180409 20:21:30.176773 48991 storage/replica_command.go:862  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180409 20:21:30.434720 48960 storage/replica_command.go:862  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180409 20:21:30.580848 49097 storage/replica_command.go:862  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180409 20:21:30.677741 48722 sql/event_log.go:121  [n1] Event: "alter_table", target: 4, info: {TableName:system.public.users Statement:ALTER TABLE system.public.users ADD COLUMN IF NOT EXISTS "isRole" BOOL NOT NULL DEFAULT false User:node MutationID:1 CascadeDroppedViews:[]}
I180409 20:21:30.710465 49019 storage/replica_command.go:862  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180409 20:21:30.851027 48722 sql/lease.go:352  [n1] publish: descID=4 (users) version=2 mtime=2018-04-09 20:21:30.848817255 +0000 UTC
I180409 20:21:30.856451 49158 storage/replica_command.go:862  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180409 20:21:30.984783 49037 storage/replica_command.go:862  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180409 20:21:31.083885 48722 sql/lease.go:352  [n1] publish: descID=4 (users) version=3 mtime=2018-04-09 20:21:31.077411199 +0000 UTC
I180409 20:21:31.236373 49186 storage/replica_command.go:862  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180409 20:21:31.341449 49169 storage/replica_command.go:862  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180409 20:21:31.351380 48722 sql/backfill.go:134  [n1] Running backfill for "users", v=3, m=1
I180409 20:21:31.593746 49179 storage/replica_command.go:862  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180409 20:21:31.707813 49135 storage/replica_command.go:862  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
W180409 20:21:31.826701 49212 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=0343b366 key=/Local/Range/Table/21/RangeDescriptor rw=true pri=0.05264911 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523305291.708086650,0 orig=1523305291.708086650,0 max=1523305291.708086650,0 wto=false rop=false seq=3
I180409 20:21:31.867051 49195 storage/replica_command.go:862  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180409 20:21:32.021967 48722 sql/lease.go:352  [n1] publish: descID=4 (users) version=4 mtime=2018-04-09 20:21:32.020194111 +0000 UTC
I180409 20:21:32.218013 48722 sql/lease.go:352  [n1] publish: descID=4 (users) version=4 mtime=2018-04-09 20:21:32.030126696 +0000 UTC
I180409 20:21:32.416362 48722 sql/event_log.go:121  [n1] Event: "finish_schema_change", target: 4, info: {MutationID:1}
I180409 20:21:32.451532 48722 sql/lease.go:275  publish (count leases): descID=4 name=users version=3 count=1
I180409 20:21:32.507528 48722 sql/lease.go:275  publish (count leases): descID=4 name=users version=3 count=1
I180409 20:21:32.508684 49217 sql/lease.go:812  new lease: 4("users") ver=4:1523305621.733037334,0, refcount=0
I180409 20:21:33.120566 48722 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:node}
I180409 20:21:33.231103 48722 server/server.go:1511  [n1] done ensuring all necessary migrations have run
I180409 20:21:33.231372 48722 server/server.go:1514  [n1] serving sql connections
I180409 20:21:33.320115 49331 sql/event_log.go:121  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:41233} Attrs: Locality: ServerVersion:2.0-3} ClusterID:741eb73d-daa0-4f5f-be6c-39921aff7551 StartedAt:1523305287994234737 LastUp:1523305287994234737}
W180409 20:21:33.444390 48722 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180409 20:21:33.491077 48722 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180409 20:21:33.558748 48722 server/config.go:538  [n?] 1 storage engine initialized
I180409 20:21:33.559072 48722 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180409 20:21:33.559290 48722 server/config.go:541  [n?] store 0: in-memory, size 0 B
W180409 20:21:33.559882 48722 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180409 20:21:33.571434 48722 server/server.go:1307  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180409 20:21:33.807771 49288 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:41233
I180409 20:21:33.811741 49383 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:39753}
I180409 20:21:33.835738 48722 storage/stores.go:309  [n?] read 0 node addresses from persistent storage
I180409 20:21:33.836288 48722 storage/stores.go:328  [n?] wrote 1 node addresses to persistent storage
I180409 20:21:33.836391 48722 server/node.go:653  [n?] connecting to gossip network to verify cluster ID...
I180409 20:21:33.836713 48722 server/node.go:678  [n?] node connected via gossip and verified as part of cluster "741eb73d-daa0-4f5f-be6c-39921aff7551"
I180409 20:21:33.887705 48722 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180409 20:21:33.915363 48722 server/node.go:345  [n?] new node allocated ID 2
I180409 20:21:33.916262 48722 gossip/gossip.go:332  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:39753" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180409 20:21:33.917311 48722 server/node.go:427  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180409 20:21:33.923499 48722 server/node.go:446  [n2] node=2: started with [] engine(s) and attributes []
I180409 20:21:33.921610 49399 storage/stores.go:328  [n1] wrote 1 node addresses to persistent storage
I180409 20:21:33.946938 48722 server/server.go:1431  [n2] starting https server at 127.0.0.1:38803
I180409 20:21:33.949669 48722 server/server.go:1432  [n2] starting grpc/postgres server at 127.0.0.1:39753
I180409 20:21:33.949785 48722 server/server.go:1433  [n2] advertising CockroachDB node at 127.0.0.1:39753
W180409 20:21:33.979064 48722 sql/jobs/registry.go:286  [n2] unable to get node liveness: node not in the liveness table
I180409 20:21:33.991808 48722 server/server.go:1511  [n2] done ensuring all necessary migrations have run
I180409 20:21:33.992062 48722 server/server.go:1514  [n2] serving sql connections
I180409 20:21:34.108629 49302 server/node.go:634  [n2] bootstrapped store [n2,s2]
I180409 20:21:34.148900 49522 sql/event_log.go:121  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:39753} Attrs: Locality: ServerVersion:2.0-3} ClusterID:741eb73d-daa0-4f5f-be6c-39921aff7551 StartedAt:1523305293923110120 LastUp:1523305293923110120}
W180409 20:21:34.380698 48722 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180409 20:21:34.546672 48722 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180409 20:21:34.556952 48722 server/config.go:538  [n?] 1 storage engine initialized
I180409 20:21:34.557180 48722 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180409 20:21:34.557241 48722 server/config.go:541  [n?] store 0: in-memory, size 0 B
W180409 20:21:34.557716 48722 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180409 20:21:34.558487 48722 server/server.go:1307  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180409 20:21:34.783521 49393 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:41233
I180409 20:21:34.789440 49620 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:34275}
I180409 20:21:34.805393 48722 storage/stores.go:309  [n?] read 0 node addresses from persistent storage
I180409 20:21:34.805779 48722 server/node.go:653  [n?] connecting to gossip network to verify cluster ID...
I180409 20:21:34.806006 48722 server/node.go:678  [n?] node connected via gossip and verified as part of cluster "741eb73d-daa0-4f5f-be6c-39921aff7551"
I180409 20:21:34.826452 49630 storage/stores.go:328  [n?] wrote 1 node addresses to persistent storage
I180409 20:21:34.832687 48722 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180409 20:21:34.836118 49630 storage/stores.go:328  [n?] wrote 2 node addresses to persistent storage
I180409 20:21:34.850321 48722 server/node.go:345  [n?] new node allocated ID 3
I180409 20:21:34.851240 48722 gossip/gossip.go:332  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:34275" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180409 20:21:34.853680 48722 server/node.go:427  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180409 20:21:34.860300 48722 server/node.go:446  [n3] node=3: started with [] engine(s) and attributes []
I180409 20:21:34.863980 48722 server/server.go:1431  [n3] starting https server at 127.0.0.1:44439
I180409 20:21:34.864206 48722 server/server.go:1432  [n3] starting grpc/postgres server at 127.0.0.1:34275
I180409 20:21:34.864390 48722 server/server.go:1433  [n3] advertising CockroachDB node at 127.0.0.1:34275
I180409 20:21:34.876259 49532 storage/stores.go:328  [n1] wrote 2 node addresses to persistent storage
I180409 20:21:34.899706 49670 storage/stores.go:328  [n2] wrote 2 node addresses to persistent storage
I180409 20:21:34.940432 48722 server/server.go:1511  [n3] done ensuring all necessary migrations have run
I180409 20:21:34.940704 48722 server/server.go:1514  [n3] serving sql connections
I180409 20:21:35.003037 49644 server/node.go:634  [n3] bootstrapped store [n3,s3]
I180409 20:21:35.062318 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot 997504ea at index 23
I180409 20:21:35.235603 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:35.253401 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:35.283523 49615 sql/event_log.go:121  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:34275} Attrs: Locality: ServerVersion:2.0-3} ClusterID:741eb73d-daa0-4f5f-be6c-39921aff7551 StartedAt:1523305294859905303 LastUp:1523305294859905303}
I180409 20:21:35.291451 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:35.336968 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:35.417373 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:35.444003 48942 storage/store.go:3834  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 13, rate-limit: 8.0 MiB/sec, 6ms
I180409 20:21:35.447273 49843 storage/replica_raftstorage.go:726  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 23 (id=997504ea, encoded size=5521, 1 rocksdb batches, 13 log entries)
I180409 20:21:35.451914 49843 storage/replica_raftstorage.go:732  [n2,s2,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=3ms commit=1ms]
I180409 20:21:35.459465 48942 storage/replica_command.go:1779  [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]
I180409 20:21:35.515903 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:35.582762 48942 storage/replica.go:3340  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:35.620181 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot 2aa27b15 at index 51
I180409 20:21:35.652428 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:35.685347 48942 storage/store.go:3834  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 77, log entries: 41, rate-limit: 8.0 MiB/sec, 64ms
I180409 20:21:35.685959 49862 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180409 20:21:35.728118 49840 storage/replica_raftstorage.go:726  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 51 (id=2aa27b15, encoded size=43228, 1 rocksdb batches, 41 log entries)
I180409 20:21:35.754275 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:35.830217 49840 storage/replica_raftstorage.go:732  [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 102ms [clear=0ms batch=0ms entries=60ms commit=41ms]
I180409 20:21:35.843478 48942 storage/replica_command.go:1779  [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]
I180409 20:21:35.855423 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:35.926244 48942 storage/replica.go:3340  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:35.975638 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot 90324c95 at index 15
I180409 20:21:35.976691 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:35.987653 48942 storage/store.go:3834  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 5, rate-limit: 8.0 MiB/sec, 11ms
I180409 20:21:35.990690 49789 storage/replica_raftstorage.go:726  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 15 (id=90324c95, encoded size=2057, 1 rocksdb batches, 5 log entries)
I180409 20:21:35.993602 49789 storage/replica_raftstorage.go:732  [n2,s2,r18/?:/Table/2{1-2}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180409 20:21:36.001910 48942 storage/replica_command.go:1779  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, next=2]
I180409 20:21:36.056355 48942 storage/replica.go:3340  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:36.064028 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot 686af185 at index 15
I180409 20:21:36.083704 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:36.204388 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:36.307091 48942 storage/store.go:3834  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 5, rate-limit: 8.0 MiB/sec, 40ms
I180409 20:21:36.317025 49808 storage/replica_raftstorage.go:726  [n3,s3,r19/?:{-}] applying preemptive snapshot at index 15 (id=686af185, encoded size=2057, 1 rocksdb batches, 5 log entries)
I180409 20:21:36.323276 49808 storage/replica_raftstorage.go:732  [n3,s3,r19/?:/Table/2{2-3}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=1ms commit=1ms]
I180409 20:21:36.325613 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:36.328022 48942 storage/replica_command.go:1779  [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]
I180409 20:21:36.416852 48942 storage/replica.go:3340  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 20:21:36.434037 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:36.451982 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot 9a59c97a at index 17
I180409 20:21:36.472110 48942 storage/store.go:3834  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 7, rate-limit: 8.0 MiB/sec, 6ms
I180409 20:21:36.474880 49897 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180409 20:21:36.476681 49921 storage/replica_raftstorage.go:726  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 17 (id=9a59c97a, encoded size=2357, 1 rocksdb batches, 7 log entries)
I180409 20:21:36.503178 48868 storage/replica_proposal.go:202  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305296.486190650,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:36.503728 49921 storage/replica_raftstorage.go:732  [n2,s2,r15/?:/Table/1{8-9}] applied preemptive snapshot in 27ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180409 20:21:36.540152 48691 storage/replica_proposal.go:202  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305296.527445152,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:36.551644 48695 storage/replica_proposal.go:202  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305296.532153051,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:36.557648 48696 storage/replica_proposal.go:202  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305296.546803910,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:36.569215 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:36.571581 48942 storage/replica_command.go:1779  [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]
I180409 20:21:36.621083 48830 storage/replica_proposal.go:202  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305296.616986856,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:36.692431 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:36.732554 48942 storage/replica.go:3340  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:36.766953 48831 storage/replica_proposal.go:202  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305296.749015366,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:36.804946 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 9b147901 at index 26
I180409 20:21:36.863502 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:36.881521 48942 storage/store.go:3834  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 966, log entries: 16, rate-limit: 8.0 MiB/sec, 76ms
I180409 20:21:36.888054 49994 storage/replica_raftstorage.go:726  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 26 (id=9b147901, encoded size=162825, 1 rocksdb batches, 16 log entries)
I180409 20:21:36.930232 49994 storage/replica_raftstorage.go:732  [n2,s2,r5/?:/System/ts{d-e}] applied preemptive snapshot in 42ms [clear=0ms batch=1ms entries=39ms commit=1ms]
I180409 20:21:36.935597 48942 storage/replica_command.go:1779  [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]
I180409 20:21:36.942679 48843 storage/replica_proposal.go:202  [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305296.932379518,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:36.989624 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:37.025829 48942 storage/replica.go:3340  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:37.093176 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot ca0baee9 at index 27
I180409 20:21:37.113133 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:37.115668 48942 storage/store.go:3834  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 13, log entries: 17, rate-limit: 8.0 MiB/sec, 13ms
I180409 20:21:37.128421 50055 storage/replica_raftstorage.go:726  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 27 (id=ca0baee9, encoded size=5499, 1 rocksdb batches, 17 log entries)
I180409 20:21:37.132992 50055 storage/replica_raftstorage.go:732  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=3ms commit=0ms]
I180409 20:21:37.148007 48872 storage/replica_proposal.go:202  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305297.133984521,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:37.159245 48942 storage/replica_command.go:1779  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, next=2]
I180409 20:21:37.249683 48942 storage/replica.go:3340  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:37.257653 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:37.287789 48698 storage/replica_proposal.go:202  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305297.277712553,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:37.311458 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 976f5921 at index 46
I180409 20:21:37.321208 48942 storage/store.go:3834  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 39, log entries: 3, rate-limit: 8.0 MiB/sec, 9ms
I180409 20:21:37.325309 50025 storage/replica_raftstorage.go:726  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 46 (id=976f5921, encoded size=69558, 1 rocksdb batches, 3 log entries)
I180409 20:21:37.339632 50025 storage/replica_raftstorage.go:732  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 14ms [clear=0ms batch=0ms entries=12ms commit=1ms]
I180409 20:21:37.345941 48942 storage/replica_command.go:1779  [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]
I180409 20:21:37.354727 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:37.424965 48942 storage/replica.go:3340  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 20:21:37.452785 48836 storage/replica_proposal.go:202  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305297.448551639,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:37.469328 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:37.487882 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 5c3b9148 at index 32
I180409 20:21:37.544091 48942 storage/store.go:3834  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 54, log entries: 22, rate-limit: 8.0 MiB/sec, 33ms
I180409 20:21:37.558714 50016 storage/replica_raftstorage.go:726  [n2,s2,r9/?:{-}] applying preemptive snapshot at index 32 (id=5c3b9148, encoded size=19387, 1 rocksdb batches, 22 log entries)
I180409 20:21:37.568200 50016 storage/replica_raftstorage.go:732  [n2,s2,r9/?:/Table/1{2-3}] applied preemptive snapshot in 9ms [clear=0ms batch=0ms entries=7ms commit=1ms]
I180409 20:21:37.604891 48942 storage/replica_command.go:1779  [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]
I180409 20:21:37.622616 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:37.704430 48942 storage/replica.go:3340  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:37.750980 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:37.752933 48853 storage/replica_proposal.go:202  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305297.740635984,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:37.765032 48859 storage/replica_proposal.go:202  [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305297.744115547,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:37.781258 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot 1a0cafd9 at index 18
I180409 20:21:37.799880 48942 storage/store.go:3834  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 8, rate-limit: 8.0 MiB/sec, 18ms
I180409 20:21:37.807923 50048 storage/replica_raftstorage.go:726  [n3,s3,r17/?:{-}] applying preemptive snapshot at index 18 (id=1a0cafd9, encoded size=2530, 1 rocksdb batches, 8 log entries)
I180409 20:21:37.811203 50048 storage/replica_raftstorage.go:732  [n3,s3,r17/?:/Table/2{0-1}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180409 20:21:37.816449 48942 storage/replica_command.go:1779  [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]
I180409 20:21:37.904975 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:37.933115 48942 storage/replica.go:3340  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 20:21:37.943823 48694 storage/replica_proposal.go:202  [n1,s1,r6/1:/{System/tse-Table/System…}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305297.939420627,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:37.957934 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 57b044bb at index 22
I180409 20:21:37.965064 48942 storage/store.go:3834  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 12, rate-limit: 8.0 MiB/sec, 6ms
I180409 20:21:37.968079 50184 storage/replica_raftstorage.go:726  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 22 (id=57b044bb, encoded size=5345, 1 rocksdb batches, 12 log entries)
I180409 20:21:37.972265 50184 storage/replica_raftstorage.go:732  [n2,s2,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180409 20:21:37.983576 48942 storage/replica_command.go:1779  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, next=2]
I180409 20:21:38.004688 48900 server/status/runtime.go:219  [n1] runtime stats: 1.4 GiB RSS, 597 goroutines, 34 MiB/86 MiB/142 MiB GO alloc/idle/total, 86 MiB/126 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (307x)
I180409 20:21:38.044977 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:38.090789 48942 storage/replica.go:3340  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:38.108224 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 572404a2 at index 89
I180409 20:21:38.132826 48942 storage/store.go:3834  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n3,s3):?: kv pairs: 62, log entries: 63, rate-limit: 8.0 MiB/sec, 24ms
I180409 20:21:38.136884 50186 storage/replica_raftstorage.go:726  [n3,s3,r1/?:{-}] applying preemptive snapshot at index 89 (id=572404a2, encoded size=65294, 1 rocksdb batches, 63 log entries)
I180409 20:21:38.142841 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:38.223576 50186 storage/replica_raftstorage.go:732  [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 86ms [clear=0ms batch=0ms entries=76ms commit=1ms]
I180409 20:21:38.231403 48942 storage/replica_command.go:1779  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r1:/{Min-System/} [(n1,s1):1, next=2]
I180409 20:21:38.256771 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:38.330600 48942 storage/replica.go:3340  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 20:21:38.342753 48835 storage/replica_proposal.go:202  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305298.337167647,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:38.366764 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot 811bb03a at index 18
I180409 20:21:38.391990 48942 storage/store.go:3834  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 8, rate-limit: 8.0 MiB/sec, 15ms
I180409 20:21:38.397510 50213 storage/replica_raftstorage.go:726  [n2,s2,r13/?:{-}] applying preemptive snapshot at index 18 (id=811bb03a, encoded size=2530, 1 rocksdb batches, 8 log entries)
I180409 20:21:38.409455 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:38.412315 50213 storage/replica_raftstorage.go:732  [n2,s2,r13/?:/Table/1{6-7}] applied preemptive snapshot in 14ms [clear=0ms batch=0ms entries=13ms commit=0ms]
I180409 20:21:38.417916 48942 storage/replica_command.go:1779  [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]
I180409 20:21:38.524697 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:38.598582 48942 storage/replica.go:3340  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:38.623469 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:38.652629 48859 storage/replica_proposal.go:202  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305298.647951579,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:38.658376 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot 7c4104d2 at index 19
I180409 20:21:38.680064 48942 storage/store.go:3834  [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, 21ms
I180409 20:21:38.685559 50177 storage/replica_raftstorage.go:726  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 19 (id=7c4104d2, encoded size=3079, 1 rocksdb batches, 9 log entries)
I180409 20:21:38.695898 50177 storage/replica_raftstorage.go:732  [n2,s2,r11/?:/Table/1{4-5}] applied preemptive snapshot in 10ms [clear=0ms batch=0ms entries=8ms commit=1ms]
I180409 20:21:38.713994 48942 storage/replica_command.go:1779  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, next=2]
I180409 20:21:38.763412 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:38.873545 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:38.943719 48942 storage/replica.go:3340  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:38.951300 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot a40444cb at index 29
I180409 20:21:38.989042 48942 storage/store.go:3834  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n2,s2):?: kv pairs: 19, log entries: 19, rate-limit: 8.0 MiB/sec, 14ms
I180409 20:21:38.992999 50295 storage/replica_raftstorage.go:726  [n2,s2,r12/?:{-}] applying preemptive snapshot at index 29 (id=a40444cb, encoded size=9112, 1 rocksdb batches, 19 log entries)
I180409 20:21:38.998757 50295 storage/replica_raftstorage.go:732  [n2,s2,r12/?:/Table/1{5-6}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=4ms commit=1ms]
I180409 20:21:39.028715 48942 storage/replica_command.go:1779  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, next=2]
I180409 20:21:39.060766 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:39.123282 48942 storage/replica.go:3340  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:39.137307 48834 storage/replica_proposal.go:202  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305299.129149330,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:39.152450 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot b0f6b4bf at index 25
I180409 20:21:39.224109 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:39.227430 48942 storage/store.go:3834  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 12, log entries: 15, rate-limit: 8.0 MiB/sec, 13ms
I180409 20:21:39.230867 50301 storage/replica_raftstorage.go:726  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 25 (id=b0f6b4bf, encoded size=5611, 1 rocksdb batches, 15 log entries)
I180409 20:21:39.252296 50301 storage/replica_raftstorage.go:732  [n3,s3,r8/?:/Table/1{1-2}] applied preemptive snapshot in 21ms [clear=0ms batch=0ms entries=3ms commit=17ms]
I180409 20:21:39.257752 48942 storage/replica_command.go:1779  [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]
I180409 20:21:39.328889 48942 storage/replica.go:3340  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 20:21:39.375831 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot e95f3a61 at index 69
I180409 20:21:39.381294 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:39.448787 48942 storage/store.go:3834  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 203, log entries: 59, rate-limit: 8.0 MiB/sec, 72ms
I180409 20:21:39.457298 50342 storage/replica_raftstorage.go:726  [n2,s2,r10/?:{-}] applying preemptive snapshot at index 69 (id=e95f3a61, encoded size=58399, 1 rocksdb batches, 59 log entries)
I180409 20:21:39.497110 50342 storage/replica_raftstorage.go:732  [n2,s2,r10/?:/Table/1{3-4}] applied preemptive snapshot in 39ms [clear=0ms batch=0ms entries=37ms commit=1ms]
I180409 20:21:39.508015 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:39.515763 48942 storage/replica_command.go:1779  [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]
I180409 20:21:39.591130 48942 storage/replica.go:3340  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:39.617033 48705 storage/replica_proposal.go:202  [n1,s1,r20/1:/{Table/23-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523305287.946634379,0 epo=1 pro=1523305299.610849432,0 following repl=(n1,s1):1 seq=2 start=1523305287.946634379,0 exp=1523305296.979448607,0 pro=1523305287.979545299,0
I180409 20:21:39.636147 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:39.657337 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot e7c48188 at index 15
I180409 20:21:39.668750 48942 storage/store.go:3834  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n3,s3):?: kv pairs: 12, log entries: 5, rate-limit: 8.0 MiB/sec, 5ms
I180409 20:21:39.672352 50372 storage/replica_raftstorage.go:726  [n3,s3,r20/?:{-}] applying preemptive snapshot at index 15 (id=e7c48188, encoded size=1238, 1 rocksdb batches, 5 log entries)
I180409 20:21:39.675091 50372 storage/replica_raftstorage.go:732  [n3,s3,r20/?:/{Table/23-Max}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180409 20:21:39.681727 48942 storage/replica_command.go:1779  [replicate,n1,s1,r20/1:/{Table/23-Max}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r20:/{Table/23-Max} [(n1,s1):1, next=2]
I180409 20:21:39.740467 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:39.785318 48942 storage/replica.go:3340  [n1,s1,r20/1:/{Table/23-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 20:21:39.812026 50358 storage/replica_raftstorage.go:520  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot d6c83ba3 at index 26
I180409 20:21:39.828911 50358 storage/store.go:3834  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 16, rate-limit: 8.0 MiB/sec, 12ms
I180409 20:21:39.832569 50362 storage/replica_raftstorage.go:726  [n3,s3,r2/?:{-}] applying preemptive snapshot at index 26 (id=d6c83ba3, encoded size=6591, 1 rocksdb batches, 16 log entries)
I180409 20:21:39.839512 50362 storage/replica_raftstorage.go:732  [n3,s3,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=3ms commit=0ms]
I180409 20:21:39.853905 50358 storage/replica_command.go:1779  [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]
I180409 20:21:39.893231 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 20:21:39.958216 50358 storage/replica.go:3340  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180409 20:21:39.995376 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot 1f4a8238 at index 18
I180409 20:21:40.007245 48942 storage/store.go:3834  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 8, rate-limit: 8.0 MiB/sec, 11ms
I180409 20:21:40.011778 50425 storage/replica_raftstorage.go:726  [n2,s2,r16/?:{-}] applying preemptive snapshot at index 18 (id=1f4a8238, encoded size=2530, 1 rocksdb batches, 8 log entries)
I180409 20:21:40.015408 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 20:21:40.020556 50425 storage/replica_raftstorage.go:732  [n2,s2,r16/?:/Table/{19-20}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=4ms commit=0ms]
I180409 20:21:40.027656 48942 storage/replica_command.go:1779  [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]
I180409 20:21:40.102742 48942 storage/replica.go:3340  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:40.129723 48942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 419442e9 at index 18
I180409 20:21:40.151101 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 20:21:40.192029 48942 storage/store.go:3834  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 8, rate-limit: 8.0 MiB/sec, 50ms
I180409 20:21:40.195753 50437 storage/replica_raftstorage.go:726  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 18 (id=419442e9, encoded size=2530, 1 rocksdb batches, 8 log entries)
I180409 20:21:40.198866 50437 storage/replica_raftstorage.go:732  [n2,s2,r14/?:/Table/1{7-8}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180409 20:21:40.204263 48942 storage/replica_command.go:1779  [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]
I180409 20:21:40.273636 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 20:21:40.312260 48942 storage/replica.go:3340  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 20:21:40.364076 48942 storage/queue.go:847  [n1,replicate] purgatory is now empty
I180409 20:21:40.375222 50407 storage/replica_raftstorage.go:520  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot 71bc7749 at index 18
I180409 20:21:40.390620 50407 storage/store.go:3834  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n2,s2):?: kv pairs: 13, log entries: 8, rate-limit: 8.0 MiB/sec, 10ms
I180409 20:21:40.393997 50395 storage/replica_raftstorage.go:726  [n2,s2,r20/?:{-}] applying preemptive snapshot at index 18 (id=71bc7749, encoded size=2272, 1 rocksdb batches, 8 log entries)
I180409 20:21:40.417126 50395 storage/replica_raftstorage.go:732  [n2,s2,r20/?:/{Table/23-Max}] applied preemptive snapshot in 22ms [clear=0ms batch=0ms entries=21ms commit=0ms]
I180409 20:21:40.422498 50407 storage/replica_command.go:1779  [replicate,n1,s1,r20/1:/{Table/23-Max}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r20:/{Table/23-Max} [(n1,s1):1, (n3,s3):2, next=3]
I180409 20:21:40.424975 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 20:21:40.493530 50407 storage/replica.go:3340  [n1,s1,r20/1:/{Table/23-Max}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180409 20:21:40.537676 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180409 20:21:40.551491 50431 storage/replica_raftstorage.go:520  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 7c0a6555 at index 21
I180409 20:21:40.559197 50431 storage/store.go:3834  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 11, rate-limit: 8.0 MiB/sec, 6ms
I180409 20:21:40.578271 50441 storage/replica_raftstorage.go:726  [n3,s3,r14/?:{-}] applying preemptive snapshot at index 21 (id=7c0a6555, encoded size=3560, 1 rocksdb batches, 11 log entries)
I180409 20:21:40.585195 50441 storage/replica_raftstorage.go:732  [n3,s3,r14/?:/Table/1{7-8}] applied preemptive snapshot in 7ms [clear=0ms batch=0ms entries=5ms commit=0ms]
I180409 20:21:40.592495 50431 storage/replica_command.go:1779  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, (n2,s2):2, next=3]
I180409 20:21:40.669447 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180409 20:21:40.702856 50431 storage/replica.go:3340  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180409 20:21:40.734064 50469 storage/replica_raftstorage.go:520  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot bc4a60a3 at index 55
I180409 20:21:40.764515 50469 storage/store.go:3834  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):?: kv pairs: 78, log entries: 45, rate-limit: 8.0 MiB/sec, 29ms
I180409 20:21:40.771486 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 17 underreplicated ranges
I180409 20:21:40.782887 50498 storage/replica_raftstorage.go:726  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 55 (id=bc4a60a3, encoded size=44431, 1 rocksdb batches, 45 log entries)
I180409 20:21:40.824427 50498 storage/replica_raftstorage.go:732  [n3,s3,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 40ms [clear=0ms batch=0ms entries=16ms commit=1ms]
I180409 20:21:40.835658 50469 storage/replica_command.go:1779  [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]
I180409 20:21:40.909824 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 17 underreplicated ranges
I180409 20:21:41.010205 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 17 underreplicated ranges
I180409 20:21:41.039404 50469 storage/replica.go:3340  [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
I180409 20:21:41.089900 50475 storage/replica_raftstorage.go:520  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot 665f77a9 at index 21
I180409 20:21:41.102187 50475 storage/store.go:3834  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 11, rate-limit: 8.0 MiB/sec, 5ms
I180409 20:21:41.105538 50522 storage/replica_raftstorage.go:726  [n2,s2,r19/?:{-}] applying preemptive snapshot at index 21 (id=665f77a9, encoded size=3560, 1 rocksdb batches, 11 log entries)
I180409 20:21:41.109456 50522 storage/replica_raftstorage.go:732  [n2,s2,r19/?:/Table/2{2-3}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180409 20:21:41.116305 50475 storage/replica_command.go:1779  [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]
I180409 20:21:41.130694 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 16 underreplicated ranges
I180409 20:21:41.210334 50475 storage/replica.go:3340  [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
I180409 20:21:41.228320 50479 storage/replica_raftstorage.go:520  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot c572e370 at index 50
I180409 20:21:41.233602 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 15 underreplicated ranges
I180409 20:21:41.252369 50479 storage/store.go:3834  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n2,s2):?: kv pairs: 40, log entries: 7, rate-limit: 8.0 MiB/sec, 7ms
I180409 20:21:41.263463 50489 storage/replica_raftstorage.go:726  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 50 (id=c572e370, encoded size=87536, 1 rocksdb batches, 7 log entries)
I180409 20:21:41.335345 50489 storage/replica_raftstorage.go:732  [n2,s2,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 58ms [clear=0ms batch=0ms entries=34ms commit=1ms]
I180409 20:21:41.354967 50479 storage/replica_command.go:1779  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, (n3,s3):2, next=3]
I180409 20:21:41.361731 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 15 underreplicated ranges
I180409 20:21:41.457939 50479 storage/replica.go:3340  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180409 20:21:41.472591 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 15 underreplicated ranges
I180409 20:21:41.488748 50513 storage/replica_raftstorage.go:520  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot a7cc94c2 at index 28
I180409 20:21:41.499065 50513 storage/store.go:3834  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 13, log entries: 18, rate-limit: 8.0 MiB/sec, 8ms
I180409 20:21:41.506714 50594 storage/replica_raftstorage.go:726  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 28 (id=a7cc94c2, encoded size=6650, 1 rocksdb batches, 18 log entries)
I180409 20:21:41.513074 50594 storage/replica_raftstorage.go:732  [n2,s2,r8/?:/Table/1{1-2}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=4ms commit=0ms]
I180409 20:21:41.544234 50513 storage/replica_command.go:1779  [replicate,n1,s1,r8/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, (n3,s3):2, next=3]
I180409 20:21:41.635532 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 14 underreplicated ranges
I180409 20:21:41.773525 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 14 underreplicated ranges
I180409 20:21:41.793817 50513 storage/replica.go:3340  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180409 20:21:41.868686 50464 storage/replica_raftstorage.go:520  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot c1d9e1d7 at index 94
I180409 20:21:41.898072 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 13 underreplicated ranges
I180409 20:21:41.905755 50464 storage/store.go:3834  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 259, log entries: 84, rate-limit: 8.0 MiB/sec, 21ms
I180409 20:21:41.921924 50611 storage/replica_raftstorage.go:726  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 94 (id=c1d9e1d7, encoded size=81139, 1 rocksdb batches, 84 log entries)
I180409 20:21:42.026695 50611 storage/replica_raftstorage.go:732  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 104ms [clear=0ms batch=0ms entries=90ms commit=1ms]
I180409 20:21:42.027797 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 13 underreplicated ranges
I180409 20:21:42.038891 50464 storage/replica_command.go:1779  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, (n2,s2):2, next=3]
I180409 20:21:42.115284 50464 storage/replica.go:3340  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180409 20:21:42.149933 50600 storage/replica_raftstorage.go:520  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 7b51b7ac at index 35
I180409 20:21:42.158923 48722 testutils/testcluster/testcluster.go:534  [n1,s1] has 12 underreplicated ranges
I180409 20:21:42.176430 50600 storage/store.go:3834  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 55, log entries: 25, rate-limit: 8.0 MiB/sec, 25ms
I180409 20:21:42.184556 50628 storage/replica_raftstorage.go:726  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 35 (id=7b51b7ac, encoded size=20417, 1 rocksdb batches, 25 log entries)
I180409 20:21:42.193027 50628 storage/replica_raftstorage.go:732  [n3,s3,r9/?:/Table/1{2-3}] applied preemptive snapshot in 8ms [clear=0ms batch=0ms entries=6ms commit=0ms]
I180409 20:21:42.215597 50600 storage/replica_command.go:1779  [replicate,n1,s1,r9/1:/Table/1{2-3}] chang

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the 2.1 milestone Apr 9, 2018
@cockroach-teamcity cockroach-teamcity added O-robot Originated from a bot. C-test-failure Broken test (automatically or manually discovered). labels Apr 9, 2018
@tbg tbg assigned dt Apr 18, 2018
@a-robinson
Copy link
Contributor

Dupe of #24136

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@dt dt

Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
2.1
Development

No branches or pull requests
3 participants
@dt @a-robinson @cockroach-teamcity