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: test/TestRestoreDatabaseVersusTable/incomplete-db, test/TestRestoreDatabaseVersusTable/tables, test/TestRestoreDatabaseVersusTable, test/TestRestoreDatabaseVersusTable/db-exists, test/TestRestoreDatabaseVersusTable/tables-needs-db, test/TestRestoreDatabaseVersusTable/db, testrace/TestRestoreDatabaseVersusTable, testrace/TestRestoreDatabaseVersusTable/incomplete-db, testrace/TestRestoreDatabaseVersusTable/db, testrace/TestRestoreDatabaseVersusTable/db-exists, testrace/TestRestoreDatabaseVersusTable/tables, testrace/TestRestoreDatabaseVersusTable/tables-needs-db #21259

Closed
cockroach-teamcity opened this issue Jan 5, 2018 · 1 comment
Closed

teamcity: failed tests on master: test/TestRestoreDatabaseVersusTable/incomplete-db, test/TestRestoreDatabaseVersusTable/tables, test/TestRestoreDatabaseVersusTable, test/TestRestoreDatabaseVersusTable/db-exists, test/TestRestoreDatabaseVersusTable/tables-needs-db, test/TestRestoreDatabaseVersusTable/db, testrace/TestRestoreDatabaseVersusTable, testrace/TestRestoreDatabaseVersusTable/incomplete-db, testrace/TestRestoreDatabaseVersusTable/db, testrace/TestRestoreDatabaseVersusTable/db-exists, testrace/TestRestoreDatabaseVersusTable/tables, testrace/TestRestoreDatabaseVersusTable/tables-needs-db #21259

cockroach-teamcity opened this issue Jan 5, 2018 · 1 comment
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed:

#468102:

--- FAIL: test/TestRestoreDatabaseVersusTable/incomplete-db (0.000s)
Test ended in panic.

------- Stdout: -------
W180105 15:16:53.110303 156965 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180105 15:16:53.112343 156965 server/config.go:516  [n?] 1 storage engine initialized
I180105 15:16:53.112365 156965 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180105 15:16:53.112372 156965 server/config.go:519  [n?] store 0: in-memory, size 0 B
I180105 15:16:53.115080 156965 server/node.go:361  [n?] **** cluster 8aa8822d-22af-4558-bcbf-d413dbe5cd32 has been created
I180105 15:16:53.115106 156965 server/server.go:934  [n?] **** add additional nodes by specifying --join=127.0.0.1:46121
I180105 15:16:53.115773 156965 storage/store.go:1209  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180105 15:16:53.115819 156965 server/node.go:486  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=3.2 KiB), ranges=1, leases=0, writes=0.00, bytesPerReplica={p10=3322.00 p25=3322.00 p50=3322.00 p75=3322.00 p90=3322.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00}
I180105 15:16:53.115850 156965 server/node.go:339  [n1] node ID 1 initialized
I180105 15:16:53.115904 156965 gossip/gossip.go:332  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:46121" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180105 15:16:53.115942 156965 storage/stores.go:331  [n1] read 0 node addresses from persistent storage
I180105 15:16:53.115990 156965 server/node.go:627  [n1] connecting to gossip network to verify cluster ID...
I180105 15:16:53.116006 156965 server/node.go:652  [n1] node connected via gossip and verified as part of cluster "8aa8822d-22af-4558-bcbf-d413dbe5cd32"
I180105 15:16:53.116020 156965 server/node.go:428  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180105 15:16:53.116058 156965 sql/distsql_physical_planner.go:122  [n1] creating DistSQLPlanner with address {tcp 127.0.0.1:46121}
I180105 15:16:53.118412 157202 storage/replica_command.go:819  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180105 15:16:53.122637 156965 server/server.go:1161  [n1] starting https server at 127.0.0.1:37519
I180105 15:16:53.122661 156965 server/server.go:1162  [n1] starting grpc/postgres server at 127.0.0.1:46121
I180105 15:16:53.122671 156965 server/server.go:1163  [n1] advertising CockroachDB node at 127.0.0.1:46121
E180105 15:16:53.122683 157203 storage/queue.go:668  [replicate,n1,s1,r1/1:/{Min-System/}] range requires a replication change, but lacks a quorum of live replicas (0/1)
I180105 15:16:53.122819 157202 storage/replica_command.go:819  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180105 15:16:53.127273 156965 sql/event_log.go:115  [n1] Event: "alter_table", target: 12, info: {TableName:eventlog Statement:ALTER TABLE system.eventlog ALTER COLUMN "uniqueID" SET DEFAULT uuid_v4() User:node MutationID:0 CascadeDroppedViews:[]}
I180105 15:16:53.129872 157202 storage/replica_command.go:819  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180105 15:16:53.132077 156965 sql/lease.go:348  [n1] publish: descID=12 (eventlog) version=2 mtime=2018-01-05 15:16:53.131808443 +0000 UTC
I180105 15:16:53.134077 157202 storage/replica_command.go:819  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180105 15:16:53.137829 157202 storage/replica_command.go:819  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180105 15:16:53.143217 157202 storage/replica_command.go:819  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180105 15:16:53.145068 156965 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}
I180105 15:16:53.146759 157202 storage/replica_command.go:819  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180105 15:16:53.151097 157202 storage/replica_command.go:819  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180105 15:16:53.154228 157202 storage/replica_command.go:819  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180105 15:16:53.155244 156965 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:node}
I180105 15:16:53.158139 157202 storage/replica_command.go:819  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180105 15:16:53.158645 156965 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}
I180105 15:16:53.161470 157202 storage/replica_command.go:819  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180105 15:16:53.164214 157202 storage/replica_command.go:819  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180105 15:16:53.166916 157202 storage/replica_command.go:819  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180105 15:16:53.168676 156965 sql/event_log.go:115  [n1] Event: "alter_table", target: 4, info: {TableName:users Statement:ALTER TABLE system.users ADD COLUMN IF NOT EXISTS "isRole" BOOL NOT NULL DEFAULT false User:node MutationID:1 CascadeDroppedViews:[]}
I180105 15:16:53.169820 157202 storage/replica_command.go:819  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180105 15:16:53.170561 156965 sql/lease.go:348  [n1] publish: descID=4 (users) version=2 mtime=2018-01-05 15:16:53.170470861 +0000 UTC
I180105 15:16:53.172640 157202 storage/replica_command.go:819  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180105 15:16:53.173898 156965 sql/lease.go:348  [n1] publish: descID=4 (users) version=3 mtime=2018-01-05 15:16:53.173810573 +0000 UTC
I180105 15:16:53.175581 157202 storage/replica_command.go:819  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180105 15:16:53.176693 156965 sql/backfill.go:132  [n1] Running backfill for "users", v=3, m=1
I180105 15:16:53.178060 157202 storage/replica_command.go:819  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180105 15:16:53.182210 157202 storage/replica_command.go:819  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180105 15:16:53.185979 157202 storage/replica_command.go:819  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180105 15:16:53.186820 156965 sql/lease.go:348  [n1] publish: descID=4 (users) version=4 mtime=2018-01-05 15:16:53.18673725 +0000 UTC
I180105 15:16:53.190102 156965 sql/event_log.go:115  [n1] Event: "finish_schema_change", target: 4, info: {MutationID:1}
I180105 15:16:53.190759 156965 sql/lease.go:274  publish (count leases): descID=4 name=users version=3 count=1
I180105 15:16:53.220522 156965 server/server.go:1232  [n1] done ensuring all necessary migrations have run
I180105 15:16:53.220559 156965 server/server.go:1235  [n1] serving sql connections
I180105 15:16:53.222341 157525 sql/event_log.go:115  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:46121} Attrs: Locality: ServerVersion:1.1-8} ClusterID:8aa8822d-22af-4558-bcbf-d413dbe5cd32 StartedAt:1515165413116008550 LastUp:1515165413116008550}
W180105 15:16:53.225494 156965 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180105 15:16:53.227614 156965 server/config.go:516  [n?] 1 storage engine initialized
I180105 15:16:53.227635 156965 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180105 15:16:53.227641 156965 server/config.go:519  [n?] store 0: in-memory, size 0 B
W180105 15:16:53.227681 156965 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180105 15:16:53.227714 156965 server/server.go:936  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180105 15:16:53.237075 157471 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:46121
I180105 15:16:53.237394 157498 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:38455}
I180105 15:16:53.238277 156965 storage/stores.go:331  [n?] read 0 node addresses from persistent storage
I180105 15:16:53.238319 156965 storage/stores.go:350  [n?] wrote 1 node addresses to persistent storage
I180105 15:16:53.238332 156965 server/node.go:627  [n?] connecting to gossip network to verify cluster ID...
I180105 15:16:53.238359 156965 server/node.go:652  [n?] node connected via gossip and verified as part of cluster "8aa8822d-22af-4558-bcbf-d413dbe5cd32"
I180105 15:16:53.238573 157580 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180105 15:16:53.239223 157579 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180105 15:16:53.239847 156965 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180105 15:16:53.240601 156965 server/node.go:332  [n?] new node allocated ID 2
I180105 15:16:53.240660 156965 gossip/gossip.go:332  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:38455" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180105 15:16:53.240711 156965 server/node.go:414  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180105 15:16:53.240731 156965 server/node.go:428  [n2] node=2: started with [] engine(s) and attributes []
I180105 15:16:53.240790 156965 sql/distsql_physical_planner.go:122  [n2] creating DistSQLPlanner with address {tcp 127.0.0.1:38455}
I180105 15:16:53.241594 157313 storage/stores.go:350  [n1] wrote 1 node addresses to persistent storage
I180105 15:16:53.246875 156965 server/server.go:1161  [n2] starting https server at 127.0.0.1:35781
I180105 15:16:53.246899 156965 server/server.go:1162  [n2] starting grpc/postgres server at 127.0.0.1:38455
I180105 15:16:53.246909 156965 server/server.go:1163  [n2] advertising CockroachDB node at 127.0.0.1:38455
I180105 15:16:53.247745 157503 server/node.go:608  [n2] bootstrapped store [n2,s2]
I180105 15:16:53.247828 156965 server/server.go:1232  [n2] done ensuring all necessary migrations have run
I180105 15:16:53.247849 156965 server/server.go:1235  [n2] serving sql connections
I180105 15:16:53.252296 157730 sql/event_log.go:115  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:38455} Attrs: Locality: ServerVersion:1.1-8} ClusterID:8aa8822d-22af-4558-bcbf-d413dbe5cd32 StartedAt:1515165413240721344 LastUp:1515165413240721344}
W180105 15:16:53.253365 156965 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180105 15:16:53.255322 156965 server/config.go:516  [n?] 1 storage engine initialized
I180105 15:16:53.255339 156965 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180105 15:16:53.255345 156965 server/config.go:519  [n?] store 0: in-memory, size 0 B
W180105 15:16:53.255388 156965 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180105 15:16:53.255425 156965 server/server.go:936  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180105 15:16:53.264615 157700 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:46121
I180105 15:16:53.264908 157719 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:45493}
I180105 15:16:53.265711 156965 storage/stores.go:331  [n?] read 0 node addresses from persistent storage
I180105 15:16:53.265778 156965 storage/stores.go:350  [n?] wrote 2 node addresses to persistent storage
I180105 15:16:53.265789 156965 server/node.go:627  [n?] connecting to gossip network to verify cluster ID...
I180105 15:16:53.265810 156965 server/node.go:652  [n?] node connected via gossip and verified as part of cluster "8aa8822d-22af-4558-bcbf-d413dbe5cd32"
I180105 15:16:53.266023 157785 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180105 15:16:53.266637 157784 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180105 15:16:53.267119 156965 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180105 15:16:53.267799 156965 server/node.go:332  [n?] new node allocated ID 3
I180105 15:16:53.267867 156965 gossip/gossip.go:332  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:45493" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180105 15:16:53.267919 156965 server/node.go:414  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180105 15:16:53.267931 156965 server/node.go:428  [n3] node=3: started with [] engine(s) and attributes []
I180105 15:16:53.267979 156965 sql/distsql_physical_planner.go:122  [n3] creating DistSQLPlanner with address {tcp 127.0.0.1:45493}
I180105 15:16:53.268747 157615 storage/stores.go:350  [n1] wrote 2 node addresses to persistent storage
I180105 15:16:53.272725 157765 storage/stores.go:350  [n2] wrote 2 node addresses to persistent storage
I180105 15:16:53.274684 156965 server/server.go:1161  [n3] starting https server at 127.0.0.1:39427
I180105 15:16:53.274706 156965 server/server.go:1162  [n3] starting grpc/postgres server at 127.0.0.1:45493
I180105 15:16:53.274716 156965 server/server.go:1163  [n3] advertising CockroachDB node at 127.0.0.1:45493
I180105 15:16:53.275275 157707 server/node.go:608  [n3] bootstrapped store [n3,s3]
I180105 15:16:53.275555 156965 server/server.go:1232  [n3] done ensuring all necessary migrations have run
I180105 15:16:53.275588 156965 server/server.go:1235  [n3] serving sql connections
I180105 15:16:53.276825 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot a082ec5f at index 28
I180105 15:16:53.277573 156965 testutils/testcluster/testcluster.go:528  [n1,s1] has 20 underreplicated ranges
I180105 15:16:53.280221 157894 sql/event_log.go:115  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:45493} Attrs: Locality: ServerVersion:1.1-8} ClusterID:8aa8822d-22af-4558-bcbf-d413dbe5cd32 StartedAt:1515165413267923202 LastUp:1515165413267923202}
I180105 15:16:53.286657 157268 storage/store.go:3567  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 50, log entries: 18, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.287021 157904 storage/replica_raftstorage.go:746  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 28 (id=a082ec5f, encoded size=16743, 1 rocksdb batches, 18 log entries)
I180105 15:16:53.288325 157904 storage/replica_raftstorage.go:752  [n3,s3,r9/?:/Table/1{2-3}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180105 15:16:53.288761 157268 storage/replica_command.go:1741  [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]
I180105 15:16:53.289147 156965 testutils/testcluster/testcluster.go:528  [n1,s1] has 20 underreplicated ranges
I180105 15:16:53.290785 157268 storage/replica.go:3192  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180105 15:16:53.291252 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot ac98abe0 at index 36
I180105 15:16:53.292218 157950 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180105 15:16:53.301007 157268 storage/store.go:3567  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 134, log entries: 26, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.301355 157986 storage/replica_raftstorage.go:746  [n2,s2,r10/?:{-}] applying preemptive snapshot at index 36 (id=ac98abe0, encoded size=32896, 1 rocksdb batches, 26 log entries)
I180105 15:16:53.302735 157986 storage/replica_raftstorage.go:752  [n2,s2,r10/?:/Table/1{3-4}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180105 15:16:53.303148 157268 storage/replica_command.go:1741  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, next=2]
I180105 15:16:53.305046 157268 storage/replica.go:3192  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180105 15:16:53.305481 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 514c8acc at index 48
I180105 15:16:53.306293 157966 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180105 15:16:53.306351 157268 storage/store.go:3567  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n2,s2):?: kv pairs: 43, log entries: 2, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.306779 157978 storage/replica_raftstorage.go:746  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 48 (id=514c8acc, encoded size=68683, 1 rocksdb batches, 2 log entries)
I180105 15:16:53.307329 157978 storage/replica_raftstorage.go:752  [n2,s2,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.307670 157268 storage/replica_command.go:1741  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, next=2]
I180105 15:16:53.309780 157268 storage/replica.go:3192  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180105 15:16:53.310216 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 15565209 at index 33
I180105 15:16:53.310932 157203 storage/store.go:3567  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 56, log entries: 23, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.311259 156965 testutils/testcluster/testcluster.go:528  [n1,s1] has 20 underreplicated ranges
I180105 15:16:53.311281 157991 storage/replica_raftstorage.go:746  [n2,s2,r9/?:{-}] applying preemptive snapshot at index 33 (id=15565209, encoded size=20452, 1 rocksdb batches, 23 log entries)
I180105 15:16:53.311681 157991 storage/replica_raftstorage.go:752  [n2,s2,r9/?:/Table/1{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.311956 157203 storage/replica_command.go:1741  [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, (n3,s3):2, next=3]
I180105 15:16:53.314309 157203 storage/replica.go:3192  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180105 15:16:53.315097 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot 2eafc608 at index 25
I180105 15:16:53.315736 157268 storage/store.go:3567  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 10, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.316193 157567 storage/replica_raftstorage.go:746  [n3,s3,r2/?:{-}] applying preemptive snapshot at index 25 (id=2eafc608, encoded size=54475, 1 rocksdb batches, 10 log entries)
I180105 15:16:53.316687 157567 storage/replica_raftstorage.go:752  [n3,s3,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.317114 157268 storage/replica_command.go:1741  [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]
I180105 15:16:53.319037 157268 storage/replica.go:3192  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180105 15:16:53.319451 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 3a2313d8 at index 15
I180105 15:16:53.319932 157268 storage/store.go:3567  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 5, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.320228 157913 storage/replica_raftstorage.go:746  [n3,s3,r14/?:{-}] applying preemptive snapshot at index 15 (id=3a2313d8, encoded size=2407, 1 rocksdb batches, 5 log entries)
I180105 15:16:53.320484 157913 storage/replica_raftstorage.go:752  [n3,s3,r14/?:/Table/1{7-8}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.320903 157268 storage/replica_command.go:1741  [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]
I180105 15:16:53.322754 157268 storage/replica.go:3192  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180105 15:16:53.323130 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot f21f018f at index 48
I180105 15:16:53.324086 157203 storage/store.go:3567  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 160, log entries: 38, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.326136 158011 storage/replica_raftstorage.go:746  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 48 (id=f21f018f, encoded size=46356, 1 rocksdb batches, 38 log entries)
I180105 15:16:53.326684 158011 storage/replica_raftstorage.go:752  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.327933 157203 storage/replica_command.go:1741  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, (n2,s2):2, next=3]
I180105 15:16:53.330850 157203 storage/replica.go:3192  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180105 15:16:53.331761 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot 9c555aa4 at index 15
I180105 15:16:53.332243 157268 storage/store.go:3567  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 5, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.332461 158027 storage/replica_raftstorage.go:746  [n2,s2,r17/?:{-}] applying preemptive snapshot at index 15 (id=9c555aa4, encoded size=2407, 1 rocksdb batches, 5 log entries)
I180105 15:16:53.332596 158027 storage/replica_raftstorage.go:752  [n2,s2,r17/?:/Table/2{0-1}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.333200 157268 storage/replica_command.go:1741  [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, next=2]
I180105 15:16:53.335151 157268 storage/replica.go:3192  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180105 15:16:53.335547 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 6d8c72e0 at index 81
I180105 15:16:53.336293 157203 storage/store.go:3567  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 61, log entries: 71, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.336589 158068 storage/replica_raftstorage.go:746  [n2,s2,r1/?:{-}] applying preemptive snapshot at index 81 (id=6d8c72e0, encoded size=18419, 1 rocksdb batches, 71 log entries)
I180105 15:16:53.336928 158068 storage/replica_raftstorage.go:752  [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.337283 157203 storage/replica_command.go:1741  [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]
I180105 15:16:53.339132 157203 storage/replica.go:3192  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180105 15:16:53.339649 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot 666853be at index 16
I180105 15:16:53.340281 157268 storage/store.go:3567  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.340556 158072 storage/replica_raftstorage.go:746  [n3,s3,r15/?:{-}] applying preemptive snapshot at index 16 (id=666853be, encoded size=2476, 1 rocksdb batches, 6 log entries)
I180105 15:16:53.340739 158072 storage/replica_raftstorage.go:752  [n3,s3,r15/?:/Table/1{8-9}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.341062 157268 storage/replica_command.go:1741  [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]
I180105 15:16:53.343380 157268 storage/replica.go:3192  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180105 15:16:53.343812 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot da56b536 at index 23
I180105 15:16:53.348241 157268 storage/store.go:3567  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 952, log entries: 13, rate-limit: 8.0 MiB/sec, 4ms
I180105 15:16:53.348670 156965 testutils/testcluster/testcluster.go:528  [n1,s1] has 18 underreplicated ranges
I180105 15:16:53.348831 157937 storage/replica_raftstorage.go:746  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 23 (id=da56b536, encoded size=159445, 1 rocksdb batches, 13 log entries)
I180105 15:16:53.350175 157937 storage/replica_raftstorage.go:752  [n2,s2,r5/?:/System/ts{d-e}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180105 15:16:53.350651 157268 storage/replica_command.go:1741  [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]
I180105 15:16:53.353406 157268 storage/replica.go:3192  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180105 15:16:53.353942 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot 1286146b at index 28
I180105 15:16:53.354801 157203 storage/store.go:3567  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 13, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.355234 158088 storage/replica_raftstorage.go:746  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 28 (id=1286146b, encoded size=55575, 1 rocksdb batches, 13 log entries)
I180105 15:16:53.355673 158088 storage/replica_raftstorage.go:752  [n2,s2,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.356060 157203 storage/replica_command.go:1741  [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]
I180105 15:16:53.358956 157203 storage/replica.go:3192  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180105 15:16:53.359794 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot 03736041 at index 25
I180105 15:16:53.360495 157268 storage/store.go:3567  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n3,s3):?: kv pairs: 20, log entries: 15, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.360801 158078 storage/replica_raftstorage.go:746  [n3,s3,r12/?:{-}] applying preemptive snapshot at index 25 (id=03736041, encoded size=7901, 1 rocksdb batches, 15 log entries)
I180105 15:16:53.361022 158078 storage/replica_raftstorage.go:752  [n3,s3,r12/?:/Table/1{5-6}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.361432 157268 storage/replica_command.go:1741  [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]
I180105 15:16:53.363991 157268 storage/replica.go:3192  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180105 15:16:53.364432 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot 1ca273a5 at index 23
I180105 15:16:53.365049 157268 storage/store.go:3567  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 14, log entries: 13, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.365371 158041 storage/replica_raftstorage.go:746  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 23 (id=1ca273a5, encoded size=6104, 1 rocksdb batches, 13 log entries)
I180105 15:16:53.365591 158041 storage/replica_raftstorage.go:752  [n3,s3,r8/?:/Table/1{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.365911 157268 storage/replica_command.go:1741  [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]
I180105 15:16:53.368325 157268 storage/replica.go:3192  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180105 15:16:53.368757 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 47a2fcd8 at index 94
I180105 15:16:53.369701 157203 storage/store.go:3567  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n3,s3):?: kv pairs: 69, log entries: 84, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.370116 158139 storage/replica_raftstorage.go:746  [n3,s3,r1/?:{-}] applying preemptive snapshot at index 94 (id=47a2fcd8, encoded size=21763, 1 rocksdb batches, 84 log entries)
I180105 15:16:53.370513 158139 storage/replica_raftstorage.go:752  [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.370909 157203 storage/replica_command.go:1741  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r1:/{Min-System/} [(n1,s1):1, (n2,s2):2, next=3]
I180105 15:16:53.373708 158031 storage/replica.go:3192  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180105 15:16:53.374689 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot b971623d at index 52
I180105 15:16:53.375723 157268 storage/store.go:3567  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 81, log entries: 42, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.376284 158048 storage/replica_raftstorage.go:746  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 52 (id=b971623d, encoded size=41663, 1 rocksdb batches, 42 log entries)
I180105 15:16:53.376711 158048 storage/replica_raftstorage.go:752  [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.377058 157268 storage/replica_command.go:1741  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, next=2]
I180105 15:16:53.379423 157268 storage/replica.go:3192  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180105 15:16:53.379860 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot b07afb77 at index 16
I180105 15:16:53.380469 157268 storage/store.go:3567  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.380821 158179 storage/replica_raftstorage.go:746  [n2,s2,r13/?:{-}] applying preemptive snapshot at index 16 (id=b07afb77, encoded size=2476, 1 rocksdb batches, 6 log entries)
I180105 15:16:53.381033 158179 storage/replica_raftstorage.go:752  [n2,s2,r13/?:/Table/1{6-7}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.381351 157268 storage/replica_command.go:1741  [replicate,n1,s1,r13/1:/Table/1{6-7}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, next=2]
I180105 15:16:53.383517 157268 storage/replica.go:3192  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180105 15:16:53.383902 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 1f4b62a9 at index 18
I180105 15:16:53.384491 157203 storage/store.go:3567  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.384895 158168 storage/replica_raftstorage.go:746  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 18 (id=1f4b62a9, encoded size=3467, 1 rocksdb batches, 8 log entries)
I180105 15:16:53.385122 158168 storage/replica_raftstorage.go:752  [n2,s2,r14/?:/Table/1{7-8}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.385435 157203 storage/replica_command.go:1741  [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]
I180105 15:16:53.387883 157203 storage/replica.go:3192  [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
I180105 15:16:53.388592 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot ac29cf6c at index 16
I180105 15:16:53.389176 157268 storage/store.go:3567  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.389491 158216 storage/replica_raftstorage.go:746  [n3,s3,r11/?:{-}] applying preemptive snapshot at index 16 (id=ac29cf6c, encoded size=2476, 1 rocksdb batches, 6 log entries)
I180105 15:16:53.389699 158216 storage/replica_raftstorage.go:752  [n3,s3,r11/?:/Table/1{4-5}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.390107 157268 storage/replica_command.go:1741  [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]
I180105 15:16:53.392375 157268 storage/replica.go:3192  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180105 15:16:53.392766 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot c0f8fa48 at index 17
I180105 15:16:53.393372 157268 storage/store.go:3567  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 7, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.393637 158153 storage/replica_raftstorage.go:746  [n3,s3,r16/?:{-}] applying preemptive snapshot at index 17 (id=c0f8fa48, encoded size=2545, 1 rocksdb batches, 7 log entries)
I180105 15:16:53.393836 158153 storage/replica_raftstorage.go:752  [n3,s3,r16/?:/Table/{19-20}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.394263 157268 storage/replica_command.go:1741  [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]
I180105 15:16:53.396243 157268 storage/replica.go:3192  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180105 15:16:53.396623 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot d35e7ed5 at index 26
I180105 15:16:53.401135 157203 storage/store.go:3567  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n3,s3):?: kv pairs: 953, log entries: 16, rate-limit: 8.0 MiB/sec, 4ms
I180105 15:16:53.401578 158191 storage/replica_raftstorage.go:746  [n3,s3,r5/?:{-}] applying preemptive snapshot at index 26 (id=d35e7ed5, encoded size=160575, 1 rocksdb batches, 16 log entries)
I180105 15:16:53.403047 158191 storage/replica_raftstorage.go:752  [n3,s3,r5/?:/System/ts{d-e}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180105 15:16:53.403560 157203 storage/replica_command.go:1741  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, (n2,s2):2, next=3]
I180105 15:16:53.406832 157203 storage/replica.go:3192  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180105 15:16:53.407715 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot c48a7dc6 at index 15
I180105 15:16:53.408370 157268 storage/store.go:3567  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.408712 158223 storage/replica_raftstorage.go:746  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 15 (id=c48a7dc6, encoded size=2407, 1 rocksdb batches, 5 log entries)
I180105 15:16:53.408884 158223 storage/replica_raftstorage.go:752  [n2,s2,r18/?:/Table/2{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.409281 157268 storage/replica_command.go:1741  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, next=2]
I180105 15:16:53.411765 157268 storage/replica.go:3192  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180105 15:16:53.412207 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot 4efe1880 at index 15
I180105 15:16:53.412677 157268 storage/store.go:3567  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 5, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.413064 158202 storage/replica_raftstorage.go:746  [n3,s3,r19/?:{-}] applying preemptive snapshot at index 15 (id=4efe1880, encoded size=2407, 1 rocksdb batches, 5 log entries)
I180105 15:16:53.413217 158202 storage/replica_raftstorage.go:752  [n3,s3,r19/?:/Table/2{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.413548 157268 storage/replica_command.go:1741  [replicate,n1,s1,r19/1:/Table/2{2-3}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, next=2]
I180105 15:16:53.415873 157268 storage/replica.go:3192  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180105 15:16:53.416445 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot 73127434 at index 28
I180105 15:16:53.419978 157203 storage/store.go:3567  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n2,s2):?: kv pairs: 21, log entries: 18, rate-limit: 8.0 MiB/sec, 3ms
I180105 15:16:53.421354 158161 storage/replica_raftstorage.go:746  [n2,s2,r12/?:{-}] applying preemptive snapshot at index 28 (id=73127434, encoded size=8961, 1 rocksdb batches, 18 log entries)
I180105 15:16:53.421577 158161 storage/replica_raftstorage.go:752  [n2,s2,r12/?:/Table/1{5-6}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.421906 157203 storage/replica_command.go:1741  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, (n3,s3):2, next=3]
I180105 15:16:53.424785 157203 storage/replica.go:3192  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180105 15:16:53.425532 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot a5773078 at index 12
I180105 15:16:53.426012 157268 storage/store.go:3567  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 2, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.426347 158249 storage/replica_raftstorage.go:746  [n3,s3,r20/?:{-}] applying preemptive snapshot at index 12 (id=a5773078, encoded size=946, 1 rocksdb batches, 2 log entries)
I180105 15:16:53.426500 158249 storage/replica_raftstorage.go:752  [n3,s3,r20/?:/{Table/23-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.426809 157268 storage/replica_command.go:1741  [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]
I180105 15:16:53.428973 157268 storage/replica.go:3192  [n1,s1,r20/1:/{Table/23-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180105 15:16:53.429486 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 435205cf at index 22
I180105 15:16:53.430026 157268 storage/store.go:3567  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 12, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.430335 158233 storage/replica_raftstorage.go:746  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 22 (id=435205cf, encoded size=6298, 1 rocksdb batches, 12 log entries)
I180105 15:16:53.430530 158233 storage/replica_raftstorage.go:752  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.430823 157268 storage/replica_command.go:1741  [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]
I180105 15:16:53.433139 157268 storage/replica.go:3192  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180105 15:16:53.433781 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot ec8100b9 at index 26
I180105 15:16:53.434389 157203 storage/store.go:3567  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 15, log entries: 16, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.434741 158239 storage/replica_raftstorage.go:746  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 26 (id=ec8100b9, encoded size=7164, 1 rocksdb batches, 16 log entries)
I180105 15:16:53.434956 158239 storage/replica_raftstorage.go:752  [n2,s2,r8/?:/Table/1{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.435638 157203 storage/replica_command.go:1741  [replicate,n1,s1,r8/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, (n3,s3):2, next=3]
I180105 15:16:53.438340 157203 storage/replica.go:3192  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180105 15:16:53.439067 157268 storage/replica_raftstorage.go:540  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 552ac9b5 at index 20
I180105 15:16:53.439546 157268 storage/store.go:3567  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 10, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.439754 158241 storage/replica_raftstorage.go:746  [n3,s3,r6/?:{-}] applying preemptive snapshot at index 20 (id=552ac9b5, encoded size=5784, 1 rocksdb batches, 10 log entries)
I180105 15:16:53.439913 158241 storage/replica_raftstorage.go:752  [n3,s3,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.439991 156965 testutils/testcluster/testcluster.go:528  [n1,s1] has 12 underreplicated ranges
I180105 15:16:53.440207 157268 storage/replica_command.go:1741  [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]
I180105 15:16:53.442357 157268 storage/replica.go:3192  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180105 15:16:53.442581 157268 storage/queue.go:735  [n1,replicate] purgatory is now empty
I180105 15:16:53.442744 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot f541bb78 at index 55
I180105 15:16:53.443612 157203 storage/store.go:3567  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):?: kv pairs: 82, log entries: 45, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.443969 158252 storage/replica_raftstorage.go:746  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 55 (id=f541bb78, encoded size=42723, 1 rocksdb batches, 45 log entries)
I180105 15:16:53.444393 158252 storage/replica_raftstorage.go:752  [n3,s3,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.444724 157203 storage/replica_command.go:1741  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n2,s2):2, next=3]
I180105 15:16:53.447187 157203 storage/replica.go:3192  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180105 15:16:53.448106 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot 369554b3 at index 18
I180105 15:16:53.448637 157203 storage/store.go:3567  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 8, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.448913 158328 storage/replica_raftstorage.go:746  [n2,s2,r19/?:{-}] applying preemptive snapshot at index 18 (id=369554b3, encoded size=3467, 1 rocksdb batches, 8 log entries)
I180105 15:16:53.449093 158328 storage/replica_raftstorage.go:752  [n2,s2,r19/?:/Table/2{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.449341 157203 storage/replica_command.go:1741  [replicate,n1,s1,r19/1:/Table/2{2-3}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, (n3,s3):2, next=3]
I180105 15:16:53.451873 157203 storage/replica.go:3192  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180105 15:16:53.452719 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot 1b57031f at index 15
I180105 15:16:53.453209 157203 storage/store.go:3567  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n2,s2):?: kv pairs: 14, log entries: 5, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.453492 158317 storage/replica_raftstorage.go:746  [n2,s2,r20/?:{-}] applying preemptive snapshot at index 15 (id=1b57031f, encoded size=2010, 1 rocksdb batches, 5 log entries)
I180105 15:16:53.453635 158317 storage/replica_raftstorage.go:752  [n2,s2,r20/?:/{Table/23-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.453996 157203 storage/replica_command.go:1741  [replicate,n1,s1,r20/1:/{Table/23-Max}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r20:/{Table/23-Max} [(n1,s1):1, (n3,s3):2, next=3]
I180105 15:16:53.456493 157203 storage/replica.go:3192  [n1,s1,r20/1:/{Table/23-Max}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180105 15:16:53.457303 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 01b7c66a at index 25
I180105 15:16:53.457917 157203 storage/store.go:3567  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 15, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.458156 158357 storage/replica_raftstorage.go:746  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 25 (id=01b7c66a, encoded size=7601, 1 rocksdb batches, 15 log entries)
I180105 15:16:53.458923 158357 storage/replica_raftstorage.go:752  [n3,s3,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180105 15:16:53.459175 157203 storage/replica_command.go:1741  [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]
I180105 15:16:53.461735 157203 storage/replica.go:3192  [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
I180105 15:16:53.462550 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 9def6563 at index 23
I180105 15:16:53.463067 157203 storage/store.go:3567  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 13, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.463404 158361 storage/replica_raftstorage.go:746  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 23 (id=9def6563, encoded size=6902, 1 rocksdb batches, 13 log entries)
I180105 15:16:53.463637 158361 storage/replica_raftstorage.go:752  [n2,s2,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.463986 157203 storage/replica_command.go:1741  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, (n3,s3):2, next=3]
I180105 15:16:53.466262 157203 storage/replica.go:3192  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180105 15:16:53.467044 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot bd40471f at index 51
I180105 15:16:53.467915 157203 storage/store.go:3567  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 44, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.468245 158374 storage/replica_raftstorage.go:746  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 51 (id=bd40471f, encoded size=69957, 1 rocksdb batches, 5 log entries)
I180105 15:16:53.468710 158374 storage/replica_raftstorage.go:752  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.469073 157203 storage/replica_command.go:1741  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, (n2,s2):2, next=3]
I180105 15:16:53.471557 158386 storage/replica.go:3192  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180105 15:16:53.472425 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot 26cd7dbc at index 18
I180105 15:16:53.472981 157203 storage/store.go:3567  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 8, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.473355 158333 storage/replica_raftstorage.go:746  [n3,s3,r17/?:{-}] applying preemptive snapshot at index 18 (id=26cd7dbc, encoded size=3467, 1 rocksdb batches, 8 log entries)
I180105 15:16:53.473536 158333 storage/replica_raftstorage.go:752  [n3,s3,r17/?:/Table/2{0-1}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.473886 157203 storage/replica_command.go:1741  [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, (n2,s2):2, next=3]
I180105 15:16:53.476246 158389 storage/replica.go:3192  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180105 15:16:53.477003 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot bc2f2c20 at index 19
I180105 15:16:53.477512 157203 storage/store.go:3567  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 9, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.477748 158336 storage/replica_raftstorage.go:746  [n3,s3,r13/?:{-}] applying preemptive snapshot at index 19 (id=bc2f2c20, encoded size=3536, 1 rocksdb batches, 9 log entries)
I180105 15:16:53.477928 158336 storage/replica_raftstorage.go:752  [n3,s3,r13/?:/Table/1{6-7}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.478195 157203 storage/replica_command.go:1741  [replicate,n1,s1,r13/1:/Table/1{6-7}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, (n2,s2):2, next=3]
I180105 15:16:53.480561 157203 storage/replica.go:3192  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180105 15:16:53.481309 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot f8701c8c at index 19
I180105 15:16:53.481868 157203 storage/store.go:3567  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 9, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.482105 158451 storage/replica_raftstorage.go:746  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 19 (id=f8701c8c, encoded size=3536, 1 rocksdb batches, 9 log entries)
I180105 15:16:53.482308 158451 storage/replica_raftstorage.go:752  [n2,s2,r11/?:/Table/1{4-5}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.482577 157203 storage/replica_command.go:1741  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, (n3,s3):2, next=3]
I180105 15:16:53.484930 157203 storage/replica.go:3192  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180105 15:16:53.485741 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot b86aadee at index 19
I180105 15:16:53.486203 157203 storage/store.go:3567  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 9, rate-limit: 8.0 MiB/sec, 0ms
I180105 15:16:53.486485 158382 storage/replica_raftstorage.go:746  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 19 (id=b86aadee, encoded size=3536, 1 rocksdb batches, 9 log entries)
I180105 15:16:53.486662 158382 storage/replica_raftstorage.go:752  [n2,s2,r15/?:/Table/1{8-9}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.486913 157203 storage/replica_command.go:1741  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, (n3,s3):2, next=3]
I180105 15:16:53.489165 157203 storage/replica.go:3192  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180105 15:16:53.490008 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot 4f6c0efa at index 20
I180105 15:16:53.490619 157203 storage/store.go:3567  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 10, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.490875 158391 storage/replica_raftstorage.go:746  [n2,s2,r16/?:{-}] applying preemptive snapshot at index 20 (id=4f6c0efa, encoded size=3605, 1 rocksdb batches, 10 log entries)
I180105 15:16:53.491048 158391 storage/replica_raftstorage.go:752  [n2,s2,r16/?:/Table/{19-20}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.491354 157203 storage/replica_command.go:1741  [replicate,n1,s1,r16/1:/Table/{19-20}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r16:/Table/{19-20} [(n1,s1):1, (n3,s3):2, next=3]
I180105 15:16:53.493647 157203 storage/replica.go:3192  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180105 15:16:53.494445 157203 storage/replica_raftstorage.go:540  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot e9bd935a at index 18
I180105 15:16:53.495032 157203 storage/store.go:3567  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180105 15:16:53.495335 158407 storage/replica_raftstorage.go:746  [n3,s3,r18/?:{-}] applying preemptive snapshot at index 18 (id=e9bd935a, encoded size=3467, 1 rocksdb batches, 8 log entries)
I180105 15:16:53.495582 158407 storage/replica_raftstorage.go:752  [n3,s3,r18/?:/Table/2{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180105 15:16:53.495903 157203 storage/replica_command.go:1741  [replicate,n1,s1,r18/1:/Table/2{1-2}] chang

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added O-robot Originated from a bot. C-test-failure Broken test (automatically or manually discovered). labels Jan 5, 2018
@benesch
Copy link
Contributor

benesch commented Jan 20, 2018

Timeout caused by slow partitioning tests. Fixed by #21392.

@benesch benesch closed this as completed Jan 20, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@benesch @cockroach-teamcity