Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

teamcity: failed tests on master: testrace/TestBackupRestoreResume, test/TestBackupRestoreResume #26050

Closed
cockroach-teamcity opened this issue May 24, 2018 · 2 comments
Closed

teamcity: failed tests on master: testrace/TestBackupRestoreResume, test/TestBackupRestoreResume #26050

cockroach-teamcity opened this issue May 24, 2018 · 2 comments
Assignees
@windchan7
Labels
A-kv-client Relating to the KV client and the KV interface. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone
2.1

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed:

#678069:

--- FAIL: testrace/TestBackupRestoreResume (0.000s)
Test ended in panic.

------- Stdout: -------
I180524 18:46:55.696151 45481 server/server.go:784  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180524 18:46:55.727979 45481 server/config.go:539  [n?] 1 storage engine initialized
I180524 18:46:55.728253 45481 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180524 18:46:55.728322 45481 server/config.go:542  [n?] store 0: in-memory, size 0 B
I180524 18:46:55.893698 45481 server/node.go:376  [n?] **** cluster 52384ad8-2b75-485e-8c7c-42c07549834f has been created
I180524 18:46:55.893958 45481 server/server.go:1358  [n?] **** add additional nodes by specifying --join=127.0.0.1:40409
I180524 18:46:55.945685 45481 storage/store.go:1450  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180524 18:46:55.946616 45481 server/node.go:506  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=0, writes=0.00, bytesPerReplica={p10=7043.00 p25=7043.00 p50=7043.00 p75=7043.00 p90=7043.00 pMax=7043.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180524 18:46:55.962408 45481 server/node.go:354  [n1] node ID 1 initialized
I180524 18:46:55.963025 45481 gossip/gossip.go:333  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:40409" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:5 > 
I180524 18:46:55.972629 45481 storage/stores.go:222  [n1] read 0 node addresses from persistent storage
I180524 18:46:55.997680 45481 server/node.go:647  [n1] connecting to gossip network to verify cluster ID...
I180524 18:46:55.998104 45481 server/node.go:672  [n1] node connected via gossip and verified as part of cluster "52384ad8-2b75-485e-8c7c-42c07549834f"
I180524 18:46:55.998652 45481 server/node.go:440  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180524 18:46:56.007942 45481 server/server.go:1485  [n1] starting https server at 127.0.0.1:37215
I180524 18:46:56.009063 45481 server/server.go:1486  [n1] starting grpc/postgres server at 127.0.0.1:40409
I180524 18:46:56.009150 45481 server/server.go:1487  [n1] advertising CockroachDB node at 127.0.0.1:40409
W180524 18:46:56.019751 45481 sql/jobs/registry.go:287  [n1] unable to get node liveness: node not in the liveness table
I180524 18:46:56.033465 45412 storage/replica_command.go:863  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180524 18:46:56.620527 45716 storage/replica_command.go:863  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
W180524 18:46:56.699877 45762 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "sql txn" id=c4eed24c key=/Table/SystemConfigSpan/Start rw=true pri=0.01096427 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527187616.094803350,0 orig=1527187616.094803350,0 max=1527187616.094803350,0 wto=false rop=false seq=7
I180524 18:46:56.928081 45456 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180524 18:46:56.963932 45733 storage/replica_command.go:863  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180524 18:46:57.247491 45743 storage/replica_command.go:863  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180524 18:46:57.497459 45796 storage/replica_command.go:863  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
I180524 18:46:57.772283 45827 storage/replica_command.go:863  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
W180524 18:46:57.810723 45729 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "sql txn" id=5fb1a72e key=/Table/SystemConfigSpan/Start rw=true pri=0.03640540 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527187617.129352303,0 orig=1527187617.129352303,0 max=1527187617.129352303,0 wto=false rop=false seq=15
I180524 18:46:57.888248 45739 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
I180524 18:46:58.025349 45817 storage/replica_command.go:863  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180524 18:46:58.375927 45828 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180524 18:46:58.391118 45851 storage/replica_command.go:863  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180524 18:46:58.605045 45841 storage/replica_command.go:863  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180524 18:46:58.925215 45854 storage/replica_command.go:863  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180524 18:46:58.955588 45761 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:root}
I180524 18:46:59.077990 45915 storage/replica_command.go:863  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180524 18:46:59.127134 45882 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}
I180524 18:46:59.239973 45974 storage/replica_command.go:863  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180524 18:46:59.407716 45965 storage/replica_command.go:863  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180524 18:46:59.469367 45989 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}
I180524 18:46:59.498660 45481 server/server.go:1564  [n1] done ensuring all necessary migrations have run
I180524 18:46:59.498950 45481 server/server.go:1567  [n1] serving sql connections
I180524 18:46:59.627767 45983 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:40409} Attrs: Locality: ServerVersion:2.0-5} ClusterID:52384ad8-2b75-485e-8c7c-42c07549834f StartedAt:1527187615998250878 LastUp:1527187615998250878}
I180524 18:46:59.667731 45981 server/server_update.go:66  [n1] no need to upgrade, cluster already at the newest version
I180524 18:46:59.706393 46000 storage/replica_command.go:863  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180524 18:47:00.002014 45900 storage/replica_command.go:863  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180524 18:47:00.226492 46082 storage/replica_command.go:863  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180524 18:47:00.349905 46040 storage/replica_command.go:863  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
W180524 18:47:00.458347 46116 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=04f2984e key=/Local/Range/Table/20/RangeDescriptor rw=true pri=0.02216040 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527187620.351905748,1 orig=1527187620.350148559,0 max=1527187620.350148559,0 wto=false rop=false seq=3
I180524 18:47:00.536600 46105 storage/replica_command.go:863  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180524 18:47:00.658299 46091 storage/replica_command.go:863  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180524 18:47:00.835431 46154 storage/replica_command.go:863  [split,n1,s1,r20/1:/{Table/23-Max}] initiating a split of this range at key /Table/50 [r21]
W180524 18:47:00.967726 46108 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=598bf73c key=/Local/Range/Table/23/RangeDescriptor rw=true pri=0.01390791 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527187620.900958931,1 orig=1527187620.835679889,0 max=1527187620.835679889,0 wto=false rop=false seq=3
W180524 18:47:00.970893 46074 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=598bf73c key=/Local/Range/Table/23/RangeDescriptor rw=true pri=0.01390791 iso=SERIALIZABLE stat=PENDING epo=0 ts=1527187620.900958931,1 orig=1527187620.835679889,0 max=1527187620.835679889,0 wto=false rop=false seq=3
I180524 18:47:01.028767 46158 storage/replica_command.go:863  [split,n1,s1,r21/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r22]
I180524 18:47:02.337741 45481 server/server.go:784  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180524 18:47:02.440901 45481 server/config.go:539  [n?] 1 storage engine initialized
I180524 18:47:02.441110 45481 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180524 18:47:02.441154 45481 server/config.go:542  [n?] store 0: in-memory, size 0 B
W180524 18:47:02.441596 45481 gossip/gossip.go:1293  [n?] no incoming or outgoing connections
I180524 18:47:02.481656 45481 server/server.go:1360  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180524 18:47:02.890504 46181 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:40409
I180524 18:47:02.899895 46325 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:37909}
I180524 18:47:02.912119 45481 storage/stores.go:222  [n?] read 0 node addresses from persistent storage
I180524 18:47:02.920745 45481 server/node.go:647  [n?] connecting to gossip network to verify cluster ID...
I180524 18:47:02.921912 46327 storage/stores.go:241  [n?] wrote 1 node addresses to persistent storage
I180524 18:47:02.925658 45481 server/node.go:672  [n?] node connected via gossip and verified as part of cluster "52384ad8-2b75-485e-8c7c-42c07549834f"
I180524 18:47:02.987715 45481 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180524 18:47:02.999660 45481 server/node.go:347  [n?] new node allocated ID 2
I180524 18:47:03.000477 45481 gossip/gossip.go:333  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:37909" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:5 > 
I180524 18:47:03.009381 45481 server/node.go:421  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180524 18:47:03.010546 45481 server/node.go:440  [n2] node=2: started with [] engine(s) and attributes []
I180524 18:47:03.020842 46183 storage/stores.go:241  [n1] wrote 1 node addresses to persistent storage
I180524 18:47:03.039506 45481 server/server.go:1485  [n2] starting https server at 127.0.0.1:39735
I180524 18:47:03.039813 45481 server/server.go:1486  [n2] starting grpc/postgres server at 127.0.0.1:37909
I180524 18:47:03.039894 45481 server/server.go:1487  [n2] advertising CockroachDB node at 127.0.0.1:37909
W180524 18:47:03.040272 45481 sql/jobs/registry.go:287  [n2] unable to get node liveness: node not in the liveness table
I180524 18:47:03.062529 45481 server/server.go:1564  [n2] done ensuring all necessary migrations have run
I180524 18:47:03.062882 45481 server/server.go:1567  [n2] serving sql connections
I180524 18:47:03.363514 46342 server/node.go:628  [n2] bootstrapped store [n2,s2]
I180524 18:47:03.648006 46301 server/server_update.go:66  [n2] no need to upgrade, cluster already at the newest version
I180524 18:47:03.717512 46303 sql/event_log.go:126  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:37909} Attrs: Locality: ServerVersion:2.0-5} ClusterID:52384ad8-2b75-485e-8c7c-42c07549834f StartedAt:1527187623009820603 LastUp:1527187623009820603}
I180524 18:47:03.982834 45481 server/server.go:784  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180524 18:47:04.056766 45481 server/config.go:539  [n?] 1 storage engine initialized
I180524 18:47:04.056970 45481 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180524 18:47:04.057020 45481 server/config.go:542  [n?] store 0: in-memory, size 0 B
W180524 18:47:04.059421 45481 gossip/gossip.go:1293  [n?] no incoming or outgoing connections
I180524 18:47:04.063420 45481 server/server.go:1360  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180524 18:47:04.404101 46551 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:40409
I180524 18:47:04.407976 46655 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:37193}
I180524 18:47:04.418903 45481 storage/stores.go:222  [n?] read 0 node addresses from persistent storage
I180524 18:47:04.433880 45481 storage/stores.go:241  [n?] wrote 1 node addresses to persistent storage
I180524 18:47:04.435322 45481 server/node.go:647  [n?] connecting to gossip network to verify cluster ID...
I180524 18:47:04.435631 45481 server/node.go:672  [n?] node connected via gossip and verified as part of cluster "52384ad8-2b75-485e-8c7c-42c07549834f"
I180524 18:47:04.451320 46537 storage/stores.go:241  [n?] wrote 2 node addresses to persistent storage
I180524 18:47:04.469494 45635 storage/replica_proposal.go:202  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.457276209,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:04.488351 45636 storage/replica_proposal.go:202  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.477713031,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:04.491947 45639 storage/replica_proposal.go:202  [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.485180112,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:04.495206 45481 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180524 18:47:04.503551 45637 storage/replica_proposal.go:202  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.498903016,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:04.535660 45646 storage/replica_proposal.go:202  [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.507615682,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:04.563438 45481 server/node.go:347  [n?] new node allocated ID 3
I180524 18:47:04.564307 45481 gossip/gossip.go:333  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:37193" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:5 > 
I180524 18:47:04.565580 45481 server/node.go:421  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180524 18:47:04.566361 45481 server/node.go:440  [n3] node=3: started with [] engine(s) and attributes []
I180524 18:47:04.573864 45481 server/server.go:1485  [n3] starting https server at 127.0.0.1:42649
I180524 18:47:04.574043 45481 server/server.go:1486  [n3] starting grpc/postgres server at 127.0.0.1:37193
I180524 18:47:04.574121 45481 server/server.go:1487  [n3] advertising CockroachDB node at 127.0.0.1:37193
I180524 18:47:04.582366 45643 storage/replica_proposal.go:202  [n1,s1,r20/1:/Table/{23-50}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.554185221,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:04.611862 46738 storage/stores.go:241  [n1] wrote 2 node addresses to persistent storage
I180524 18:47:04.615944 45650 storage/replica_proposal.go:202  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.605611213,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:04.639131 46757 storage/stores.go:241  [n2] wrote 2 node addresses to persistent storage
I180524 18:47:04.652315 45654 storage/replica_proposal.go:202  [n1,s1,r22/1:/{Table/51-Max}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.630884280,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:04.661201 45481 server/server.go:1564  [n3] done ensuring all necessary migrations have run
I180524 18:47:04.681992 45481 server/server.go:1567  [n3] serving sql connections
I180524 18:47:04.747687 45659 storage/replica_proposal.go:202  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.686690486,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:04.751217 45661 storage/replica_proposal.go:202  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.713220589,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:04.798306 45663 storage/replica_proposal.go:202  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.770047238,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:04.848286 46639 server/node.go:628  [n3] bootstrapped store [n3,s3]
I180524 18:47:04.958389 45662 storage/replica_proposal.go:202  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.869600295,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:04.987557 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot c6619af5 at index 18
I180524 18:47:04.999015 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 10ms
I180524 18:47:05.002463 46702 storage/replica_raftstorage.go:730  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 18 (id=c6619af5, encoded size=2417, 1 rocksdb batches, 8 log entries)
I180524 18:47:05.011948 46702 storage/replica_raftstorage.go:736  [n2,s2,r11/?:/Table/1{4-5}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=4ms commit=1ms]
I180524 18:47:05.023494 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:05.026399 45711 storage/replica_command.go:1777  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, next=2]
I180524 18:47:05.026654 45670 storage/replica_proposal.go:202  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187624.981355844,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:05.147318 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:05.158045 45620 storage/replica_proposal.go:202  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187625.153221602,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:05.227079 46913 storage/store.go:2492  [replicaGC,n2,s2,r11/?:/Table/1{4-5}] removing replica
I180524 18:47:05.229357 46913 storage/replica.go:829  [replicaGC,n2,s2,r11/?:/Table/1{4-5}] removed 6 (0+6) keys in 1ms [clear=0ms commit=1ms]
I180524 18:47:05.233493 46762 server/server_update.go:66  [n3] no need to upgrade, cluster already at the newest version
I180524 18:47:05.243465 46764 sql/event_log.go:126  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:37193} Attrs: Locality: ServerVersion:2.0-5} ClusterID:52384ad8-2b75-485e-8c7c-42c07549834f StartedAt:1527187624565974146 LastUp:1527187624565974146}
I180524 18:47:05.284103 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:05.316444 45625 storage/replica_proposal.go:202  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187625.301964471,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:05.389618 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:05.391997 45711 storage/replica.go:3320  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180524 18:47:05.413624 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot 5d7b235e at index 18
I180524 18:47:05.428463 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 14ms
I180524 18:47:05.434561 46973 storage/replica_raftstorage.go:730  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 18 (id=5d7b235e, encoded size=2580, 1 rocksdb batches, 8 log entries)
I180524 18:47:05.438252 46973 storage/replica_raftstorage.go:736  [n2,s2,r15/?:/Table/1{8-9}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180524 18:47:05.444076 45711 storage/replica_command.go:1777  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, next=2]
E180524 18:47:05.451969 46975 storage/queue.go:778  [replicaGC,n2,s2,r11/2:{-}] cannot process uninitialized replica
I180524 18:47:05.456524 47045 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180524 18:47:05.471418 47074 storage/replica_raftstorage.go:520  [raftsnapshot,n1,s1,r11/1:/Table/1{4-5}] generated Raft snapshot 3bbfa064 at index 20
I180524 18:47:05.503112 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:05.518991 45711 storage/replica.go:3320  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180524 18:47:05.526313 47074 storage/store_snapshot.go:605  [raftsnapshot,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n2,s2):2: kv pairs: 10, log entries: 10, rate-limit: 8.0 MiB/sec, 54ms
I180524 18:47:05.533076 47077 storage/replica_raftstorage.go:730  [n2,s2,r11/2:{-}] applying Raft snapshot at index 20 (id=3bbfa064, encoded size=3776, 1 rocksdb batches, 10 log entries)
I180524 18:47:05.549568 47077 storage/replica_raftstorage.go:736  [n2,s2,r11/2:/Table/1{4-5}] applied Raft snapshot in 16ms [clear=9ms batch=0ms entries=5ms commit=1ms]
I180524 18:47:05.569578 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot d571f9e1 at index 18
I180524 18:47:05.605857 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 35ms
I180524 18:47:05.606267 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:05.615087 47095 storage/replica_raftstorage.go:730  [n2,s2,r19/?:{-}] applying preemptive snapshot at index 18 (id=d571f9e1, encoded size=2417, 1 rocksdb batches, 8 log entries)
I180524 18:47:05.618434 47095 storage/replica_raftstorage.go:736  [n2,s2,r19/?:/Table/2{2-3}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180524 18:47:05.637769 45711 storage/replica_command.go:1777  [replicate,n1,s1,r19/1:/Table/2{2-3}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, next=2]
I180524 18:47:05.782567 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:05.811985 45711 storage/replica.go:3320  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180524 18:47:05.875088 45664 storage/replica_proposal.go:202  [n1,s1,r21/1:/Table/5{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187625.862393589,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:05.898260 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:05.900454 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r21/1:/Table/5{0-1}] generated preemptive snapshot cee8a4a6 at index 18
I180524 18:47:05.906552 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r21/1:/Table/5{0-1}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 5ms
I180524 18:47:05.916853 47105 storage/replica_raftstorage.go:730  [n2,s2,r21/?:{-}] applying preemptive snapshot at index 18 (id=cee8a4a6, encoded size=2394, 1 rocksdb batches, 8 log entries)
I180524 18:47:05.920019 47105 storage/replica_raftstorage.go:736  [n2,s2,r21/?:/Table/5{0-1}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180524 18:47:05.925463 45711 storage/replica_command.go:1777  [replicate,n1,s1,r21/1:/Table/5{0-1}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r21:/Table/5{0-1} [(n1,s1):1, next=2]
I180524 18:47:06.032989 45614 server/status/runtime.go:219  [n1] runtime stats: 1.4 GiB RSS, 586 goroutines, 40 MiB/97 MiB/162 MiB GO alloc/idle/total, 76 MiB/115 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (244x)
I180524 18:47:06.035031 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:06.113643 45711 storage/replica.go:3320  [n1,s1,r21/1:/Table/5{0-1}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180524 18:47:06.139164 45619 storage/replica_proposal.go:202  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187626.126477955,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:06.162549 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:06.163737 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot 5a83d907 at index 18
I180524 18:47:06.178902 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 14ms
I180524 18:47:06.181491 47149 storage/replica_raftstorage.go:730  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 18 (id=5a83d907, encoded size=2421, 1 rocksdb batches, 8 log entries)
I180524 18:47:06.184829 47149 storage/replica_raftstorage.go:736  [n2,s2,r18/?:/Table/2{1-2}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180524 18:47:06.192628 45711 storage/replica_command.go:1777  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, next=2]
I180524 18:47:06.302662 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:06.361834 45711 storage/replica.go:3320  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180524 18:47:06.433088 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot c475fd8e at index 85
I180524 18:47:06.434405 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:06.446304 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 60, log entries: 6, rate-limit: 8.0 MiB/sec, 12ms
I180524 18:47:06.449901 47038 storage/replica_raftstorage.go:730  [n2,s2,r1/?:{-}] applying preemptive snapshot at index 85 (id=c475fd8e, encoded size=3497, 1 rocksdb batches, 6 log entries)
I180524 18:47:06.453558 47038 storage/replica_raftstorage.go:736  [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=1ms]
I180524 18:47:06.491971 45711 storage/replica_command.go:1777  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r1:/{Min-System/} [(n1,s1):1, next=2]
I180524 18:47:06.572276 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:06.648237 45711 storage/replica.go:3320  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
W180524 18:47:06.650854 45616 server/node.go:802  [n1,summaries] health alerts detected: {Alerts:[{StoreID:1 Category:METRICS Description:ranges.underreplicated Value:22} {StoreID:1 Category:METRICS Description:queue.replicate.process.failure Value:295}]}
I180524 18:47:06.763260 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:06.804090 45650 storage/replica_proposal.go:202  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187626.711245981,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:06.818282 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot 1267e7c1 at index 19
I180524 18:47:06.834270 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 9, rate-limit: 8.0 MiB/sec, 15ms
I180524 18:47:06.837230 47315 storage/replica_raftstorage.go:730  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 19 (id=1267e7c1, encoded size=3649, 1 rocksdb batches, 9 log entries)
I180524 18:47:06.841011 47315 storage/replica_raftstorage.go:736  [n3,s3,r8/?:/Table/1{1-2}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180524 18:47:06.876241 45711 storage/replica_command.go:1777  [replicate,n1,s1,r8/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, next=2]
I180524 18:47:06.902448 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:07.021030 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:07.115283 45711 storage/replica.go:3320  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180524 18:47:07.188395 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 1e4f935d at index 27
I180524 18:47:07.208902 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:07.217596 47411 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180524 18:47:07.224149 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n3,s3):?: kv pairs: 13, log entries: 17, rate-limit: 8.0 MiB/sec, 35ms
I180524 18:47:07.232185 47394 storage/replica_raftstorage.go:730  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 27 (id=1e4f935d, encoded size=5604, 1 rocksdb batches, 17 log entries)
I180524 18:47:07.254132 47394 storage/replica_raftstorage.go:736  [n3,s3,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 22ms [clear=0ms batch=0ms entries=20ms commit=1ms]
I180524 18:47:07.294133 45711 storage/replica_command.go:1777  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, next=2]
I180524 18:47:07.365815 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:07.439854 45711 storage/replica.go:3320  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180524 18:47:07.449156 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 0d25386c at index 26
I180524 18:47:07.464278 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:07.517892 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n3,s3):?: kv pairs: 966, log entries: 3, rate-limit: 8.0 MiB/sec, 68ms
I180524 18:47:07.524908 47345 storage/replica_raftstorage.go:730  [n3,s3,r5/?:{-}] applying preemptive snapshot at index 26 (id=0d25386c, encoded size=190453, 1 rocksdb batches, 3 log entries)
I180524 18:47:07.595783 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:07.631552 47345 storage/replica_raftstorage.go:736  [n3,s3,r5/?:/System/ts{d-e}] applied preemptive snapshot in 106ms [clear=0ms batch=1ms entries=73ms commit=4ms]
I180524 18:47:07.642099 45711 storage/replica_command.go:1777  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, next=2]
I180524 18:47:07.706614 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:07.818765 45711 storage/replica.go:3320  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180524 18:47:07.828222 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot 100b9c27 at index 21
I180524 18:47:07.838099 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 11, rate-limit: 8.0 MiB/sec, 9ms
I180524 18:47:07.841607 47540 storage/replica_raftstorage.go:730  [n3,s3,r2/?:{-}] applying preemptive snapshot at index 21 (id=100b9c27, encoded size=5139, 1 rocksdb batches, 11 log entries)
I180524 18:47:07.848078 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:07.850058 47540 storage/replica_raftstorage.go:736  [n3,s3,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 8ms [clear=0ms batch=0ms entries=6ms commit=1ms]
I180524 18:47:07.878767 45711 storage/replica_command.go:1777  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, next=2]
I180524 18:47:07.953490 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:08.074707 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:08.099602 45711 storage/replica.go:3320  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180524 18:47:08.107467 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot e4bde28c at index 32
I180524 18:47:08.130371 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 53, log entries: 22, rate-limit: 8.0 MiB/sec, 10ms
I180524 18:47:08.176412 47544 storage/replica_raftstorage.go:730  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 32 (id=e4bde28c, encoded size=17280, 1 rocksdb batches, 22 log entries)
I180524 18:47:08.214397 47544 storage/replica_raftstorage.go:736  [n3,s3,r9/?:/Table/1{2-3}] applied preemptive snapshot in 38ms [clear=0ms batch=0ms entries=5ms commit=31ms]
I180524 18:47:08.222156 45711 storage/replica_command.go:1777  [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, next=2]
I180524 18:47:08.228518 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:08.344331 45711 storage/replica.go:3320  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180524 18:47:08.390516 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:08.433032 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot 3681e287 at index 63
I180524 18:47:08.445835 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 189, log entries: 53, rate-limit: 8.0 MiB/sec, 12ms
I180524 18:47:08.456015 47562 storage/replica_raftstorage.go:730  [n2,s2,r10/?:{-}] applying preemptive snapshot at index 63 (id=3681e287, encoded size=57345, 1 rocksdb batches, 53 log entries)
I180524 18:47:08.516126 47562 storage/replica_raftstorage.go:736  [n2,s2,r10/?:/Table/1{3-4}] applied preemptive snapshot in 60ms [clear=0ms batch=0ms entries=57ms commit=2ms]
I180524 18:47:08.519376 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:08.539103 45711 storage/replica_command.go:1777  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, next=2]
I180524 18:47:08.721553 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:08.748525 45711 storage/replica.go:3320  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180524 18:47:08.757726 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot 9e65ffb4 at index 18
I180524 18:47:08.776296 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 16ms
I180524 18:47:08.779674 47698 storage/replica_raftstorage.go:730  [n3,s3,r12/?:{-}] applying preemptive snapshot at index 18 (id=9e65ffb4, encoded size=2417, 1 rocksdb batches, 8 log entries)
I180524 18:47:08.782936 47698 storage/replica_raftstorage.go:736  [n3,s3,r12/?:/Table/1{5-6}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180524 18:47:08.787836 45711 storage/replica_command.go:1777  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, next=2]
I180524 18:47:08.845926 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:08.940253 45711 storage/replica.go:3320  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180524 18:47:08.941700 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:08.974565 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 2bad2db8 at index 43
I180524 18:47:09.004591 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 37, log entries: 2, rate-limit: 8.0 MiB/sec, 25ms
I180524 18:47:09.020262 47628 storage/replica_raftstorage.go:730  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 43 (id=2bad2db8, encoded size=69329, 1 rocksdb batches, 2 log entries)
I180524 18:47:09.027902 47628 storage/replica_raftstorage.go:736  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 7ms [clear=0ms batch=0ms entries=4ms commit=1ms]
I180524 18:47:09.063974 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:09.076364 45711 storage/replica_command.go:1777  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, next=2]
I180524 18:47:09.193908 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:09.250393 45711 storage/replica.go:3320  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180524 18:47:09.279675 45622 storage/replica_proposal.go:202  [n1,s1,r6/1:/{System/tse-Table/System…}] new range lease repl=(n1,s1):1 seq=3 start=1527187615.909574566,0 epo=1 pro=1527187629.266614045,0 following repl=(n1,s1):1 seq=2 start=1527187615.909574566,0 exp=1527187624.940205134,0 pro=1527187615.940286293,0
I180524 18:47:09.290162 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 60571ad8 at index 22
I180524 18:47:09.317379 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 12, rate-limit: 8.0 MiB/sec, 24ms
I180524 18:47:09.321490 47765 storage/replica_raftstorage.go:730  [n3,s3,r6/?:{-}] applying preemptive snapshot at index 22 (id=60571ad8, encoded size=5181, 1 rocksdb batches, 12 log entries)
I180524 18:47:09.324104 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:09.326289 47765 storage/replica_raftstorage.go:736  [n3,s3,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=3ms commit=1ms]
I180524 18:47:09.343796 45711 storage/replica_command.go:1777  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, next=2]
I180524 18:47:09.462272 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:09.582258 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:09.599743 45711 storage/replica.go:3320  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180524 18:47:09.627743 47697 storage/replica_raftstorage.go:520  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot c77d243c at index 21
I180524 18:47:09.645737 47697 storage/store_snapshot.go:605  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 17ms
I180524 18:47:09.654138 47843 storage/replica_raftstorage.go:730  [n3,s3,r11/?:{-}] applying preemptive snapshot at index 21 (id=c77d243c, encoded size=3545, 1 rocksdb batches, 11 log entries)
I180524 18:47:09.699339 47843 storage/replica_raftstorage.go:736  [n3,s3,r11/?:/Table/1{4-5}] applied preemptive snapshot in 45ms [clear=0ms batch=0ms entries=9ms commit=3ms]
I180524 18:47:09.707671 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:09.757386 47697 storage/replica_command.go:1777  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, (n2,s2):2, next=3]
I180524 18:47:09.822866 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:09.957390 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 22 underreplicated ranges
I180524 18:47:09.977021 47697 storage/replica.go:3320  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180524 18:47:10.008184 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r20/1:/Table/{23-50}] generated preemptive snapshot aa3ff35f at index 18
I180524 18:47:10.043116 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r20/1:/Table/{23-50}] streamed snapshot to (n3,s3):?: kv pairs: 12, log entries: 8, rate-limit: 8.0 MiB/sec, 32ms
I180524 18:47:10.046652 47837 storage/replica_raftstorage.go:730  [n3,s3,r20/?:{-}] applying preemptive snapshot at index 18 (id=aa3ff35f, encoded size=2714, 1 rocksdb batches, 8 log entries)
I180524 18:47:10.054307 47837 storage/replica_raftstorage.go:736  [n3,s3,r20/?:/Table/{23-50}] applied preemptive snapshot in 7ms [clear=0ms batch=0ms entries=5ms commit=1ms]
I180524 18:47:10.096095 45711 storage/replica_command.go:1777  [replicate,n1,s1,r20/1:/Table/{23-50}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r20:/Table/{23-50} [(n1,s1):1, next=2]
I180524 18:47:10.102299 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:10.255830 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:10.316645 45711 storage/replica.go:3320  [n1,s1,r20/1:/Table/{23-50}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180524 18:47:10.346873 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r22/1:/{Table/51-Max}] generated preemptive snapshot b73766fd at index 14
I180524 18:47:10.355102 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:10.398569 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r22/1:/{Table/51-Max}] streamed snapshot to (n2,s2):?: kv pairs: 7, log entries: 4, rate-limit: 8.0 MiB/sec, 51ms
I180524 18:47:10.447930 47883 storage/replica_raftstorage.go:730  [n2,s2,r22/?:{-}] applying preemptive snapshot at index 14 (id=b73766fd, encoded size=774, 1 rocksdb batches, 4 log entries)
I180524 18:47:10.455210 47883 storage/replica_raftstorage.go:736  [n2,s2,r22/?:/{Table/51-Max}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180524 18:47:10.479732 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:10.481655 45711 storage/replica_command.go:1777  [replicate,n1,s1,r22/1:/{Table/51-Max}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r22:/{Table/51-Max} [(n1,s1):1, next=2]
I180524 18:47:10.599381 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:10.602053 45711 storage/replica.go:3320  [n1,s1,r22/1:/{Table/51-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180524 18:47:10.613526 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot 94e3e78e at index 18
I180524 18:47:10.648427 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 34ms
I180524 18:47:10.652466 47944 storage/replica_raftstorage.go:730  [n3,s3,r13/?:{-}] applying preemptive snapshot at index 18 (id=94e3e78e, encoded size=2582, 1 rocksdb batches, 8 log entries)
I180524 18:47:10.656483 47944 storage/replica_raftstorage.go:736  [n3,s3,r13/?:/Table/1{6-7}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=1ms commit=1ms]
I180524 18:47:10.690649 45711 storage/replica_command.go:1777  [replicate,n1,s1,r13/1:/Table/1{6-7}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, next=2]
I180524 18:47:10.741777 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:10.850112 45711 storage/replica.go:3320  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180524 18:47:10.864612 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:10.871838 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot 44b887a4 at index 18
I180524 18:47:10.913418 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 39ms
I180524 18:47:10.934905 48016 storage/replica_raftstorage.go:730  [n3,s3,r16/?:{-}] applying preemptive snapshot at index 18 (id=44b887a4, encoded size=2421, 1 rocksdb batches, 8 log entries)
I180524 18:47:10.948943 48016 storage/replica_raftstorage.go:736  [n3,s3,r16/?:/Table/{19-20}] applied preemptive snapshot in 14ms [clear=4ms batch=0ms entries=3ms commit=3ms]
I180524 18:47:10.967491 45711 storage/replica_command.go:1777  [replicate,n1,s1,r16/1:/Table/{19-20}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r16:/Table/{19-20} [(n1,s1):1, next=2]
I180524 18:47:10.986062 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:11.096390 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:11.213666 45711 storage/replica.go:3320  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180524 18:47:11.261814 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 60001a2b at index 19
I180524 18:47:11.265381 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:11.277832 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 9, rate-limit: 8.0 MiB/sec, 13ms
I180524 18:47:11.281592 48062 storage/replica_raftstorage.go:730  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 19 (id=60001a2b, encoded size=2898, 1 rocksdb batches, 9 log entries)
I180524 18:47:11.285115 48062 storage/replica_raftstorage.go:736  [n2,s2,r14/?:/Table/1{7-8}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180524 18:47:11.307890 45711 storage/replica_command.go:1777  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, next=2]
I180524 18:47:11.407176 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:11.543102 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:11.556873 45711 storage/replica.go:3320  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180524 18:47:11.615490 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot eb2194b6 at index 33
I180524 18:47:11.662949 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 57, log entries: 23, rate-limit: 8.0 MiB/sec, 36ms
I180524 18:47:11.670356 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:11.699922 48182 storage/replica_raftstorage.go:730  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 33 (id=eb2194b6, encoded size=16420, 1 rocksdb batches, 23 log entries)
I180524 18:47:11.712093 48182 storage/replica_raftstorage.go:736  [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 12ms [clear=0ms batch=0ms entries=9ms commit=1ms]
I180524 18:47:11.738962 45711 storage/replica_command.go:1777  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, next=2]
I180524 18:47:11.789414 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:11.796951 45711 storage/replica.go:3320  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180524 18:47:11.810307 45711 storage/replica_raftstorage.go:520  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot 3d35e93e at index 18
I180524 18:47:11.825587 45711 storage/store_snapshot.go:605  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 14ms
I180524 18:47:11.848374 48109 storage/replica_raftstorage.go:730  [n2,s2,r17/?:{-}] applying preemptive snapshot at index 18 (id=3d35e93e, encoded size=2582, 1 rocksdb batches, 8 log entries)
I180524 18:47:11.854025 48109 storage/replica_raftstorage.go:736  [n2,s2,r17/?:/Table/2{0-1}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=2ms commit=1ms]
I180524 18:47:11.873267 45711 storage/replica_command.go:1777  [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, next=2]
I180524 18:47:11.907480 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:12.044324 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:12.169121 45711 storage/replica.go:3320  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180524 18:47:12.196726 45711 storage/queue.go:864  [n1,replicate] purgatory is now empty
I180524 18:47:12.200197 48263 storage/replica_raftstorage.go:520  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 25a312ed at index 25
I180524 18:47:12.207176 48263 storage/store_snapshot.go:605  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 15, rate-limit: 8.0 MiB/sec, 6ms
I180524 18:47:12.211505 48223 storage/replica_raftstorage.go:730  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 25 (id=25a312ed, encoded size=6248, 1 rocksdb batches, 15 log entries)
I180524 18:47:12.216471 48223 storage/replica_raftstorage.go:736  [n2,s2,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=3ms commit=1ms]
I180524 18:47:12.252183 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:12.280027 48263 storage/replica_command.go:1777  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, (n3,s3):2, next=3]
I180524 18:47:12.392113 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:12.491652 48263 storage/replica.go:3320  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180524 18:47:12.512747 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 21 underreplicated ranges
I180524 18:47:12.583312 48325 storage/replica_raftstorage.go:520  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot a27a8638 at index 21
I180524 18:47:12.590282 48325 storage/store_snapshot.go:605  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 6ms
I180524 18:47:12.594392 48283 storage/replica_raftstorage.go:730  [n3,s3,r17/?:{-}] applying preemptive snapshot at index 21 (id=a27a8638, encoded size=3610, 1 rocksdb batches, 11 log entries)
I180524 18:47:12.630487 48283 storage/replica_raftstorage.go:736  [n3,s3,r17/?:/Table/2{0-1}] applied preemptive snapshot in 36ms [clear=18ms batch=0ms entries=2ms commit=14ms]
I180524 18:47:12.637663 48325 storage/replica_command.go:1777  [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, (n2,s2):2, next=3]
I180524 18:47:12.758782 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 20 underreplicated ranges
I180524 18:47:12.913646 48325 storage/replica.go:3320  [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
I180524 18:47:12.929305 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 20 underreplicated ranges
I180524 18:47:12.971887 48377 storage/replica_raftstorage.go:520  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot d1ee50e3 at index 21
I180524 18:47:13.024776 46347 server/status/runtime.go:219  [n2] runtime stats: 1.4 GiB RSS, 607 goroutines, 46 MiB/91 MiB/162 MiB GO alloc/idle/total, 87 MiB/129 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (251x)
I180524 18:47:13.044295 48377 storage/store_snapshot.go:605  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 71ms
I180524 18:47:13.057435 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 19 underreplicated ranges
I180524 18:47:13.074038 48286 storage/replica_raftstorage.go:730  [n3,s3,r15/?:{-}] applying preemptive snapshot at index 21 (id=d1ee50e3, encoded size=3608, 1 rocksdb batches, 11 log entries)
I180524 18:47:13.079494 48286 storage/replica_raftstorage.go:736  [n3,s3,r15/?:/Table/1{8-9}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=3ms commit=1ms]
I180524 18:47:13.098263 48377 storage/replica_command.go:1777  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, (n2,s2):2, next=3]
I180524 18:47:13.190625 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 19 underreplicated ranges
I180524 18:47:13.328298 48377 storage/replica.go:3320  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3] next=4
I180524 18:47:13.366785 45481 testutils/testcluster/testcluster.go:536  [n1,s1] has 19 underreplicated ranges
I180524 18:47:13.390619 48500 storage/replica_raftstorage.go:520  [replicate,n1,s1,r21/1:/Table/5{0-1}] generated preemptive snapshot 49f8346d at index 21
I180524 18:47:13.406760 48500 storage/store_snapshot.go:605  [replicate,n1,s1,r21/1:/Table/5{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 11, rate-limit: 8.0 MiB/sec, 15ms
I180524 18:47:13.416039 48428 storage/replica_raftstorage.go:730  [n3,s3,r21/?:{-}] applying preemptive snapshot at index 21 (id=49f8346d, encoded size=3422, 1 rocksdb batches, 11 log entries)
I180524 18:47:13.437845 48428 storage/repl

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the 2.1 milestone May 24, 2018
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels May 24, 2018
@tbg
Copy link
Member

tbg commented May 30, 2018

I180524 18:47:38.879348 53375 storage/replica_command.go:863 [n1,s1,r34/1:/{Table/54-Max}] initiating a split of this range at key /Table/55/1/500 [r35]
F180524 18:47:39.033497 45671 storage/replica.go:3873 [n1,s1,r5/1:/System/ts{d-e}] while purging index %d: while purging index 54: IO error: /go/src/github.com/cockroachdb/cockroach/artifacts/cockroach-auxiliary515476655/sideloading/5/5.1/i54.t12: File not found

@tbg tbg added the A-kv-client Relating to the KV client and the KV interface. label May 30, 2018
@windchan7
Copy link
Contributor

#26259

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@windchan7 windchan7

Labels
A-kv-client Relating to the KV client and the KV interface. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
2.1
Development

No branches or pull requests
3 participants
@tbg @cockroach-teamcity @windchan7