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

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

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

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:

#594688:

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

------- Stdout: -------
W180409 19:39:02.534259 50135 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180409 19:39:02.671815 50135 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180409 19:39:02.687093 50135 server/config.go:538  [n?] 1 storage engine initialized
I180409 19:39:02.687400 50135 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180409 19:39:02.687517 50135 server/config.go:541  [n?] store 0: in-memory, size 0 B
I180409 19:39:02.828696 50135 util/stop/stopper.go:470  [n?] quiescing; tasks left:
1      [async] storage.pendingLeaseRequest: requesting lease
I180409 19:39:02.862714 50135 server/node.go:374  [n?] **** cluster 94a074eb-eb39-49e0-8bbd-d8b7f72a4ef2 has been created
I180409 19:39:02.862958 50135 server/server.go:1305  [n?] **** add additional nodes by specifying --join=127.0.0.1:39645
I180409 19:39:02.938559 50185 kv/dist_sender.go:368  [n1] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180409 19:39:02.947528 50135 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 19:39:02.948104 50135 server/node.go:352  [n1] node ID 1 initialized
I180409 19:39:02.949706 50135 gossip/gossip.go:332  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:39645" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180409 19:39:02.953621 50135 storage/stores.go:309  [n1] read 0 node addresses from persistent storage
I180409 19:39:02.955735 50135 server/node.go:653  [n1] connecting to gossip network to verify cluster ID...
I180409 19:39:02.957222 50135 server/node.go:678  [n1] node connected via gossip and verified as part of cluster "94a074eb-eb39-49e0-8bbd-d8b7f72a4ef2"
I180409 19:39:02.957787 50135 server/node.go:446  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180409 19:39:02.983065 50135 server/server.go:1431  [n1] starting https server at 127.0.0.1:38385
I180409 19:39:02.983317 50135 server/server.go:1432  [n1] starting grpc/postgres server at 127.0.0.1:39645
I180409 19:39:02.983411 50135 server/server.go:1433  [n1] advertising CockroachDB node at 127.0.0.1:39645
W180409 19:39:02.994948 50135 sql/jobs/registry.go:286  [n1] unable to get node liveness: node not in the liveness table
I180409 19:39:03.006275 50182 storage/replica_command.go:862  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180409 19:39:03.286843 50189 storage/replica_command.go:862  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180409 19:39:03.398076 50402 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=cb1f0723 key=/Table/SystemConfigSpan/Start rw=true pri=0.02824948 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523302743.141336326,0 orig=1523302743.141336326,0 max=1523302743.141336326,0 wto=false rop=false seq=7
I180409 19:39:03.540804 50135 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}
I180409 19:39:03.830219 50239 storage/replica_command.go:862  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
W180409 19:39:04.046402 50191 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=05d0a37e key=/Local/Range/System/NodeLiveness/RangeDescriptor rw=true pri=0.00240351 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523302743.830511691,0 orig=1523302743.830511691,0 max=1523302743.830511691,0 wto=false rop=false seq=3
I180409 19:39:04.102155 50405 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 19:39:04.372450 50408 storage/replica_command.go:862  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
W180409 19:39:04.439584 50097 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=677e4df3 key=/Table/SystemConfigSpan/Start rw=true pri=0.04804009 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523302744.088851449,0 orig=1523302744.088851449,0 max=1523302744.088851449,0 wto=false rop=false seq=14
I180409 19:39:04.457817 50135 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:node}
I180409 19:39:04.612692 50468 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 19:39:04.661485 50443 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=1f05d49c key=/Table/SystemConfigSpan/Start rw=true pri=0.01992197 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523302744.485471972,0 orig=1523302744.485471972,0 max=1523302744.485471972,0 wto=false rop=false seq=7
I180409 19:39:04.734569 50135 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}
I180409 19:39:04.809574 50411 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 19:39:05.034215 50415 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 19:39:05.172363 50459 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 19:39:05.347505 50532 storage/replica_command.go:862  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
W180409 19:39:05.494839 50493 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=73b412c1 key=/Local/Range/Table/13/RangeDescriptor rw=true pri=0.01647049 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523302745.352181443,0 orig=1523302745.352181443,0 max=1523302745.352181443,0 wto=false rop=false seq=3
I180409 19:39:05.564025 50516 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 19:39:05.580040 50135 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 19:39:05.735235 50135 sql/lease.go:352  [n1] publish: descID=4 (users) version=2 mtime=2018-04-09 19:39:05.733093674 +0000 UTC
I180409 19:39:05.751216 50581 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 19:39:05.881028 50553 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 19:39:06.116499 50524 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 19:39:06.192846 50135 sql/lease.go:352  [n1] publish: descID=4 (users) version=3 mtime=2018-04-09 19:39:06.190773127 +0000 UTC
I180409 19:39:06.255633 50612 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 19:39:06.433900 50602 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 19:39:06.590810 50135 sql/backfill.go:134  [n1] Running backfill for "users", v=3, m=1
W180409 19:39:06.631314 50529 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=7c3cb0d8 key=/Local/Range/Table/19/RangeDescriptor rw=true pri=0.02817204 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523302746.441279146,0 orig=1523302746.441279146,0 max=1523302746.441279146,0 wto=false rop=false seq=3
I180409 19:39:06.681448 50574 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 19:39:06.987199 50589 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 19:39:07.236752 50723 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 19:39:07.434891 50135 sql/lease.go:352  [n1] publish: descID=4 (users) version=4 mtime=2018-04-09 19:39:07.432775092 +0000 UTC
W180409 19:39:07.444358 50623 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=ec41d5bb key=/Local/Range/Table/22/RangeDescriptor rw=true pri=0.01743054 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523302747.262105939,0 orig=1523302747.262105939,0 max=1523302747.262105939,0 wto=false rop=false seq=3
I180409 19:39:07.650982 50135 sql/lease.go:352  [n1] publish: descID=4 (users) version=4 mtime=2018-04-09 19:39:07.498627487 +0000 UTC
I180409 19:39:07.826655 50135 sql/event_log.go:121  [n1] Event: "finish_schema_change", target: 4, info: {MutationID:1}
I180409 19:39:07.879088 50755 sql/lease.go:812  new lease: 4("users") ver=4:1523303104.855191656,0, refcount=0
I180409 19:39:07.902648 50135 sql/lease.go:275  publish (count leases): descID=4 name=users version=3 count=1
I180409 19:39:08.383022 50135 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:node}
I180409 19:39:08.475344 50135 server/server.go:1511  [n1] done ensuring all necessary migrations have run
I180409 19:39:08.475675 50135 server/server.go:1514  [n1] serving sql connections
I180409 19:39:08.518342 50762 sql/event_log.go:121  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:39645} Attrs: Locality: ServerVersion:2.0-3} ClusterID:94a074eb-eb39-49e0-8bbd-d8b7f72a4ef2 StartedAt:1523302742957303855 LastUp:1523302742957303855}
W180409 19:39:08.690387 50135 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180409 19:39:08.880720 50135 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180409 19:39:08.901188 50135 server/config.go:538  [n?] 1 storage engine initialized
I180409 19:39:08.914916 50135 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180409 19:39:08.915415 50135 server/config.go:541  [n?] store 0: in-memory, size 0 B
W180409 19:39:08.916198 50135 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180409 19:39:08.933434 50135 server/server.go:1307  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180409 19:39:09.176935 50769 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:39645
I180409 19:39:09.189499 50745 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:44675}
I180409 19:39:09.208505 50135 storage/stores.go:309  [n?] read 0 node addresses from persistent storage
I180409 19:39:09.209040 50135 storage/stores.go:328  [n?] wrote 1 node addresses to persistent storage
I180409 19:39:09.209126 50135 server/node.go:653  [n?] connecting to gossip network to verify cluster ID...
I180409 19:39:09.209365 50135 server/node.go:678  [n?] node connected via gossip and verified as part of cluster "94a074eb-eb39-49e0-8bbd-d8b7f72a4ef2"
I180409 19:39:09.248625 50135 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180409 19:39:09.268078 50135 server/node.go:345  [n?] new node allocated ID 2
I180409 19:39:09.269064 50135 gossip/gossip.go:332  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:44675" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180409 19:39:09.270170 50135 server/node.go:427  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180409 19:39:09.270911 50135 server/node.go:446  [n2] node=2: started with [] engine(s) and attributes []
I180409 19:39:09.286848 50808 storage/stores.go:328  [n1] wrote 1 node addresses to persistent storage
I180409 19:39:09.290426 50135 server/server.go:1431  [n2] starting https server at 127.0.0.1:38873
I180409 19:39:09.290637 50135 server/server.go:1432  [n2] starting grpc/postgres server at 127.0.0.1:44675
I180409 19:39:09.290698 50135 server/server.go:1433  [n2] advertising CockroachDB node at 127.0.0.1:44675
W180409 19:39:09.290980 50135 sql/jobs/registry.go:286  [n2] unable to get node liveness: node not in the liveness table
I180409 19:39:09.322578 50135 server/server.go:1511  [n2] done ensuring all necessary migrations have run
I180409 19:39:09.322837 50135 server/server.go:1514  [n2] serving sql connections
I180409 19:39:09.531521 50866 server/node.go:634  [n2] bootstrapped store [n2,s2]
I180409 19:39:09.600290 50812 sql/event_log.go:121  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:44675} Attrs: Locality: ServerVersion:2.0-3} ClusterID:94a074eb-eb39-49e0-8bbd-d8b7f72a4ef2 StartedAt:1523302749270525636 LastUp:1523302749270525636}
W180409 19:39:09.674222 50135 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180409 19:39:09.806658 50135 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180409 19:39:09.839594 50135 server/config.go:538  [n?] 1 storage engine initialized
I180409 19:39:09.839837 50135 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180409 19:39:09.840151 50135 server/config.go:541  [n?] store 0: in-memory, size 0 B
W180409 19:39:09.840743 50135 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180409 19:39:09.841639 50135 server/server.go:1307  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180409 19:39:10.198911 50749 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:39645
I180409 19:39:10.201517 51003 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:39343}
I180409 19:39:10.230107 50135 storage/stores.go:309  [n?] read 0 node addresses from persistent storage
I180409 19:39:10.230559 50135 server/node.go:653  [n?] connecting to gossip network to verify cluster ID...
I180409 19:39:10.232537 50135 server/node.go:678  [n?] node connected via gossip and verified as part of cluster "94a074eb-eb39-49e0-8bbd-d8b7f72a4ef2"
I180409 19:39:10.233161 51008 storage/stores.go:328  [n?] wrote 1 node addresses to persistent storage
I180409 19:39:10.233838 51008 storage/stores.go:328  [n?] wrote 2 node addresses to persistent storage
I180409 19:39:10.258944 50135 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180409 19:39:10.288534 50135 server/node.go:345  [n?] new node allocated ID 3
I180409 19:39:10.289294 50135 gossip/gossip.go:332  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:39343" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180409 19:39:10.290300 50135 server/node.go:427  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180409 19:39:10.290931 50135 server/node.go:446  [n3] node=3: started with [] engine(s) and attributes []
I180409 19:39:10.308000 50135 server/server.go:1431  [n3] starting https server at 127.0.0.1:42161
I180409 19:39:10.308225 50135 server/server.go:1432  [n3] starting grpc/postgres server at 127.0.0.1:39343
I180409 19:39:10.308282 50135 server/server.go:1433  [n3] advertising CockroachDB node at 127.0.0.1:39343
I180409 19:39:10.318825 50989 storage/stores.go:328  [n1] wrote 2 node addresses to persistent storage
I180409 19:39:10.323957 50135 server/server.go:1511  [n3] done ensuring all necessary migrations have run
I180409 19:39:10.349609 50135 server/server.go:1514  [n3] serving sql connections
I180409 19:39:10.368421 50993 storage/stores.go:328  [n2] wrote 2 node addresses to persistent storage
I180409 19:39:10.586453 51157 sql/event_log.go:121  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:39343} Attrs: Locality: ServerVersion:2.0-3} ClusterID:94a074eb-eb39-49e0-8bbd-d8b7f72a4ef2 StartedAt:1523302750290610446 LastUp:1523302750290610446}
I180409 19:39:10.588013 51088 server/node.go:634  [n3] bootstrapped store [n3,s3]
I180409 19:39:10.655348 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:10.661459 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot 4403e06c at index 15
I180409 19:39:10.739142 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:10.812517 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:10.876827 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:10.968176 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:11.026226 50390 storage/store.go:3834  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 7, log entries: 5, rate-limit: 8.0 MiB/sec, 8ms
I180409 19:39:11.031282 51332 storage/replica_raftstorage.go:726  [n2,s2,r19/?:{-}] applying preemptive snapshot at index 15 (id=4403e06c, encoded size=1919, 1 rocksdb batches, 5 log entries)
I180409 19:39:11.037327 51332 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 19:39:11.049203 50390 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 19:39:11.087648 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:11.140658 50390 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 19:39:11.165058 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot 69e7c178 at index 24
I180409 19:39:11.171715 50390 storage/store.go:3834  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 14, rate-limit: 8.0 MiB/sec, 5ms
I180409 19:39:11.174958 51304 storage/replica_raftstorage.go:726  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 24 (id=69e7c178, encoded size=5300, 1 rocksdb batches, 14 log entries)
I180409 19:39:11.180168 51304 storage/replica_raftstorage.go:732  [n2,s2,r8/?:/Table/1{1-2}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=3ms commit=1ms]
I180409 19:39:11.216341 50390 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]
I180409 19:39:11.224292 51321 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180409 19:39:11.237905 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:11.372268 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:11.388545 50390 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
I180409 19:39:11.396320 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot e78c5d87 at index 31
I180409 19:39:11.417649 50316 storage/replica_proposal.go:202  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302751.412855865,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:11.459198 50326 storage/replica_proposal.go:202  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302751.416333881,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:11.506380 50325 storage/replica_proposal.go:202  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302751.467344190,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:11.572815 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:11.655830 50390 storage/store.go:3834  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 53, log entries: 21, rate-limit: 8.0 MiB/sec, 7ms
I180409 19:39:11.659206 51345 storage/replica_raftstorage.go:726  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 31 (id=e78c5d87, encoded size=18311, 1 rocksdb batches, 21 log entries)
I180409 19:39:11.667481 51345 storage/replica_raftstorage.go:732  [n3,s3,r9/?:/Table/1{2-3}] applied preemptive snapshot in 8ms [clear=0ms batch=0ms entries=6ms commit=1ms]
I180409 19:39:11.682125 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:11.690947 50282 storage/replica_proposal.go:202  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302751.686418378,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:11.698094 50390 storage/replica_command.go:1779  [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, next=2]
I180409 19:39:11.749661 50277 storage/replica_proposal.go:202  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302751.736992898,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:11.856114 50390 storage/replica.go:3340  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 19:39:11.874073 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:11.911870 50292 storage/replica_proposal.go:202  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302751.897874157,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:11.917838 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 8650c8c3 at index 18
I180409 19:39:11.921153 51429 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180409 19:39:12.005643 50390 storage/store.go:3834  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 33ms
I180409 19:39:12.011970 51375 storage/replica_raftstorage.go:726  [n3,s3,r14/?:{-}] applying preemptive snapshot at index 18 (id=8650c8c3, encoded size=2398, 1 rocksdb batches, 8 log entries)
I180409 19:39:12.017566 51375 storage/replica_raftstorage.go:732  [n3,s3,r14/?:/Table/1{7-8}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=1ms commit=3ms]
I180409 19:39:12.028642 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:12.042647 50390 storage/replica_command.go:1779  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, next=2]
I180409 19:39:12.115007 50895 storage/replica_proposal.go:202  [n2,s2,r19/2:/Table/2{2-3}] new range lease repl=(n2,s2):2 seq=3 start=1523302751.907040471,1 epo=1 pro=1523302752.074208959,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:12.150611 51404 storage/replica_raftstorage.go:520  [replicate,n2,s2,r19/2:/Table/2{2-3}] generated preemptive snapshot e8e3afd3 at index 21
I180409 19:39:12.172870 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:12.187463 50390 storage/replica.go:3340  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 19:39:12.285657 50307 storage/replica_proposal.go:202  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302752.245383972,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:12.316456 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 12d16e49 at index 26
I180409 19:39:12.333501 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:12.422847 50390 storage/store.go:3834  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n3,s3):?: kv pairs: 965, log entries: 2, rate-limit: 8.0 MiB/sec, 96ms
I180409 19:39:12.448894 51450 storage/replica_raftstorage.go:726  [n3,s3,r5/?:{-}] applying preemptive snapshot at index 26 (id=12d16e49, encoded size=98441, 1 rocksdb batches, 2 log entries)
I180409 19:39:12.452319 51450 storage/replica_raftstorage.go:732  [n3,s3,r5/?:/System/ts{d-e}] applied preemptive snapshot in 3ms [clear=0ms batch=1ms entries=0ms commit=1ms]
I180409 19:39:12.457919 50390 storage/replica_command.go:1779  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, next=2]
I180409 19:39:12.479191 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:12.584406 50390 storage/replica.go:3340  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 19:39:12.608612 50334 storage/replica_proposal.go:202  [n1,s1,r20/1:/{Table/23-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302752.603827794,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:12.614990 51404 storage/store.go:3834  [replicate,n2,s2,r19/2:/Table/2{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 36ms
I180409 19:39:12.620798 51526 storage/replica_raftstorage.go:726  [n3,s3,r19/?:{-}] applying preemptive snapshot at index 21 (id=e8e3afd3, encoded size=3439, 1 rocksdb batches, 11 log entries)
I180409 19:39:12.629813 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:12.657676 51526 storage/replica_raftstorage.go:732  [n3,s3,r19/?:/Table/2{2-3}] applied preemptive snapshot in 16ms [clear=0ms batch=0ms entries=2ms commit=12ms]
I180409 19:39:12.689764 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot 40ad91c1 at index 15
I180409 19:39:12.708846 50390 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, 18ms
I180409 19:39:12.713404 51571 storage/replica_raftstorage.go:726  [n3,s3,r20/?:{-}] applying preemptive snapshot at index 15 (id=40ad91c1, encoded size=1175, 1 rocksdb batches, 5 log entries)
I180409 19:39:12.716478 51571 storage/replica_raftstorage.go:732  [n3,s3,r20/?:/{Table/23-Max}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180409 19:39:12.722268 50390 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 19:39:12.749270 51404 storage/replica_command.go:1779  [replicate,n2,s2,r19/2:/Table/2{2-3}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, (n2,s2):2, next=3]
I180409 19:39:12.778257 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:12.867476 50390 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 19:39:12.889573 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:12.957994 50295 storage/replica_proposal.go:202  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302752.941461531,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:12.987139 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot 354806d6 at index 18
I180409 19:39:13.013020 50390 storage/store.go:3834  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 15ms
I180409 19:39:13.058176 51620 storage/replica_raftstorage.go:726  [n3,s3,r16/?:{-}] applying preemptive snapshot at index 18 (id=354806d6, encoded size=2398, 1 rocksdb batches, 8 log entries)
I180409 19:39:13.061745 51620 storage/replica_raftstorage.go:732  [n3,s3,r16/?:/Table/{19-20}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180409 19:39:13.062126 50353 server/status/runtime.go:219  [n1] runtime stats: 1.3 GiB RSS, 613 goroutines, 48 MiB/70 MiB/137 MiB GO alloc/idle/total, 85 MiB/119 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (319x)
I180409 19:39:13.071302 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180409 19:39:13.079576 50390 storage/replica_command.go:1779  [replicate,n1,s1,r16/1:/Table/{19-20}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r16:/Table/{19-20} [(n1,s1):1, next=2]
I180409 19:39:13.162653 51605 storage/replica.go:3340  [n2,s2,r19/2:/Table/2{2-3}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180409 19:39:13.195494 50390 storage/replica.go:3340  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 19:39:13.206939 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:13.219130 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 24433c42 at index 27
I180409 19:39:13.273247 50390 storage/store.go:3834  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 17, rate-limit: 8.0 MiB/sec, 49ms
I180409 19:39:13.276934 51466 storage/replica_raftstorage.go:726  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 27 (id=24433c42, encoded size=5454, 1 rocksdb batches, 17 log entries)
I180409 19:39:13.281460 51466 storage/replica_raftstorage.go:732  [n3,s3,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=3ms commit=0ms]
I180409 19:39:13.314149 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:13.348437 50390 storage/replica_command.go:1779  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, next=2]
I180409 19:39:13.414971 50390 storage/replica.go:3340  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 19:39:13.431970 50336 storage/replica_proposal.go:202  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302753.420718973,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:13.441057 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot a909900c at index 44
I180409 19:39:13.449082 50390 storage/store.go:3834  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 39, log entries: 34, rate-limit: 8.0 MiB/sec, 7ms
I180409 19:39:13.468162 51469 storage/replica_raftstorage.go:726  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 44 (id=a909900c, encoded size=113770, 1 rocksdb batches, 34 log entries)
I180409 19:39:13.477781 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:13.489219 51626 storage/raft_transport.go:459  [n3] raft transport stream to node 2 established
I180409 19:39:13.585574 51469 storage/replica_raftstorage.go:732  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 117ms [clear=0ms batch=0ms entries=115ms commit=1ms]
I180409 19:39:13.591867 50390 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 19:39:13.631632 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:13.673280 50390 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 19:39:13.694189 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot b17c530f at index 25
I180409 19:39:13.703149 50390 storage/store.go:3834  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 8, rate-limit: 8.0 MiB/sec, 6ms
I180409 19:39:13.708105 51599 storage/replica_raftstorage.go:726  [n3,s3,r2/?:{-}] applying preemptive snapshot at index 25 (id=b17c530f, encoded size=51638, 1 rocksdb batches, 8 log entries)
I180409 19:39:13.749568 51599 storage/replica_raftstorage.go:732  [n3,s3,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 38ms [clear=0ms batch=0ms entries=14ms commit=23ms]
I180409 19:39:13.770301 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:13.775652 50390 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 19:39:13.887846 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:14.018608 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:14.053418 50390 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 19:39:14.119583 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot 349a3f3c at index 30
I180409 19:39:14.139782 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:14.189385 50390 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, 67ms
I180409 19:39:14.208282 51657 storage/replica_raftstorage.go:726  [n3,s3,r12/?:{-}] applying preemptive snapshot at index 30 (id=349a3f3c, encoded size=9115, 1 rocksdb batches, 20 log entries)
I180409 19:39:14.214904 51657 storage/replica_raftstorage.go:732  [n3,s3,r12/?:/Table/1{5-6}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=4ms commit=0ms]
I180409 19:39:14.243894 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:14.252762 50390 storage/replica_command.go:1779  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, next=2]
I180409 19:39:14.354529 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:14.433109 50390 storage/replica.go:3340  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 19:39:14.458082 50325 storage/replica_proposal.go:202  [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302754.439870374,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:14.471342 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot 139adf8f at index 19
I180409 19:39:14.483565 50390 storage/store.go:3834  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 9, rate-limit: 8.0 MiB/sec, 11ms
I180409 19:39:14.506760 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:14.511354 51722 storage/replica_raftstorage.go:726  [n3,s3,r17/?:{-}] applying preemptive snapshot at index 19 (id=139adf8f, encoded size=2710, 1 rocksdb batches, 9 log entries)
I180409 19:39:14.525085 51722 storage/replica_raftstorage.go:732  [n3,s3,r17/?:/Table/2{0-1}] applied preemptive snapshot in 13ms [clear=10ms batch=0ms entries=2ms commit=0ms]
I180409 19:39:14.545355 50390 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 19:39:14.632009 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:14.691449 50390 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 19:39:14.740532 50278 storage/replica_proposal.go:202  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302754.707667655,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:14.753746 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot bfc4cf98 at index 18
I180409 19:39:14.760520 50390 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, 6ms
I180409 19:39:14.767529 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:14.793631 51726 storage/replica_raftstorage.go:726  [n3,s3,r13/?:{-}] applying preemptive snapshot at index 18 (id=bfc4cf98, encoded size=2398, 1 rocksdb batches, 8 log entries)
I180409 19:39:14.799141 51726 storage/replica_raftstorage.go:732  [n3,s3,r13/?:/Table/1{6-7}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=2ms commit=2ms]
I180409 19:39:14.805663 50390 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 19:39:14.916239 50390 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 19:39:14.946492 50301 storage/replica_proposal.go:202  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302754.937008026,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:14.953551 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot 2e2931a5 at index 19
I180409 19:39:14.985136 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:14.987322 50390 storage/store.go:3834  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 29ms
I180409 19:39:15.001481 51752 storage/replica_raftstorage.go:726  [n3,s3,r11/?:{-}] applying preemptive snapshot at index 19 (id=2e2931a5, encoded size=2560, 1 rocksdb batches, 9 log entries)
I180409 19:39:15.005009 51752 storage/replica_raftstorage.go:732  [n3,s3,r11/?:/Table/1{4-5}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180409 19:39:15.010903 50390 storage/replica_command.go:1779  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, next=2]
I180409 19:39:15.168064 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:15.178860 50390 storage/replica.go:3340  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 19:39:15.203487 50324 storage/replica_proposal.go:202  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302755.185150958,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:15.229835 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot 11ecb2b8 at index 18
I180409 19:39:15.264478 50390 storage/store.go:3834  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 26ms
I180409 19:39:15.268275 51826 storage/replica_raftstorage.go:726  [n3,s3,r15/?:{-}] applying preemptive snapshot at index 18 (id=11ecb2b8, encoded size=2398, 1 rocksdb batches, 8 log entries)
I180409 19:39:15.271574 51826 storage/replica_raftstorage.go:732  [n3,s3,r15/?:/Table/1{8-9}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180409 19:39:15.293474 50390 storage/replica_command.go:1779  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, next=2]
I180409 19:39:15.299509 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:15.422630 50390 storage/replica.go:3340  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 19:39:15.434498 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:15.500375 50327 storage/replica_proposal.go:202  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302755.474798276,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:15.519448 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot f24bdf87 at index 18
I180409 19:39:15.526386 50390 storage/store.go:3834  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 6ms
I180409 19:39:15.532890 51829 storage/replica_raftstorage.go:726  [n3,s3,r18/?:{-}] applying preemptive snapshot at index 18 (id=f24bdf87, encoded size=2398, 1 rocksdb batches, 8 log entries)
I180409 19:39:15.539907 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:15.542735 51829 storage/replica_raftstorage.go:732  [n3,s3,r18/?:/Table/2{1-2}] applied preemptive snapshot in 9ms [clear=0ms batch=0ms entries=7ms commit=1ms]
I180409 19:39:15.582543 50390 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 19:39:15.655980 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:15.717404 50390 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 19:39:15.727751 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot bc39ab5b at index 99
I180409 19:39:15.750577 50390 storage/store.go:3834  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n3,s3):?: kv pairs: 69, log entries: 89, rate-limit: 8.0 MiB/sec, 12ms
I180409 19:39:15.765128 51849 storage/replica_raftstorage.go:726  [n3,s3,r1/?:{-}] applying preemptive snapshot at index 99 (id=bc39ab5b, encoded size=21861, 1 rocksdb batches, 89 log entries)
I180409 19:39:15.786523 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:15.801503 51849 storage/replica_raftstorage.go:732  [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 36ms [clear=0ms batch=0ms entries=34ms commit=1ms]
I180409 19:39:15.828371 50390 storage/replica_command.go:1779  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r1:/{Min-System/} [(n1,s1):1, next=2]
I180409 19:39:15.889378 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:15.915654 50390 storage/replica.go:3340  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 19:39:15.941747 50300 storage/replica_proposal.go:202  [n1,s1,r6/1:/{System/tse-Table/System…}] new range lease repl=(n1,s1):1 seq=3 start=1523302742.867420129,0 epo=1 pro=1523302755.935775013,0 following repl=(n1,s1):1 seq=2 start=1523302742.867420129,0 exp=1523302751.907040471,0 pro=1523302742.907125798,0
I180409 19:39:15.946979 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot e477f66f at index 24
I180409 19:39:15.976748 50390 storage/store.go:3834  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 14, rate-limit: 8.0 MiB/sec, 29ms
I180409 19:39:15.980677 51834 storage/replica_raftstorage.go:726  [n3,s3,r6/?:{-}] applying preemptive snapshot at index 24 (id=e477f66f, encoded size=6510, 1 rocksdb batches, 14 log entries)
I180409 19:39:15.986105 51834 storage/replica_raftstorage.go:732  [n3,s3,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=3ms commit=0ms]
I180409 19:39:16.025562 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:16.036193 50390 storage/replica_command.go:1779  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, next=2]
I180409 19:39:16.133764 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:16.147355 50390 storage/replica.go:3340  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180409 19:39:16.172649 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot 6b45805e at index 76
I180409 19:39:16.190498 50390 storage/store.go:3834  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 217, log entries: 66, rate-limit: 8.0 MiB/sec, 10ms
I180409 19:39:16.204857 51808 storage/replica_raftstorage.go:726  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 76 (id=6b45805e, encoded size=64672, 1 rocksdb batches, 66 log entries)
I180409 19:39:16.264461 51808 storage/replica_raftstorage.go:732  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 59ms [clear=0ms batch=3ms entries=46ms commit=1ms]
I180409 19:39:16.276363 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:16.287471 50390 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 19:39:16.370198 50390 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 19:39:16.378055 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:16.388064 50390 storage/replica_raftstorage.go:520  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot 383d64d9 at index 50
I180409 19:39:16.414895 50390 storage/store.go:3834  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):?: kv pairs: 75, log entries: 40, rate-limit: 8.0 MiB/sec, 8ms
I180409 19:39:16.421959 51897 storage/replica_raftstorage.go:726  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 50 (id=383d64d9, encoded size=35805, 1 rocksdb batches, 40 log entries)
I180409 19:39:16.452761 51897 storage/replica_raftstorage.go:732  [n3,s3,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 30ms [clear=0ms batch=0ms entries=28ms commit=1ms]
I180409 19:39:16.461605 50390 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 19:39:16.504704 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:16.573210 50390 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 19:39:16.586780 50390 storage/queue.go:847  [n1,replicate] purgatory is now empty
I180409 19:39:16.599760 51990 storage/replica_raftstorage.go:520  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot b6f3a6e5 at index 52
I180409 19:39:16.635742 51990 storage/store.go:3834  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 77, log entries: 42, rate-limit: 8.0 MiB/sec, 12ms
I180409 19:39:16.637677 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:16.640562 51960 storage/replica_raftstorage.go:726  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 52 (id=b6f3a6e5, encoded size=37052, 1 rocksdb batches, 42 log entries)
I180409 19:39:16.670477 51960 storage/replica_raftstorage.go:732  [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 30ms [clear=0ms batch=0ms entries=27ms commit=1ms]
I180409 19:39:16.727315 51990 storage/replica_command.go:1779  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n3,s3):2, next=3]
I180409 19:39:16.772322 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180409 19:39:16.834461 51990 storage/replica.go:3340  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180409 19:39:16.936009 51942 storage/replica_raftstorage.go:520  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot 440d3f26 at index 84
I180409 19:39:16.943117 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180409 19:39:16.961006 51942 storage/store.go:3834  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 233, log entries: 74, rate-limit: 8.0 MiB/sec, 15ms
I180409 19:39:16.967656 51909 storage/replica_raftstorage.go:726  [n2,s2,r10/?:{-}] applying preemptive snapshot at index 84 (id=440d3f26, encoded size=71358, 1 rocksdb batches, 74 log entries)
I180409 19:39:17.067189 51909 storage/replica_raftstorage.go:732  [n2,s2,r10/?:/Table/1{3-4}] applied preemptive snapshot in 98ms [clear=0ms batch=0ms entries=63ms commit=34ms]
I180409 19:39:17.070194 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180409 19:39:17.104323 51942 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]
I180409 19:39:17.178067 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180409 19:39:17.245184 51942 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
I180409 19:39:17.301550 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 17 underreplicated ranges
I180409 19:39:17.310978 51948 storage/replica_raftstorage.go:520  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot fa0a7e16 at index 28
I180409 19:39:17.326171 51948 storage/store.go:3834  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 12, log entries: 18, rate-limit: 8.0 MiB/sec, 12ms
I180409 19:39:17.329593 52035 storage/replica_raftstorage.go:726  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 28 (id=fa0a7e16, encoded size=6518, 1 rocksdb batches, 18 log entries)
I180409 19:39:17.337740 52035 storage/replica_raftstorage.go:732  [n3,s3,r8/?:/Table/1{1-2}] applied preemptive snapshot in 8ms [clear=0ms batch=0ms entries=5ms commit=0ms]
I180409 19:39:17.366204 51948 storage/replica_command.go:1779  [replicate,n1,s1,r8/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, (n2,s2):2, next=3]
I180409 19:39:17.439611 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 17 underreplicated ranges
I180409 19:39:17.497527 51948 storage/replica.go:3340  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180409 19:39:17.525494 52041 storage/replica_raftstorage.go:520  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 47537d8b at index 21
I180409 19:39:17.543060 52041 storage/store.go:3834  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 16ms
I180409 19:39:17.548000 52005 storage/replica_raftstorage.go:726  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 21 (id=47537d8b, encoded size=3428, 1 rocksdb batches, 11 log entries)
I180409 19:39:17.554284 52005 storage/replica_raftstorage.go:732  [n2,s2,r14/?:/Table/1{7-8}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=4ms commit=0ms]
I180409 19:39:17.557472 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 16 underreplicated ranges
I180409 19:39:17.572385 52041 storage/replica_command.go:1779  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, (n3,s3):2, next=3]
I180409 19:39:17.753456 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 16 underreplicated ranges
I180409 19:39:17.812605 52041 storage/replica.go:3340  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180409 19:39:17.877923 52015 storage/replica_raftstorage.go:520  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot c2742ff2 at index 34
I180409 19:39:17.908566 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 15 underreplicated ranges
I180409 19:39:17.925334 52015 storage/store.go:3834  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 17, log entries: 24, rate-limit: 8.0 MiB/sec, 28ms
I180409 19:39:17.942964 51918 storage/replica_raftstorage.go:726  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 34 (id=c2742ff2, encoded size=7416, 1 rocksdb batches, 24 log entries)
I180409 19:39:17.962269 51918 storage/replica_raftstorage.go:732  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 19ms [clear=0ms batch=0ms entries=15ms commit=0ms]
I180409 19:39:17.976484 52015 storage/replica_command.go:1779  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, (n3,s3):2, next=3]
I180409 19:39:18.016945 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 15 underreplicated ranges
I180409 19:39:18.159585 52045 storage/replica.go:3340  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180409 19:39:18.189090 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 15 underreplicated ranges
I180409 19:39:18.255319 52118 storage/replica_raftstorage.go:520  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot 6061a807 at index 21
I180409 19:39:18.290337 52118 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, 34ms
I180409 19:39:18.301867 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 14 underreplicated ranges
I180409 19:39:18.303710 52121 storage/replica_raftstorage.go:726  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 21 (id=6061a807, encoded size=3431, 1 rocksdb batches, 11 log entries)
I180409 19:39:18.314586 52121 storage/replica_raftstorage.go:732  [n2,s2,r18/?:/Table/2{1-2}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180409 19:39:18.346339 52118 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 19:39:18.436409 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 14 underreplicated ranges
I180409 19:39:18.485873 52118 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 19:39:18.519067 52080 storage/replica_raftstorage.go:520  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 8da87a6d at index 121
I180409 19:39:18.554680 52080 storage/store.go:3834  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 81, log entries: 111, rate-limit: 8.0 MiB/sec, 34ms
I180409 19:39:18.557367 50135 testutils/testcluster/testcluster.go:534  [n1,s1] has 13 underreplicated ranges
I180409 19:39:18.568472 52113 storage/replica_raftstorage.go:726  [n2,s2,r1/?:{-}] applying preemptive snapshot at index 121 (id=8da87a6d, encoded size=26741, 1 ro

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