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/TestBackupAsOfSystemTime, testrace/TestBackupAsOfSystemTime #21244

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

teamcity: failed tests on master: test/TestBackupAsOfSystemTime, testrace/TestBackupAsOfSystemTime #21244

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

#467212:

--- FAIL: test/TestBackupAsOfSystemTime (0.000s)
Test ended in panic.

------- Stdout: -------
W180104 21:10:19.298215 151740 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180104 21:10:19.300754 151740 server/config.go:516  [n?] 1 storage engine initialized
I180104 21:10:19.300787 151740 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180104 21:10:19.300795 151740 server/config.go:519  [n?] store 0: in-memory, size 0 B
I180104 21:10:19.304124 151740 server/node.go:361  [n?] **** cluster 6b38b794-d0a7-4b76-8e85-f5b5ee2164f3 has been created
I180104 21:10:19.304171 151740 server/server.go:934  [n?] **** add additional nodes by specifying --join=127.0.0.1:35881
I180104 21:10:19.305027 151740 storage/store.go:1209  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180104 21:10:19.305076 151740 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}
I180104 21:10:19.305111 151740 server/node.go:339  [n1] node ID 1 initialized
I180104 21:10:19.305154 151740 gossip/gossip.go:332  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:35881" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180104 21:10:19.305192 151740 storage/stores.go:331  [n1] read 0 node addresses from persistent storage
I180104 21:10:19.305247 151740 server/node.go:627  [n1] connecting to gossip network to verify cluster ID...
I180104 21:10:19.305264 151740 server/node.go:652  [n1] node connected via gossip and verified as part of cluster "6b38b794-d0a7-4b76-8e85-f5b5ee2164f3"
I180104 21:10:19.305285 151740 server/node.go:428  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180104 21:10:19.305319 151740 sql/distsql_physical_planner.go:122  [n1] creating DistSQLPlanner with address {tcp 127.0.0.1:35881}
I180104 21:10:19.311018 151824 storage/replica_command.go:819  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180104 21:10:19.312763 151740 server/server.go:1161  [n1] starting https server at 127.0.0.1:41855
I180104 21:10:19.312796 151740 server/server.go:1162  [n1] starting grpc/postgres server at 127.0.0.1:35881
I180104 21:10:19.312840 151740 server/server.go:1163  [n1] advertising CockroachDB node at 127.0.0.1:35881
I180104 21:10:19.317496 151824 storage/replica_command.go:819  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180104 21:10:19.320984 151740 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:[]}
I180104 21:10:19.322480 151824 storage/replica_command.go:819  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180104 21:10:19.326034 151740 sql/lease.go:348  [n1] publish: descID=12 (eventlog) version=2 mtime=2018-01-04 21:10:19.325904068 +0000 UTC
I180104 21:10:19.327543 151824 storage/replica_command.go:819  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180104 21:10:19.331740 151824 storage/replica_command.go:819  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180104 21:10:19.341741 151824 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]
I180104 21:10:19.346328 151824 storage/replica_command.go:819  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
W180104 21:10:19.347102 152135 storage/intent_resolver.go:324  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=c0130802 key=/Table/SystemConfigSpan/Start rw=true pri=0.01556273 iso=SERIALIZABLE stat=PENDING epo=0 ts=1515100219.337508764,0 orig=1515100219.337508764,0 max=1515100219.337508764,0 wto=false rop=false seq=10
I180104 21:10:19.347687 151740 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}
I180104 21:10:19.350442 151824 storage/replica_command.go:819  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180104 21:10:19.354150 151824 storage/replica_command.go:819  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180104 21:10:19.356089 151740 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:node}
I180104 21:10:19.358409 151824 storage/replica_command.go:819  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180104 21:10:19.359674 151740 sql/event_log.go:115  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}
I180104 21:10:19.362144 151824 storage/replica_command.go:819  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180104 21:10:19.368798 151824 storage/replica_command.go:819  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180104 21:10:19.372458 151824 storage/replica_command.go:819  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180104 21:10:19.376219 151740 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:[]}
I180104 21:10:19.376414 151824 storage/replica_command.go:819  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180104 21:10:19.379464 151740 sql/lease.go:348  [n1] publish: descID=4 (users) version=2 mtime=2018-01-04 21:10:19.379134709 +0000 UTC
I180104 21:10:19.380542 151824 storage/replica_command.go:819  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180104 21:10:19.384559 151824 storage/replica_command.go:819  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180104 21:10:19.385555 151740 sql/lease.go:348  [n1] publish: descID=4 (users) version=3 mtime=2018-01-04 21:10:19.385408391 +0000 UTC
I180104 21:10:19.388227 151824 storage/replica_command.go:819  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180104 21:10:19.389405 151740 sql/backfill.go:132  [n1] Running backfill for "users", v=3, m=1
I180104 21:10:19.391887 151824 storage/replica_command.go:819  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180104 21:10:19.397921 151824 storage/replica_command.go:819  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180104 21:10:19.403944 151740 sql/lease.go:348  [n1] publish: descID=4 (users) version=4 mtime=2018-01-04 21:10:19.403840658 +0000 UTC
I180104 21:10:19.408559 151740 sql/event_log.go:115  [n1] Event: "finish_schema_change", target: 4, info: {MutationID:1}
I180104 21:10:19.409471 151740 sql/lease.go:274  publish (count leases): descID=4 name=users version=3 count=1
I180104 21:10:19.445669 151740 server/server.go:1232  [n1] done ensuring all necessary migrations have run
I180104 21:10:19.445724 151740 server/server.go:1235  [n1] serving sql connections
I180104 21:10:19.447949 152294 sql/event_log.go:115  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:35881} Attrs: Locality: ServerVersion:1.1-8} ClusterID:6b38b794-d0a7-4b76-8e85-f5b5ee2164f3 StartedAt:1515100219305266619 LastUp:1515100219305266619}
W180104 21:10:19.451203 151740 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180104 21:10:19.454906 151740 server/config.go:516  [n?] 1 storage engine initialized
I180104 21:10:19.454931 151740 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180104 21:10:19.454937 151740 server/config.go:519  [n?] store 0: in-memory, size 0 B
W180104 21:10:19.455000 151740 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180104 21:10:19.455074 151740 server/server.go:936  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180104 21:10:19.465952 152268 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:35881
I180104 21:10:19.466302 152402 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:36583}
I180104 21:10:19.467182 151740 storage/stores.go:331  [n?] read 0 node addresses from persistent storage
I180104 21:10:19.467231 151740 storage/stores.go:350  [n?] wrote 1 node addresses to persistent storage
I180104 21:10:19.467240 151740 server/node.go:627  [n?] connecting to gossip network to verify cluster ID...
I180104 21:10:19.467261 151740 server/node.go:652  [n?] node connected via gossip and verified as part of cluster "6b38b794-d0a7-4b76-8e85-f5b5ee2164f3"
I180104 21:10:19.467502 152431 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180104 21:10:19.468394 152430 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180104 21:10:19.469182 151740 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180104 21:10:19.470197 151740 server/node.go:332  [n?] new node allocated ID 2
I180104 21:10:19.470276 151740 gossip/gossip.go:332  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:36583" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180104 21:10:19.470330 151740 server/node.go:414  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180104 21:10:19.470376 151740 server/node.go:428  [n2] node=2: started with [] engine(s) and attributes []
I180104 21:10:19.470425 151740 sql/distsql_physical_planner.go:122  [n2] creating DistSQLPlanner with address {tcp 127.0.0.1:36583}
I180104 21:10:19.471124 152390 storage/stores.go:350  [n1] wrote 1 node addresses to persistent storage
I180104 21:10:19.473361 152157 server/node.go:608  [n2] bootstrapped store [n2,s2]
I180104 21:10:19.473675 151740 server/server.go:1161  [n2] starting https server at 127.0.0.1:34905
I180104 21:10:19.473711 151740 server/server.go:1162  [n2] starting grpc/postgres server at 127.0.0.1:36583
I180104 21:10:19.473725 151740 server/server.go:1163  [n2] advertising CockroachDB node at 127.0.0.1:36583
I180104 21:10:19.474456 151740 server/server.go:1232  [n2] done ensuring all necessary migrations have run
I180104 21:10:19.474481 151740 server/server.go:1235  [n2] serving sql connections
I180104 21:10:19.484355 152546 sql/event_log.go:115  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:36583} Attrs: Locality: ServerVersion:1.1-8} ClusterID:6b38b794-d0a7-4b76-8e85-f5b5ee2164f3 StartedAt:1515100219470365260 LastUp:1515100219470365260}
W180104 21:10:19.486474 151740 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180104 21:10:19.488791 151740 server/config.go:516  [n?] 1 storage engine initialized
I180104 21:10:19.488819 151740 server/config.go:519  [n?] RocksDB cache size: 128 MiB
I180104 21:10:19.488825 151740 server/config.go:519  [n?] store 0: in-memory, size 0 B
W180104 21:10:19.488878 151740 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180104 21:10:19.488904 151740 server/server.go:936  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180104 21:10:19.500287 152550 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:35881
I180104 21:10:19.500567 152369 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:39551}
I180104 21:10:19.501540 151740 storage/stores.go:331  [n?] read 0 node addresses from persistent storage
I180104 21:10:19.501585 151740 storage/stores.go:350  [n?] wrote 2 node addresses to persistent storage
I180104 21:10:19.501594 151740 server/node.go:627  [n?] connecting to gossip network to verify cluster ID...
I180104 21:10:19.501612 151740 server/node.go:652  [n?] node connected via gossip and verified as part of cluster "6b38b794-d0a7-4b76-8e85-f5b5ee2164f3"
I180104 21:10:19.501907 152611 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180104 21:10:19.502722 152610 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180104 21:10:19.504069 151740 kv/dist_sender.go:354  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180104 21:10:19.505059 151740 server/node.go:332  [n?] new node allocated ID 3
I180104 21:10:19.505139 151740 gossip/gossip.go:332  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:39551" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:8 > 
I180104 21:10:19.505191 151740 server/node.go:414  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180104 21:10:19.505207 151740 server/node.go:428  [n3] node=3: started with [] engine(s) and attributes []
I180104 21:10:19.505247 151740 sql/distsql_physical_planner.go:122  [n3] creating DistSQLPlanner with address {tcp 127.0.0.1:39551}
I180104 21:10:19.505961 152559 storage/stores.go:350  [n1] wrote 2 node addresses to persistent storage
I180104 21:10:19.506310 152616 storage/stores.go:350  [n2] wrote 2 node addresses to persistent storage
I180104 21:10:19.511523 152344 server/node.go:608  [n3] bootstrapped store [n3,s3]
I180104 21:10:19.511592 151740 server/server.go:1161  [n3] starting https server at 127.0.0.1:34877
I180104 21:10:19.511611 151740 server/server.go:1162  [n3] starting grpc/postgres server at 127.0.0.1:39551
I180104 21:10:19.511621 151740 server/server.go:1163  [n3] advertising CockroachDB node at 127.0.0.1:39551
I180104 21:10:19.512907 151740 server/server.go:1232  [n3] done ensuring all necessary migrations have run
I180104 21:10:19.512932 151740 server/server.go:1235  [n3] serving sql connections
I180104 21:10:19.513870 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 6c9dcaa2 at index 28
I180104 21:10:19.515554 151740 testutils/testcluster/testcluster.go:528  [n1,s1] has 20 underreplicated ranges
I180104 21:10:19.518279 152754 sql/event_log.go:115  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:39551} Attrs: Locality: ServerVersion:1.1-8} ClusterID:6b38b794-d0a7-4b76-8e85-f5b5ee2164f3 StartedAt:1515100219505198697 LastUp:1515100219505198697}
I180104 21:10:19.524762 151844 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
I180104 21:10:19.525069 152255 storage/replica_raftstorage.go:746  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 28 (id=6c9dcaa2, encoded size=16743, 1 rocksdb batches, 18 log entries)
I180104 21:10:19.525976 152255 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]
I180104 21:10:19.526073 151740 testutils/testcluster/testcluster.go:528  [n1,s1] has 20 underreplicated ranges
I180104 21:10:19.526744 151844 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]
I180104 21:10:19.530219 151844 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
I180104 21:10:19.530999 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 7924c885 at index 16
I180104 21:10:19.532369 152780 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180104 21:10:19.542972 151844 storage/store.go:3567  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.543279 152801 storage/replica_raftstorage.go:746  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 16 (id=7924c885, encoded size=2476, 1 rocksdb batches, 6 log entries)
I180104 21:10:19.544128 152801 storage/replica_raftstorage.go:752  [n2,s2,r14/?:/Table/1{7-8}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180104 21:10:19.544559 151844 storage/replica_command.go:1741  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, next=2]
I180104 21:10:19.546310 151844 storage/replica.go:3192  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180104 21:10:19.546549 151740 testutils/testcluster/testcluster.go:528  [n1,s1] has 20 underreplicated ranges
I180104 21:10:19.547194 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot c6463f8e at index 15
I180104 21:10:19.547935 151844 storage/store.go:3567  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.548433 152837 storage/replica_raftstorage.go:746  [n2,s2,r16/?:{-}] applying preemptive snapshot at index 15 (id=c6463f8e, encoded size=2407, 1 rocksdb batches, 5 log entries)
I180104 21:10:19.548641 152850 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180104 21:10:19.548699 152837 storage/replica_raftstorage.go:752  [n2,s2,r16/?:/Table/{19-20}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.549279 151844 storage/replica_command.go:1741  [replicate,n1,s1,r16/1:/Table/{19-20}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r16:/Table/{19-20} [(n1,s1):1, next=2]
I180104 21:10:19.551171 151844 storage/replica.go:3192  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180104 21:10:19.551746 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 22edb218 at index 33
I180104 21:10:19.552963 151825 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
I180104 21:10:19.553393 152813 storage/replica_raftstorage.go:746  [n2,s2,r9/?:{-}] applying preemptive snapshot at index 33 (id=22edb218, encoded size=20454, 1 rocksdb batches, 23 log entries)
I180104 21:10:19.553882 152813 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]
I180104 21:10:19.554293 151825 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]
I180104 21:10:19.556829 151825 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
I180104 21:10:19.557943 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 362445bf at index 27
I180104 21:10:19.565074 151844 storage/store.go:3567  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n3,s3):?: kv pairs: 952, log entries: 17, rate-limit: 8.0 MiB/sec, 7ms
I180104 21:10:19.565682 152866 storage/replica_raftstorage.go:746  [n3,s3,r5/?:{-}] applying preemptive snapshot at index 27 (id=362445bf, encoded size=160497, 1 rocksdb batches, 17 log entries)
I180104 21:10:19.568267 152866 storage/replica_raftstorage.go:752  [n3,s3,r5/?:/System/ts{d-e}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=1ms]
I180104 21:10:19.569818 151844 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]
I180104 21:10:19.571555 151844 storage/replica.go:3192  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180104 21:10:19.572001 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot 739946c7 at index 21
I180104 21:10:19.572868 151844 storage/store.go:3567  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 11, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.573227 152747 storage/replica_raftstorage.go:746  [n3,s3,r2/?:{-}] applying preemptive snapshot at index 21 (id=739946c7, encoded size=6571, 1 rocksdb batches, 11 log entries)
I180104 21:10:19.573434 152747 storage/replica_raftstorage.go:752  [n3,s3,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.574150 151844 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]
I180104 21:10:19.576377 151844 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
I180104 21:10:19.576961 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 8310aff5 at index 19
I180104 21:10:19.577673 151825 storage/store.go:3567  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 9, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.578157 152859 storage/replica_raftstorage.go:746  [n3,s3,r14/?:{-}] applying preemptive snapshot at index 19 (id=8310aff5, encoded size=3536, 1 rocksdb batches, 9 log entries)
I180104 21:10:19.578455 152859 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]
I180104 21:10:19.578971 151825 storage/replica_command.go:1741  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, (n2,s2):2, next=3]
I180104 21:10:19.582027 151825 storage/replica.go:3192  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180104 21:10:19.583731 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot 4773c4d4 at index 15
I180104 21:10:19.584947 151844 storage/store.go:3567  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.585563 152751 storage/replica_raftstorage.go:746  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 15 (id=4773c4d4, encoded size=2407, 1 rocksdb batches, 5 log entries)
I180104 21:10:19.585820 152751 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]
I180104 21:10:19.586471 151844 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]
I180104 21:10:19.588927 151844 storage/replica.go:3192  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180104 21:10:19.589495 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot e6bbfbc5 at index 22
I180104 21:10:19.589561 151740 testutils/testcluster/testcluster.go:528  [n1,s1] has 18 underreplicated ranges
I180104 21:10:19.590319 151844 storage/store.go:3567  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 12, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.590879 152883 storage/replica_raftstorage.go:746  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 22 (id=e6bbfbc5, encoded size=5797, 1 rocksdb batches, 12 log entries)
I180104 21:10:19.591126 152883 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]
I180104 21:10:19.591717 151844 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]
I180104 21:10:19.594215 151844 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
I180104 21:10:19.594881 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot b66cf842 at index 18
I180104 21:10:19.595617 151825 storage/store.go:3567  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.596214 152734 storage/replica_raftstorage.go:746  [n3,s3,r16/?:{-}] applying preemptive snapshot at index 18 (id=b66cf842, encoded size=3467, 1 rocksdb batches, 8 log entries)
I180104 21:10:19.596574 152734 storage/replica_raftstorage.go:752  [n3,s3,r16/?:/Table/{19-20}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.597115 151825 storage/replica_command.go:1741  [replicate,n1,s1,r16/1:/Table/{19-20}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r16:/Table/{19-20} [(n1,s1):1, (n2,s2):2, next=3]
I180104 21:10:19.599205 151825 storage/replica.go:3192  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180104 21:10:19.600405 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot c175df0e at index 54
I180104 21:10:19.601410 151844 storage/store.go:3567  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 81, log entries: 44, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.601966 152885 storage/replica_raftstorage.go:746  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 54 (id=c175df0e, encoded size=43039, 1 rocksdb batches, 44 log entries)
I180104 21:10:19.602484 152885 storage/replica_raftstorage.go:752  [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.602853 151844 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]
I180104 21:10:19.604370 151844 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
I180104 21:10:19.604821 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot b1d508c0 at index 15
I180104 21:10:19.605566 151844 storage/store.go:3567  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.606025 152949 storage/replica_raftstorage.go:746  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 15 (id=b1d508c0, encoded size=2407, 1 rocksdb batches, 5 log entries)
I180104 21:10:19.606257 152949 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]
I180104 21:10:19.606697 151844 storage/replica_command.go:1741  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, next=2]
I180104 21:10:19.608369 151844 storage/replica.go:3192  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180104 21:10:19.608772 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot b179c99d at index 24
I180104 21:10:19.609489 151825 storage/store.go:3567  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 14, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.609784 152889 storage/replica_raftstorage.go:746  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 24 (id=b179c99d, encoded size=7671, 1 rocksdb batches, 14 log entries)
I180104 21:10:19.609984 152889 storage/replica_raftstorage.go:752  [n2,s2,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.610453 151825 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]
I180104 21:10:19.612468 151825 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
I180104 21:10:19.615003 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 035b439e at index 17
I180104 21:10:19.616057 151844 storage/store.go:3567  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 7, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.616383 152955 storage/replica_raftstorage.go:746  [n3,s3,r6/?:{-}] applying preemptive snapshot at index 17 (id=035b439e, encoded size=4337, 1 rocksdb batches, 7 log entries)
I180104 21:10:19.616603 152955 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]
I180104 21:10:19.617192 151844 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]
I180104 21:10:19.619355 151844 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
I180104 21:10:19.619914 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot 32021a0d at index 18
I180104 21:10:19.620950 151825 storage/store.go:3567  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.621207 152919 storage/replica_raftstorage.go:746  [n3,s3,r15/?:{-}] applying preemptive snapshot at index 18 (id=32021a0d, encoded size=3467, 1 rocksdb batches, 8 log entries)
I180104 21:10:19.621423 152919 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]
I180104 21:10:19.622064 151825 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]
I180104 21:10:19.625521 151825 storage/replica.go:3192  [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
I180104 21:10:19.626829 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot fba4e78d at index 64
I180104 21:10:19.628396 151844 storage/store.go:3567  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 204, log entries: 54, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.628822 152962 storage/replica_raftstorage.go:746  [n2,s2,r10/?:{-}] applying preemptive snapshot at index 64 (id=fba4e78d, encoded size=68293, 1 rocksdb batches, 54 log entries)
I180104 21:10:19.629480 152962 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]
I180104 21:10:19.630193 151844 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]
I180104 21:10:19.632655 151844 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
I180104 21:10:19.633239 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot 5321c297 at index 15
I180104 21:10:19.634037 151844 storage/store.go:3567  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.634307 152909 storage/replica_raftstorage.go:746  [n3,s3,r17/?:{-}] applying preemptive snapshot at index 15 (id=5321c297, encoded size=2407, 1 rocksdb batches, 5 log entries)
I180104 21:10:19.634488 152909 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]
I180104 21:10:19.634930 151844 storage/replica_command.go:1741  [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, next=2]
I180104 21:10:19.636901 151844 storage/replica.go:3192  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180104 21:10:19.637309 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot d7824cd7 at index 18
I180104 21:10:19.637886 151825 storage/store.go:3567  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.638129 152978 storage/replica_raftstorage.go:746  [n3,s3,r11/?:{-}] applying preemptive snapshot at index 18 (id=d7824cd7, encoded size=3467, 1 rocksdb batches, 8 log entries)
I180104 21:10:19.638281 152978 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]
I180104 21:10:19.638680 151825 storage/replica_command.go:1741  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, (n2,s2):2, next=3]
I180104 21:10:19.641911 151825 storage/replica.go:3192  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180104 21:10:19.642670 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot 28840c02 at index 15
I180104 21:10:19.643290 151844 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, 0ms
I180104 21:10:19.643646 153010 storage/replica_raftstorage.go:746  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 15 (id=28840c02, encoded size=2407, 1 rocksdb batches, 5 log entries)
I180104 21:10:19.643803 153010 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]
I180104 21:10:19.644046 151844 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]
I180104 21:10:19.646890 151844 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
I180104 21:10:19.647360 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot d06083a5 at index 25
I180104 21:10:19.648290 151844 storage/store.go:3567  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n2,s2):?: kv pairs: 20, log entries: 15, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.648841 152999 storage/replica_raftstorage.go:746  [n2,s2,r12/?:{-}] applying preemptive snapshot at index 25 (id=d06083a5, encoded size=7907, 1 rocksdb batches, 15 log entries)
I180104 21:10:19.649185 152999 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]
I180104 21:10:19.649568 151844 storage/replica_command.go:1741  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, next=2]
I180104 21:10:19.651854 151844 storage/replica.go:3192  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180104 21:10:19.652254 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot abf86ea7 at index 20
I180104 21:10:19.652840 151825 storage/store.go:3567  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 10, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.653135 152923 storage/replica_raftstorage.go:746  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 20 (id=abf86ea7, encoded size=5455, 1 rocksdb batches, 10 log entries)
I180104 21:10:19.653307 152923 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]
I180104 21:10:19.653699 151825 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]
I180104 21:10:19.656173 151825 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
I180104 21:10:19.656975 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 58088bcf at index 21
I180104 21:10:19.657486 151844 storage/store.go:3567  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n3,s3):?: kv pairs: 12, log entries: 11, rate-limit: 8.0 MiB/sec, 0ms
I180104 21:10:19.657761 153004 storage/replica_raftstorage.go:746  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 21 (id=58088bcf, encoded size=5671, 1 rocksdb batches, 11 log entries)
I180104 21:10:19.657938 153004 storage/replica_raftstorage.go:752  [n3,s3,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.658226 151844 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]
I180104 21:10:19.660123 151844 storage/replica.go:3192  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180104 21:10:19.660485 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot a8b3871c at index 15
I180104 21:10:19.661103 151844 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, 1ms
I180104 21:10:19.661549 153029 storage/replica_raftstorage.go:746  [n3,s3,r19/?:{-}] applying preemptive snapshot at index 15 (id=a8b3871c, encoded size=2407, 1 rocksdb batches, 5 log entries)
I180104 21:10:19.661776 153029 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]
I180104 21:10:19.662115 151844 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]
I180104 21:10:19.663981 151844 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
I180104 21:10:19.664404 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot 53c5994f at index 82
I180104 21:10:19.665510 151825 storage/store.go:3567  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 245, log entries: 72, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.666006 153042 storage/replica_raftstorage.go:746  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 82 (id=53c5994f, encoded size=89330, 1 rocksdb batches, 72 log entries)
I180104 21:10:19.666820 153042 storage/replica_raftstorage.go:752  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180104 21:10:19.670610 151825 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]
I180104 21:10:19.674893 151825 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
I180104 21:10:19.676318 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot 88ec3f93 at index 12
I180104 21:10:19.676974 151844 storage/store.go:3567  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n2,s2):?: kv pairs: 13, log entries: 2, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.677355 153045 storage/replica_raftstorage.go:746  [n2,s2,r20/?:{-}] applying preemptive snapshot at index 12 (id=88ec3f93, encoded size=946, 1 rocksdb batches, 2 log entries)
I180104 21:10:19.677538 153045 storage/replica_raftstorage.go:752  [n2,s2,r20/?:/{Table/23-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.678001 151844 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]
I180104 21:10:19.680400 151844 storage/replica.go:3192  [n1,s1,r20/1:/{Table/23-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180104 21:10:19.680960 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 31979697 at index 117
I180104 21:10:19.681504 151740 testutils/testcluster/testcluster.go:528  [n1,s1] has 12 underreplicated ranges
I180104 21:10:19.682640 151844 storage/store.go:3567  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 78, log entries: 98, rate-limit: 8.0 MiB/sec, 2ms
I180104 21:10:19.683168 152989 storage/replica_raftstorage.go:746  [n2,s2,r1/?:{-}] applying preemptive snapshot at index 117 (id=31979697, encoded size=72526, 1 rocksdb batches, 98 log entries)
I180104 21:10:19.683796 152989 storage/replica_raftstorage.go:752  [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.684321 151844 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]
I180104 21:10:19.686718 151844 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
I180104 21:10:19.687457 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot c6073caa at index 18
I180104 21:10:19.688581 151825 storage/store.go:3567  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 8, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.688885 153049 storage/replica_raftstorage.go:746  [n2,s2,r17/?:{-}] applying preemptive snapshot at index 18 (id=c6073caa, encoded size=3467, 1 rocksdb batches, 8 log entries)
I180104 21:10:19.689075 153049 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]
I180104 21:10:19.689592 151825 storage/replica_command.go:1741  [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, (n3,s3):2, next=3]
I180104 21:10:19.694658 151825 storage/replica.go:3192  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180104 21:10:19.696386 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 84a0c98f at index 47
I180104 21:10:19.697663 151844 storage/store.go:3567  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 43, log entries: 2, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.698139 153090 storage/replica_raftstorage.go:746  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 47 (id=84a0c98f, encoded size=68683, 1 rocksdb batches, 2 log entries)
I180104 21:10:19.698620 153090 storage/replica_raftstorage.go:752  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.699027 151844 storage/replica_command.go:1741  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, next=2]
I180104 21:10:19.701683 151844 storage/replica.go:3192  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180104 21:10:19.702181 151844 storage/replica_raftstorage.go:540  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot 4332d854 at index 15
I180104 21:10:19.702699 151844 storage/store.go:3567  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 5, rate-limit: 8.0 MiB/sec, 0ms
I180104 21:10:19.702927 153055 storage/replica_raftstorage.go:746  [n2,s2,r13/?:{-}] applying preemptive snapshot at index 15 (id=4332d854, encoded size=2407, 1 rocksdb batches, 5 log entries)
I180104 21:10:19.703078 153055 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]
I180104 21:10:19.703414 151844 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]
I180104 21:10:19.706391 151844 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
I180104 21:10:19.706771 151844 storage/queue.go:735  [n1,replicate] purgatory is now empty
I180104 21:10:19.706965 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 9ef05021 at index 31
I180104 21:10:19.711964 151825 storage/store.go:3567  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 953, log entries: 5, rate-limit: 8.0 MiB/sec, 5ms
I180104 21:10:19.712439 153039 storage/replica_raftstorage.go:746  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 31 (id=9ef05021, encoded size=126498, 1 rocksdb batches, 5 log entries)
I180104 21:10:19.713171 153039 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]
I180104 21:10:19.713598 151825 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]
I180104 21:10:19.717419 151825 storage/replica.go:3192  [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
I180104 21:10:19.718687 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot 80233f28 at index 15
I180104 21:10:19.719566 151825 storage/store.go:3567  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n3,s3):?: kv pairs: 14, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.719965 153112 storage/replica_raftstorage.go:746  [n3,s3,r20/?:{-}] applying preemptive snapshot at index 15 (id=80233f28, encoded size=2010, 1 rocksdb batches, 5 log entries)
I180104 21:10:19.720166 153112 storage/replica_raftstorage.go:752  [n3,s3,r20/?:/{Table/23-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.720593 151825 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]
I180104 21:10:19.725049 151825 storage/replica.go:3192  [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
I180104 21:10:19.726483 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot d2d08eb5 at index 130
I180104 21:10:19.727460 151825 storage/store.go:3567  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n3,s3):?: kv pairs: 86, log entries: 111, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.727977 153096 storage/replica_raftstorage.go:746  [n3,s3,r1/?:{-}] applying preemptive snapshot at index 130 (id=d2d08eb5, encoded size=75876, 1 rocksdb batches, 111 log entries)
I180104 21:10:19.728542 153096 storage/replica_raftstorage.go:752  [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.728897 151825 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]
I180104 21:10:19.731367 153098 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
I180104 21:10:19.733209 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot cdaac7f7 at index 50
I180104 21:10:19.734205 151825 storage/store.go:3567  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n2,s2):?: kv pairs: 44, log entries: 5, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.734718 153146 storage/replica_raftstorage.go:746  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 50 (id=cdaac7f7, encoded size=69957, 1 rocksdb batches, 5 log entries)
I180104 21:10:19.735374 153146 storage/replica_raftstorage.go:752  [n2,s2,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.735992 151825 storage/replica_command.go:1741  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, (n3,s3):2, next=3]
I180104 21:10:19.739577 151825 storage/replica.go:3192  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180104 21:10:19.741390 152650 storage/replica_proposal.go:196  [n3,s3,r5/2:/System/ts{d-e}] new range lease repl=(n3,s3):2 seq=2 start=1515100219.740627946,0 epo=1 pro=1515100219.740632007,0 following repl=(n1,s1):1 seq=1 start=0.000000000,0 exp=1515100228.305065282,0 pro=1515100219.305086250,0
I180104 21:10:19.741794 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot f9e00040 at index 18
I180104 21:10:19.745721 151825 storage/store.go:3567  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 8, rate-limit: 8.0 MiB/sec, 4ms
I180104 21:10:19.746626 153153 storage/replica_raftstorage.go:746  [n3,s3,r13/?:{-}] applying preemptive snapshot at index 18 (id=f9e00040, encoded size=3467, 1 rocksdb batches, 8 log entries)
I180104 21:10:19.746961 153153 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]
I180104 21:10:19.748327 151825 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]
I180104 21:10:19.752713 153118 storage/raft_transport.go:459  [n3] raft transport stream to node 2 established
I180104 21:10:19.752978 151825 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
I180104 21:10:19.754166 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot a6472d69 at index 25
I180104 21:10:19.755348 151825 storage/store.go:3567  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 14, log entries: 15, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.755719 153085 storage/replica_raftstorage.go:746  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 25 (id=a6472d69, encoded size=6857, 1 rocksdb batches, 15 log entries)
I180104 21:10:19.755947 153085 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]
I180104 21:10:19.756309 151825 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]
I180104 21:10:19.759595 151825 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
I180104 21:10:19.760902 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot 7d9508b8 at index 18
I180104 21:10:19.761927 151825 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
I180104 21:10:19.762361 153131 storage/replica_raftstorage.go:746  [n3,s3,r18/?:{-}] applying preemptive snapshot at index 18 (id=7d9508b8, encoded size=3467, 1 rocksdb batches, 8 log entries)
I180104 21:10:19.762468 153208 storage/raft_transport.go:459  [n2] raft transport stream to node 3 established
I180104 21:10:19.762633 153131 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]
I180104 21:10:19.762960 151825 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]
I180104 21:10:19.765522 151825 storage/replica.go:3192  [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
I180104 21:10:19.766521 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot a034d423 at index 28
I180104 21:10:19.767196 151825 storage/store.go:3567  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n3,s3):?: kv pairs: 21, log entries: 18, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.767578 153134 storage/replica_raftstorage.go:746  [n3,s3,r12/?:{-}] applying preemptive snapshot at index 28 (id=a034d423, encoded size=8967, 1 rocksdb batches, 18 log entries)
I180104 21:10:19.767851 153134 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]
I180104 21:10:19.768247 151825 storage/replica_command.go:1741  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, (n2,s2):2, next=3]
I180104 21:10:19.772041 151825 storage/replica.go:3192  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180104 21:10:19.773373 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot e2a4b45f at index 57
I180104 21:10:19.774508 151825 storage/store.go:3567  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):?: kv pairs: 82, log entries: 47, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.775217 153136 storage/replica_raftstorage.go:746  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 57 (id=e2a4b45f, encoded size=44099, 1 rocksdb batches, 47 log entries)
I180104 21:10:19.776102 153136 storage/replica_raftstorage.go:752  [n3,s3,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.776679 151825 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]
I180104 21:10:19.780172 151825 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
I180104 21:10:19.781387 151825 storage/replica_raftstorage.go:540  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot f9067f83 at index 24
I180104 21:10:19.782218 151825 storage/store.go:3567  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 13, log entries: 14, rate-limit: 8.0 MiB/sec, 1ms
I180104 21:10:19.782632 153184 storage/replica_raftstorage.go:746  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 24 (id=f9067f83, encoded size=6974, 1 rocksdb batches, 14 log entries)
I180104 21:10:19.782886 153184 storage/replica_raftstorage.go:752  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180104 21:10:19.783118 151740 testutils/testcluster/testcluster.go:528  [n1,s1] has 2 underreplicated ranges
I180104 21:10:19.783347 151825 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]
I180104 21:10:19.786578 151825 storage/replica.go:3192  [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
I180104 21:10:19

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 4, 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