gistfile1.txt

I181203 10:35:11.295894 1 rand.go:75  Random seed: -1406632157081116611
=== RUN   TestSplitTriggerRaftSnapshotRace
W181203 10:35:11.327146 9 server/status/runtime.go:295  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I181203 10:35:11.354126 9 server/server.go:849  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I181203 10:35:11.354300 9 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I181203 10:35:11.354330 9 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I181203 10:35:11.384100 9 server/config.go:484  [n?] 1 storage engine initialized
I181203 10:35:11.384123 9 server/config.go:487  [n?] RocksDB cache size: 128 MiB
I181203 10:35:11.384132 9 server/config.go:487  [n?] store 0: in-memory, size 0 B
I181203 10:35:11.402658 9 util/stop/stopper.go:537  [n?] quiescing; tasks left:
1      [async] closedts-rangefeed-subscriber
I181203 10:35:11.403607 9 server/node.go:370  [n?] **** cluster 4c40209a-4384-4e10-b1e5-1714db8e2e62 has been created
I181203 10:35:11.403643 9 server/server.go:1395  [n?] **** add additional nodes by specifying --join=127.0.0.1:38155
I181203 10:35:11.404126 9 gossip/gossip.go:393  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:38155" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:1 patch:0 unstable:3 > build_tag:"v2.2.0-alpha.20181119-478-gb66795c905" started_at:1543833311403972202
I181203 10:35:11.405474 9 server/node.go:474  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=7.1 KiB), ranges=1, leases=0, queries=0.00, writes=0.00, bytesPerReplica={p10=7227.00 p25=7227.00 p50=7227.00 p75=7227.00 p90=7227.00 pMax=7227.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I181203 10:35:11.405533 9 storage/stores.go:242  [n1] read 0 node addresses from persistent storage
I181203 10:35:11.405774 9 server/node.go:697  [n1] connecting to gossip network to verify cluster ID...
I181203 10:35:11.405994 9 server/node.go:722  [n1] node connected via gossip and verified as part of cluster "4c40209a-4384-4e10-b1e5-1714db8e2e62"
I181203 10:35:11.406069 9 server/node.go:546  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I181203 10:35:11.406362 9 server/status/recorder.go:610  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 31 GiB, using system memory
I181203 10:35:11.406407 9 server/server.go:1821  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I181203 10:35:11.406511 9 server/server.go:1527  [n1] starting https server at 127.0.0.1:38193 (use: 127.0.0.1:38193)
I181203 10:35:11.406542 9 server/server.go:1529  [n1] starting grpc/postgres server at 127.0.0.1:38155
I181203 10:35:11.406560 9 server/server.go:1530  [n1] advertising CockroachDB node at 127.0.0.1:38155
W181203 10:35:11.406580 9 jobs/registry.go:318  [n1] unable to get node liveness: node not in the liveness table
I181203 10:35:11.415139 61 storage/replica_command.go:349  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I181203 10:35:11.441461 627 storage/replica_command.go:349  [n1,split,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I181203 10:35:11.486771 613 storage/replica_command.go:349  [n1,split,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I181203 10:35:11.497366 549 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I181203 10:35:11.510616 660 storage/replica_command.go:349  [n1,split,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I181203 10:35:11.530145 575 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:2.1-3 User:root}
I181203 10:35:11.542069 676 storage/replica_command.go:349  [n1,split,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I181203 10:35:11.585946 597 storage/replica_command.go:349  [n1,split,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I181203 10:35:11.621528 617 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I181203 10:35:11.628803 604 storage/replica_command.go:349  [n1,split,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I181203 10:35:11.660947 691 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:4ba56419-af3b-4f3c-b3f1-002c1c0d9368 User:root}
I181203 10:35:11.677026 551 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I181203 10:35:11.682647 554 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I181203 10:35:11.685573 9 server/server.go:1583  [n1] done ensuring all necessary migrations have run
I181203 10:35:11.685619 9 server/server.go:1586  [n1] serving sql connections
I181203 10:35:11.686385 9 server/testserver.go:421  had 7 ranges at startup, expected 20
I181203 10:35:11.686670 9 server/testserver.go:421  had 7 ranges at startup, expected 20
I181203 10:35:11.693486 593 storage/replica_command.go:349  [n1,split,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I181203 10:35:11.693965 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.694115 590 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:38155} Attrs: Locality: ServerVersion:2.1-3 BuildTag:v2.2.0-alpha.20181119-478-gb66795c905 StartedAt:1543833311403972202 LocalityAddress:[]} ClusterID:4c40209a-4384-4e10-b1e5-1714db8e2e62 StartedAt:1543833311403972202 LastUp:1543833311403972202}
I181203 10:35:11.694606 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.694917 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.695029 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.695095 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.695158 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.695221 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.695618 587 server/server_update.go:68  [n1] no need to upgrade, cluster already at the newest version
I181203 10:35:11.695720 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.695895 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.695971 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.696046 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.696232 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.696320 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.696505 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.696735 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.696974 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.697290 9 server/testserver.go:421  had 8 ranges at startup, expected 20
I181203 10:35:11.702080 731 storage/replica_command.go:349  [n1,split,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I181203 10:35:11.706962 9 server/testserver.go:421  had 9 ranges at startup, expected 20
I181203 10:35:11.708484 9 server/testserver.go:421  had 9 ranges at startup, expected 20
I181203 10:35:11.710042 9 server/testserver.go:421  had 9 ranges at startup, expected 20
I181203 10:35:11.714456 9 server/testserver.go:421  had 9 ranges at startup, expected 20
I181203 10:35:11.718866 9 server/testserver.go:421  had 9 ranges at startup, expected 20
I181203 10:35:11.743006 739 storage/replica_command.go:349  [n1,split,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I181203 10:35:11.745885 9 server/testserver.go:421  had 10 ranges at startup, expected 20
I181203 10:35:11.752218 711 storage/replica_command.go:349  [n1,split,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I181203 10:35:11.761709 721 storage/replica_command.go:349  [n1,split,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I181203 10:35:11.764024 9 server/testserver.go:421  had 12 ranges at startup, expected 20
I181203 10:35:11.802201 9 server/testserver.go:421  had 13 ranges at startup, expected 20
I181203 10:35:11.802363 760 storage/replica_command.go:349  [n1,split,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I181203 10:35:11.841507 789 storage/replica_command.go:349  [n1,split,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I181203 10:35:11.869171 763 storage/replica_command.go:349  [n1,split,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I181203 10:35:11.870767 9 server/testserver.go:421  had 15 ranges at startup, expected 20
I181203 10:35:11.890486 793 storage/replica_command.go:349  [n1,split,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I181203 10:35:11.908286 818 storage/replica_command.go:349  [n1,split,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
W181203 10:35:11.923121 808 storage/intent_resolver.go:675  [n1,s1] failed to push during intent resolution: failed to push "split" id=1dab1698 key=/Local/Range/Table/19/RangeDescriptor rw=true pri=0.03397330 iso=SERIALIZABLE stat=PENDING epo=0 ts=1543833311.890497279,0 orig=1543833311.890497279,0 max=1543833311.890497279,0 wto=false rop=false seq=1
I181203 10:35:11.925216 800 storage/replica_command.go:349  [n1,split,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I181203 10:35:11.939616 814 storage/replica_command.go:349  [n1,split,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
W181203 10:35:12.017009 9 server/status/runtime.go:295  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I181203 10:35:12.063248 9 server/server.go:849  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I181203 10:35:12.063555 9 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I181203 10:35:12.063577 9 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I181203 10:35:12.067237 9 server/config.go:484  [n?] 1 storage engine initialized
I181203 10:35:12.067255 9 server/config.go:487  [n?] RocksDB cache size: 128 MiB
I181203 10:35:12.067265 9 server/config.go:487  [n?] store 0: in-memory, size 0 B
W181203 10:35:12.086261 9 gossip/gossip.go:1501  [n?] no incoming or outgoing connections
I181203 10:35:12.086303 9 server/server.go:1400  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I181203 10:35:12.133166 935 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:38155
I181203 10:35:12.133547 925 gossip/server.go:232  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:42519}
I181203 10:35:12.134422 9 server/node.go:697  [n?] connecting to gossip network to verify cluster ID...
I181203 10:35:12.134451 9 server/node.go:722  [n?] node connected via gossip and verified as part of cluster "4c40209a-4384-4e10-b1e5-1714db8e2e62"
I181203 10:35:12.135625 925 gossip/server.go:232  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:42519}
I181203 10:35:12.141308 9 server/node.go:425  [n?] new node allocated ID 2
I181203 10:35:12.141379 9 gossip/gossip.go:393  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:42519" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:1 patch:0 unstable:3 > build_tag:"v2.2.0-alpha.20181119-478-gb66795c905" started_at:1543833312141319323
I181203 10:35:12.141446 9 storage/stores.go:242  [n2] read 0 node addresses from persistent storage
I181203 10:35:12.141484 9 storage/stores.go:261  [n2] wrote 1 node addresses to persistent storage
I181203 10:35:12.142456 12 storage/stores.go:261  [n1] wrote 1 node addresses to persistent storage
I181203 10:35:12.143760 9 server/node.go:672  [n2] bootstrapped store [n2,s2]
I181203 10:35:12.144109 9 server/node.go:546  [n2] node=2: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I181203 10:35:12.144370 9 server/status/recorder.go:610  [n2] available memory from cgroups (8.0 EiB) exceeds system memory 31 GiB, using system memory
I181203 10:35:12.144391 9 server/server.go:1821  [n2] Could not start heap profiler worker due to: directory to store profiles could not be determined
I181203 10:35:12.144471 9 server/server.go:1527  [n2] starting https server at 127.0.0.1:41637 (use: 127.0.0.1:41637)
I181203 10:35:12.144485 9 server/server.go:1529  [n2] starting grpc/postgres server at 127.0.0.1:42519
I181203 10:35:12.144496 9 server/server.go:1530  [n2] advertising CockroachDB node at 127.0.0.1:42519
I181203 10:35:12.151074 9 server/server.go:1583  [n2] done ensuring all necessary migrations have run
I181203 10:35:12.151094 9 server/server.go:1586  [n2] serving sql connections
W181203 10:35:12.197334 9 server/status/runtime.go:295  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I181203 10:35:12.209943 9 server/server.go:849  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I181203 10:35:12.210063 9 base/addr_validation.go:279  [n?] server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I181203 10:35:12.210082 9 base/addr_validation.go:319  [n?] web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I181203 10:35:12.210245 1186 server/server_update.go:68  [n2] no need to upgrade, cluster already at the newest version
I181203 10:35:12.213689 9 server/config.go:484  [n?] 1 storage engine initialized
I181203 10:35:12.213715 9 server/config.go:487  [n?] RocksDB cache size: 128 MiB
I181203 10:35:12.213724 9 server/config.go:487  [n?] store 0: in-memory, size 0 B
W181203 10:35:12.213783 9 gossip/gossip.go:1501  [n?] no incoming or outgoing connections
I181203 10:35:12.219651 9 server/server.go:1400  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I181203 10:35:12.222166 1189 sql/event_log.go:126  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:42519} Attrs: Locality: ServerVersion:2.1-3 BuildTag:v2.2.0-alpha.20181119-478-gb66795c905 StartedAt:1543833312141319323 LocalityAddress:[]} ClusterID:4c40209a-4384-4e10-b1e5-1714db8e2e62 StartedAt:1543833312141319323 LastUp:1543833312141319323}
I181203 10:35:12.242173 1267 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:38155
I181203 10:35:12.248625 1210 gossip/server.go:232  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:32785}
I181203 10:35:12.249811 9 server/node.go:697  [n?] connecting to gossip network to verify cluster ID...
I181203 10:35:12.249858 9 server/node.go:722  [n?] node connected via gossip and verified as part of cluster "4c40209a-4384-4e10-b1e5-1714db8e2e62"
I181203 10:35:12.251376 1210 gossip/server.go:232  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:32785}
I181203 10:35:12.253226 9 server/node.go:425  [n?] new node allocated ID 3
I181203 10:35:12.253293 9 gossip/gossip.go:393  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:32785" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:1 patch:0 unstable:3 > build_tag:"v2.2.0-alpha.20181119-478-gb66795c905" started_at:1543833312253242771
I181203 10:35:12.253363 9 storage/stores.go:242  [n3] read 0 node addresses from persistent storage
I181203 10:35:12.253407 9 storage/stores.go:261  [n3] wrote 2 node addresses to persistent storage
I181203 10:35:12.254585 12 storage/stores.go:261  [n1] wrote 2 node addresses to persistent storage
I181203 10:35:12.261366 886 storage/stores.go:261  [n2] wrote 2 node addresses to persistent storage
I181203 10:35:12.262441 9 server/node.go:672  [n3] bootstrapped store [n3,s3]
I181203 10:35:12.262762 9 server/node.go:546  [n3] node=3: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I181203 10:35:12.262994 9 server/status/recorder.go:610  [n3] available memory from cgroups (8.0 EiB) exceeds system memory 31 GiB, using system memory
I181203 10:35:12.263014 9 server/server.go:1821  [n3] Could not start heap profiler worker due to: directory to store profiles could not be determined
I181203 10:35:12.263091 9 server/server.go:1527  [n3] starting https server at 127.0.0.1:33805 (use: 127.0.0.1:33805)
I181203 10:35:12.263105 9 server/server.go:1529  [n3] starting grpc/postgres server at 127.0.0.1:32785
I181203 10:35:12.263116 9 server/server.go:1530  [n3] advertising CockroachDB node at 127.0.0.1:32785
I181203 10:35:12.263758 9 server/server.go:1583  [n3] done ensuring all necessary migrations have run
I181203 10:35:12.263776 9 server/server.go:1586  [n3] serving sql connections
I181203 10:35:12.285489 9 testutils/testcluster/testcluster.go:564  [n1,s1] has 20 underreplicated ranges
I181203 10:35:12.294221 127 storage/store_snapshot.go:746  [n1,replicate,s1,r2/1:/System/{-NodeLive…}] sending preemptive snapshot c98d516e at applied index 20
I181203 10:35:12.295694 127 storage/store_snapshot.go:789  [n1,replicate,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 10, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.296380 9 testutils/testcluster/testcluster.go:564  [n1,s1] has 20 underreplicated ranges
I181203 10:35:12.325386 1638 storage/replica_raftstorage.go:811  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 20 (id=c98d516e, encoded size=4250, 1 rocksdb batches, 10 log entries)
I181203 10:35:12.327951 1638 storage/replica_raftstorage.go:817  [n2,s2,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=2ms]
I181203 10:35:12.337802 9 testutils/testcluster/testcluster.go:564  [n1,s1] has 20 underreplicated ranges
I181203 10:35:12.338862 127 storage/replica_command.go:899  [n1,replicate,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, next=2, gen=1]
I181203 10:35:12.343289 127 storage/replica.go:4002  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I181203 10:35:12.379260 1196 server/server_update.go:68  [n3] no need to upgrade, cluster already at the newest version
I181203 10:35:12.380821 9 testutils/testcluster/testcluster.go:564  [n1,s1] has 20 underreplicated ranges
I181203 10:35:12.392429 127 storage/store_snapshot.go:746  [n1,replicate,s1,r3/1:/System/NodeLiveness{-Max}] sending preemptive snapshot 514ad369 at applied index 29
I181203 10:35:12.392867 127 storage/store_snapshot.go:789  [n1,replicate,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 11, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.393309 1552 storage/replica_raftstorage.go:811  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 29 (id=514ad369, encoded size=59905, 1 rocksdb batches, 11 log entries)
I181203 10:35:12.394383 1552 storage/replica_raftstorage.go:817  [n3,s3,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:12.394690 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.414745 127 storage/replica.go:4002  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I181203 10:35:12.419499 1199 sql/event_log.go:126  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:32785} Attrs: Locality: ServerVersion:2.1-3 BuildTag:v2.2.0-alpha.20181119-478-gb66795c905 StartedAt:1543833312253242771 LocalityAddress:[]} ClusterID:4c40209a-4384-4e10-b1e5-1714db8e2e62 StartedAt:1543833312253242771 LastUp:1543833312253242771}
I181203 10:35:12.419849 127 storage/store_snapshot.go:746  [n1,replicate,s1,r9/1:/Table/1{2-3}] sending preemptive snapshot 73feacf8 at applied index 21
I181203 10:35:12.420285 127 storage/store_snapshot.go:789  [n1,replicate,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 52, log entries: 11, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.422419 881 storage/replica_raftstorage.go:811  [n2,s2,r9/?:{-}] applying preemptive snapshot at index 21 (id=73feacf8, encoded size=12465, 1 rocksdb batches, 11 log entries)
I181203 10:35:12.423333 881 storage/replica_raftstorage.go:817  [n2,s2,r9/?:/Table/1{2-3}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:12.423614 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.427956 127 storage/replica.go:4002  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I181203 10:35:12.432753 127 storage/store_snapshot.go:746  [n1,replicate,s1,r16/1:/Table/{19-20}] sending preemptive snapshot 1c55a8ab at applied index 16
I181203 10:35:12.433001 127 storage/store_snapshot.go:789  [n1,replicate,s1,r16/1:/Table/{19-20}] streamed snapshot to (n3,s3):?: kv pairs: 7, log entries: 6, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.433310 1799 storage/replica_raftstorage.go:811  [n3,s3,r16/?:{-}] applying preemptive snapshot at index 16 (id=1c55a8ab, encoded size=1971, 1 rocksdb batches, 6 log entries)
I181203 10:35:12.437277 1799 storage/replica_raftstorage.go:817  [n3,s3,r16/?:/Table/{19-20}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=4ms commit=0ms]
I181203 10:35:12.444353 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.448778 127 storage/replica.go:4002  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I181203 10:35:12.451159 127 storage/store_snapshot.go:746  [n1,replicate,s1,r5/1:/System/ts{d-e}] sending preemptive snapshot a46f722a at applied index 21
I181203 10:35:12.459099 127 storage/store_snapshot.go:789  [n1,replicate,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 1406, log entries: 2, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:12.460467 1782 storage/replica_raftstorage.go:811  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 21 (id=a46f722a, encoded size=196812, 1 rocksdb batches, 2 log entries)
I181203 10:35:12.462720 1782 storage/replica_raftstorage.go:817  [n2,s2,r5/?:/System/ts{d-e}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=2ms]
I181203 10:35:12.463076 127 storage/replica_command.go:899  [n1,replicate,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, next=2, gen=1]
I181203 10:35:12.469248 9 testutils/testcluster/testcluster.go:564  [n1,s1] has 20 underreplicated ranges
I181203 10:35:12.469956 127 storage/replica.go:4002  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I181203 10:35:12.486212 127 storage/store_snapshot.go:746  [n1,replicate,s1,r11/1:/Table/1{4-5}] sending preemptive snapshot 4e0627d6 at applied index 16
I181203 10:35:12.486487 127 storage/store_snapshot.go:789  [n1,replicate,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n3,s3):?: kv pairs: 7, log entries: 6, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:12.486922 1801 storage/replica_raftstorage.go:811  [n3,s3,r11/?:{-}] applying preemptive snapshot at index 16 (id=4e0627d6, encoded size=1967, 1 rocksdb batches, 6 log entries)
I181203 10:35:12.487607 1801 storage/replica_raftstorage.go:817  [n3,s3,r11/?:/Table/1{4-5}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181203 10:35:12.487943 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.493614 127 storage/replica.go:4002  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I181203 10:35:12.496159 127 storage/store_snapshot.go:746  [n1,replicate,s1,r10/1:/Table/1{3-4}] sending preemptive snapshot 6f37559e at applied index 47
I181203 10:35:12.497489 127 storage/store_snapshot.go:789  [n1,replicate,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 157, log entries: 37, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.498097 1713 storage/replica_raftstorage.go:811  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 47 (id=6f37559e, encoded size=41288, 1 rocksdb batches, 37 log entries)
I181203 10:35:12.501086 1713 storage/replica_raftstorage.go:817  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=3ms commit=0ms]
I181203 10:35:12.501431 127 storage/replica_command.go:899  [n1,replicate,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, next=2, gen=1]
I181203 10:35:12.506457 127 storage/replica.go:4002  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I181203 10:35:12.508458 127 storage/store_snapshot.go:746  [n1,replicate,s1,r13/1:/Table/1{6-7}] sending preemptive snapshot c7703146 at applied index 16
I181203 10:35:12.510404 127 storage/store_snapshot.go:789  [n1,replicate,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 7, log entries: 6, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.511069 1842 storage/replica_raftstorage.go:811  [n2,s2,r13/?:{-}] applying preemptive snapshot at index 16 (id=c7703146, encoded size=1971, 1 rocksdb batches, 6 log entries)
I181203 10:35:12.511684 1842 storage/replica_raftstorage.go:817  [n2,s2,r13/?:/Table/1{6-7}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181203 10:35:12.524578 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.534154 127 storage/replica.go:4002  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I181203 10:35:12.537867 127 storage/store_snapshot.go:746  [n1,replicate,s1,r17/1:/Table/2{0-1}] sending preemptive snapshot 14ce86da at applied index 16
I181203 10:35:12.538016 127 storage/store_snapshot.go:789  [n1,replicate,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n2,s2):?: kv pairs: 7, log entries: 6, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.538451 1832 storage/replica_raftstorage.go:811  [n2,s2,r17/?:{-}] applying preemptive snapshot at index 16 (id=14ce86da, encoded size=1967, 1 rocksdb batches, 6 log entries)
I181203 10:35:12.548057 1832 storage/replica_raftstorage.go:817  [n2,s2,r17/?:/Table/2{0-1}] applied preemptive snapshot in 10ms [clear=0ms batch=0ms entries=2ms commit=7ms]
I181203 10:35:12.548544 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.557553 127 storage/replica.go:4002  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I181203 10:35:12.571530 127 storage/store_snapshot.go:746  [n1,replicate,s1,r4/1:/System/{NodeLive…-tsd}] sending preemptive snapshot cac6cf1e at applied index 40
I181203 10:35:12.574309 1722 storage/replica_raftstorage.go:811  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 40 (id=cac6cf1e, encoded size=100044, 1 rocksdb batches, 30 log entries)
I181203 10:35:12.578325 9 testutils/testcluster/testcluster.go:564  [n1,s1] has 20 underreplicated ranges
I181203 10:35:12.579216 127 storage/store_snapshot.go:789  [n1,replicate,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 36, log entries: 30, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:12.591872 1722 storage/replica_raftstorage.go:817  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 17ms [clear=0ms batch=0ms entries=16ms commit=1ms]
I181203 10:35:12.593399 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.604076 127 storage/replica.go:4002  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I181203 10:35:12.606153 127 storage/store_snapshot.go:746  [n1,replicate,s1,r7/1:/Table/{SystemCon…-11}] sending preemptive snapshot 984fc9a1 at applied index 34
I181203 10:35:12.607045 127 storage/store_snapshot.go:789  [n1,replicate,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 59, log entries: 24, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.607857 1819 storage/replica_raftstorage.go:811  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 34 (id=984fc9a1, encoded size=21521, 1 rocksdb batches, 24 log entries)
I181203 10:35:12.611913 1819 storage/replica_raftstorage.go:817  [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=3ms commit=0ms]
I181203 10:35:12.613804 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.620875 127 storage/replica.go:4002  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I181203 10:35:12.627433 127 storage/store_snapshot.go:746  [n1,replicate,s1,r12/1:/Table/1{5-6}] sending preemptive snapshot 2a6d1025 at applied index 16
I181203 10:35:12.628482 127 storage/store_snapshot.go:789  [n1,replicate,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n3,s3):?: kv pairs: 7, log entries: 6, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:12.628813 1879 storage/replica_raftstorage.go:811  [n3,s3,r12/?:{-}] applying preemptive snapshot at index 16 (id=2a6d1025, encoded size=2134, 1 rocksdb batches, 6 log entries)
I181203 10:35:12.629327 1879 storage/replica_raftstorage.go:817  [n3,s3,r12/?:/Table/1{5-6}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181203 10:35:12.629577 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.634663 127 storage/replica.go:4002  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I181203 10:35:12.642415 127 storage/store_snapshot.go:746  [n1,replicate,s1,r14/1:/Table/1{7-8}] sending preemptive snapshot f921f564 at applied index 16
I181203 10:35:12.642686 127 storage/store_snapshot.go:789  [n1,replicate,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 7, log entries: 6, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:12.643105 1724 storage/replica_raftstorage.go:811  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 16 (id=f921f564, encoded size=1967, 1 rocksdb batches, 6 log entries)
I181203 10:35:12.643690 1724 storage/replica_raftstorage.go:817  [n2,s2,r14/?:/Table/1{7-8}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181203 10:35:12.644050 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.659581 127 storage/replica.go:4002  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I181203 10:35:12.662220 127 storage/store_snapshot.go:746  [n1,replicate,s1,r15/1:/Table/1{8-9}] sending preemptive snapshot 75ca2504 at applied index 16
I181203 10:35:12.662446 127 storage/store_snapshot.go:789  [n1,replicate,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n3,s3):?: kv pairs: 7, log entries: 6, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.662770 1884 storage/replica_raftstorage.go:811  [n3,s3,r15/?:{-}] applying preemptive snapshot at index 16 (id=75ca2504, encoded size=2134, 1 rocksdb batches, 6 log entries)
I181203 10:35:12.663290 1884 storage/replica_raftstorage.go:817  [n3,s3,r15/?:/Table/1{8-9}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181203 10:35:12.663559 127 storage/replica_command.go:899  [n1,replicate,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, next=2, gen=1]
I181203 10:35:12.673143 127 storage/replica.go:4002  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I181203 10:35:12.675358 127 storage/store_snapshot.go:746  [n1,replicate,s1,r18/1:/Table/2{1-2}] sending preemptive snapshot b547bb8e at applied index 16
I181203 10:35:12.675566 127 storage/store_snapshot.go:789  [n1,replicate,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 7, log entries: 6, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.675883 1725 storage/replica_raftstorage.go:811  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 16 (id=b547bb8e, encoded size=1967, 1 rocksdb batches, 6 log entries)
I181203 10:35:12.676408 1725 storage/replica_raftstorage.go:817  [n2,s2,r18/?:/Table/2{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181203 10:35:12.676653 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.681097 9 testutils/testcluster/testcluster.go:564  [n1,s1] has 20 underreplicated ranges
I181203 10:35:12.682496 127 storage/replica.go:4002  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I181203 10:35:12.685059 127 storage/store_snapshot.go:746  [n1,replicate,s1,r19/1:/Table/2{2-3}] sending preemptive snapshot 88b4f9b0 at applied index 16
I181203 10:35:12.685242 127 storage/store_snapshot.go:789  [n1,replicate,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 7, log entries: 6, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.685558 1890 storage/replica_raftstorage.go:811  [n3,s3,r19/?:{-}] applying preemptive snapshot at index 16 (id=88b4f9b0, encoded size=1967, 1 rocksdb batches, 6 log entries)
I181203 10:35:12.686093 1890 storage/replica_raftstorage.go:817  [n3,s3,r19/?:/Table/2{2-3}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181203 10:35:12.686358 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.696144 127 storage/replica.go:4002  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I181203 10:35:12.697203 127 storage/store_snapshot.go:746  [n1,replicate,s1,r1/1:/{Min-System/}] sending preemptive snapshot 92cf3c8c at applied index 94
I181203 10:35:12.698444 127 storage/store_snapshot.go:789  [n1,replicate,s1,r1/1:/{Min-System/}] streamed snapshot to (n3,s3):?: kv pairs: 69, log entries: 84, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.700635 1852 storage/replica_raftstorage.go:811  [n3,s3,r1/?:{-}] applying preemptive snapshot at index 94 (id=92cf3c8c, encoded size=20864, 1 rocksdb batches, 84 log entries)
I181203 10:35:12.734092 1852 storage/replica_raftstorage.go:817  [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 33ms [clear=0ms batch=0ms entries=33ms commit=0ms]
I181203 10:35:12.734534 127 storage/replica_command.go:899  [n1,replicate,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r1:/{Min-System/} [(n1,s1):1, next=2, gen=1]
I181203 10:35:12.742776 127 storage/replica.go:4002  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I181203 10:35:12.745697 127 storage/store_snapshot.go:746  [n1,replicate,s1,r6/1:/{System/tse-Table/System…}] sending preemptive snapshot 9d624364 at applied index 22
I181203 10:35:12.747351 127 storage/store_snapshot.go:789  [n1,replicate,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 7, log entries: 12, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.747898 1727 storage/replica_raftstorage.go:811  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 22 (id=9d624364, encoded size=5740, 1 rocksdb batches, 12 log entries)
I181203 10:35:12.748966 1727 storage/replica_raftstorage.go:817  [n2,s2,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:12.749227 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.755194 127 storage/replica.go:4002  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I181203 10:35:12.768651 9 testutils/testcluster/testcluster.go:564  [n1,s1] has 20 underreplicated ranges
I181203 10:35:12.768860 127 storage/store_snapshot.go:746  [n1,replicate,s1,r8/1:/Table/1{1-2}] sending preemptive snapshot f918fb27 at applied index 18
I181203 10:35:12.769085 127 storage/store_snapshot.go:789  [n1,replicate,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:12.770105 1888 storage/replica_raftstorage.go:811  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 18 (id=f918fb27, encoded size=4552, 1 rocksdb batches, 8 log entries)
I181203 10:35:12.770871 1888 storage/replica_raftstorage.go:817  [n3,s3,r8/?:/Table/1{1-2}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:12.775045 127 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.780781 127 storage/replica.go:4002  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I181203 10:35:12.790536 127 storage/store_snapshot.go:746  [n1,replicate,s1,r20/1:/{Table/23-Max}] sending preemptive snapshot a96eb425 at applied index 12
I181203 10:35:12.790716 127 storage/store_snapshot.go:789  [n1,replicate,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 2, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:12.792657 1909 storage/replica_raftstorage.go:811  [n2,s2,r20/?:{-}] applying preemptive snapshot at index 12 (id=a96eb425, encoded size=476, 1 rocksdb batches, 2 log entries)
I181203 10:35:12.792983 1909 storage/replica_raftstorage.go:817  [n2,s2,r20/?:/{Table/23-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181203 10:35:12.795425 127 storage/replica_command.go:899  [n1,replicate,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, gen=0]
I181203 10:35:12.800964 127 storage/replica.go:4002  [n1,s1,r20/1:/{Table/23-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I181203 10:35:12.801444 127 storage/queue.go:923  [n1,replicate] purgatory is now empty
I181203 10:35:12.804060 1932 storage/store_snapshot.go:746  [n1,replicate,s1,r2/1:/System/{-NodeLive…}] sending preemptive snapshot b381d2fc at applied index 23
I181203 10:35:12.805416 1932 storage/store_snapshot.go:789  [n1,replicate,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 13, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.805803 1936 storage/replica_raftstorage.go:811  [n3,s3,r2/?:{-}] applying preemptive snapshot at index 23 (id=b381d2fc, encoded size=5322, 1 rocksdb batches, 13 log entries)
I181203 10:35:12.806755 1936 storage/replica_raftstorage.go:817  [n3,s3,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:12.807022 1932 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.843841 1932 storage/replica.go:4002  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I181203 10:35:12.846527 1938 storage/store_snapshot.go:746  [n1,replicate,s1,r3/1:/System/NodeLiveness{-Max}] sending preemptive snapshot 8dab0074 at applied index 32
I181203 10:35:12.848486 1938 storage/store_snapshot.go:789  [n1,replicate,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 14, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.848970 1954 storage/replica_raftstorage.go:811  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 32 (id=8dab0074, encoded size=61117, 1 rocksdb batches, 14 log entries)
I181203 10:35:12.850307 1954 storage/replica_raftstorage.go:817  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:12.852238 1938 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.870713 1938 storage/replica.go:4002  [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
I181203 10:35:12.875256 9 testutils/testcluster/testcluster.go:564  [n1,s1] has 18 underreplicated ranges
I181203 10:35:12.875927 1959 storage/store_snapshot.go:746  [n1,replicate,s1,r9/1:/Table/1{2-3}] sending preemptive snapshot bc020f66 at applied index 24
I181203 10:35:12.880867 1959 storage/store_snapshot.go:789  [n1,replicate,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 53, log entries: 14, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:12.881289 1942 storage/replica_raftstorage.go:811  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 24 (id=bc020f66, encoded size=13497, 1 rocksdb batches, 14 log entries)
I181203 10:35:12.882434 1942 storage/replica_raftstorage.go:817  [n3,s3,r9/?:/Table/1{2-3}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:12.882740 1959 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.889342 1959 storage/replica.go:4002  [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
I181203 10:35:12.892004 1894 storage/store_snapshot.go:746  [n1,replicate,s1,r16/1:/Table/{19-20}] sending preemptive snapshot 2197baeb at applied index 19
I181203 10:35:12.892188 1894 storage/store_snapshot.go:789  [n1,replicate,s1,r16/1:/Table/{19-20}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.892563 1898 storage/replica_raftstorage.go:811  [n2,s2,r16/?:{-}] applying preemptive snapshot at index 19 (id=2197baeb, encoded size=3003, 1 rocksdb batches, 9 log entries)
I181203 10:35:12.893317 1898 storage/replica_raftstorage.go:817  [n2,s2,r16/?:/Table/{19-20}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:12.893579 1894 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.901651 1894 storage/replica.go:4002  [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
I181203 10:35:12.905118 1901 storage/store_snapshot.go:746  [n1,replicate,s1,r5/1:/System/ts{d-e}] sending preemptive snapshot d05c82be at applied index 24
I181203 10:35:12.911773 1901 storage/store_snapshot.go:789  [n1,replicate,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n3,s3):?: kv pairs: 1407, log entries: 5, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:12.912479 1905 storage/replica_raftstorage.go:811  [n3,s3,r5/?:{-}] applying preemptive snapshot at index 24 (id=d05c82be, encoded size=197895, 1 rocksdb batches, 5 log entries)
I181203 10:35:12.918228 1905 storage/replica_raftstorage.go:817  [n3,s3,r5/?:/System/ts{d-e}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=0ms commit=5ms]
I181203 10:35:12.918683 1901 storage/replica_command.go:899  [n1,replicate,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, (n2,s2):2, next=3, gen=1]
I181203 10:35:12.925429 1901 storage/replica.go:4002  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I181203 10:35:12.928739 1947 storage/store_snapshot.go:746  [n1,replicate,s1,r11/1:/Table/1{4-5}] sending preemptive snapshot 9d67c8c6 at applied index 19
I181203 10:35:12.929082 1947 storage/store_snapshot.go:789  [n1,replicate,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:12.929436 1987 storage/replica_raftstorage.go:811  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 19 (id=9d67c8c6, encoded size=2999, 1 rocksdb batches, 9 log entries)
I181203 10:35:12.930135 1987 storage/replica_raftstorage.go:817  [n2,s2,r11/?:/Table/1{4-5}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181203 10:35:12.931706 1947 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:12.937409 1947 storage/replica.go:4002  [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
I181203 10:35:12.959548 1912 storage/store_snapshot.go:746  [n1,replicate,s1,r10/1:/Table/1{3-4}] sending preemptive snapshot 26f1050f at applied index 89
I181203 10:35:12.960551 1912 storage/store_snapshot.go:789  [n1,replicate,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 258, log entries: 79, rate-limit: 8.0 MiB/sec, 0.02s
I181203 10:35:12.961489 1952 storage/replica_raftstorage.go:811  [n2,s2,r10/?:{-}] applying preemptive snapshot at index 89 (id=26f1050f, encoded size=81780, 1 rocksdb batches, 79 log entries)
I181203 10:35:12.967204 1952 storage/replica_raftstorage.go:817  [n2,s2,r10/?:/Table/1{3-4}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=5ms commit=1ms]
I181203 10:35:12.967599 1912 storage/replica_command.go:899  [n1,replicate,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I181203 10:35:12.981644 9 testutils/testcluster/testcluster.go:564  [n1,s1] has 14 underreplicated ranges
I181203 10:35:13.010632 1912 storage/replica.go:4002  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I181203 10:35:13.013558 1965 storage/store_snapshot.go:746  [n1,replicate,s1,r13/1:/Table/1{6-7}] sending preemptive snapshot fe6a89a9 at applied index 19
I181203 10:35:13.013801 1965 storage/store_snapshot.go:789  [n1,replicate,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:13.014210 1968 storage/replica_raftstorage.go:811  [n3,s3,r13/?:{-}] applying preemptive snapshot at index 19 (id=fe6a89a9, encoded size=3003, 1 rocksdb batches, 9 log entries)
I181203 10:35:13.014965 1968 storage/replica_raftstorage.go:817  [n3,s3,r13/?:/Table/1{6-7}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:13.015240 1965 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:13.020915 1965 storage/replica.go:4002  [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
I181203 10:35:13.032806 1917 storage/store_snapshot.go:746  [n1,replicate,s1,r17/1:/Table/2{0-1}] sending preemptive snapshot 5b7934f7 at applied index 19
I181203 10:35:13.033363 1917 storage/store_snapshot.go:789  [n1,replicate,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:13.033737 1921 storage/replica_raftstorage.go:811  [n3,s3,r17/?:{-}] applying preemptive snapshot at index 19 (id=5b7934f7, encoded size=2999, 1 rocksdb batches, 9 log entries)
I181203 10:35:13.038407 1921 storage/replica_raftstorage.go:817  [n3,s3,r17/?:/Table/2{0-1}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=4ms commit=0ms]
I181203 10:35:13.039755 1917 storage/replica_command.go:899  [n1,replicate,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, (n2,s2):2, next=3, gen=1]
I181203 10:35:13.045472 1917 storage/replica.go:4002  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I181203 10:35:13.050220 2019 storage/store_snapshot.go:746  [n1,replicate,s1,r4/1:/System/{NodeLive…-tsd}] sending preemptive snapshot eea06ba5 at applied index 43
I181203 10:35:13.052983 2019 storage/store_snapshot.go:789  [n1,replicate,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n2,s2):?: kv pairs: 37, log entries: 33, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:13.067139 2023 storage/replica_raftstorage.go:811  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 43 (id=eea06ba5, encoded size=101228, 1 rocksdb batches, 33 log entries)
I181203 10:35:13.070277 2023 storage/replica_raftstorage.go:817  [n2,s2,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=1ms]
I181203 10:35:13.070750 2019 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:13.073543 9 testutils/testcluster/testcluster.go:564  [n1,s1] has 11 underreplicated ranges
I181203 10:35:13.087458 2019 storage/replica.go:4002  [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
I181203 10:35:13.090383 2005 storage/store_snapshot.go:746  [n1,replicate,s1,r7/1:/Table/{SystemCon…-11}] sending preemptive snapshot 55ebd9a8 at applied index 37
I181203 10:35:13.090803 2005 storage/store_snapshot.go:789  [n1,replicate,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):?: kv pairs: 60, log entries: 27, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:13.091259 2008 storage/replica_raftstorage.go:811  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 37 (id=55ebd9a8, encoded size=22562, 1 rocksdb batches, 27 log entries)
I181203 10:35:13.093117 2008 storage/replica_raftstorage.go:817  [n3,s3,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I181203 10:35:13.093376 2005 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:13.100756 2005 storage/replica.go:4002  [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
I181203 10:35:13.102677 2027 storage/split_queue.go:215  [n1,split,s1,r7/1:/Table/{SystemCon…-11}] initiating a split based on load at key /Table/3/1/1/2/1
E181203 10:35:13.102837 2027 storage/queue.go:837  [n1,split,s1,r7/1:/Table/{SystemCon…-11}] unable to split [n1,s1,r7/1:/Table/{SystemCon…-11}] at key /Table/3/1/1/2/1: cannot split range at key /Table/3/1/1/2/1
I181203 10:35:13.104794 2025 storage/store_snapshot.go:746  [n1,replicate,s1,r12/1:/Table/1{5-6}] sending preemptive snapshot 5c182507 at applied index 19
I181203 10:35:13.107942 2025 storage/store_snapshot.go:789  [n1,replicate,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:13.108292 2066 storage/replica_raftstorage.go:811  [n2,s2,r12/?:{-}] applying preemptive snapshot at index 19 (id=5c182507, encoded size=3166, 1 rocksdb batches, 9 log entries)
I181203 10:35:13.109061 2066 storage/replica_raftstorage.go:817  [n2,s2,r12/?:/Table/1{5-6}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:13.109340 2025 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:13.118563 2025 storage/replica.go:4002  [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
I181203 10:35:13.120337 1977 storage/store_snapshot.go:746  [n1,replicate,s1,r14/1:/Table/1{7-8}] sending preemptive snapshot e0a31d58 at applied index 19
I181203 10:35:13.120529 1977 storage/store_snapshot.go:789  [n1,replicate,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:13.120901 2068 storage/replica_raftstorage.go:811  [n3,s3,r14/?:{-}] applying preemptive snapshot at index 19 (id=e0a31d58, encoded size=2999, 1 rocksdb batches, 9 log entries)
I181203 10:35:13.121871 2068 storage/replica_raftstorage.go:817  [n3,s3,r14/?:/Table/1{7-8}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:13.124570 1977 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:13.135196 1977 storage/replica.go:4002  [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
I181203 10:35:13.149380 2031 storage/store_snapshot.go:746  [n1,replicate,s1,r15/1:/Table/1{8-9}] sending preemptive snapshot adffb4b3 at applied index 19
I181203 10:35:13.149883 2031 storage/store_snapshot.go:789  [n1,replicate,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:13.150278 2082 storage/replica_raftstorage.go:811  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 19 (id=adffb4b3, encoded size=3163, 1 rocksdb batches, 9 log entries)
I181203 10:35:13.151017 2082 storage/replica_raftstorage.go:817  [n2,s2,r15/?:/Table/1{8-9}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:13.152669 2031 storage/replica_command.go:899  [n1,replicate,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I181203 10:35:13.162433 2031 storage/replica.go:4002  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I181203 10:35:13.171896 9 testutils/testcluster/testcluster.go:564  [n1,s1] has 6 underreplicated ranges
I181203 10:35:13.172773 2084 storage/store_snapshot.go:746  [n1,replicate,s1,r18/1:/Table/2{1-2}] sending preemptive snapshot d145c6f0 at applied index 19
I181203 10:35:13.178131 2084 storage/store_snapshot.go:789  [n1,replicate,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:13.178498 2037 storage/replica_raftstorage.go:811  [n3,s3,r18/?:{-}] applying preemptive snapshot at index 19 (id=d145c6f0, encoded size=2999, 1 rocksdb batches, 9 log entries)
I181203 10:35:13.179248 2037 storage/replica_raftstorage.go:817  [n3,s3,r18/?:/Table/2{1-2}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:13.185708 2084 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:13.190985 2084 storage/replica.go:4002  [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
I181203 10:35:13.192742 2039 storage/store_snapshot.go:746  [n1,replicate,s1,r19/1:/Table/2{2-3}] sending preemptive snapshot 79a353d5 at applied index 19
I181203 10:35:13.192958 2039 storage/store_snapshot.go:789  [n1,replicate,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:13.193320 2042 storage/replica_raftstorage.go:811  [n2,s2,r19/?:{-}] applying preemptive snapshot at index 19 (id=79a353d5, encoded size=2999, 1 rocksdb batches, 9 log entries)
I181203 10:35:13.194045 2042 storage/replica_raftstorage.go:817  [n2,s2,r19/?:/Table/2{2-3}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:13.194308 2039 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:13.200177 2039 storage/replica.go:4002  [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
I181203 10:35:13.202589 2056 storage/store_snapshot.go:746  [n1,replicate,s1,r1/1:/{Min-System/}] sending preemptive snapshot fd924c41 at applied index 136
I181203 10:35:13.206416 2056 storage/store_snapshot.go:789  [n1,replicate,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 91, log entries: 126, rate-limit: 8.0 MiB/sec, 0.01s
I181203 10:35:13.206893 2060 storage/replica_raftstorage.go:811  [n2,s2,r1/?:{-}] applying preemptive snapshot at index 136 (id=fd924c41, encoded size=29418, 1 rocksdb batches, 126 log entries)
I181203 10:35:13.214602 2060 storage/replica_raftstorage.go:817  [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 8ms [clear=0ms batch=0ms entries=7ms commit=0ms]
I181203 10:35:13.214944 2056 storage/replica_command.go:899  [n1,replicate,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r1:/{Min-System/} [(n1,s1):1, (n3,s3):2, next=3, gen=1]
I181203 10:35:13.224903 2056 storage/replica.go:4002  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I181203 10:35:13.227191 2086 storage/store_snapshot.go:746  [n1,replicate,s1,r6/1:/{System/tse-Table/System…}] sending preemptive snapshot 3c7c80d3 at applied index 25
I181203 10:35:13.227462 2086 storage/store_snapshot.go:789  [n1,replicate,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 15, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:13.228212 1984 storage/replica_raftstorage.go:811  [n3,s3,r6/?:{-}] applying preemptive snapshot at index 25 (id=3c7c80d3, encoded size=6811, 1 rocksdb batches, 15 log entries)
I181203 10:35:13.229331 1984 storage/replica_raftstorage.go:817  [n3,s3,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:13.229888 2086 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:13.234708 2086 storage/replica.go:4002  [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
I181203 10:35:13.236998 2098 storage/store_snapshot.go:746  [n1,replicate,s1,r8/1:/Table/1{1-2}] sending preemptive snapshot d7d8e0a5 at applied index 21
I181203 10:35:13.237728 2098 storage/store_snapshot.go:789  [n1,replicate,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:13.238191 2101 storage/replica_raftstorage.go:811  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 21 (id=d7d8e0a5, encoded size=5581, 1 rocksdb batches, 11 log entries)
I181203 10:35:13.239096 2101 storage/replica_raftstorage.go:817  [n2,s2,r8/?:/Table/1{1-2}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I181203 10:35:13.239359 2098 storage/replica_command.go:899  [n1,replicate,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, gen=1]
I181203 10:35:13.244749 2098 storage/replica.go:4002  [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
I181203 10:35:13.246854 1839 storage/store_snapshot.go:746  [n1,replicate,s1,r20/1:/{Table/23-Max}] sending preemptive snapshot 3a923c40 at applied index 15
I181203 10:35:13.246999 1839 storage/store_snapshot.go:789  [n1,replicate,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 5, rate-limit: 8.0 MiB/sec, 0.00s
I181203 10:35:13.247347 2115 storage/replica_raftstorage.go:811  [n3,s3,r20/?:{-}] applying preemptive snapshot at index 15 (id=3a923c40, encoded size=1508, 1 rocksdb batches, 5 log entries)
I181203 10:35:13.247871 2115 storage/replica_raftstorage.go:817  [n3,s3,r20/?:/{Table/23-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181203 10:35:13.248108 1839 storage/replica_command.go:899  [n1,replicate,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, gen=0]
I181203 10:35:13.258257 1839 storage/replica.go:4002  [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
I181203 10:35:13.505466 2184 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-63" [r22]
I181203 10:35:13.506307 2187 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-34" [r23]
I181203 10:35:13.509780 2235 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-3" [r21]
I181203 10:35:13.510218 2198 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-68" [r24]
I181203 10:35:13.510274 2188 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-12" [r25]
I181203 10:35:13.510510 2189 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-27" [r26]
I181203 10:35:13.510603 2177 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-1" [r27]
I181203 10:35:13.510721 2190 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-31" [r28]
I181203 10:35:13.510791 2191 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-11" [r29]
I181203 10:35:13.511038 2192 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-10" [r30]
I181203 10:35:13.513657 2196 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-95" [r33]
I181203 10:35:13.513816 2199 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-94" [r36]
I181203 10:35:13.513940 2194 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-66" [r31]
I181203 10:35:13.514001 2204 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-17" [r38]
I181203 10:35:13.514074 2197 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-83" [r34]
I181203 10:35:13.514141 2195 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-71" [r32]
I181203 10:35:13.514213 2200 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-41" [r37]
I181203 10:35:13.514279 2203 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-26" [r35]
I181203 10:35:13.514385 2201 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-45" [r39]
I181203 10:35:13.514498 2202 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-78" [r40]
I181203 10:35:13.517300 2222 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-86" [r44]
I181203 10:35:13.517488 2210 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-55" [r45]
I181203 10:35:13.517559 2207 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-47" [r41]
I181203 10:35:13.517727 2211 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-60" [r46]
I181203 10:35:13.517786 2206 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-75" [r42]
I181203 10:35:13.517946 2212 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-79" [r47]
I181203 10:35:13.518036 2208 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-37" [r43]
I181203 10:35:13.518172 2213 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-70" [r48]
I181203 10:35:13.518366 2214 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-97" [r49]
I181203 10:35:13.518574 2215 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-9" [r50]
I181203 10:35:13.518775 2218 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-53" [r54]
I181203 10:35:13.518974 2217 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-67" [r57]
I181203 10:35:13.518998 2228 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-80" [r59]
I181203 10:35:13.519190 2073 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-59" [r60]
I181203 10:35:13.519224 2161 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-93" [r55]
I181203 10:35:13.519353 2205 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-13" [r51]
I181203 10:35:13.519406 2216 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-18" [r56]
I181203 10:35:13.518980 2072 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-21" [r58]
I181203 10:35:13.519614 2221 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-73" [r53]
I181203 10:35:13.519686 2219 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-8" [r52]
I181203 10:35:13.520085 2225 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-32" [r65]
I181203 10:35:13.520358 2077 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-39" [r68]
I181203 10:35:13.520387 2227 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-0" [r69]
I181203 10:35:13.520406 2074 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-40" [r62]
I181203 10:35:13.520387 2223 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-88" [r61]
I181203 10:35:13.520564 2224 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-92" [r63]
I181203 10:35:13.520582 2078 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-42" [r70]
I181203 10:35:13.520752 2075 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-52" [r64]
I181203 10:35:13.520889 2076 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-5" [r66]
I181203 10:35:13.521140 2226 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-85" [r67]
I181203 10:35:13.521230 2152 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-69" [r74]
I181203 10:35:13.521430 2220 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-87" [r71]
I181203 10:35:13.521504 2162 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-62" [r75]
I181203 10:35:13.521674 2175 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-64" [r72]
I181203 10:35:13.521795 2153 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-49" [r76]
I181203 10:35:13.521956 2079 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-96" [r73]
I181203 10:35:13.522031 2080 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-24" [r77]
I181203 10:35:13.522166 2163 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-58" [r78]
I181203 10:35:13.522253 2164 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-44" [r81]
I181203 10:35:13.522399 2154 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-61" [r79]
I181203 10:35:13.522524 2155 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-56" [r82]
I181203 10:35:13.522676 2081 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-38" [r80]
I181203 10:35:13.522818 2165 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-77" [r83]
I181203 10:35:13.522995 2149 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-50" [r95]
I181203 10:35:13.523091 2160 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-84" [r96]
I181203 10:35:13.523161 2156 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-54" [r84]
I181203 10:35:13.523261 2170 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-29" [r97]
I181203 10:35:13.523350 2151 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-82" [r99]
I181203 10:35:13.523372 2159 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-90" [r93]
I181203 10:35:13.523389 2148 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-2" [r92]
I181203 10:35:13.523415 2157 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-22" [r87]
I181203 10:35:13.523513 2150 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-51" [r98]
I181203 10:35:13.523550 2171 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-65" [r100]
I181203 10:35:13.523630 2166 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-48" [r85]
I181203 10:35:13.523520 2169 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-81" [r94]
I181203 10:35:13.523684 2168 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-19" [r91]
I181203 10:35:13.523798 2146 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-36" [r86]
I181203 10:35:13.523910 2147 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-99" [r89]
I181203 10:35:13.523962 2158 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-23" [r90]
I181203 10:35:13.524077 2167 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-25" [r88]
I181203 10:35:13.524283 2173 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-6" [r105]
I181203 10:35:13.524341 2174 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-16" [r107]
I181203 10:35:13.524469 2182 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-57" [r101]
I181203 10:35:13.524501 2229 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-74" [r106]
I181203 10:35:13.524520 2185 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-28" [r109]
I181203 10:35:13.524549 2232 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-14" [r110]
I181203 10:35:13.524667 2172 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-76" [r102]
I181203 10:35:13.524723 2230 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-89" [r108]
I181203 10:35:13.524746 2176 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-7" [r103]
I181203 10:35:13.524848 2231 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-33" [r104]
I181203 10:35:13.525224 2233 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-72" [r112]
I181203 10:35:13.525246 2179 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-30" [r113]
I181203 10:35:13.525382 2183 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-20" [r111]
I181203 10:35:13.525428 2234 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-4" [r114]
I181203 10:35:13.525226 2209 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-91" [r115]
I181203 10:35:13.525516 2180 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-15" [r118]
I181203 10:35:13.525626 2193 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-46" [r120]
I181203 10:35:13.525635 2178 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-98" [r116]
I181203 10:35:13.525681 2186 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-43" [r117]
I181203 10:35:13.525775 2181 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-35" [r119]
I181203 10:35:13.531129 27 gossip/gossip.go:1515  [n1] node has connected to cluster via gossip
I181203 10:35:13.531349 27 storage/stores.go:261  [n1] wrote 2 node addresses to persistent storage
I181203 10:35:13.572536 2311 storage/replica_command.go:492  [n1,merge,s1,r6/1:{/System/tse-key-63}] initiating a merge of r22:{key-63-/Table/SystemConfigSpan/Start} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=0] into this range
I181203 10:35:13.602624 340 storage/store.go:2563  [n1,s1,r6/1:{/System/tse-key-63}] removing replica r22/1
I181203 10:35:13.611174 1336 storage/store.go:2563  [n3,s3,r6/3:{/System/tse-key-63}] removing replica r22/3
I181203 10:35:13.611985 1039 storage/store.go:2563  [n2,s2,r6/2:{/System/tse-key-63}] removing replica r22/2
I181203 10:35:13.612292 2187 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-34" [r121]
I181203 10:35:13.613483 2189 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-27" [r122]
I181203 10:35:13.613648 2177 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-1" [r123]
I181203 10:35:13.615342 2235 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-3" [r124]
I181203 10:35:13.619271 2191 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-11" [r125]
I181203 10:35:13.619928 2188 storage/replica_command.go:349  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "key-12" [r126]
I181203 10:35:13.677407 2363 storage/replica_command.go:349  [n2,s2,r6/2:{/System/tse-key-34}] initiating a split of this range at key "key-31" [r141]
I181203 10:35:13.677414 2284 storage/replica_command.go:349  [n2,s2,r6/2:{/System/tse-key-34}] initiating a split of this range at key "key-10" [r142]
I181203 10:35:13.719174 2201 storage/replica_command.go:349  [n1,s1,r121/1:{key-34-/Table/Syste…}] initiating a split of this range at key "key-45" [r127]
I181203 10:35:13.721509 2202 storage/replica_command.go:349  [n1,s1,r121/1:{key-34-/Table/Syste…}] initiating a split of this range at key "key-78" [r128]
I181203 10:35:13.721708 2210 storage/replica_command.go:349  [n1,s1,r121/1:{key-34-/Table/Syste…}] initiating a split of this range at key "key-55" [r129]
I181203 10:35:13.723216 2200 storage/replica_command.go:349  [n1,s1,r121/1:{key-34-/Table/Syste…}] initiating a split of this range at key "key-41" [r130]
I181203 10:35:13.724439 2628 storage/replica_command.go:349  [n2,s2,r6/2:{/System/tse-key-34}] initiating a split of this range at key "key-17" [r143]
I181203 10:35:13.728568 2197 storage/replica_command.go:349  [n1,s1,r121/1:{key-34-/Table/Syste…}] initiating a split of this range at key "key-83" [r132]
I181203 10:35:13.730231 2473 storage/replica_command.go:349  [n2,s2,r6/2:{/System/tse-key-34}] initiating a split of this range at key "key-26" [r144]
I181203 10:35:13.746241 2693 storage/replica_command.go:492  [n1,merge,s1,r121/1:key-{34-45}] initiating a merge of r127:{key-45-/Table/SystemConfigSpan/Start} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=0] into this range
I181203 10:35:13.768346 2207 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-47" [r133]
I181203 10:35:13.773772 2808 storage/replica_command.go:349  [n2,s2,r6/2:{/System/tse-key-34}] initiating a split of this range at key "key-11" [r145]
I181203 10:35:13.787876 2210 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-55" [r134]
I181203 10:35:13.793675 2200 storage/replica_command.go:349  [n1,s1,r121/1:key-{34-45}] initiating a split of this range at key "key-41" [r135]
I181203 10:35:13.797292 2912 storage/replica_command.go:349  [n2,s2,r6/2:{/System/tse-key-34}] initiating a split of this range at key "key-12" [r146]
I181203 10:35:13.797793 2202 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-78" [r136]
I181203 10:35:13.800370 2197 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-83" [r137]
I181203 10:35:13.802741 2554 storage/replica_command.go:349  [n2,s2,r6/2:{/System/tse-key-34}] initiating a split of this range at key "key-1" [r147]
I181203 10:35:13.820985 2199 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-94" [r138]
I181203 10:35:13.821155 2196 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-95" [r139]
I181203 10:35:13.829229 2198 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-68" [r161]
I181203 10:35:13.840570 2175 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-64" [r162]
I181203 10:35:13.863685 2195 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-71" [r140]
I181203 10:35:13.879036 1265 gossip/gossip.go:1515  [n3] node has connected to cluster via gossip
I181203 10:35:13.908418 1265 storage/stores.go:261  [n3] wrote 2 node addresses to persistent storage
I181203 10:35:13.936225 2222 storage/replica_command.go:349  [n1,s1,r121/1:key-{34-45}] initiating a split of this range at key "key-86" [r131]; delayed split for 0.2s to avoid Raft snapshot
I181203 10:35:14.031050 3138 storage/replica_command.go:349  [n2,s2,r142/2:key-{10-34}] initiating a split of this range at key "key-17" [r150]
I181203 10:35:14.043753 3133 storage/replica_command.go:349  [n2,s2,r142/2:key-{10-34}] initiating a split of this range at key "key-26" [r152]
I181203 10:35:14.080531 2212 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-79" [r163]
I181203 10:35:14.080611 2073 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-59" [r164]
I181203 10:35:14.080627 2226 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-85" [r165]
I181203 10:35:14.081045 3032 storage/replica_command.go:349  [n2,s2,r6/2:{/System/tse-key-10}] initiating a split of this range at key "key-0" [r153]
I181203 10:35:14.081518 2990 storage/replica_command.go:349  [n2,s2,r142/2:key-1{0-7}] initiating a split of this range at key "key-11" [r154]
I181203 10:35:14.084896 2209 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-91" [r166]
I181203 10:35:14.086734 2215 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-9" [r167]
I181203 10:35:14.101877 3192 storage/replica_command.go:349  [n2,s2,r142/2:key-1{0-7}] initiating a split of this range at key "key-12" [r155]
I181203 10:35:14.103462 2176 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-7" [r168]
I181203 10:35:14.104859 2163 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-58" [r169]
I181203 10:35:14.105370 2973 storage/replica_command.go:349  [n2,s2,r6/2:{/System/tse-key-10}] initiating a split of this range at key "key-27" [r149]; delayed split for 0.2s to avoid Raft snapshot
I181203 10:35:14.105847 2221 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-73" [r170]
I181203 10:35:14.107841 2164 storage/replica_command.go:349  [n1,s1,r121/1:key-{34-45}] initiating a split of this range at key "key-44" [r171]
I181203 10:35:14.108337 2558 storage/replica_command.go:349  [n2,s2,r6/2:{/System/tse-key-10}] initiating a split of this range at key "key-3" [r148]; delayed split for 0.2s to avoid Raft snapshot
I181203 10:35:14.108612 2554 storage/replica_command.go:349  [n2,s2,r6/2:{/System/tse-key-10}] initiating a split of this range at key "key-1" [r156]
I181203 10:35:14.110074 2156 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-54" [r172]
I181203 10:35:14.113861 3198 storage/replica_command.go:349  [n2,s2,r142/2:key-1{0-7}] initiating a split of this range at key "key-15" [r157]
I181203 10:35:14.113999 3195 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-26" [r158]
I181203 10:35:14.114106 3197 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-25" [r159]
I181203 10:35:14.114130 3196 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-21" [r160]
I181203 10:35:14.119964 2193 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-46" [r173]
I181203 10:35:14.122367 2800 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-23" [r181]
I181203 10:35:14.124086 2160 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-84" [r174]
I181203 10:35:14.130105 2171 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-65" [r175]
I181203 10:35:14.130200 2076 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-5" [r176]
I181203 10:35:14.130564 2224 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-92" [r177]
I181203 10:35:14.137427 2152 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-69" [r178]
I181203 10:35:14.137603 2173 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-6" [r179]
I181203 10:35:14.138609 2220 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-87" [r180]
I181203 10:35:14.145903 3253 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-33" [r182]
I181203 10:35:14.146081 2162 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-62" [r193]
I181203 10:35:14.146264 2233 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-72" [r191]
I181203 10:35:14.146389 3252 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-24" [r183]
I181203 10:35:14.146411 2169 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-81" [r192]
I181203 10:35:14.147995 2165 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-77" [r194]
I181203 10:35:14.148011 2155 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-56" [r195]
I181203 10:35:14.152324 2206 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-75" [r196]
I181203 10:35:14.153858 2181 storage/replica_command.go:349  [n1,s1,r121/1:key-{34-45}] initiating a split of this range at key "key-35" [r197]
I181203 10:35:14.156842 2166 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-48" [r198]
I181203 10:35:14.157212 2208 storage/replica_command.go:349  [n1,s1,r121/1:key-{34-45}] initiating a split of this range at key "key-37" [r199]
I181203 10:35:14.157554 2182 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-57" [r200]
I181203 10:35:14.157756 2146 storage/replica_command.go:349  [n1,s1,r121/1:key-{34-45}] initiating a split of this range at key "key-36" [r202]
I181203 10:35:14.173201 2150 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-51" [r201]
I181203 10:35:14.173264 2151 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-82" [r203]
I181203 10:35:14.176955 2075 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-52" [r204]
I181203 10:35:14.179085 2079 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-96" [r205]
I181203 10:35:14.184930 2229 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-74" [r207]
I181203 10:35:14.185065 2172 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-76" [r206]
I181203 10:35:14.185077 2228 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-80" [r210]
I181203 10:35:14.185155 2154 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-61" [r208]
I181203 10:35:14.185160 2219 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-8" [r209]
I181203 10:35:14.234417 2732 storage/replica_command.go:349  [n2,s2,r142/2:key-1{0-1}] initiating a split of this range at key "key-31" [r151]; delayed split for 0.2s to avoid Raft snapshot
I181203 10:35:14.236114 3005 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-22" [r184]
I181203 10:35:14.236946 3224 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-2" [r185]
I181203 10:35:14.238217 3223 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-28" [r186]
I181203 10:35:14.238821 3225 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-29" [r187]
I181203 10:35:14.238911 3363 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-32" [r188]
I181203 10:35:14.239099 2736 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-19" [r189]
I181203 10:35:14.239765 2149 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-50" [r212]
I181203 10:35:14.239850 2234 storage/replica_command.go:349  [n1,s1,r121/1:key-{34-45}] initiating a split of this range at key "key-4" [r213]
I181203 10:35:14.240169 3364 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-20" [r190]
I181203 10:35:14.240192 2081 storage/replica_command.go:349  [n1,s1,r121/1:key-{34-45}] initiating a split of this range at key "key-38" [r214]
I181203 10:35:14.240337 2217 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-67" [r218]
I181203 10:35:14.240488 2230 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-89" [r216]
I181203 10:35:14.240677 2147 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-99" [r215]
I181203 10:35:14.241212 2074 storage/replica_command.go:349  [n1,s1,r121/1:key-{34-45}] initiating a split of this range at key "key-40" [r220]
I181203 10:35:14.241395 2214 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-97" [r219]
I181203 10:35:14.241417 2213 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-70" [r217]
I181203 10:35:14.241898 2161 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-93" [r211]
I181203 10:35:14.249383 2077 storage/replica_command.go:349  [n1,s1,r121/1:key-{34-45}] initiating a split of this range at key "key-39" [r230]
I181203 10:35:14.249708 2159 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-90" [r224]
I181203 10:35:14.249745 2223 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-88" [r227]
I181203 10:35:14.249867 2178 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-98" [r228]
I181203 10:35:14.249935 2211 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-60" [r225]
I181203 10:35:14.250087 2078 storage/replica_command.go:349  [n1,s1,r121/1:key-{34-45}] initiating a split of this range at key "key-42" [r226]
I181203 10:35:14.250132 2153 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-49" [r229]
I181203 10:35:14.250359 2194 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-66" [r222]
I181203 10:35:14.250526 2186 storage/replica_command.go:349  [n1,s1,r121/1:key-{34-45}] initiating a split of this range at key "key-43" [r221]
I181203 10:35:14.250701 3022 storage/replica_command.go:349  [n2,s2,r154/2:key-1{1-7}] initiating a split of this range at key "key-12" [r238]
I181203 10:35:14.250863 3321 storage/replica_command.go:349  [n2,s2,r154/2:key-1{1-7}] initiating a split of this range at key "key-16" [r234]
I181203 10:35:14.250929 3320 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-27" [r235]
I181203 10:35:14.250943 3226 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-3" [r231]
I181203 10:35:14.250992 3365 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-18" [r232]
I181203 10:35:14.251105 3270 storage/replica_command.go:349  [n2,s2,r154/2:key-1{1-7}] initiating a split of this range at key "key-15" [r233]
I181203 10:35:14.251183 3287 storage/replica_command.go:349  [n2,s2,r154/2:key-1{1-7}] initiating a split of this range at key "key-14" [r237]
I181203 10:35:14.251237 2846 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-30" [r236]
I181203 10:35:14.251966 3399 storage/replica_command.go:349  [n2,s2,r154/2:key-1{1-7}] initiating a split of this range at key "key-13" [r239]
I181203 10:35:14.252999 2218 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-53" [r223]
I181203 10:35:14.308018 3288 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-34}] initiating a split of this range at key "key-31" [r240]
I181203 10:35:14.331960 3461 storage/replica_command.go:349  [n2,s2,r153/2:key-{0-10}] initiating a split of this range at key "key-1" [r251]
I181203 10:35:14.338606 3072 storage/replica_command.go:349  [n2,s2,r237/2:key-1{4-7}] initiating a split of this range at key "key-16" [r252]
I181203 10:35:14.339532 3477 storage/replica_command.go:349  [n2,s2,r237/2:key-1{4-7}] initiating a split of this range at key "key-15" [r253]
I181203 10:35:14.375064 3197 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-26}] initiating a split of this range at key "key-25" [r254]
I181203 10:35:14.377935 2800 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-26}] initiating a split of this range at key "key-23" [r255]
I181203 10:35:14.378429 3224 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-26}] initiating a split of this range at key "key-2" [r256]
I181203 10:35:14.378587 3252 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-26}] initiating a split of this range at key "key-24" [r257]
I181203 10:35:14.379292 3541 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-34}] initiating a split of this range at key "key-31" [r258]
I181203 10:35:14.381992 3574 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-34}] initiating a split of this range at key "key-3" [r259]
I181203 10:35:14.382164 3022 storage/replica_command.go:349  [n2,s2,r154/2:key-1{1-4}] initiating a split of this range at key "key-12" [r260]
I181203 10:35:14.386258 3399 storage/replica_command.go:349  [n2,s2,r154/2:key-1{1-4}] initiating a split of this range at key "key-13" [r262]
I181203 10:35:14.386337 3527 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-34}] initiating a split of this range at key "key-33" [r263]
I181203 10:35:14.386426 3404 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-34}] initiating a split of this range at key "key-28" [r265]
I181203 10:35:14.386608 3005 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-26}] initiating a split of this range at key "key-22" [r264]
I181203 10:35:14.386262 3196 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-26}] initiating a split of this range at key "key-21" [r261]
I181203 10:35:14.387591 3365 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-26}] initiating a split of this range at key "key-18" [r266]
I181203 10:35:14.388679 3364 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-26}] initiating a split of this range at key "key-20" [r267]
I181203 10:35:14.389179 2736 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-26}] initiating a split of this range at key "key-19" [r268]
I181203 10:35:14.389530 3589 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-34}] initiating a split of this range at key "key-32" [r269]
I181203 10:35:14.389582 3588 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-34}] initiating a split of this range at key "key-27" [r270]
I181203 10:35:14.432042 3388 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-34}] initiating a split of this range at key "key-30" [r272]
I181203 10:35:14.435646 3453 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-34}] initiating a split of this range at key "key-29" [r271]
I181203 10:35:14.502729 933 gossip/gossip.go:1515  [n2] node has connected to cluster via gossip
I181203 10:35:14.502912 933 storage/stores.go:261  [n2] wrote 2 node addresses to persistent storage
I181203 10:35:14.521435 3574 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-31}] initiating a split of this range at key "key-3" [r273]
I181203 10:35:14.526608 3477 storage/replica_command.go:349  [n2,s2,r237/2:key-1{4-6}] initiating a split of this range at key "key-15" [r274]
I181203 10:35:14.536495 3756 storage/replica_command.go:349  [n2,s2,r258/2:key-3{1-4}] initiating a split of this range at key "key-33" [r275]
I181203 10:35:14.536734 3608 storage/replica_command.go:349  [n2,s2,r258/2:key-3{1-4}] initiating a split of this range at key "key-32" [r276]
I181203 10:35:14.539407 3588 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-31}] initiating a split of this range at key "key-27" [r277]
I181203 10:35:14.539410 3388 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-31}] initiating a split of this range at key "key-30" [r278]
I181203 10:35:14.539427 3404 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-31}] initiating a split of this range at key "key-28" [r279]
I181203 10:35:14.539541 3453 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-31}] initiating a split of this range at key "key-29" [r280]
I181203 10:35:14.585209 2800 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-25}] initiating a split of this range at key "key-23" [r281]
I181203 10:35:14.589535 3364 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-25}] initiating a split of this range at key "key-20" [r282]
I181203 10:35:14.589914 3005 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-25}] initiating a split of this range at key "key-22" [r283]
I181203 10:35:14.590964 3224 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-25}] initiating a split of this range at key "key-2" [r284]
I181203 10:35:14.591900 3365 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-25}] initiating a split of this range at key "key-18" [r285]
I181203 10:35:14.593104 3196 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-25}] initiating a split of this range at key "key-21" [r286]
I181203 10:35:14.634908 3252 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-25}] initiating a split of this range at key "key-24" [r287]
I181203 10:35:14.636041 2736 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-25}] initiating a split of this range at key "key-19" [r289]
I181203 10:35:14.637936 3739 storage/replica_command.go:349  [n2,s2,r260/2:key-1{2-4}] initiating a split of this range at key "key-13" [r290]
I181203 10:35:14.658437 3608 storage/replica_command.go:349  [n2,s2,r258/2:key-3{1-3}] initiating a split of this range at key "key-32" [r288]
I181203 10:35:14.679775 3453 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-3}] initiating a split of this range at key "key-29" [r291]
I181203 10:35:14.693436 3588 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-3}] initiating a split of this range at key "key-27" [r292]
I181203 10:35:14.696862 3404 storage/replica_command.go:349  [n2,s2,r158/2:key-{26-3}] initiating a split of this range at key "key-28" [r293]
I181203 10:35:14.700252 4067 storage/replica_command.go:349  [n2,s2,r273/2:key-3{-1}] initiating a split of this range at key "key-30" [r294]
I181203 10:35:14.909900 3364 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-23}] initiating a split of this range at key "key-20" [r295]
I181203 10:35:14.918946 3853 storage/replica_command.go:349  [n2,s2,r281/2:key-2{3-5}] initiating a split of this range at key "key-24" [r296]
I181203 10:35:14.919132 3404 storage/replica_command.go:349  [n2,s2,r158/2:key-2{6-9}] initiating a split of this range at key "key-28" [r297]
I181203 10:35:14.923594 3196 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-23}] initiating a split of this range at key "key-21" [r298]
I181203 10:35:14.930920 3224 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-23}] initiating a split of this range at key "key-2" [r299]
I181203 10:35:14.934937 3588 storage/replica_command.go:349  [n2,s2,r158/2:key-2{6-9}] initiating a split of this range at key "key-27" [r300]
I181203 10:35:14.942319 3365 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-23}] initiating a split of this range at key "key-18" [r301]
I181203 10:35:14.976741 2736 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-23}] initiating a split of this range at key "key-19" [r302]
I181203 10:35:14.999980 3005 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-23}] initiating a split of this range at key "key-22" [r303]
I181203 10:35:15.360874 4174 storage/replica_command.go:349  [n2,s2,r295/2:key-2{0-3}] initiating a split of this range at key "key-21" [r304]
I181203 10:35:15.376020 3224 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-20}] initiating a split of this range at key "key-2" [r305]
I181203 10:35:15.387137 4521 storage/replica_command.go:349  [n2,s2,r304/2:key-2{1-3}] initiating a split of this range at key "key-22" [r306]
I181203 10:35:15.419272 2736 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-2}] initiating a split of this range at key "key-19" [r307]
I181203 10:35:15.431534 3365 storage/replica_command.go:349  [n2,s2,r150/2:key-{17-2}] initiating a split of this range at key "key-18" [r308]
I181203 10:35:15.524181 3588 storage/replica_command.go:349  [n2,s2,r158/2:key-2{6-8}] initiating a split of this range at key "key-27" [r309]
I181203 10:35:16.330626 3365 storage/replica_command.go:349  [n2,s2,r150/2:key-1{7-9}] initiating a split of this range at key "key-18" [r310]
I181203 10:35:20.282093 2108 storage/replica_command.go:492  [n2,merge,s2,r6/2:{/System/tse-key-0}] initiating a merge of r121:key-{34-45} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=1] into this range
I181203 10:35:20.288672 7476 storage/replica_command.go:492  [n2,merge,s2,r142/2:key-1{0-1}] initiating a merge of r154:key-1{1-2} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=2] into this range
E181203 10:35:20.289405 2218 storage/replica.go:7004  [n1,s1,r10/1:/Table/1{3-4}] stalling replica due to: range does not match splits: ("key-45"-"key-53") + ("key-53"-/Table/SystemConfigSpan/Start) != [n1,s1,r10/1:/Table/1{3-4}]
W181203 10:35:20.289632 2218 internal/client/txn.go:532  [n1,s1,r127/1:{key-45-/Table/Syste…}] failure aborting transaction: replica corruption (processed=true): range does not match splits: ("key-45"-"key-53") + ("key-53"-/Table/SystemConfigSpan/Start) != [n1,s1,r10/1:/Table/1{3-4}]; abort caused by: replica corruption (processed=true): range does not match splits: ("key-45"-"key-53") + ("key-53"-/Table/SystemConfigSpan/Start) != [n1,s1,r10/1:/Table/1{3-4}]
W181203 10:35:20.302629 7412 storage/intent_resolver.go:745  [n2,s2] failed to cleanup transaction intents: failed to resolve intents: replica corruption (processed=true): range does not match splits: ("key-45"-"key-53") + ("key-53"-/Table/SystemConfigSpan/Start) != [n1,s1,r10/1:/Table/1{3-4}]
I181203 10:35:20.819753 7603 storage/replica_consistency.go:127  [n1,consistencyChecker,s1,r5/1:/System/ts{d-e}] triggering stats recomputation to resolve delta of {ContainsEstimates:true LastUpdateNanos:1543833312931218590 IntentAge:0 GCBytesAge:0 LiveBytes:-44604 LiveCount:-932 KeyBytes:-43414 KeyCount:-932 ValBytes:-1190 ValCount:-932 IntentBytes:0 IntentCount:0 SysBytes:0 SysCount:0}
I181203 10:35:21.288788 8202 storage/replica_command.go:492  [n2,merge,s2,r150/2:key-1{7-8}] initiating a merge of r310:key-1{8-9} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4, gen=0] into this range
I181203 10:35:21.410775 542 server/status/runtime.go:465  [n1] runtime stats: 178 MiB RSS, 1094 goroutines, 43 MiB/22 MiB/105 MiB GO alloc/idle/total, 59 MiB/81 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (29x), 111 MiB/111 MiB (r/w)net
W181203 10:35:21.530677 544 server/node.go:886  [n1,summaries] health alerts detected: {Alerts:[{StoreID:1 Category:METRICS Description:queue.replicate.process.failure Value:81} {StoreID:1 Category:METRICS Description:queue.split.process.failure Value:1}]}
I181203 10:35:21.727082 2222 storage/replica_command.go:349  [n1,s1,r127/1:{key-45-/Table/Syste…}] initiating a split of this range at key "key-86" [r241]
I181203 10:35:22.024806 8715 util/stop/stopper.go:537  quiescing; tasks left:
2      [async] closedts-subscription
1      [async] closedts-rangefeed-subscriber
I181203 10:35:22.025251 8713 util/stop/stopper.go:537  quiescing; tasks left:
2      [async] closedts-subscription
1      [async] closedts-rangefeed-subscriber
I181203 10:35:22.025381 8714 util/stop/stopper.go:537  quiescing; tasks left:
2      [async] closedts-subscription
1      [async] closedts-rangefeed-subscriber
W181203 10:35:22.027801 1699 storage/raft_transport.go:584  [n1] while processing outgoing Raft queue to node 2: rpc error: code = Unavailable desc = transport is closing:
W181203 10:35:22.028001 1706 storage/raft_transport.go:584  [n1] while processing outgoing Raft queue to node 3: rpc error: code = Unavailable desc = transport is closing:
W181203 10:35:22.029217 1675 storage/raft_transport.go:584  [n3] while processing outgoing Raft queue to node 1: rpc error: code = Canceled desc = context canceled:
W181203 10:35:22.029273 1265 gossip/gossip.go:1501  [n3] no incoming or outgoing connections
W181203 10:35:22.029397 3043 storage/raft_transport.go:584  [n3] while processing outgoing Raft queue to node 2: rpc error: code = Canceled desc = context canceled:
W181203 10:35:22.031575 933 gossip/gossip.go:1501  [n2] no incoming or outgoing connections
W181203 10:35:22.032213 1642 storage/raft_transport.go:584  [n2] while processing outgoing Raft queue to node 1: EOF:
W181203 10:35:22.035646 2926 storage/raft_transport.go:584  [n2] while processing outgoing Raft queue to node 3: rpc error: code = Canceled desc = context canceled:
I181203 10:35:22.035911 8715 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] closedts-subscription
1      [async] closedts-rangefeed-subscriber
I181203 10:35:22.035944 8715 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] closedts-subscription
I181203 10:35:22.044924 8714 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] closedts-subscription
1      [async] closedts-rangefeed-subscriber
I181203 10:35:22.044993 8714 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] closedts-subscription
I181203 10:35:22.045044 8713 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] closedts-subscription
1      [async] closedts-rangefeed-subscriber
I181203 10:35:22.045061 8713 util/stop/stopper.go:537  quiescing; tasks left:
1      [async] closedts-subscription
I181203 10:35:22.064903 8561 rpc/nodedialer/nodedialer.go:91  [ct-client] unable to connect to n2: context canceled
I181203 10:35:22.064967 8722 rpc/nodedialer/nodedialer.go:91  [ct-client] unable to connect to n1: context canceled
--- FAIL: TestSplitTriggerRaftSnapshotRace (10.79s)
	client_split_test.go:562: "key-53": split unexpected error: split at key "key-53" failed: replica corruption (processed=true): range does not match splits: ("key-45"-"key-53") + ("key-53"-/Table/SystemConfigSpan/Start) != [n1,s1,r10/1:/Table/1{3-4}]
FAIL