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 #24637

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

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

cockroach-teamcity opened this issue Apr 10, 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:

#595593:

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

------- Stdout: -------
W180410 18:14:33.584617 50139 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180410 18:14:33.749107 50139 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180410 18:14:33.789056 50139 server/config.go:538  [n?] 1 storage engine initialized
I180410 18:14:33.789247 50139 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180410 18:14:33.789339 50139 server/config.go:541  [n?] store 0: in-memory, size 0 B
I180410 18:14:33.927828 50139 server/node.go:374  [n?] **** cluster 3ece07ce-a519-4589-96b3-131fa70bff31 has been created
I180410 18:14:33.928062 50139 server/server.go:1305  [n?] **** add additional nodes by specifying --join=127.0.0.1:44743
I180410 18:14:33.960395 50139 storage/store.go:1399  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180410 18:14:33.972902 50139 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}
I180410 18:14:33.973652 50139 server/node.go:352  [n1] node ID 1 initialized
I180410 18:14:33.982337 50139 gossip/gossip.go:332  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:44743" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180410 18:14:33.985610 50139 storage/stores.go:309  [n1] read 0 node addresses from persistent storage
I180410 18:14:33.991189 50139 server/node.go:653  [n1] connecting to gossip network to verify cluster ID...
I180410 18:14:33.992260 50139 server/node.go:678  [n1] node connected via gossip and verified as part of cluster "3ece07ce-a519-4589-96b3-131fa70bff31"
I180410 18:14:33.996207 50139 server/node.go:446  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180410 18:14:34.019165 50139 server/server.go:1431  [n1] starting https server at 127.0.0.1:42453
I180410 18:14:34.019759 50139 server/server.go:1432  [n1] starting grpc/postgres server at 127.0.0.1:44743
I180410 18:14:34.020067 50139 server/server.go:1433  [n1] advertising CockroachDB node at 127.0.0.1:44743
W180410 18:14:34.023585 50139 sql/jobs/registry.go:286  [n1] unable to get node liveness: node not in the liveness table
I180410 18:14:34.067503 50386 storage/replica_command.go:862  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180410 18:14:34.461806 50361 storage/replica_command.go:862  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180410 18:14:34.919698 50065 storage/replica_command.go:862  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180410 18:14:34.959495 50139 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}
I180410 18:14:35.188001 50408 storage/replica_command.go:862  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180410 18:14:35.515903 50411 storage/replica_command.go:862  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
W180410 18:14:35.543137 50455 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=4faaf9ba key=/Table/SystemConfigSpan/Start rw=true pri=0.01155101 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523384075.311660851,0 orig=1523384075.311660851,0 max=1523384075.311660851,0 wto=false rop=false seq=13
I180410 18:14:35.639440 50139 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:node}
I180410 18:14:35.672893 50208 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]
I180410 18:14:35.842605 50474 storage/replica_command.go:862  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
W180410 18:14:35.892110 50399 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=4259e83b key=/Table/SystemConfigSpan/Start rw=true pri=0.01394157 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523384075.647137896,0 orig=1523384075.647137896,0 max=1523384075.647137896,0 wto=false rop=false seq=8
I180410 18:14:35.958354 50139 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}
I180410 18:14:36.089485 50460 storage/replica_command.go:862  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
W180410 18:14:36.208623 50432 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=0d66ed4c key=/Local/Range/Table/11/RangeDescriptor rw=true pri=0.00649444 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523384076.089686286,0 orig=1523384076.089686286,0 max=1523384076.089686286,0 wto=false rop=false seq=3
I180410 18:14:36.296333 50487 storage/replica_command.go:862  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180410 18:14:36.569814 50547 storage/replica_command.go:862  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
W180410 18:14:36.758224 50496 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=338becf5 key=/Local/Range/Table/13/RangeDescriptor rw=true pri=0.06599398 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523384076.570043795,0 orig=1523384076.570043795,0 max=1523384076.570043795,0 wto=false rop=false seq=3
I180410 18:14:36.804757 50579 storage/replica_command.go:862  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180410 18:14:36.962422 50594 storage/replica_command.go:862  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180410 18:14:36.968393 50139 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:[]}
I180410 18:14:37.109810 50139 sql/lease.go:352  [n1] publish: descID=4 (users) version=2 mtime=2018-04-10 18:14:37.108179904 +0000 UTC
I180410 18:14:37.256859 50587 storage/replica_command.go:862  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
W180410 18:14:37.445445 50612 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=3e8d08c8 key=/Local/Range/Table/16/RangeDescriptor rw=true pri=0.01080371 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523384077.257123539,0 orig=1523384077.257123539,0 max=1523384077.257123539,0 wto=false rop=false seq=3
I180410 18:14:37.451614 50139 sql/lease.go:352  [n1] publish: descID=4 (users) version=3 mtime=2018-04-10 18:14:37.41874905 +0000 UTC
I180410 18:14:37.514134 50512 storage/replica_command.go:862  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180410 18:14:37.653070 50139 sql/backfill.go:134  [n1] Running backfill for "users", v=3, m=1
I180410 18:14:37.695918 50646 storage/replica_command.go:862  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180410 18:14:37.851972 50513 storage/replica_command.go:862  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180410 18:14:37.996390 50620 storage/replica_command.go:862  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
W180410 18:14:38.119222 50664 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=20c583c6 key=/Local/Range/Table/20/RangeDescriptor rw=true pri=0.02409057 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523384077.996608590,0 orig=1523384077.996608590,0 max=1523384077.996608590,0 wto=false rop=false seq=3
W180410 18:14:38.122081 50575 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=20c583c6 key=/Local/Range/Table/20/RangeDescriptor rw=true pri=0.02409057 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523384077.996608590,0 orig=1523384077.996608590,0 max=1523384077.996608590,0 wto=false rop=false seq=3
I180410 18:14:38.143903 50651 storage/replica_command.go:862  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180410 18:14:38.216346 50139 sql/lease.go:352  [n1] publish: descID=4 (users) version=4 mtime=2018-04-10 18:14:38.208301886 +0000 UTC
I180410 18:14:38.281404 50722 storage/replica_command.go:862  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180410 18:14:38.535526 50139 sql/event_log.go:121  [n1] Event: "finish_schema_change", target: 4, info: {MutationID:1}
I180410 18:14:38.588527 50139 sql/lease.go:275  publish (count leases): descID=4 name=users version=3 count=1
I180410 18:14:38.606241 50726 sql/lease.go:812  new lease: 4("users") ver=4:1523384364.175169892,0, refcount=0
I180410 18:14:38.633081 50139 sql/lease.go:275  publish (count leases): descID=4 name=users version=3 count=1
I180410 18:14:39.182025 50139 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:node}
I180410 18:14:39.317803 50139 server/server.go:1511  [n1] done ensuring all necessary migrations have run
I180410 18:14:39.318031 50139 server/server.go:1514  [n1] serving sql connections
I180410 18:14:39.390850 50762 sql/event_log.go:121  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:44743} Attrs: Locality: ServerVersion:2.0-3} ClusterID:3ece07ce-a519-4589-96b3-131fa70bff31 StartedAt:1523384073992335861 LastUp:1523384073992335861}
W180410 18:14:39.543207 50139 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180410 18:14:39.679145 50139 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180410 18:14:39.719406 50139 server/config.go:538  [n?] 1 storage engine initialized
I180410 18:14:39.719616 50139 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180410 18:14:39.719693 50139 server/config.go:541  [n?] store 0: in-memory, size 0 B
W180410 18:14:39.720176 50139 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180410 18:14:39.731996 50139 server/server.go:1307  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180410 18:14:39.994533 50735 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:44743
I180410 18:14:40.005857 50777 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:45395}
I180410 18:14:40.014137 50139 storage/stores.go:309  [n?] read 0 node addresses from persistent storage
I180410 18:14:40.014682 50139 storage/stores.go:328  [n?] wrote 1 node addresses to persistent storage
I180410 18:14:40.014846 50139 server/node.go:653  [n?] connecting to gossip network to verify cluster ID...
I180410 18:14:40.015099 50139 server/node.go:678  [n?] node connected via gossip and verified as part of cluster "3ece07ce-a519-4589-96b3-131fa70bff31"
I180410 18:14:40.087071 50139 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180410 18:14:40.100090 50139 server/node.go:345  [n?] new node allocated ID 2
I180410 18:14:40.100869 50139 gossip/gossip.go:332  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:45395" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180410 18:14:40.107924 50139 server/node.go:427  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180410 18:14:40.114145 50139 server/node.go:446  [n2] node=2: started with [] engine(s) and attributes []
I180410 18:14:40.112506 50874 storage/stores.go:328  [n1] wrote 1 node addresses to persistent storage
I180410 18:14:40.154083 50139 server/server.go:1431  [n2] starting https server at 127.0.0.1:34535
I180410 18:14:40.166511 50139 server/server.go:1432  [n2] starting grpc/postgres server at 127.0.0.1:45395
I180410 18:14:40.167386 50139 server/server.go:1433  [n2] advertising CockroachDB node at 127.0.0.1:45395
W180410 18:14:40.171526 50139 sql/jobs/registry.go:286  [n2] unable to get node liveness: node not in the liveness table
I180410 18:14:40.230592 50139 server/server.go:1511  [n2] done ensuring all necessary migrations have run
I180410 18:14:40.230833 50139 server/server.go:1514  [n2] serving sql connections
I180410 18:14:40.378110 50715 server/node.go:634  [n2] bootstrapped store [n2,s2]
I180410 18:14:40.430934 50832 sql/event_log.go:121  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:45395} Attrs: Locality: ServerVersion:2.0-3} ClusterID:3ece07ce-a519-4589-96b3-131fa70bff31 StartedAt:1523384080113747669 LastUp:1523384080113747669}
W180410 18:14:40.621882 50139 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180410 18:14:40.729153 50139 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180410 18:14:40.761241 50139 server/config.go:538  [n?] 1 storage engine initialized
I180410 18:14:40.761522 50139 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180410 18:14:40.761635 50139 server/config.go:541  [n?] store 0: in-memory, size 0 B
W180410 18:14:40.762073 50139 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180410 18:14:40.802331 50139 server/server.go:1307  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180410 18:14:41.026749 50971 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:44743
I180410 18:14:41.043243 51078 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:44725}
I180410 18:14:41.100816 50139 storage/stores.go:309  [n?] read 0 node addresses from persistent storage
I180410 18:14:41.101304 50139 storage/stores.go:328  [n?] wrote 2 node addresses to persistent storage
I180410 18:14:41.101379 50139 server/node.go:653  [n?] connecting to gossip network to verify cluster ID...
I180410 18:14:41.101581 50139 server/node.go:678  [n?] node connected via gossip and verified as part of cluster "3ece07ce-a519-4589-96b3-131fa70bff31"
I180410 18:14:41.129081 50139 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180410 18:14:41.138788 50139 server/node.go:345  [n?] new node allocated ID 3
I180410 18:14:41.139579 50139 gossip/gossip.go:332  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:44725" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180410 18:14:41.140602 50139 server/node.go:427  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180410 18:14:41.141541 50139 server/node.go:446  [n3] node=3: started with [] engine(s) and attributes []
I180410 18:14:41.144920 50139 server/server.go:1431  [n3] starting https server at 127.0.0.1:36397
I180410 18:14:41.145192 50139 server/server.go:1432  [n3] starting grpc/postgres server at 127.0.0.1:44725
I180410 18:14:41.145348 50139 server/server.go:1433  [n3] advertising CockroachDB node at 127.0.0.1:44725
I180410 18:14:41.166883 51094 storage/stores.go:328  [n1] wrote 2 node addresses to persistent storage
I180410 18:14:41.171327 50139 server/server.go:1511  [n3] done ensuring all necessary migrations have run
I180410 18:14:41.171665 50139 server/server.go:1514  [n3] serving sql connections
I180410 18:14:41.188363 50988 storage/stores.go:328  [n2] wrote 2 node addresses to persistent storage
I180410 18:14:41.326141 51128 server/node.go:634  [n3] bootstrapped store [n3,s3]
I180410 18:14:41.380909 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot fa633e20 at index 36
I180410 18:14:41.411692 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:41.464821 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:41.486576 51007 sql/event_log.go:121  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:44725} Attrs: Locality: ServerVersion:2.0-3} ClusterID:3ece07ce-a519-4589-96b3-131fa70bff31 StartedAt:1523384081141003397 LastUp:1523384081141003397}
I180410 18:14:41.500586 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:41.564920 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:41.670457 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:41.786716 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:41.795561 50393 storage/store.go:3834  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 123, log entries: 26, rate-limit: 8.0 MiB/sec, 21ms
I180410 18:14:41.799023 51294 storage/replica_raftstorage.go:726  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 36 (id=fa633e20, encoded size=27203, 1 rocksdb batches, 26 log entries)
I180410 18:14:41.808110 51294 storage/replica_raftstorage.go:732  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 9ms [clear=0ms batch=0ms entries=7ms commit=0ms]
I180410 18:14:41.823101 50393 storage/replica_command.go:1779  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, next=2]
I180410 18:14:41.914911 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:41.963831 50393 storage/replica.go:3340  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180410 18:14:41.982797 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot 81f8d9d7 at index 17
I180410 18:14:42.002297 50393 storage/store.go:3834  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 7, rate-limit: 8.0 MiB/sec, 11ms
I180410 18:14:42.005294 51270 storage/replica_raftstorage.go:726  [n3,s3,r19/?:{-}] applying preemptive snapshot at index 17 (id=81f8d9d7, encoded size=2357, 1 rocksdb batches, 7 log entries)
I180410 18:14:42.008200 51270 storage/replica_raftstorage.go:732  [n3,s3,r19/?:/Table/2{2-3}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180410 18:14:42.012749 50393 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]
I180410 18:14:42.031539 51247 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180410 18:14:42.048934 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:42.103986 50393 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
I180410 18:14:42.119544 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot 29791122 at index 15
I180410 18:14:42.144612 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:42.269786 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:42.380836 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:42.473007 50393 storage/store.go:3834  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 5, rate-limit: 8.0 MiB/sec, 4ms
I180410 18:14:42.475861 51264 storage/replica_raftstorage.go:726  [n2,s2,r13/?:{-}] applying preemptive snapshot at index 15 (id=29791122, encoded size=2057, 1 rocksdb batches, 5 log entries)
I180410 18:14:42.478552 51264 storage/replica_raftstorage.go:732  [n2,s2,r13/?:/Table/1{6-7}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180410 18:14:42.485264 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:42.492028 50320 storage/replica_proposal.go:202  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384082.487964448,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:42.496511 50393 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]
I180410 18:14:42.506969 50318 storage/replica_proposal.go:202  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384082.500647135,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:42.550803 50323 storage/replica_proposal.go:202  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384082.533209029,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:42.582942 50331 storage/replica_proposal.go:202  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384082.540581201,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:42.593829 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:42.649747 50393 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
I180410 18:14:42.673459 51399 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180410 18:14:42.683560 50328 storage/replica_proposal.go:202  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384082.668589014,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:42.696513 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot e218dbe7 at index 18
I180410 18:14:42.714037 50393 storage/store.go:3834  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 8, rate-limit: 8.0 MiB/sec, 16ms
I180410 18:14:42.716948 51278 storage/replica_raftstorage.go:726  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 18 (id=e218dbe7, encoded size=2524, 1 rocksdb batches, 8 log entries)
I180410 18:14:42.720032 51278 storage/replica_raftstorage.go:732  [n2,s2,r15/?:/Table/1{8-9}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180410 18:14:42.731885 50393 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]
I180410 18:14:42.790393 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:42.838568 50393 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
I180410 18:14:42.859449 50298 storage/replica_proposal.go:202  [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384082.844019235,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:42.875853 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot 67565062 at index 17
I180410 18:14:42.884221 50393 storage/store.go:3834  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 7, rate-limit: 8.0 MiB/sec, 7ms
I180410 18:14:42.934215 51420 storage/replica_raftstorage.go:726  [n3,s3,r17/?:{-}] applying preemptive snapshot at index 17 (id=67565062, encoded size=2316, 1 rocksdb batches, 7 log entries)
I180410 18:14:42.944313 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:42.975876 51420 storage/replica_raftstorage.go:732  [n3,s3,r17/?:/Table/2{0-1}] applied preemptive snapshot in 41ms [clear=0ms batch=0ms entries=1ms commit=1ms]
I180410 18:14:42.980943 50393 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]
I180410 18:14:43.044134 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:43.160375 50393 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
I180410 18:14:43.162395 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:43.218210 50331 storage/replica_proposal.go:202  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384083.198766282,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:43.227649 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot 85feb796 at index 18
I180410 18:14:43.250383 50393 storage/store.go:3834  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 8, rate-limit: 8.0 MiB/sec, 22ms
I180410 18:14:43.259845 51500 storage/replica_raftstorage.go:726  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 18 (id=85feb796, encoded size=2524, 1 rocksdb batches, 8 log entries)
I180410 18:14:43.269434 51500 storage/replica_raftstorage.go:732  [n2,s2,r18/?:/Table/2{1-2}] applied preemptive snapshot in 9ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180410 18:14:43.279136 50393 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]
I180410 18:14:43.283414 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:43.388058 50393 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
I180410 18:14:43.388466 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:43.397377 50343 storage/replica_proposal.go:202  [n1,s1,r20/1:/{Table/23-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384083.393448685,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:43.451867 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot 77d0c173 at index 15
I180410 18:14:43.479170 50393 storage/store.go:3834  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 5, rate-limit: 8.0 MiB/sec, 26ms
I180410 18:14:43.481808 51527 storage/replica_raftstorage.go:726  [n2,s2,r20/?:{-}] applying preemptive snapshot at index 15 (id=77d0c173, encoded size=1232, 1 rocksdb batches, 5 log entries)
I180410 18:14:43.484220 51527 storage/replica_raftstorage.go:732  [n2,s2,r20/?:/{Table/23-Max}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180410 18:14:43.494592 50393 storage/replica_command.go:1779  [replicate,n1,s1,r20/1:/{Table/23-Max}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r20:/{Table/23-Max} [(n1,s1):1, next=2]
I180410 18:14:43.521205 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:43.531879 51215 storage/replica_proposal.go:202  [n3,s3,r19/2:/Table/2{2-3}] new range lease repl=(n3,s3):2 seq=3 start=1523384082.961135430,1 epo=1 pro=1523384083.505675058,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:43.545882 51484 storage/replica_raftstorage.go:520  [replicate,n3,s3,r19/2:/Table/2{2-3}] generated preemptive snapshot 6bc619a7 at index 21
I180410 18:14:43.654790 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:43.656255 50393 storage/replica.go:3340  [n1,s1,r20/1:/{Table/23-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 18:14:43.675242 50306 storage/replica_proposal.go:202  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384083.665581879,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:43.717477 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 1a0aa6b7 at index 24
I180410 18:14:43.760650 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:43.788958 50393 storage/store.go:3834  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 966, log entries: 14, rate-limit: 8.0 MiB/sec, 70ms
I180410 18:14:43.802547 51531 storage/replica_raftstorage.go:726  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 24 (id=1a0aa6b7, encoded size=161523, 1 rocksdb batches, 14 log entries)
I180410 18:14:43.860802 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:43.895500 51531 storage/replica_raftstorage.go:732  [n2,s2,r5/?:/System/ts{d-e}] applied preemptive snapshot in 93ms [clear=0ms batch=1ms entries=90ms commit=1ms]
I180410 18:14:43.901072 50393 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]
I180410 18:14:43.926936 51484 storage/store.go:3834  [replicate,n3,s3,r19/2:/Table/2{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 11, rate-limit: 8.0 MiB/sec, 9ms
I180410 18:14:43.930156 51567 storage/replica_raftstorage.go:726  [n2,s2,r19/?:{-}] applying preemptive snapshot at index 21 (id=6bc619a7, encoded size=3557, 1 rocksdb batches, 11 log entries)
I180410 18:14:43.933689 51567 storage/replica_raftstorage.go:732  [n2,s2,r19/?:/Table/2{2-3}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180410 18:14:43.947916 51484 storage/replica_command.go:1779  [replicate,n3,s3,r19/2:/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]
I180410 18:14:44.031348 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:44.100071 50375 server/status/runtime.go:219  [n1] runtime stats: 1.4 GiB RSS, 610 goroutines, 47 MiB/73 MiB/140 MiB GO alloc/idle/total, 85 MiB/126 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (307x)
I180410 18:14:44.107205 50393 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
I180410 18:14:44.141743 50334 storage/replica_proposal.go:202  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384084.123340982,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:44.151048 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:44.172802 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot ca38067a at index 19
I180410 18:14:44.183538 50393 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, 10ms
I180410 18:14:44.186614 51638 storage/replica_raftstorage.go:726  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 19 (id=ca38067a, encoded size=3069, 1 rocksdb batches, 9 log entries)
I180410 18:14:44.216015 51638 storage/replica_raftstorage.go:732  [n2,s2,r11/?:/Table/1{4-5}] applied preemptive snapshot in 29ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180410 18:14:44.220658 50393 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]
I180410 18:14:44.292261 51612 storage/replica.go:3340  [n3,s3,r19/2:/Table/2{2-3}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180410 18:14:44.298911 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 18:14:44.382049 50393 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
I180410 18:14:44.422747 50301 storage/replica_proposal.go:202  [n1,s1,r6/1:/{System/tse-Table/System…}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384084.417033091,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:44.430892 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 90b586b7 at index 21
I180410 18:14:44.441530 50393 storage/store.go:3834  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 11, rate-limit: 8.0 MiB/sec, 10ms
I180410 18:14:44.444627 51628 storage/replica_raftstorage.go:726  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 21 (id=90b586b7, encoded size=4489, 1 rocksdb batches, 11 log entries)
I180410 18:14:44.452517 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:44.475760 51628 storage/replica_raftstorage.go:732  [n2,s2,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 30ms [clear=0ms batch=0ms entries=9ms commit=1ms]
I180410 18:14:44.503016 50393 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]
I180410 18:14:44.579726 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:44.655243 50393 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
I180410 18:14:44.706173 50329 storage/replica_proposal.go:202  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384084.702098067,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:44.741879 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 41472051 at index 18
I180410 18:14:44.779183 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:44.789890 50393 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, 40ms
I180410 18:14:44.790974 51682 storage/raft_transport.go:459  [n2] raft transport stream to node 3 established
I180410 18:14:44.794727 51735 storage/replica_raftstorage.go:726  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 18 (id=41472051, encoded size=2524, 1 rocksdb batches, 8 log entries)
I180410 18:14:44.797791 51735 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]
I180410 18:14:44.822764 50393 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]
I180410 18:14:44.897732 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:44.931520 50393 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
I180410 18:14:44.965939 50293 storage/replica_proposal.go:202  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384084.937326659,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:45.025424 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot d5ee8dea at index 18
I180410 18:14:45.050870 50393 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, 8ms
I180410 18:14:45.094381 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:45.099948 51760 storage/replica_raftstorage.go:726  [n2,s2,r16/?:{-}] applying preemptive snapshot at index 18 (id=d5ee8dea, encoded size=2524, 1 rocksdb batches, 8 log entries)
I180410 18:14:45.123367 51760 storage/replica_raftstorage.go:732  [n2,s2,r16/?:/Table/{19-20}] applied preemptive snapshot in 23ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180410 18:14:45.175217 50393 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]
I180410 18:14:45.214792 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:45.251497 50393 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
I180410 18:14:45.281378 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 617a0ca9 at index 30
I180410 18:14:45.294491 50393 storage/store.go:3834  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 15, log entries: 20, rate-limit: 8.0 MiB/sec, 4ms
I180410 18:14:45.311781 51705 storage/replica_raftstorage.go:726  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 30 (id=617a0ca9, encoded size=6413, 1 rocksdb batches, 20 log entries)
I180410 18:14:45.334497 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:45.337627 51705 storage/replica_raftstorage.go:732  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 25ms [clear=0ms batch=0ms entries=24ms commit=0ms]
I180410 18:14:45.344673 50393 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]
I180410 18:14:45.432323 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:45.439505 50393 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
I180410 18:14:45.446093 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 08ff1bc4 at index 91
I180410 18:14:45.498327 50393 storage/store.go:3834  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 65, log entries: 81, rate-limit: 8.0 MiB/sec, 30ms
I180410 18:14:45.508452 51826 storage/replica_raftstorage.go:726  [n2,s2,r1/?:{-}] applying preemptive snapshot at index 91 (id=08ff1bc4, encoded size=20097, 1 rocksdb batches, 81 log entries)
I180410 18:14:45.533324 50332 storage/replica_proposal.go:202  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384085.512901112,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:45.549521 51826 storage/replica_raftstorage.go:732  [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 41ms [clear=0ms batch=0ms entries=24ms commit=1ms]
I180410 18:14:45.573789 50393 storage/replica_command.go:1779  [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]
I180410 18:14:45.610158 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:45.634476 50393 storage/replica.go:3340  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 18:14:45.694576 50300 storage/replica_proposal.go:202  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384085.678894108,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:45.720140 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot e774393d at index 25
I180410 18:14:45.724758 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:45.746665 50393 storage/store.go:3834  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 15, rate-limit: 8.0 MiB/sec, 5ms
I180410 18:14:45.749670 51782 storage/replica_raftstorage.go:726  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 25 (id=e774393d, encoded size=5686, 1 rocksdb batches, 15 log entries)
I180410 18:14:45.754058 51782 storage/replica_raftstorage.go:732  [n2,s2,r8/?:/Table/1{1-2}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=3ms commit=0ms]
I180410 18:14:45.778389 50393 storage/replica_command.go:1779  [replicate,n1,s1,r8/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, next=2]
I180410 18:14:45.837963 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:45.889096 50393 storage/replica.go:3340  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 18:14:45.901690 50096 storage/replica_proposal.go:202  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1523384073.931946516,0 epo=1 pro=1523384085.894685057,0 following repl=(n1,s1):1 seq=2 start=1523384073.931946516,0 exp=1523384082.961135430,0 pro=1523384073.961242459,0
I180410 18:14:45.952687 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 4dfe225b at index 31
I180410 18:14:45.973465 50393 storage/store.go:3834  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 54, log entries: 21, rate-limit: 8.0 MiB/sec, 13ms
I180410 18:14:45.977424 51829 storage/replica_raftstorage.go:726  [n2,s2,r9/?:{-}] applying preemptive snapshot at index 31 (id=4dfe225b, encoded size=17209, 1 rocksdb batches, 21 log entries)
I180410 18:14:45.984977 51829 storage/replica_raftstorage.go:732  [n2,s2,r9/?:/Table/1{2-3}] applied preemptive snapshot in 7ms [clear=0ms batch=0ms entries=6ms commit=0ms]
I180410 18:14:46.008375 50393 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]
I180410 18:14:46.034470 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:46.158026 50393 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
I180410 18:14:46.172883 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:46.179073 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot 316f0cad at index 55
I180410 18:14:46.217393 50393 storage/store.go:3834  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 79, log entries: 45, rate-limit: 8.0 MiB/sec, 12ms
I180410 18:14:46.221525 51805 storage/replica_raftstorage.go:726  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 55 (id=316f0cad, encoded size=38336, 1 rocksdb batches, 45 log entries)
I180410 18:14:46.257131 51805 storage/replica_raftstorage.go:732  [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 35ms [clear=0ms batch=0ms entries=33ms commit=1ms]
I180410 18:14:46.264488 50393 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]
I180410 18:14:46.339731 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:46.377821 50393 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
I180410 18:14:46.389895 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot 710a036a at index 24
I180410 18:14:46.407718 50393 storage/store.go:3834  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 11ms
I180410 18:14:46.422407 51880 storage/replica_raftstorage.go:726  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 24 (id=710a036a, encoded size=52204, 1 rocksdb batches, 9 log entries)
I180410 18:14:46.440209 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:46.525939 51880 storage/replica_raftstorage.go:732  [n2,s2,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 103ms [clear=0ms batch=0ms entries=92ms commit=10ms]
I180410 18:14:46.533932 50393 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]
I180410 18:14:46.542950 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:46.677928 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:46.688215 50393 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
I180410 18:14:46.733405 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot 823ab983 at index 27
I180410 18:14:46.788565 50393 storage/store.go:3834  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n2,s2):?: kv pairs: 19, log entries: 17, rate-limit: 8.0 MiB/sec, 9ms
I180410 18:14:46.792125 51955 storage/replica_raftstorage.go:726  [n2,s2,r12/?:{-}] applying preemptive snapshot at index 27 (id=823ab983, encoded size=8123, 1 rocksdb batches, 17 log entries)
I180410 18:14:46.826040 51955 storage/replica_raftstorage.go:732  [n2,s2,r12/?:/Table/1{5-6}] applied preemptive snapshot in 10ms [clear=0ms batch=0ms entries=4ms commit=0ms]
I180410 18:14:46.827965 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:46.855022 50393 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]
I180410 18:14:46.972090 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:47.008481 50393 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
I180410 18:14:47.069705 50393 storage/replica_raftstorage.go:520  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 5730fc51 at index 47
I180410 18:14:47.079187 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:47.085441 50393 storage/store.go:3834  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n2,s2):?: kv pairs: 40, log entries: 2, rate-limit: 8.0 MiB/sec, 7ms
I180410 18:14:47.089958 51943 storage/replica_raftstorage.go:726  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 47 (id=5730fc51, encoded size=69487, 1 rocksdb batches, 2 log entries)
I180410 18:14:47.097427 51943 storage/replica_raftstorage.go:732  [n2,s2,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 7ms [clear=0ms batch=0ms entries=5ms commit=1ms]
I180410 18:14:47.116752 50393 storage/replica_command.go:1779  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, next=2]
I180410 18:14:47.190997 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:47.193123 50393 storage/replica.go:3340  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 18:14:47.231363 50393 storage/queue.go:847  [n1,replicate] purgatory is now empty
I180410 18:14:47.235349 51970 storage/replica_raftstorage.go:520  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot b6ba3ba4 at index 80
I180410 18:14:47.289056 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:47.298122 51970 storage/store.go:3834  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 234, log entries: 70, rate-limit: 8.0 MiB/sec, 62ms
I180410 18:14:47.302170 51973 storage/replica_raftstorage.go:726  [n2,s2,r10/?:{-}] applying preemptive snapshot at index 80 (id=b6ba3ba4, encoded size=69271, 1 rocksdb batches, 70 log entries)
I180410 18:14:47.323375 51973 storage/replica_raftstorage.go:732  [n2,s2,r10/?:/Table/1{3-4}] applied preemptive snapshot in 21ms [clear=0ms batch=0ms entries=19ms commit=1ms]
I180410 18:14:47.331807 51970 storage/replica_command.go:1779  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, (n3,s3):2, next=3]
I180410 18:14:47.386001 51970 storage/replica.go:3340  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180410 18:14:47.404459 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 18:14:47.444082 51867 storage/replica_raftstorage.go:520  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot d34f3fcc at index 50
I180410 18:14:47.489316 51867 storage/store.go:3834  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 41, log entries: 5, rate-limit: 8.0 MiB/sec, 44ms
I180410 18:14:47.493547 51870 storage/replica_raftstorage.go:726  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 50 (id=d34f3fcc, encoded size=70672, 1 rocksdb batches, 5 log entries)
I180410 18:14:47.519572 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180410 18:14:47.537563 51870 storage/replica_raftstorage.go:732  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 29ms [clear=0ms batch=0ms entries=15ms commit=13ms]
I180410 18:14:47.553567 51867 storage/replica_command.go:1779  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, (n2,s2):2, next=3]
I180410 18:14:47.627471 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180410 18:14:47.749796 51867 storage/replica.go:3340  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180410 18:14:47.757693 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180410 18:14:47.856648 52039 storage/replica_raftstorage.go:520  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot 34213a61 at index 21
I180410 18:14:47.879639 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 17 underreplicated ranges
I180410 18:14:47.888996 52039 storage/store.go:3834  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 11, rate-limit: 8.0 MiB/sec, 31ms
I180410 18:14:47.899329 52042 storage/replica_raftstorage.go:726  [n3,s3,r15/?:{-}] applying preemptive snapshot at index 21 (id=34213a61, encoded size=3554, 1 rocksdb batches, 11 log entries)
I180410 18:14:47.904842 52042 storage/replica_raftstorage.go:732  [n3,s3,r15/?:/Table/1{8-9}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=4ms commit=0ms]
I180410 18:14:47.919602 52039 storage/replica_command.go:1779  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, (n2,s2):2, next=3]
I180410 18:14:47.983124 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 17 underreplicated ranges
I180410 18:14:48.018821 52039 storage/replica.go:3340  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180410 18:14:48.047954 52030 storage/replica_raftstorage.go:520  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot c01533a1 at index 30
I180410 18:14:48.082762 52030 storage/store.go:3834  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n3,s3):?: kv pairs: 20, log entries: 20, rate-limit: 8.0 MiB/sec, 34ms
I180410 18:14:48.098157 52044 storage/replica_raftstorage.go:726  [n3,s3,r12/?:{-}] applying preemptive snapshot at index 30 (id=c01533a1, encoded size=9153, 1 rocksdb batches, 20 log entries)
I180410 18:14:48.105315 52044 storage/replica_raftstorage.go:732  [n3,s3,r12/?:/Table/1{5-6}] applied preemptive snapshot in 7ms [clear=0ms batch=0ms entries=5ms commit=0ms]
I180410 18:14:48.125520 52030 storage/replica_command.go:1779  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, (n2,s2):2, next=3]
I180410 18:14:48.156266 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 16 underreplicated ranges
I180410 18:14:48.258747 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 16 underreplicated ranges
I180410 18:14:48.275052 52030 storage/replica.go:3340  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180410 18:14:48.331103 52055 storage/replica_raftstorage.go:520  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 059dd5a7 at index 29
I180410 18:14:48.397218 52055 storage/store.go:3834  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n3,s3):?: kv pairs: 967, log entries: 2, rate-limit: 8.0 MiB/sec, 57ms
I180410 18:14:48.400381 52100 storage/replica_raftstorage.go:726  [n3,s3,r5/?:{-}] applying preemptive snapshot at index 29 (id=059dd5a7, encoded size=152787, 1 rocksdb batches, 2 log entries)
I180410 18:14:48.410494 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 15 underreplicated ranges
I180410 18:14:48.449509 52100 storage/replica_raftstorage.go:732  [n3,s3,r5/?:/System/ts{d-e}] applied preemptive snapshot in 49ms [clear=0ms batch=1ms entries=46ms commit=1ms]
I180410 18:14:48.489881 52055 storage/replica_command.go:1779  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, (n2,s2):2, next=3]
I180410 18:14:48.557104 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 15 underreplicated ranges
I180410 18:14:48.641089 52055 storage/replica.go:3340  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180410 18:14:48.659748 52130 storage/replica_raftstorage.go:520  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 87bbe2dd at index 34
I180410 18:14:48.700196 52130 storage/store.go:3834  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 55, log entries: 24, rate-limit: 8.0 MiB/sec, 39ms
I180410 18:14:48.703963 52080 storage/replica_raftstorage.go:726  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 34 (id=87bbe2dd, encoded size=18234, 1 rocksdb batches, 24 log entries)
I180410 18:14:48.704217 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 14 underreplicated ranges
I180410 18:14:48.761181 52080 storage/replica_raftstorage.go:732  [n3,s3,r9/?:/Table/1{2-3}] applied preemptive snapshot in 57ms [clear=0ms batch=0ms entries=10ms commit=0ms]
I180410 18:14:48.780562 52130 storage/replica_command.go:1779  [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]
I180410 18:14:48.822034 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 14 underreplicated ranges
I180410 18:14:48.906013 52130 storage/replica.go:3340  [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
I180410 18:14:48.932422 50139 testutils/testcluster/testcluster.go:534  [n1,s1] has 14 underreplicated ranges
I180410 18:14:48.956986 52162 storage/replica_raftstorage.go:520  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot be9752c9 at index 58
I180410 18:14:48.976200 52162 storage/store.go:3834  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):?: kv pairs: 80, log entries: 48, rate-limit: 8.0 MiB/sec, 18ms
I180410 18:14:48.982397 52107 storage/replica_raftstorage.go:726  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 58 (id=be9752c9, encoded size=39366, 1 rocksdb batches, 48 log entries)
I180410 18:14:49.027536 52107 storage/replica_raftstorage.go:732  [n3,s3,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 34ms [clear=0ms batch=0ms entries=32ms commit=0ms]
I180410 18:14:49.0331

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the 2.1 milestone Apr 10, 2018
@cockroach-teamcity cockroach-teamcity added O-robot Originated from a bot. C-test-failure Broken test (automatically or manually discovered). labels Apr 10, 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