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, test/TestRestoreDatabaseVersusTable/db, testrace/TestRestoreDatabaseVersusTable, testrace/TestRestoreDatabaseVersusTable/incomplete-db, testrace/TestRestoreDatabaseVersusTable/db #21332

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

teamcity: failed tests on master: test/TestRestoreDatabaseVersusTable/incomplete-db, test/TestRestoreDatabaseVersusTable, test/TestRestoreDatabaseVersusTable/db, testrace/TestRestoreDatabaseVersusTable, testrace/TestRestoreDatabaseVersusTable/incomplete-db, testrace/TestRestoreDatabaseVersusTable/db #21332

cockroach-teamcity opened this issue Jan 8, 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:

#471756:

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

------- Stdout: -------
W180108 22:45:40.025402 152487 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180108 22:45:40.027196 152487 server/config.go:516  [n?] 1 storage engine initialized
I180108 22:45:40.027216 152487 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180108 22:45:40.027222 152487 server/config.go:519  [n?] store 0: in-memory, size 0 B
I180108 22:45:40.029468 152487 server/node.go:361  [n?] **** cluster 9381c5fc-d03e-44df-b389-185bab6b7d24 has been created
I180108 22:45:40.029496 152487 server/server.go:934  [n?] **** add additional nodes by specifying --join=127.0.0.1:38705
I180108 22:45:40.030132 152487 storage/store.go:1209  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180108 22:45:40.030266 152487 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}
I180108 22:45:40.030325 152487 server/node.go:339  [n1] node ID 1 initialized
I180108 22:45:40.030378 152487 gossip/gossip.go:332  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:38705" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180108 22:45:40.030453 152487 storage/stores.go:331  [n1] read 0 node addresses from persistent storage
I180108 22:45:40.030507 152487 server/node.go:627  [n1] connecting to gossip network to verify cluster ID...
I180108 22:45:40.030526 152487 server/node.go:652  [n1] node connected via gossip and verified as part of cluster "9381c5fc-d03e-44df-b389-185bab6b7d24"
I180108 22:45:40.030545 152487 server/node.go:428  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180108 22:45:40.030584 152487 sql/distsql_physical_planner.go:122  [n1] creating DistSQLPlanner with address {tcp 127.0.0.1:38705}
I180108 22:45:40.032577 152678 storage/replica_command.go:819  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180108 22:45:40.036035 152487 server/server.go:1161  [n1] starting https server at 127.0.0.1:38629
I180108 22:45:40.036062 152487 server/server.go:1162  [n1] starting grpc/postgres server at 127.0.0.1:38705
I180108 22:45:40.036072 152487 server/server.go:1163  [n1] advertising CockroachDB node at 127.0.0.1:38705
I180108 22:45:40.040707 152678 storage/replica_command.go:819  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180108 22:45:40.041238 152432 storage/intent_resolver.go:324  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=84be2e14 key=/Table/SystemConfigSpan/Start rw=true pri=0.02169306 iso=SERIALIZABLE stat=PENDING epo=0 ts=1515451540.037387546,0 orig=1515451540.037387546,0 max=1515451540.037387546,0 wto=false rop=false seq=7
I180108 22:45:40.043439 152487 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:[]}
I180108 22:45:40.047157 152678 storage/replica_command.go:819  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180108 22:45:40.049493 152487 sql/lease.go:348  [n1] publish: descID=12 (eventlog) version=2 mtime=2018-01-08 22:45:40.049370387 +0000 UTC
I180108 22:45:40.051638 152678 storage/replica_command.go:819  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180108 22:45:40.056671 152678 storage/replica_command.go:819  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180108 22:45:40.062235 152678 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]
W180108 22:45:40.062608 152736 storage/intent_resolver.go:324  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=2fe2c02d key=/Table/SystemConfigSpan/Start rw=true pri=0.01112754 iso=SERIALIZABLE stat=PENDING epo=0 ts=1515451540.058495995,0 orig=1515451540.058495995,0 max=1515451540.058495995,0 wto=false rop=false seq=7
I180108 22:45:40.063858 152487 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}
I180108 22:45:40.065600 152678 storage/replica_command.go:819  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180108 22:45:40.068791 152678 storage/replica_command.go:819  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180108 22:45:40.072853 152678 storage/replica_command.go:819  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180108 22:45:40.075889 152487 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:node}
I180108 22:45:40.078236 152678 storage/replica_command.go:819  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180108 22:45:40.079389 152487 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}
I180108 22:45:40.081652 152678 storage/replica_command.go:819  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180108 22:45:40.084425 152678 storage/replica_command.go:819  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180108 22:45:40.087529 152678 storage/replica_command.go:819  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180108 22:45:40.090217 152487 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:[]}
I180108 22:45:40.090558 152678 storage/replica_command.go:819  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180108 22:45:40.092020 152487 sql/lease.go:348  [n1] publish: descID=4 (users) version=2 mtime=2018-01-08 22:45:40.091942818 +0000 UTC
I180108 22:45:40.093670 152678 storage/replica_command.go:819  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180108 22:45:40.095303 152487 sql/lease.go:348  [n1] publish: descID=4 (users) version=3 mtime=2018-01-08 22:45:40.095223728 +0000 UTC
I180108 22:45:40.097459 152678 storage/replica_command.go:819  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180108 22:45:40.097998 152487 sql/backfill.go:132  [n1] Running backfill for "users", v=3, m=1
I180108 22:45:40.100087 152678 storage/replica_command.go:819  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180108 22:45:40.102808 152678 storage/replica_command.go:819  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180108 22:45:40.105567 152487 sql/lease.go:348  [n1] publish: descID=4 (users) version=4 mtime=2018-01-08 22:45:40.105481342 +0000 UTC
I180108 22:45:40.106391 152678 storage/replica_command.go:819  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180108 22:45:40.111860 152487 sql/event_log.go:115  [n1] Event: "finish_schema_change", target: 4, info: {MutationID:1}
I180108 22:45:40.112850 152487 sql/lease.go:274  publish (count leases): descID=4 name=users version=3 count=1
I180108 22:45:40.142990 152487 server/server.go:1232  [n1] done ensuring all necessary migrations have run
I180108 22:45:40.143030 152487 server/server.go:1235  [n1] serving sql connections
I180108 22:45:40.145650 153012 sql/event_log.go:115  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:38705} Attrs: Locality: ServerVersion:1.1-8} ClusterID:9381c5fc-d03e-44df-b389-185bab6b7d24 StartedAt:1515451540030531681 LastUp:1515451540030531681}
W180108 22:45:40.148144 152487 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180108 22:45:40.150435 152487 server/config.go:516  [n?] 1 storage engine initialized
I180108 22:45:40.150461 152487 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180108 22:45:40.150467 152487 server/config.go:519  [n?] store 0: in-memory, size 0 B
W180108 22:45:40.150520 152487 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180108 22:45:40.150567 152487 server/server.go:936  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180108 22:45:40.162980 152954 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:38705
I180108 22:45:40.163407 152923 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:39899}
I180108 22:45:40.164386 152487 storage/stores.go:331  [n?] read 0 node addresses from persistent storage
I180108 22:45:40.164435 152487 storage/stores.go:350  [n?] wrote 1 node addresses to persistent storage
I180108 22:45:40.164445 152487 server/node.go:627  [n?] connecting to gossip network to verify cluster ID...
I180108 22:45:40.164470 152487 server/node.go:652  [n?] node connected via gossip and verified as part of cluster "9381c5fc-d03e-44df-b389-185bab6b7d24"
I180108 22:45:40.164711 153066 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180108 22:45:40.165661 153065 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180108 22:45:40.166401 152487 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180108 22:45:40.167305 152487 server/node.go:332  [n?] new node allocated ID 2
I180108 22:45:40.167382 152487 gossip/gossip.go:332  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:39899" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180108 22:45:40.167449 152487 server/node.go:414  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180108 22:45:40.167485 152487 server/node.go:428  [n2] node=2: started with [] engine(s) and attributes []
I180108 22:45:40.167560 152487 sql/distsql_physical_planner.go:122  [n2] creating DistSQLPlanner with address {tcp 127.0.0.1:39899}
I180108 22:45:40.167924 153106 storage/stores.go:350  [n1] wrote 1 node addresses to persistent storage
I180108 22:45:40.168631 153071 server/node.go:608  [n2] bootstrapped store [n2,s2]
I180108 22:45:40.174641 152487 server/server.go:1161  [n2] starting https server at 127.0.0.1:38303
I180108 22:45:40.174669 152487 server/server.go:1162  [n2] starting grpc/postgres server at 127.0.0.1:39899
I180108 22:45:40.174680 152487 server/server.go:1163  [n2] advertising CockroachDB node at 127.0.0.1:39899
I180108 22:45:40.175639 152487 server/server.go:1232  [n2] done ensuring all necessary migrations have run
I180108 22:45:40.175669 152487 server/server.go:1235  [n2] serving sql connections
I180108 22:45:40.180023 152927 sql/event_log.go:115  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:39899} Attrs: Locality: ServerVersion:1.1-8} ClusterID:9381c5fc-d03e-44df-b389-185bab6b7d24 StartedAt:1515451540167461776 LastUp:1515451540167461776}
W180108 22:45:40.181681 152487 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180108 22:45:40.183939 152487 server/config.go:516  [n?] 1 storage engine initialized
I180108 22:45:40.183958 152487 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180108 22:45:40.183965 152487 server/config.go:519  [n?] store 0: in-memory, size 0 B
W180108 22:45:40.184025 152487 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180108 22:45:40.184060 152487 server/server.go:936  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180108 22:45:40.195480 153234 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:38705
I180108 22:45:40.195822 153239 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:41387}
I180108 22:45:40.196686 152487 storage/stores.go:331  [n?] read 0 node addresses from persistent storage
I180108 22:45:40.196733 152487 storage/stores.go:350  [n?] wrote 2 node addresses to persistent storage
I180108 22:45:40.196747 152487 server/node.go:627  [n?] connecting to gossip network to verify cluster ID...
I180108 22:45:40.196766 152487 server/node.go:652  [n?] node connected via gossip and verified as part of cluster "9381c5fc-d03e-44df-b389-185bab6b7d24"
I180108 22:45:40.196999 153287 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180108 22:45:40.197738 153286 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180108 22:45:40.198407 152487 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180108 22:45:40.199276 152487 server/node.go:332  [n?] new node allocated ID 3
I180108 22:45:40.199347 152487 gossip/gossip.go:332  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:41387" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180108 22:45:40.199400 152487 server/node.go:414  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180108 22:45:40.199418 152487 server/node.go:428  [n3] node=3: started with [] engine(s) and attributes []
I180108 22:45:40.199461 152487 sql/distsql_physical_planner.go:122  [n3] creating DistSQLPlanner with address {tcp 127.0.0.1:41387}
I180108 22:45:40.200241 153052 storage/stores.go:350  [n1] wrote 2 node addresses to persistent storage
I180108 22:45:40.200573 153205 storage/stores.go:350  [n2] wrote 2 node addresses to persistent storage
I180108 22:45:40.205990 153257 server/node.go:608  [n3] bootstrapped store [n3,s3]
I180108 22:45:40.207201 152487 server/server.go:1161  [n3] starting https server at 127.0.0.1:33177
I180108 22:45:40.207224 152487 server/server.go:1162  [n3] starting grpc/postgres server at 127.0.0.1:41387
I180108 22:45:40.207234 152487 server/server.go:1163  [n3] advertising CockroachDB node at 127.0.0.1:41387
I180108 22:45:40.208987 152487 server/server.go:1232  [n3] done ensuring all necessary migrations have run
I180108 22:45:40.209057 152487 server/server.go:1235  [n3] serving sql connections
I180108 22:45:40.209116 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot eaacbebc at index 15
I180108 22:45:40.210780 152487 testutils/testcluster/testcluster.go:528  [n1,s1] has 20 underreplicated ranges
I180108 22:45:40.213982 153416 sql/event_log.go:115  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:41387} Attrs: Locality: ServerVersion:1.1-8} ClusterID:9381c5fc-d03e-44df-b389-185bab6b7d24 StartedAt:1515451540199409030 LastUp:1515451540199409030}
I180108 22:45:40.218696 152754 storage/store.go:3567  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.218998 153445 storage/replica_raftstorage.go:746  [n3,s3,r14/?:{-}] applying preemptive snapshot at index 15 (id=eaacbebc, encoded size=2547, 1 rocksdb batches, 5 log entries)
I180108 22:45:40.219728 153445 storage/replica_raftstorage.go:752  [n3,s3,r14/?:/Table/1{7-8}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180108 22:45:40.220181 152754 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]
I180108 22:45:40.220495 152487 testutils/testcluster/testcluster.go:528  [n1,s1] has 20 underreplicated ranges
I180108 22:45:40.221680 152754 storage/replica.go:3203  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180108 22:45:40.222084 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot 49b7f32c at index 15
I180108 22:45:40.223069 153459 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180108 22:45:40.231537 152754 storage/store.go:3567  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.231769 153297 storage/replica_raftstorage.go:746  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 15 (id=49b7f32c, encoded size=2547, 1 rocksdb batches, 5 log entries)
I180108 22:45:40.231949 153297 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]
I180108 22:45:40.232484 152754 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]
I180108 22:45:40.233974 152754 storage/replica.go:3203  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180108 22:45:40.234415 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot c2816772 at index 52
I180108 22:45:40.235392 152754 storage/store.go:3567  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):?: kv pairs: 83, log entries: 42, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.235525 153506 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180108 22:45:40.235868 153479 storage/replica_raftstorage.go:746  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 52 (id=c2816772, encoded size=41841, 1 rocksdb batches, 42 log entries)
I180108 22:45:40.236395 153479 storage/replica_raftstorage.go:752  [n3,s3,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.236764 152754 storage/replica_command.go:1741  [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]
I180108 22:45:40.238210 152754 storage/replica.go:3203  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180108 22:45:40.238613 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot fe2cb007 at index 18
I180108 22:45:40.239170 152679 storage/store.go:3567  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 8, rate-limit: 8.0 MiB/sec, 0ms
I180108 22:45:40.239325 152487 testutils/testcluster/testcluster.go:528  [n1,s1] has 20 underreplicated ranges
I180108 22:45:40.239388 153513 storage/replica_raftstorage.go:746  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 18 (id=fe2cb007, encoded size=3607, 1 rocksdb batches, 8 log entries)
I180108 22:45:40.239550 153513 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]
I180108 22:45:40.239974 152679 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]
I180108 22:45:40.241914 152679 storage/replica.go:3203  [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
I180108 22:45:40.242749 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot 2389917a at index 22
I180108 22:45:40.243351 152754 storage/store.go:3567  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 14, log entries: 12, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.243699 153515 storage/replica_raftstorage.go:746  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 22 (id=2389917a, encoded size=5868, 1 rocksdb batches, 12 log entries)
I180108 22:45:40.243911 153515 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]
I180108 22:45:40.244276 152754 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]
I180108 22:45:40.245876 152754 storage/replica.go:3203  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180108 22:45:40.246303 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot 5e354e2c at index 15
I180108 22:45:40.246894 152754 storage/store.go:3567  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.247166 153519 storage/replica_raftstorage.go:746  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 15 (id=5e354e2c, encoded size=2547, 1 rocksdb batches, 5 log entries)
I180108 22:45:40.247338 153519 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]
I180108 22:45:40.247661 152754 storage/replica_command.go:1741  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, next=2]
I180108 22:45:40.249045 152754 storage/replica.go:3203  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180108 22:45:40.249415 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 5d7ff53c at index 80
I180108 22:45:40.250669 152679 storage/store.go:3567  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 59, log entries: 70, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.251094 153103 storage/replica_raftstorage.go:746  [n2,s2,r1/?:{-}] applying preemptive snapshot at index 80 (id=5d7ff53c, encoded size=35613, 1 rocksdb batches, 70 log entries)
I180108 22:45:40.251548 153103 storage/replica_raftstorage.go:752  [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.251920 152679 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]
I180108 22:45:40.253298 152679 storage/replica.go:3203  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180108 22:45:40.253705 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot e0549e5e at index 24
I180108 22:45:40.254291 152754 storage/store.go:3567  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 14, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.254556 153530 storage/replica_raftstorage.go:746  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 24 (id=e0549e5e, encoded size=5943, 1 rocksdb batches, 14 log entries)
I180108 22:45:40.254750 153530 storage/replica_raftstorage.go:752  [n3,s3,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.255303 152754 storage/replica_command.go:1741  [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]
I180108 22:45:40.257172 152754 storage/replica.go:3203  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180108 22:45:40.257527 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot 74c76ae1 at index 17
I180108 22:45:40.258260 152754 storage/store.go:3567  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 7, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.258529 153573 storage/replica_raftstorage.go:746  [n2,s2,r17/?:{-}] applying preemptive snapshot at index 17 (id=74c76ae1, encoded size=2685, 1 rocksdb batches, 7 log entries)
I180108 22:45:40.258694 153573 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]
I180108 22:45:40.259237 152754 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]
I180108 22:45:40.261423 152754 storage/replica.go:3203  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180108 22:45:40.261764 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot f6ae10aa at index 18
I180108 22:45:40.262358 152679 storage/store.go:3567  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 12, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.262698 153559 storage/replica_raftstorage.go:746  [n3,s3,r18/?:{-}] applying preemptive snapshot at index 18 (id=f6ae10aa, encoded size=3607, 1 rocksdb batches, 8 log entries)
I180108 22:45:40.262904 153559 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]
I180108 22:45:40.263283 152679 storage/replica_command.go:1741  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, (n2,s2):2, next=3]
I180108 22:45:40.265875 153605 storage/replica.go:3203  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180108 22:45:40.266683 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 97df55f2 at index 30
I180108 22:45:40.267609 152754 storage/store.go:3567  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 56, log entries: 20, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.267999 153562 storage/replica_raftstorage.go:746  [n2,s2,r9/?:{-}] applying preemptive snapshot at index 30 (id=97df55f2, encoded size=19472, 1 rocksdb batches, 20 log entries)
I180108 22:45:40.268346 153562 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]
I180108 22:45:40.268692 152754 storage/replica_command.go:1741  [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, next=2]
I180108 22:45:40.270516 152754 storage/replica.go:3203  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180108 22:45:40.270947 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot f7f1cf0e at index 16
I180108 22:45:40.271539 152754 storage/store.go:3567  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.271780 153568 storage/replica_raftstorage.go:746  [n3,s3,r11/?:{-}] applying preemptive snapshot at index 16 (id=f7f1cf0e, encoded size=2616, 1 rocksdb batches, 6 log entries)
I180108 22:45:40.271921 153568 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]
I180108 22:45:40.272193 152754 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]
I180108 22:45:40.274197 152754 storage/replica.go:3203  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180108 22:45:40.274689 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 3dbe245f at index 93
I180108 22:45:40.275754 152679 storage/store.go:3567  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n3,s3):?: kv pairs: 67, log entries: 83, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.276266 153615 storage/replica_raftstorage.go:746  [n3,s3,r1/?:{-}] applying preemptive snapshot at index 93 (id=3dbe245f, encoded size=38949, 1 rocksdb batches, 83 log entries)
I180108 22:45:40.276691 153615 storage/replica_raftstorage.go:752  [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.277077 152679 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]
I180108 22:45:40.279200 153652 storage/replica.go:3203  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180108 22:45:40.279782 152487 testutils/testcluster/testcluster.go:528  [n1,s1] has 18 underreplicated ranges
I180108 22:45:40.280200 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 1db88616 at index 49
I180108 22:45:40.284405 152754 storage/store.go:3567  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n2,s2):?: kv pairs: 45, log entries: 2, rate-limit: 8.0 MiB/sec, 4ms
I180108 22:45:40.286493 153598 storage/replica_raftstorage.go:746  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 49 (id=1db88616, encoded size=68855, 1 rocksdb batches, 2 log entries)
I180108 22:45:40.287269 153598 storage/replica_raftstorage.go:752  [n2,s2,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180108 22:45:40.287734 152754 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]
I180108 22:45:40.289777 152754 storage/replica.go:3203  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180108 22:45:40.290242 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot 3f65d474 at index 61
I180108 22:45:40.291458 152754 storage/store.go:3567  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 200, log entries: 51, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.291813 153682 storage/replica_raftstorage.go:746  [n2,s2,r10/?:{-}] applying preemptive snapshot at index 61 (id=3f65d474, encoded size=62838, 1 rocksdb batches, 51 log entries)
I180108 22:45:40.292520 153682 storage/replica_raftstorage.go:752  [n2,s2,r10/?:/Table/1{3-4}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.293012 152754 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]
I180108 22:45:40.295428 152754 storage/replica.go:3203  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180108 22:45:40.295923 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot 2350dfee at index 25
I180108 22:45:40.296724 152679 storage/store.go:3567  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 15, log entries: 15, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.297075 153675 storage/replica_raftstorage.go:746  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 25 (id=2350dfee, encoded size=6928, 1 rocksdb batches, 15 log entries)
I180108 22:45:40.297371 153675 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]
I180108 22:45:40.297698 152679 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]
I180108 22:45:40.300916 152679 storage/replica.go:3203  [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
I180108 22:45:40.301880 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot f77f502a at index 25
I180108 22:45:40.302680 152754 storage/store.go:3567  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n3,s3):?: kv pairs: 21, log entries: 15, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.303032 153686 storage/replica_raftstorage.go:746  [n3,s3,r12/?:{-}] applying preemptive snapshot at index 25 (id=f77f502a, encoded size=8037, 1 rocksdb batches, 15 log entries)
I180108 22:45:40.303342 153686 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]
I180108 22:45:40.303704 152754 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]
I180108 22:45:40.306410 152754 storage/replica.go:3203  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180108 22:45:40.306824 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot d6f1c816 at index 15
I180108 22:45:40.307495 152754 storage/store.go:3567  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.307867 153662 storage/replica_raftstorage.go:746  [n3,s3,r16/?:{-}] applying preemptive snapshot at index 15 (id=d6f1c816, encoded size=2547, 1 rocksdb batches, 5 log entries)
I180108 22:45:40.308067 153662 storage/replica_raftstorage.go:752  [n3,s3,r16/?:/Table/{19-20}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.308666 152754 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]
I180108 22:45:40.311149 152754 storage/replica.go:3203  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180108 22:45:40.311569 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot ad6544e7 at index 18
I180108 22:45:40.312199 152679 storage/store.go:3567  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n3,s3):?: kv pairs: 12, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.312455 153441 storage/replica_raftstorage.go:746  [n3,s3,r15/?:{-}] applying preemptive snapshot at index 18 (id=ad6544e7, encoded size=3607, 1 rocksdb batches, 8 log entries)
I180108 22:45:40.312651 153441 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]
I180108 22:45:40.313004 152679 storage/replica_command.go:1741  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, (n2,s2):2, next=3]
I180108 22:45:40.316097 152679 storage/replica.go:3203  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180108 22:45:40.317068 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot 5cf05c5e at index 12
I180108 22:45:40.317638 152754 storage/store.go:3567  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n2,s2):?: kv pairs: 14, log entries: 2, rate-limit: 8.0 MiB/sec, 0ms
I180108 22:45:40.317919 153746 storage/replica_raftstorage.go:746  [n2,s2,r20/?:{-}] applying preemptive snapshot at index 12 (id=5cf05c5e, encoded size=1016, 1 rocksdb batches, 2 log entries)
I180108 22:45:40.318091 153746 storage/replica_raftstorage.go:752  [n2,s2,r20/?:/{Table/23-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.318369 152754 storage/replica_command.go:1741  [replicate,n1,s1,r20/1:/{Table/23-Max}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r20:/{Table/23-Max} [(n1,s1):1, next=2]
I180108 22:45:40.320785 152754 storage/replica.go:3203  [n1,s1,r20/1:/{Table/23-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180108 22:45:40.321287 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot 9ea6820d at index 15
I180108 22:45:40.321928 152754 storage/store.go:3567  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.322209 153732 storage/replica_raftstorage.go:746  [n3,s3,r19/?:{-}] applying preemptive snapshot at index 15 (id=9ea6820d, encoded size=2547, 1 rocksdb batches, 5 log entries)
I180108 22:45:40.322374 153732 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]
I180108 22:45:40.322768 152754 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]
I180108 22:45:40.325170 152754 storage/replica.go:3203  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180108 22:45:40.325582 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot f6cc9e60 at index 33
I180108 22:45:40.326387 152679 storage/store.go:3567  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 57, log entries: 23, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.326770 153696 storage/replica_raftstorage.go:746  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 33 (id=f6cc9e60, encoded size=20532, 1 rocksdb batches, 23 log entries)
I180108 22:45:40.327190 153696 storage/replica_raftstorage.go:752  [n3,s3,r9/?:/Table/1{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.327500 152679 storage/replica_command.go:1741  [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, (n2,s2):2, next=3]
I180108 22:45:40.330370 152679 storage/replica.go:3203  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180108 22:45:40.331968 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot 965e66a2 at index 16
I180108 22:45:40.332420 152754 storage/store.go:3567  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 6, rate-limit: 8.0 MiB/sec, 0ms
I180108 22:45:40.332685 153778 storage/replica_raftstorage.go:746  [n2,s2,r13/?:{-}] applying preemptive snapshot at index 16 (id=965e66a2, encoded size=2616, 1 rocksdb batches, 6 log entries)
I180108 22:45:40.332845 153778 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]
I180108 22:45:40.333155 152754 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]
I180108 22:45:40.336140 152754 storage/replica.go:3203  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180108 22:45:40.336650 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot 85581991 at index 20
I180108 22:45:40.339426 152754 storage/store.go:3567  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 10, rate-limit: 8.0 MiB/sec, 3ms
I180108 22:45:40.339857 153737 storage/replica_raftstorage.go:746  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 20 (id=85581991, encoded size=54738, 1 rocksdb batches, 10 log entries)
I180108 22:45:40.340277 153737 storage/replica_raftstorage.go:752  [n2,s2,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.340844 152754 storage/replica_command.go:1741  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, next=2]
I180108 22:45:40.341318 153719 storage/raft_transport.go:459  [n3] raft transport stream to node 2 established
I180108 22:45:40.343799 152754 storage/replica.go:3203  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180108 22:45:40.344350 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot 2fc5337d at index 19
I180108 22:45:40.345019 152679 storage/store.go:3567  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 9, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.345325 153630 storage/replica_raftstorage.go:746  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 19 (id=2fc5337d, encoded size=3676, 1 rocksdb batches, 9 log entries)
I180108 22:45:40.345520 153630 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]
I180108 22:45:40.345826 152679 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]
I180108 22:45:40.348783 152679 storage/replica.go:3203  [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
I180108 22:45:40.349713 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 5353aa82 at index 24
I180108 22:45:40.350263 153813 storage/raft_transport.go:459  [n2] raft transport stream to node 3 established
I180108 22:45:40.351511 152487 testutils/testcluster/testcluster.go:528  [n1,s1] has 13 underreplicated ranges
I180108 22:45:40.354289 152754 storage/store.go:3567  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n3,s3):?: kv pairs: 953, log entries: 14, rate-limit: 8.0 MiB/sec, 5ms
I180108 22:45:40.354842 153842 storage/replica_raftstorage.go:746  [n3,s3,r5/?:{-}] applying preemptive snapshot at index 24 (id=5353aa82, encoded size=161457, 1 rocksdb batches, 14 log entries)
I180108 22:45:40.357253 153842 storage/replica_raftstorage.go:752  [n3,s3,r5/?:/System/ts{d-e}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=2ms]
I180108 22:45:40.357738 152754 storage/replica_command.go:1741  [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]
I180108 22:45:40.360838 152754 storage/replica.go:3203  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180108 22:45:40.361288 152754 storage/replica_raftstorage.go:540  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 2a5da092 at index 18
I180108 22:45:40.361959 152754 storage/store.go:3567  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.362268 153878 storage/replica_raftstorage.go:746  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 18 (id=2a5da092, encoded size=5307, 1 rocksdb batches, 8 log entries)
I180108 22:45:40.362477 153878 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]
I180108 22:45:40.362816 152754 storage/replica_command.go:1741  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, next=2]
I180108 22:45:40.365508 152754 storage/replica.go:3203  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180108 22:45:40.365779 152754 storage/queue.go:735  [n1,replicate] purgatory is now empty
I180108 22:45:40.365956 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 6896d94f at index 52
I180108 22:45:40.366794 152679 storage/store.go:3567  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 46, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.367212 153922 storage/replica_raftstorage.go:746  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 52 (id=6896d94f, encoded size=70129, 1 rocksdb batches, 5 log entries)
I180108 22:45:40.367721 153922 storage/replica_raftstorage.go:752  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.368123 152679 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]
I180108 22:45:40.371969 153908 storage/replica.go:3203  [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
I180108 22:45:40.372923 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot 9a64c7aa at index 92
I180108 22:45:40.374242 152679 storage/store.go:3567  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 271, log entries: 4, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.374642 153927 storage/replica_raftstorage.go:746  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 92 (id=9a64c7aa, encoded size=36295, 1 rocksdb batches, 4 log entries)
I180108 22:45:40.375153 153927 storage/replica_raftstorage.go:752  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.375488 152679 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]
I180108 22:45:40.379193 152679 storage/replica.go:3203  [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
I180108 22:45:40.380295 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot e21a8ef5 at index 19
I180108 22:45:40.380931 152679 storage/store.go:3567  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n3,s3):?: kv pairs: 12, log entries: 9, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.382205 153899 storage/replica_raftstorage.go:746  [n3,s3,r13/?:{-}] applying preemptive snapshot at index 19 (id=e21a8ef5, encoded size=3676, 1 rocksdb batches, 9 log entries)
I180108 22:45:40.382670 153899 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]
I180108 22:45:40.385592 152679 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]
I180108 22:45:40.389225 152679 storage/replica.go:3203  [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
I180108 22:45:40.390132 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot 1a441850 at index 23
I180108 22:45:40.391055 152679 storage/store.go:3567  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 13, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.391510 153913 storage/replica_raftstorage.go:746  [n3,s3,r2/?:{-}] applying preemptive snapshot at index 23 (id=1a441850, encoded size=55838, 1 rocksdb batches, 13 log entries)
I180108 22:45:40.392232 153913 storage/replica_raftstorage.go:752  [n3,s3,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180108 22:45:40.392522 152679 storage/replica_command.go:1741  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, (n2,s2):2, next=3]
I180108 22:45:40.395774 152679 storage/replica.go:3203  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180108 22:45:40.396741 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 958a086e at index 28
I180108 22:45:40.400925 152679 storage/store.go:3567  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 954, log entries: 5, rate-limit: 8.0 MiB/sec, 4ms
I180108 22:45:40.401410 153902 storage/replica_raftstorage.go:746  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 28 (id=958a086e, encoded size=127769, 1 rocksdb batches, 5 log entries)
I180108 22:45:40.402289 153902 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]
I180108 22:45:40.402641 152679 storage/replica_command.go:1741  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, (n3,s3):2, next=3]
I180108 22:45:40.405812 152679 storage/replica.go:3203  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180108 22:45:40.406722 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot e556779b at index 18
I180108 22:45:40.407237 152679 storage/store.go:3567  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 8, rate-limit: 8.0 MiB/sec, 0ms
I180108 22:45:40.407491 153971 storage/replica_raftstorage.go:746  [n2,s2,r19/?:{-}] applying preemptive snapshot at index 18 (id=e556779b, encoded size=3607, 1 rocksdb batches, 8 log entries)
I180108 22:45:40.407657 153971 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]
I180108 22:45:40.408007 152679 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]
I180108 22:45:40.411277 152679 storage/replica.go:3203  [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
I180108 22:45:40.412186 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot 5dc691e6 at index 15
I180108 22:45:40.412709 152679 storage/store.go:3567  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n3,s3):?: kv pairs: 15, log entries: 5, rate-limit: 8.0 MiB/sec, 0ms
I180108 22:45:40.413023 153886 storage/replica_raftstorage.go:746  [n3,s3,r20/?:{-}] applying preemptive snapshot at index 15 (id=5dc691e6, encoded size=2080, 1 rocksdb batches, 5 log entries)
I180108 22:45:40.413174 153886 storage/replica_raftstorage.go:752  [n3,s3,r20/?:/{Table/23-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.413493 152679 storage/replica_command.go:1741  [replicate,n1,s1,r20/1:/{Table/23-Max}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r20:/{Table/23-Max} [(n1,s1):1, (n2,s2):2, next=3]
I180108 22:45:40.416657 152679 storage/replica.go:3203  [n1,s1,r20/1:/{Table/23-Max}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180108 22:45:40.417668 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot 7df02f36 at index 18
I180108 22:45:40.418322 152679 storage/store.go:3567  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.418720 153958 storage/replica_raftstorage.go:746  [n2,s2,r16/?:{-}] applying preemptive snapshot at index 18 (id=7df02f36, encoded size=3607, 1 rocksdb batches, 8 log entries)
I180108 22:45:40.418969 153958 storage/replica_raftstorage.go:752  [n2,s2,r16/?:/Table/{19-20}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.419310 152679 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]
I180108 22:45:40.422708 152679 storage/replica.go:3203  [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
I180108 22:45:40.423602 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot b24aa8a2 at index 28
I180108 22:45:40.424309 152679 storage/store.go:3567  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n2,s2):?: kv pairs: 22, log entries: 18, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.424608 153961 storage/replica_raftstorage.go:746  [n2,s2,r12/?:{-}] applying preemptive snapshot at index 28 (id=b24aa8a2, encoded size=9097, 1 rocksdb batches, 18 log entries)
I180108 22:45:40.424823 153961 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]
I180108 22:45:40.425149 152679 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]
I180108 22:45:40.427921 152679 storage/replica.go:3203  [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
I180108 22:45:40.428880 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 316ddfb3 at index 21
I180108 22:45:40.429524 152679 storage/store.go:3567  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n3,s3):?: kv pairs: 12, log entries: 11, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.429782 153947 storage/replica_raftstorage.go:746  [n3,s3,r6/?:{-}] applying preemptive snapshot at index 21 (id=316ddfb3, encoded size=6425, 1 rocksdb batches, 11 log entries)
I180108 22:45:40.429971 153947 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]
I180108 22:45:40.430386 152679 storage/replica_command.go:1741  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, (n2,s2):2, next=3]
I180108 22:45:40.433626 152679 storage/replica.go:3203  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180108 22:45:40.434486 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot 96b5a8c0 at index 55
I180108 22:45:40.435359 152679 storage/store.go:3567  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 84, log entries: 45, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.435689 153983 storage/replica_raftstorage.go:746  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 55 (id=96b5a8c0, encoded size=42901, 1 rocksdb batches, 45 log entries)
I180108 22:45:40.436161 153983 storage/replica_raftstorage.go:752  [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.436433 152679 storage/replica_command.go:1741  [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]
I180108 22:45:40.440339 152679 storage/replica.go:3203  [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
I180108 22:45:40.441411 152679 storage/replica_raftstorage.go:540  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 7262afd0 at index 27
I180108 22:45:40.442030 152679 storage/store.go:3567  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 14, log entries: 17, rate-limit: 8.0 MiB/sec, 1ms
I180108 22:45:40.442267 153995 storage/replica_raftstorage.go:746  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 27 (id=7262afd0, encoded size=7246, 1 rocksdb batches, 17 log entries)
I180108 22:45:40.442478 153995 storage/replica_raftstorage.go:752  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180108 22:45:40.442758 152679 storage/replica_command.go:1741  [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]
I180108 22:45:40.446236 154057 storage/replica.go:3203  [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
I180108 22:45:40.447311 152679 storage/replica_raftst

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 8, 2018
@benesch
Copy link
Contributor

benesch commented Jan 20, 2018

Timed out due to 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