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

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

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

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:

#594883:

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

------- Stdout: -------
W180409 22:03:51.691501 47174 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180409 22:03:51.754542 47174 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180409 22:03:51.782952 47174 server/config.go:538  [n?] 1 storage engine initialized
I180409 22:03:51.783166 47174 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180409 22:03:51.783224 47174 server/config.go:541  [n?] store 0: in-memory, size 0 B
I180409 22:03:51.956668 47174 server/node.go:374  [n?] **** cluster bf28dff6-23e7-4b62-9495-e74aa24185ab has been created
I180409 22:03:51.956885 47174 server/server.go:1305  [n?] **** add additional nodes by specifying --join=127.0.0.1:44679
I180409 22:03:52.044467 47136 kv/dist_sender.go:368  [n1] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180409 22:03:52.050832 47174 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=1, 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 22:03:52.051301 47174 server/node.go:352  [n1] node ID 1 initialized
I180409 22:03:52.051752 47174 gossip/gossip.go:332  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:44679" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180409 22:03:52.052770 47174 storage/stores.go:309  [n1] read 0 node addresses from persistent storage
I180409 22:03:52.053244 47174 server/node.go:653  [n1] connecting to gossip network to verify cluster ID...
I180409 22:03:52.053425 47174 server/node.go:678  [n1] node connected via gossip and verified as part of cluster "bf28dff6-23e7-4b62-9495-e74aa24185ab"
I180409 22:03:52.067163 47174 server/node.go:446  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180409 22:03:52.070614 47174 server/server.go:1431  [n1] starting https server at 127.0.0.1:44493
I180409 22:03:52.070818 47174 server/server.go:1432  [n1] starting grpc/postgres server at 127.0.0.1:44679
I180409 22:03:52.070888 47174 server/server.go:1433  [n1] advertising CockroachDB node at 127.0.0.1:44679
W180409 22:03:52.071233 47174 sql/jobs/registry.go:286  [n1] unable to get node liveness: node not in the liveness table
I180409 22:03:52.195166 47135 storage/replica_command.go:862  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180409 22:03:52.959959 47311 storage/replica_command.go:862  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180409 22:03:53.150984 47174 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}
I180409 22:03:53.194947 47491 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 22:03:53.651724 47470 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 22:03:53.859567 47174 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:node}
I180409 22:03:53.894568 47539 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 22:03:54.140522 47472 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 22:03:54.200626 47487 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=4a8347bb key=/Table/SystemConfigSpan/Start rw=true pri=0.04207748 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523311433.908136052,0 orig=1523311433.908136052,0 max=1523311433.908136052,0 wto=false rop=false seq=8
I180409 22:03:54.216381 47174 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}
I180409 22:03:54.288633 47554 storage/replica_command.go:862  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180409 22:03:54.562333 47572 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 22:03:54.764598 47457 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 22:03:54.973500 47619 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 22:03:55.180118 47594 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 22:03:55.337437 47174 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 22:03:55.401128 47553 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 22:03:55.529168 47174 sql/lease.go:352  [n1] publish: descID=4 (users) version=2 mtime=2018-04-09 22:03:55.522585078 +0000 UTC
I180409 22:03:55.597042 47630 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 22:03:55.839384 47642 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 22:03:55.930675 47174 sql/lease.go:352  [n1] publish: descID=4 (users) version=3 mtime=2018-04-09 22:03:55.927009572 +0000 UTC
W180409 22:03:55.971217 47645 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=8ea3554a key=/Local/Range/Table/17/RangeDescriptor rw=true pri=0.03717942 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523311435.839600238,0 orig=1523311435.839600238,0 max=1523311435.839600238,0 wto=false rop=false seq=3
I180409 22:03:55.984405 47674 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 22:03:56.215549 47567 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 22:03:56.232529 47174 sql/backfill.go:134  [n1] Running backfill for "users", v=3, m=1
I180409 22:03:56.417850 47665 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 22:03:56.639175 47746 storage/replica_command.go:862  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180409 22:03:56.738994 47174 sql/lease.go:352  [n1] publish: descID=4 (users) version=4 mtime=2018-04-09 22:03:56.737243473 +0000 UTC
I180409 22:03:56.897750 47681 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 22:03:57.056112 47174 sql/event_log.go:121  [n1] Event: "finish_schema_change", target: 4, info: {MutationID:1}
I180409 22:03:57.140297 47781 sql/lease.go:812  new lease: 4("users") ver=4:1523311735.554284971,0, refcount=0
I180409 22:03:57.149912 47174 sql/lease.go:275  publish (count leases): descID=4 name=users version=3 count=1
I180409 22:03:57.200067 47174 sql/lease.go:275  publish (count leases): descID=4 name=users version=3 count=1
I180409 22:03:57.951047 47174 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:node}
I180409 22:03:58.000218 47174 server/server.go:1511  [n1] done ensuring all necessary migrations have run
I180409 22:03:58.000441 47174 server/server.go:1514  [n1] serving sql connections
I180409 22:03:58.046235 47813 sql/event_log.go:121  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:44679} Attrs: Locality: ServerVersion:2.0-3} ClusterID:bf28dff6-23e7-4b62-9495-e74aa24185ab StartedAt:1523311432053489470 LastUp:1523311432053489470}
W180409 22:03:58.297916 47174 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180409 22:03:58.437214 47174 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180409 22:03:58.443650 47174 server/config.go:538  [n?] 1 storage engine initialized
I180409 22:03:58.443901 47174 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180409 22:03:58.443984 47174 server/config.go:541  [n?] store 0: in-memory, size 0 B
W180409 22:03:58.444364 47174 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180409 22:03:58.444993 47174 server/server.go:1307  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180409 22:03:58.728920 47873 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:44679
I180409 22:03:58.732787 47741 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:46495}
I180409 22:03:58.748551 47174 storage/stores.go:309  [n?] read 0 node addresses from persistent storage
I180409 22:03:58.749762 47174 server/node.go:653  [n?] connecting to gossip network to verify cluster ID...
I180409 22:03:58.751169 47174 server/node.go:678  [n?] node connected via gossip and verified as part of cluster "bf28dff6-23e7-4b62-9495-e74aa24185ab"
I180409 22:03:58.755677 47835 storage/stores.go:328  [n?] wrote 1 node addresses to persistent storage
I180409 22:03:58.806281 47174 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180409 22:03:58.821703 47174 server/node.go:345  [n?] new node allocated ID 2
I180409 22:03:58.822452 47174 gossip/gossip.go:332  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:46495" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180409 22:03:58.823483 47174 server/node.go:427  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180409 22:03:58.824144 47174 server/node.go:446  [n2] node=2: started with [] engine(s) and attributes []
I180409 22:03:58.827326 47174 server/server.go:1431  [n2] starting https server at 127.0.0.1:38153
I180409 22:03:58.827542 47174 server/server.go:1432  [n2] starting grpc/postgres server at 127.0.0.1:46495
I180409 22:03:58.827625 47174 server/server.go:1433  [n2] advertising CockroachDB node at 127.0.0.1:46495
W180409 22:03:58.827981 47174 sql/jobs/registry.go:286  [n2] unable to get node liveness: node not in the liveness table
I180409 22:03:58.857575 47899 storage/stores.go:328  [n1] wrote 1 node addresses to persistent storage
I180409 22:03:58.862766 47174 server/server.go:1511  [n2] done ensuring all necessary migrations have run
I180409 22:03:58.877956 47174 server/server.go:1514  [n2] serving sql connections
I180409 22:03:59.098340 47908 server/node.go:634  [n2] bootstrapped store [n2,s2]
I180409 22:03:59.106870 47888 sql/event_log.go:121  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:46495} Attrs: Locality: ServerVersion:2.0-3} ClusterID:bf28dff6-23e7-4b62-9495-e74aa24185ab StartedAt:1523311438823810962 LastUp:1523311438823810962}
W180409 22:03:59.327602 47174 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180409 22:03:59.465444 47174 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180409 22:03:59.472025 47174 server/config.go:538  [n?] 1 storage engine initialized
I180409 22:03:59.472224 47174 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180409 22:03:59.472306 47174 server/config.go:541  [n?] store 0: in-memory, size 0 B
W180409 22:03:59.472719 47174 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180409 22:03:59.473478 47174 server/server.go:1307  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180409 22:03:59.836699 47983 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:44679
I180409 22:03:59.843491 48065 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:45403}
I180409 22:03:59.886622 47174 storage/stores.go:309  [n?] read 0 node addresses from persistent storage
I180409 22:03:59.887214 47174 storage/stores.go:328  [n?] wrote 2 node addresses to persistent storage
I180409 22:03:59.887362 47174 server/node.go:653  [n?] connecting to gossip network to verify cluster ID...
I180409 22:03:59.887578 47174 server/node.go:678  [n?] node connected via gossip and verified as part of cluster "bf28dff6-23e7-4b62-9495-e74aa24185ab"
I180409 22:03:59.906085 47174 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180409 22:03:59.938907 47174 server/node.go:345  [n?] new node allocated ID 3
I180409 22:03:59.939720 47174 gossip/gossip.go:332  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:45403" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180409 22:03:59.940713 47174 server/node.go:427  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180409 22:03:59.941372 47174 server/node.go:446  [n3] node=3: started with [] engine(s) and attributes []
I180409 22:03:59.951594 48139 storage/stores.go:328  [n1] wrote 2 node addresses to persistent storage
I180409 22:03:59.957874 47174 server/server.go:1431  [n3] starting https server at 127.0.0.1:41803
I180409 22:03:59.965855 47174 server/server.go:1432  [n3] starting grpc/postgres server at 127.0.0.1:45403
I180409 22:03:59.966190 47174 server/server.go:1433  [n3] advertising CockroachDB node at 127.0.0.1:45403
I180409 22:03:59.968054 48274 storage/stores.go:328  [n2] wrote 2 node addresses to persistent storage
I180409 22:03:59.975035 47174 server/server.go:1511  [n3] done ensuring all necessary migrations have run
I180409 22:03:59.975319 47174 server/server.go:1514  [n3] serving sql connections
I180409 22:04:00.098984 48079 server/node.go:634  [n3] bootstrapped store [n3,s3]
I180409 22:04:00.140921 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot 4c275c08 at index 26
I180409 22:04:00.181436 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:00.291895 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:00.324139 48277 sql/event_log.go:121  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:45403} Attrs: Locality: ServerVersion:2.0-3} ClusterID:bf28dff6-23e7-4b62-9495-e74aa24185ab StartedAt:1523311439941040802 LastUp:1523311439941040802}
I180409 22:04:00.327225 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:00.385190 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:00.477370 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:00.552965 47411 storage/replica_proposal.go:202  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311440.518778243,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:00.572621 47415 storage/replica_proposal.go:202  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311440.567117659,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:00.603648 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:00.666089 47313 storage/store.go:3834  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n2,s2):?: kv pairs: 18, log entries: 16, rate-limit: 8.0 MiB/sec, 17ms
I180409 22:04:00.673767 48287 storage/replica_raftstorage.go:726  [n2,s2,r12/?:{-}] applying preemptive snapshot at index 26 (id=4c275c08, encoded size=7755, 1 rocksdb batches, 16 log entries)
I180409 22:04:00.679445 48287 storage/replica_raftstorage.go:732  [n2,s2,r12/?:/Table/1{5-6}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=3ms commit=1ms]
I180409 22:04:00.691557 47313 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 22:04:00.704225 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:00.839363 47227 storage/replica_proposal.go:202  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311440.766199032,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:00.855075 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:00.917077 47313 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 22:04:00.931620 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 6322b150 at index 25
I180409 22:04:00.961432 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:00.975850 48377 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180409 22:04:00.980131 47313 storage/store.go:3834  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 15, rate-limit: 8.0 MiB/sec, 47ms
I180409 22:04:00.985023 48271 storage/replica_raftstorage.go:726  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 25 (id=6322b150, encoded size=5180, 1 rocksdb batches, 15 log entries)
I180409 22:04:00.996855 48271 storage/replica_raftstorage.go:732  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 11ms [clear=0ms batch=0ms entries=8ms commit=1ms]
I180409 22:04:01.037085 47313 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 22:04:01.132288 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:01.133756 47378 storage/replica_proposal.go:202  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311441.129254265,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:01.206286 47313 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 22:04:01.225638 47387 storage/replica_proposal.go:202  [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311441.218059486,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:01.235739 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot f61ac6d4 at index 18
I180409 22:04:01.319046 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:01.434464 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:01.564043 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:01.608762 47313 storage/store.go:3834  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 50ms
I180409 22:04:01.612160 48458 storage/replica_raftstorage.go:726  [n3,s3,r17/?:{-}] applying preemptive snapshot at index 18 (id=f61ac6d4, encoded size=2394, 1 rocksdb batches, 8 log entries)
I180409 22:04:01.615889 48458 storage/replica_raftstorage.go:732  [n3,s3,r17/?:/Table/2{0-1}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=1ms]
I180409 22:04:01.621611 47313 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 22:04:01.663256 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:01.713308 47313 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 22:04:01.737819 47401 storage/replica_proposal.go:202  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311441.729181130,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:01.772188 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot b729184e at index 16
I180409 22:04:01.782298 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:01.785641 48504 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180409 22:04:01.799519 47416 storage/replica_proposal.go:202  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311441.791721452,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:01.803074 47313 storage/store.go:3834  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 7, log entries: 6, rate-limit: 8.0 MiB/sec, 30ms
I180409 22:04:01.835537 48414 storage/replica_raftstorage.go:726  [n3,s3,r18/?:{-}] applying preemptive snapshot at index 16 (id=b729184e, encoded size=2094, 1 rocksdb batches, 6 log entries)
I180409 22:04:01.839504 48414 storage/replica_raftstorage.go:732  [n3,s3,r18/?:/Table/2{1-2}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180409 22:04:01.845137 47313 storage/replica_command.go:1779  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, next=2]
I180409 22:04:01.902319 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:01.996507 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:02.024855 47313 storage/replica.go:3340  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 22:04:02.074116 47431 server/status/runtime.go:219  [n1] runtime stats: 1.3 GiB RSS, 601 goroutines, 35 MiB/86 MiB/143 MiB GO alloc/idle/total, 84 MiB/126 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (303x)
I180409 22:04:02.108445 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:02.109042 47370 storage/replica_proposal.go:202  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311442.092981011,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:02.191391 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot ee5fb5c4 at index 19
I180409 22:04:02.217071 47379 storage/replica_proposal.go:202  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311442.200357757,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:02.219792 47313 storage/store.go:3834  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 24ms
I180409 22:04:02.223324 48562 storage/replica_raftstorage.go:726  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 19 (id=ee5fb5c4, encoded size=2556, 1 rocksdb batches, 9 log entries)
I180409 22:04:02.235141 48562 storage/replica_raftstorage.go:732  [n2,s2,r11/?:/Table/1{4-5}] applied preemptive snapshot in 11ms [clear=0ms batch=0ms entries=1ms commit=9ms]
I180409 22:04:02.251075 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:02.252860 47313 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 22:04:02.346643 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:02.372690 47313 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 22:04:02.408859 47397 storage/replica_proposal.go:202  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311442.378219948,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:02.436901 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot e7bda288 at index 46
I180409 22:04:02.446512 47313 storage/store.go:3834  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 39, log entries: 36, rate-limit: 8.0 MiB/sec, 8ms
I180409 22:04:02.460224 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:02.507837 48526 storage/replica_raftstorage.go:726  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 46 (id=e7bda288, encoded size=115010, 1 rocksdb batches, 36 log entries)
I180409 22:04:02.597865 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:02.626028 48526 storage/replica_raftstorage.go:732  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 118ms [clear=0ms batch=0ms entries=116ms commit=1ms]
I180409 22:04:02.659356 47313 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 22:04:02.703209 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:02.706036 47313 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 22:04:02.767993 48564 storage/replica_raftstorage.go:520  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot 71bdc291 at index 30
I180409 22:04:02.774932 48564 storage/store.go:3834  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n3,s3):?: kv pairs: 19, log entries: 20, rate-limit: 8.0 MiB/sec, 6ms
I180409 22:04:02.778255 48627 storage/replica_raftstorage.go:726  [n3,s3,r12/?:{-}] applying preemptive snapshot at index 30 (id=71bdc291, encoded size=8962, 1 rocksdb batches, 20 log entries)
I180409 22:04:02.791996 48627 storage/replica_raftstorage.go:732  [n3,s3,r12/?:/Table/1{5-6}] applied preemptive snapshot in 13ms [clear=0ms batch=0ms entries=12ms commit=0ms]
I180409 22:04:02.811456 48564 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]
I180409 22:04:02.834907 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:02.939428 48564 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
I180409 22:04:02.949775 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 22:04:02.966134 47233 storage/replica_proposal.go:202  [n1,s1,r20/1:/{Table/23-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311442.961929046,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:02.982408 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot 6c7d4ddc at index 15
I180409 22:04:02.988356 47313 storage/store.go:3834  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 5, rate-limit: 8.0 MiB/sec, 5ms
I180409 22:04:02.991210 48619 storage/replica_raftstorage.go:726  [n3,s3,r20/?:{-}] applying preemptive snapshot at index 15 (id=6c7d4ddc, encoded size=1171, 1 rocksdb batches, 5 log entries)
I180409 22:04:02.999622 48619 storage/replica_raftstorage.go:732  [n3,s3,r20/?:/{Table/23-Max}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180409 22:04:03.015364 47313 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 22:04:03.049149 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:03.145135 47313 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 22:04:03.164019 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:03.180731 47383 storage/replica_proposal.go:202  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311443.174800223,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:03.197053 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot ee5abf7e at index 31
I180409 22:04:03.212114 47313 storage/store.go:3834  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 53, log entries: 21, rate-limit: 8.0 MiB/sec, 14ms
I180409 22:04:03.217258 48651 storage/replica_raftstorage.go:726  [n2,s2,r9/?:{-}] applying preemptive snapshot at index 31 (id=ee5abf7e, encoded size=17071, 1 rocksdb batches, 21 log entries)
I180409 22:04:03.235990 48651 storage/replica_raftstorage.go:732  [n2,s2,r9/?:/Table/1{2-3}] applied preemptive snapshot in 18ms [clear=0ms batch=0ms entries=10ms commit=0ms]
I180409 22:04:03.253235 47313 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 22:04:03.277913 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:03.361041 47313 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 22:04:03.395030 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot 3141b00d at index 18
I180409 22:04:03.397613 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:03.406858 47313 storage/store.go:3834  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 8ms
I180409 22:04:03.431412 48572 storage/replica_raftstorage.go:726  [n3,s3,r13/?:{-}] applying preemptive snapshot at index 18 (id=3141b00d, encoded size=2394, 1 rocksdb batches, 8 log entries)
I180409 22:04:03.446272 48572 storage/replica_raftstorage.go:732  [n3,s3,r13/?:/Table/1{6-7}] applied preemptive snapshot in 14ms [clear=0ms batch=0ms entries=13ms commit=0ms]
I180409 22:04:03.504657 47313 storage/replica_command.go:1779  [replicate,n1,s1,r13/1:/Table/1{6-7}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, next=2]
I180409 22:04:03.536951 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:03.545486 47413 storage/replica_proposal.go:202  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311443.527601426,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:03.680794 47313 storage/replica.go:3340  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 22:04:03.712005 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:03.734580 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 76a1faea at index 85
I180409 22:04:03.764034 47313 storage/store.go:3834  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 61, log entries: 9, rate-limit: 8.0 MiB/sec, 27ms
I180409 22:04:03.768825 48698 storage/replica_raftstorage.go:726  [n2,s2,r1/?:{-}] applying preemptive snapshot at index 85 (id=76a1faea, encoded size=4110, 1 rocksdb batches, 9 log entries)
I180409 22:04:03.780461 48698 storage/replica_raftstorage.go:732  [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 11ms [clear=0ms batch=0ms entries=7ms commit=3ms]
I180409 22:04:03.845153 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:03.847431 47313 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]
I180409 22:04:03.962579 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:03.974438 47313 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
I180409 22:04:04.043533 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot 81c60040 at index 18
I180409 22:04:04.096272 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:04.098160 47313 storage/store.go:3834  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 37ms
I180409 22:04:04.101248 48742 storage/replica_raftstorage.go:726  [n2,s2,r16/?:{-}] applying preemptive snapshot at index 18 (id=81c60040, encoded size=2394, 1 rocksdb batches, 8 log entries)
I180409 22:04:04.104965 48742 storage/replica_raftstorage.go:732  [n2,s2,r16/?:/Table/{19-20}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180409 22:04:04.111349 47313 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 22:04:04.194953 47313 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 22:04:04.284640 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:04.289649 47407 storage/replica_proposal.go:202  [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311444.278570478,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:04.318725 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot 40eac040 at index 18
I180409 22:04:04.324610 47313 storage/store.go:3834  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 5ms
I180409 22:04:04.328248 48716 storage/replica_raftstorage.go:726  [n2,s2,r19/?:{-}] applying preemptive snapshot at index 18 (id=40eac040, encoded size=2394, 1 rocksdb batches, 8 log entries)
I180409 22:04:04.339441 48716 storage/replica_raftstorage.go:732  [n2,s2,r19/?:/Table/2{2-3}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180409 22:04:04.344985 47313 storage/replica_command.go:1779  [replicate,n1,s1,r19/1:/Table/2{2-3}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, next=2]
I180409 22:04:04.402397 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:04.460582 47313 storage/replica.go:3340  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180409 22:04:04.533533 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot 48a05481 at index 51
I180409 22:04:04.610318 47313 storage/store.go:3834  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):?: kv pairs: 75, log entries: 41, rate-limit: 8.0 MiB/sec, 20ms
I180409 22:04:04.620380 48671 storage/replica_raftstorage.go:726  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 51 (id=48a05481, encoded size=36320, 1 rocksdb batches, 41 log entries)
I180409 22:04:04.634445 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:04.664162 48671 storage/replica_raftstorage.go:732  [n3,s3,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 37ms [clear=0ms batch=0ms entries=35ms commit=1ms]
I180409 22:04:04.678727 47313 storage/replica_command.go:1779  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, next=2]
I180409 22:04:04.731121 47313 storage/replica.go:3340  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 22:04:04.795643 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:04.799676 47382 storage/replica_proposal.go:202  [n1,s1,r6/1:/{System/tse-Table/System…}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311444.772996383,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:04.818558 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot aa0d793b at index 21
I180409 22:04:04.834404 47313 storage/store.go:3834  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 4ms
I180409 22:04:04.837638 48821 storage/replica_raftstorage.go:726  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 21 (id=aa0d793b, encoded size=4285, 1 rocksdb batches, 11 log entries)
I180409 22:04:04.866298 48821 storage/replica_raftstorage.go:732  [n2,s2,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 26ms [clear=0ms batch=0ms entries=25ms commit=0ms]
I180409 22:04:04.883523 47313 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 22:04:04.928234 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:04.961579 47313 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 22:04:04.970498 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot 6dcb635c at index 67
I180409 22:04:04.998556 47313 storage/store.go:3834  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 202, log entries: 57, rate-limit: 8.0 MiB/sec, 27ms
I180409 22:04:05.002754 48808 storage/replica_raftstorage.go:726  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 67 (id=6dcb635c, encoded size=57192, 1 rocksdb batches, 57 log entries)
I180409 22:04:05.027212 48808 storage/replica_raftstorage.go:732  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 24ms [clear=0ms batch=0ms entries=22ms commit=1ms]
I180409 22:04:05.037488 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:05.046571 47313 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]
I180409 22:04:05.155222 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:05.224661 47313 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
I180409 22:04:05.245557 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot cec74c5b at index 18
I180409 22:04:05.259569 47313 storage/store.go:3834  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 7ms
I180409 22:04:05.267023 48812 storage/replica_raftstorage.go:726  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 18 (id=cec74c5b, encoded size=2394, 1 rocksdb batches, 8 log entries)
I180409 22:04:05.270005 48812 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]
I180409 22:04:05.279409 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:05.281876 47313 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 22:04:05.397417 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:05.413313 47313 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 22:04:05.428228 47373 storage/replica_proposal.go:202  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311445.424044853,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:05.470165 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 54e45b28 at index 18
I180409 22:04:05.486580 47313 storage/store.go:3834  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 11ms
I180409 22:04:05.490076 48887 storage/replica_raftstorage.go:726  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 18 (id=54e45b28, encoded size=2394, 1 rocksdb batches, 8 log entries)
I180409 22:04:05.503983 48887 storage/replica_raftstorage.go:732  [n2,s2,r14/?:/Table/1{7-8}] applied preemptive snapshot in 14ms [clear=0ms batch=0ms entries=1ms commit=11ms]
I180409 22:04:05.527010 47313 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 22:04:05.553204 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:05.711132 47313 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 22:04:05.719822 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:05.721021 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 5be492e1 at index 26
I180409 22:04:05.833924 47313 storage/store.go:3834  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 965, log entries: 2, rate-limit: 8.0 MiB/sec, 112ms
I180409 22:04:05.861308 48914 storage/replica_raftstorage.go:726  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 26 (id=5be492e1, encoded size=152659, 1 rocksdb batches, 2 log entries)
I180409 22:04:05.870532 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:05.915672 48914 storage/replica_raftstorage.go:732  [n2,s2,r5/?:/System/ts{d-e}] applied preemptive snapshot in 54ms [clear=0ms batch=2ms entries=47ms commit=2ms]
I180409 22:04:05.922561 47313 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 22:04:06.003054 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:06.007135 47313 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 22:04:06.047193 47232 storage/replica_proposal.go:202  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1523311431.971061041,0 epo=1 pro=1523311446.035171868,0 following repl=(n1,s1):1 seq=2 start=1523311431.971061041,0 exp=1523311441.015365391,0 pro=1523311432.015447323,0
I180409 22:04:06.063466 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot 2454b2d5 at index 25
I180409 22:04:06.080210 47313 storage/store.go:3834  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 15, rate-limit: 8.0 MiB/sec, 14ms
I180409 22:04:06.082932 48947 storage/replica_raftstorage.go:726  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 25 (id=2454b2d5, encoded size=5550, 1 rocksdb batches, 15 log entries)
I180409 22:04:06.101441 48947 storage/replica_raftstorage.go:732  [n3,s3,r8/?:/Table/1{1-2}] applied preemptive snapshot in 17ms [clear=0ms batch=0ms entries=11ms commit=2ms]
I180409 22:04:06.105663 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:06.112942 47313 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 22:04:06.188485 47313 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 22:04:06.225416 47313 storage/replica_raftstorage.go:520  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot 46e7998c at index 24
I180409 22:04:06.230333 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:06.248091 47313 storage/store.go:3834  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 14, rate-limit: 8.0 MiB/sec, 17ms
I180409 22:04:06.252054 48941 storage/replica_raftstorage.go:726  [n3,s3,r2/?:{-}] applying preemptive snapshot at index 24 (id=46e7998c, encoded size=22545, 1 rocksdb batches, 14 log entries)
I180409 22:04:06.265363 48941 storage/replica_raftstorage.go:732  [n3,s3,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 11ms [clear=0ms batch=0ms entries=9ms commit=0ms]
I180409 22:04:06.309716 47313 storage/replica_command.go:1779  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, next=2]
I180409 22:04:06.348767 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:06.403239 47313 storage/replica.go:3340  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 22:04:06.448830 47313 storage/queue.go:847  [n1,replicate] purgatory is now empty
I180409 22:04:06.459840 48974 storage/replica_raftstorage.go:520  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot b8805786 at index 51
I180409 22:04:06.478619 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:06.541134 48974 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, 80ms
I180409 22:04:06.566682 48926 storage/replica_raftstorage.go:726  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 51 (id=b8805786, encoded size=69498, 1 rocksdb batches, 2 log entries)
I180409 22:04:06.575083 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:06.592430 48926 storage/replica_raftstorage.go:732  [n2,s2,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 25ms [clear=0ms batch=2ms entries=21ms commit=2ms]
I180409 22:04:06.598839 48974 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 22:04:06.693658 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:06.812991 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 22:04:06.832005 48956 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 22:04:06.853022 49001 storage/replica_raftstorage.go:520  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot 2711232b at index 27
I180409 22:04:06.859822 49001 storage/store.go:3834  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 17, rate-limit: 8.0 MiB/sec, 6ms
I180409 22:04:06.874031 49003 storage/replica_raftstorage.go:726  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 27 (id=2711232b, encoded size=23617, 1 rocksdb batches, 17 log entries)
I180409 22:04:06.919118 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180409 22:04:06.924084 49003 storage/replica_raftstorage.go:732  [n2,s2,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 50ms [clear=0ms batch=0ms entries=7ms commit=0ms]
I180409 22:04:06.930852 49001 storage/replica_command.go:1779  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, (n3,s3):2, next=3]
I180409 22:04:07.024303 49001 storage/replica.go:3340  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180409 22:04:07.033812 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180409 22:04:07.066566 49048 storage/replica_raftstorage.go:520  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot b685959a at index 33
I180409 22:04:07.097974 49048 storage/store.go:3834  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n3,s3):?: kv pairs: 17, log entries: 23, rate-limit: 8.0 MiB/sec, 19ms
I180409 22:04:07.101339 49079 storage/replica_raftstorage.go:726  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 33 (id=b685959a, encoded size=7314, 1 rocksdb batches, 23 log entries)
I180409 22:04:07.126531 49079 storage/replica_raftstorage.go:732  [n3,s3,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 25ms [clear=0ms batch=0ms entries=20ms commit=4ms]
I180409 22:04:07.145799 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 17 underreplicated ranges
I180409 22:04:07.152859 49048 storage/replica_command.go:1779  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, next=3]
I180409 22:04:07.238839 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 17 underreplicated ranges
I180409 22:04:07.352160 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 17 underreplicated ranges
I180409 22:04:07.362319 49072 storage/replica.go:3340  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180409 22:04:07.407986 49122 storage/replica_raftstorage.go:520  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot 1dfdd03a at index 21
I180409 22:04:07.429884 49122 storage/store.go:3834  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 20ms
I180409 22:04:07.438751 49124 storage/replica_raftstorage.go:726  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 21 (id=1dfdd03a, encoded size=3426, 1 rocksdb batches, 11 log entries)
I180409 22:04:07.444996 49124 storage/replica_raftstorage.go:732  [n2,s2,r18/?:/Table/2{1-2}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=4ms commit=0ms]
I180409 22:04:07.462971 49122 storage/replica_command.go:1779  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, (n3,s3):2, next=3]
I180409 22:04:07.481019 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 16 underreplicated ranges
I180409 22:04:07.563130 49122 storage/replica.go:3340  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180409 22:04:07.601263 49119 storage/replica_raftstorage.go:520  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot bfe7d6eb at index 34
I180409 22:04:07.648790 49119 storage/store.go:3834  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 54, log entries: 24, rate-limit: 8.0 MiB/sec, 46ms
I180409 22:04:07.661179 49131 storage/replica_raftstorage.go:726  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 34 (id=bfe7d6eb, encoded size=18103, 1 rocksdb batches, 24 log entries)
I180409 22:04:07.667905 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 15 underreplicated ranges
I180409 22:04:07.670828 49131 storage/replica_raftstorage.go:732  [n3,s3,r9/?:/Table/1{2-3}] applied preemptive snapshot in 9ms [clear=0ms batch=0ms entries=8ms commit=0ms]
I180409 22:04:07.705930 49119 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]
I180409 22:04:07.791151 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 15 underreplicated ranges
I180409 22:04:07.792524 49202 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
I180409 22:04:07.876671 49219 storage/replica_raftstorage.go:520  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot d90704a3 at index 21
I180409 22:04:07.892253 49219 storage/store.go:3834  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 14ms
I180409 22:04:07.898079 49223 storage/replica_raftstorage.go:726  [n3,s3,r15/?:{-}] applying preemptive snapshot at index 21 (id=d90704a3, encoded size=3426, 1 rocksdb batches, 11 log entries)
I180409 22:04:07.901568 49223 storage/replica_raftstorage.go:732  [n3,s3,r15/?:/Table/1{8-9}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180409 22:04:07.902475 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 14 underreplicated ranges
I180409 22:04:07.975880 49219 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]
I180409 22:04:08.094708 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 14 underreplicated ranges
I180409 22:04:08.198904 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 14 underreplicated ranges
I180409 22:04:08.208393 49219 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
I180409 22:04:08.265554 49199 storage/replica_raftstorage.go:520  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot a470a53a at index 21
I180409 22:04:08.273807 49199 storage/store.go:3834  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 7ms
I180409 22:04:08.297451 49150 storage/replica_raftstorage.go:726  [n3,s3,r14/?:{-}] applying preemptive snapshot at index 21 (id=a470a53a, encoded size=3426, 1 rocksdb batches, 11 log entries)
I180409 22:04:08.307763 49150 storage/replica_raftstorage.go:732  [n3,s3,r14/?:/Table/1{7-8}] applied preemptive snapshot in 10ms [clear=0ms batch=0ms entries=2ms commit=1ms]
I180409 22:04:08.313281 49199 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 22:04:08.314764 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 13 underreplicated ranges
I180409 22:04:08.425479 47174 testutils/testcluster/testcluster.go:534  [n1,s1] has 13 underreplicated ranges
I180409 22:04:08.527983 49199 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 22:04:08.544555 49256 storage/replica_raftstorage.go:520  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot 2c7576ee at index 21
I180409 22:04:08.570404 49256 storage/store.go:3834  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 25ms
I180409 22:04:08.578151 49259 storage/replica_raftstorage.go:726  [n2,s2,r13/?:{-}] applying preemptive snapshot at index 21 (id=2c7576ee, encoded size=3426, 1 rocksdb batches, 11 log entries)
I180409 22:04:08.587537 49259 storage/replica_raftstorage.go:732  [n2,s2,r13/?:/Table/1{6-7}] applied preemptive snapshot in 9ms [clear=0ms batch=0ms entries=7ms commit=0ms]
I180409 22:04:08.588666 47174 testutils/testcluster/testcluster.g

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