{"action":"closed","issue":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/27831","repository_url":"https://api.github.com/repos/cockroachdb/cockroach","labels_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/27831/labels{/name}","comments_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/27831/comments","events_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/27831/events","html_url":"https://github.com/cockroachdb/cockroach/issues/27831","id":343378162,"node_id":"MDU6SXNzdWUzNDMzNzgxNjI=","number":27831,"title":"sql: TestShowTraceReplica/UPSERT_INTO_d.t2_VALUES_(1) failed under stress","user":{"login":"cockroach-teamcity","id":20559710,"node_id":"MDQ6VXNlcjIwNTU5NzEw","avatar_url":"https://avatars0.githubusercontent.com/u/20559710?v=4","gravatar_id":"","url":"https://api.github.com/users/cockroach-teamcity","html_url":"https://github.com/cockroach-teamcity","followers_url":"https://api.github.com/users/cockroach-teamcity/followers","following_url":"https://api.github.com/users/cockroach-teamcity/following{/other_user}","gists_url":"https://api.github.com/users/cockroach-teamcity/gists{/gist_id}","starred_url":"https://api.github.com/users/cockroach-teamcity/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cockroach-teamcity/subscriptions","organizations_url":"https://api.github.com/users/cockroach-teamcity/orgs","repos_url":"https://api.github.com/users/cockroach-teamcity/repos","events_url":"https://api.github.com/users/cockroach-teamcity/events{/privacy}","received_events_url":"https://api.github.com/users/cockroach-teamcity/received_events","type":"User","site_admin":false},"labels":[{"id":191587409,"node_id":"MDU6TGFiZWwxOTE1ODc0MDk=","url":"https://api.github.com/repos/cockroachdb/cockroach/labels/C-test-failure","name":"C-test-failure","color":"c5def5","default":false},{"id":335217860,"node_id":"MDU6TGFiZWwzMzUyMTc4NjA=","url":"https://api.github.com/repos/cockroachdb/cockroach/labels/O-robot","name":"O-robot","color":"666ad1","default":false}],"state":"closed","locked":false,"assignee":{"login":"danhhz","id":52528,"node_id":"MDQ6VXNlcjUyNTI4","avatar_url":"https://avatars1.githubusercontent.com/u/52528?v=4","gravatar_id":"","url":"https://api.github.com/users/danhhz","html_url":"https://github.com/danhhz","followers_url":"https://api.github.com/users/danhhz/followers","following_url":"https://api.github.com/users/danhhz/following{/other_user}","gists_url":"https://api.github.com/users/danhhz/gists{/gist_id}","starred_url":"https://api.github.com/users/danhhz/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/danhhz/subscriptions","organizations_url":"https://api.github.com/users/danhhz/orgs","repos_url":"https://api.github.com/users/danhhz/repos","events_url":"https://api.github.com/users/danhhz/events{/privacy}","received_events_url":"https://api.github.com/users/danhhz/received_events","type":"User","site_admin":false},"assignees":[{"login":"danhhz","id":52528,"node_id":"MDQ6VXNlcjUyNTI4","avatar_url":"https://avatars1.githubusercontent.com/u/52528?v=4","gravatar_id":"","url":"https://api.github.com/users/danhhz","html_url":"https://github.com/danhhz","followers_url":"https://api.github.com/users/danhhz/followers","following_url":"https://api.github.com/users/danhhz/following{/other_user}","gists_url":"https://api.github.com/users/danhhz/gists{/gist_id}","starred_url":"https://api.github.com/users/danhhz/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/danhhz/subscriptions","organizations_url":"https://api.github.com/users/danhhz/orgs","repos_url":"https://api.github.com/users/danhhz/repos","events_url":"https://api.github.com/users/danhhz/events{/privacy}","received_events_url":"https://api.github.com/users/danhhz/received_events","type":"User","site_admin":false}],"milestone":{"url":"https://api.github.com/repos/cockroachdb/cockroach/milestones/13","html_url":"https://github.com/cockroachdb/cockroach/milestone/13","labels_url":"https://api.github.com/repos/cockroachdb/cockroach/milestones/13/labels","id":2745639,"node_id":"MDk6TWlsZXN0b25lMjc0NTYzOQ==","number":13,"title":"2.1","description":"","creator":{"login":"knz","id":642886,"node_id":"MDQ6VXNlcjY0Mjg4Ng==","avatar_url":"https://avatars3.githubusercontent.com/u/642886?v=4","gravatar_id":"","url":"https://api.github.com/users/knz","html_url":"https://github.com/knz","followers_url":"https://api.github.com/users/knz/followers","following_url":"https://api.github.com/users/knz/following{/other_user}","gists_url":"https://api.github.com/users/knz/gists{/gist_id}","starred_url":"https://api.github.com/users/knz/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/knz/subscriptions","organizations_url":"https://api.github.com/users/knz/orgs","repos_url":"https://api.github.com/users/knz/repos","events_url":"https://api.github.com/users/knz/events{/privacy}","received_events_url":"https://api.github.com/users/knz/received_events","type":"User","site_admin":false},"open_issues":676,"closed_issues":1024,"state":"open","created_at":"2017-09-05T15:30:49Z","updated_at":"2018-07-23T16:39:00Z","due_on":null,"closed_at":null},"comments":2,"created_at":"2018-07-22T05:18:26Z","updated_at":"2018-07-23T16:39:00Z","closed_at":"2018-07-23T16:39:00Z","author_association":"MEMBER","body":"SHA: https://github.com/cockroachdb/cockroach/commits/15e96b9fc4065e936eaf4f3f744cd75b41209261\n\nParameters:\n```\nTAGS=\nGOFLAGS=\n```\n\nFailed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=790312&tab=buildLog\n\n```\nI180722 05:17:01.680091 165380 storage/replica_command.go:743  [replicate,n4,s4,r23/2:/Table/5{2-3}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r23:/Table/5{2-3} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:01.718232 165177 rpc/nodedialer/nodedialer.go:90  [replica consistency checker,n4,s4,r23/2:/Table/5{2-3}] connection to n4 established\nI180722 05:17:01.744863 165380 storage/replica.go:3613  [n4,s4,r23/2:/Table/5{2-3}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:01.746382 164979 storage/store.go:3585  [n1,s1,r23/1:/Table/5{2-3}] added to replica GC queue (peer suggestion)\nW180722 05:17:01.855634 165392 storage/intent_resolver.go:642  [n3,s3] failed to push during intent resolution: failed to push \"split\" id=4fa570c6 key=/Local/Range/Table/53/RangeDescriptor rw=true pri=0.02969443 iso=SERIALIZABLE stat=PENDING epo=0 ts=1532236618.830824870,0 orig=1532236618.830824870,0 max=1532236618.830824870,0 wto=false rop=false seq=1\nI180722 05:17:01.861348 165459 storage/replica_command.go:279  [split,n1,s1,r26/1:/{Table/54-Max}] initiating a split of this range at key /Table/55 [r27]\nE180722 05:17:01.862560 165462 storage/queue.go:778  [replicate,n1,s1,r25/1:/Table/5{3-4}] no removable replicas from range that needs a removal: [raft progress unknown]\nI180722 05:17:01.865309 165418 storage/store.go:2513  [replicaGC,n1,s1,r23/1:/Table/5{2-3}] removing replica\nI180722 05:17:01.865538 165418 storage/replica.go:836  [replicaGC,n1,s1,r23/1:/Table/5{2-3}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:01.873804 165490 storage/replica_range_lease.go:554  [replicate,n1,s1,r26/1:/Table/5{4-5}] transferring lease to s4\nI180722 05:17:01.875220 165490 storage/replica_range_lease.go:617  [replicate,n1,s1,r26/1:/Table/5{4-5}] done transferring lease to s4: <nil>\nI180722 05:17:01.875561 164769 storage/replica_proposal.go:222  [n4,s4,r26/2:/Table/5{4-5}] new range lease repl=(n4,s4):2 seq=3 start=1532236621.873820447,0 epo=1 pro=1532236621.873823604,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nE180722 05:17:01.875904 165498 storage/queue.go:778  [replicate,n1,s1,r27/1:/{Table/55-Max}] no removable replicas from range that needs a removal: [raft progress unknown]\nI180722 05:17:02.065863 165590 storage/replica_raftstorage.go:520  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot db40edea at index 23\nI180722 05:17:02.069686 165590 storage/store_snapshot.go:605  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n4,s4):?: kv pairs: 13, log entries: 13, rate-limit: 2.0 MiB/sec, 4ms\nI180722 05:17:02.070203 165573 storage/replica_raftstorage.go:737  [n4,s4,r8/?:{-}] applying preemptive snapshot at index 23 (id=db40edea, encoded size=6123, 1 rocksdb batches, 13 log entries)\nI180722 05:17:02.070519 165573 storage/replica_raftstorage.go:743  [n4,s4,r8/?:/Table/1{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:02.070999 165590 storage/replica_command.go:743  [replicate,n1,s1,r8/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, next=2]\nI180722 05:17:02.092445 165590 storage/replica.go:3613  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:02.131680 165710 storage/replica_range_lease.go:554  [replicate,n1,s1,r8/1:/Table/1{1-2}] transferring lease to s4\nI180722 05:17:02.133459 165710 storage/replica_range_lease.go:617  [replicate,n1,s1,r8/1:/Table/1{1-2}] done transferring lease to s4: <nil>\nI180722 05:17:02.134264 164605 storage/replica_proposal.go:222  [n4,s4,r8/2:/Table/1{1-2}] new range lease repl=(n4,s4):2 seq=3 start=1532236622.131728438,0 epo=1 pro=1532236622.131731746,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:02.664007 165529 storage/replica_command.go:743  [replicate,n4,s4,r22/2:/Table/5{1-2}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r22:/Table/5{1-2} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:02.669096 165529 storage/replica.go:3613  [n4,s4,r22/2:/Table/5{1-2}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:02.671745 164979 storage/store.go:3585  [n1,s1,r22/1:/Table/5{1-2}] added to replica GC queue (peer suggestion)\nI180722 05:17:02.672268 165620 storage/store.go:2513  [replicaGC,n1,s1,r22/1:/Table/5{1-2}] removing replica\nI180722 05:17:02.672523 165620 storage/replica.go:836  [replicaGC,n1,s1,r22/1:/Table/5{1-2}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:03.067868 165626 storage/replica_raftstorage.go:520  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 2795c6cf at index 21\nI180722 05:17:03.083726 165626 storage/store_snapshot.go:605  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n4,s4):?: kv pairs: 1241, log entries: 4, rate-limit: 2.0 MiB/sec, 16ms\nI180722 05:17:03.084893 165749 storage/replica_raftstorage.go:737  [n4,s4,r5/?:{-}] applying preemptive snapshot at index 21 (id=2795c6cf, encoded size=187531, 1 rocksdb batches, 4 log entries)\nI180722 05:17:03.086561 165749 storage/replica_raftstorage.go:743  [n4,s4,r5/?:/System/ts{d-e}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=1ms]\nI180722 05:17:03.087660 165626 storage/replica_command.go:743  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, next=2]\nI180722 05:17:03.092402 165628 storage/replica_consistency.go:129  [replica consistency checker,n1,s1,r5/1:/System/ts{d-e}] triggering stats recomputation to resolve delta of {ContainsEstimates:true LastUpdateNanos:1532236618668274539 IntentAge:0 GCBytesAge:0 LiveBytes:-35790 LiveCount:-798 KeyBytes:-36324 KeyCount:-798 ValBytes:534 ValCount:-798 IntentBytes:0 IntentCount:0 SysBytes:0 SysCount:0}\nI180722 05:17:03.094398 165626 storage/replica.go:3613  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:03.101894 165805 storage/replica_range_lease.go:554  [replicate,n1,s1,r5/1:/System/ts{d-e}] transferring lease to s4\nI180722 05:17:03.102784 165805 storage/replica_range_lease.go:617  [replicate,n1,s1,r5/1:/System/ts{d-e}] done transferring lease to s4: <nil>\nI180722 05:17:03.103430 164769 storage/replica_proposal.go:222  [n4,s4,r5/2:/System/ts{d-e}] new range lease repl=(n4,s4):2 seq=3 start=1532236623.101913627,0 epo=1 pro=1532236623.101916426,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:03.719119 165826 storage/replica_command.go:743  [replicate,n4,s4,r4/2:/System/{NodeLive…-tsd}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:03.723944 165826 storage/replica.go:3613  [n4,s4,r4/2:/System/{NodeLive…-tsd}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:03.726834 165839 storage/store.go:2513  [replicaGC,n1,s1,r4/1:/System/{NodeLive…-tsd}] removing replica\nI180722 05:17:03.727188 165839 storage/replica.go:836  [replicaGC,n1,s1,r4/1:/System/{NodeLive…-tsd}] removed 30 (21+9) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:04.066679 165821 storage/replica_raftstorage.go:520  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot eb7a6e88 at index 17\nI180722 05:17:04.067389 165821 storage/store_snapshot.go:605  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n4,s4):?: kv pairs: 9, log entries: 7, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:04.067779 165824 storage/replica_raftstorage.go:737  [n4,s4,r14/?:{-}] applying preemptive snapshot at index 17 (id=eb7a6e88, encoded size=2547, 1 rocksdb batches, 7 log entries)\nI180722 05:17:04.068004 165824 storage/replica_raftstorage.go:743  [n4,s4,r14/?:/Table/1{7-8}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:04.068445 165821 storage/replica_command.go:743  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, next=2]\nI180722 05:17:04.077030 165821 storage/replica.go:3613  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:04.080678 165774 storage/replica_range_lease.go:554  [replicate,n1,s1,r14/1:/Table/1{7-8}] transferring lease to s4\nI180722 05:17:04.081324 165774 storage/replica_range_lease.go:617  [replicate,n1,s1,r14/1:/Table/1{7-8}] done transferring lease to s4: <nil>\nI180722 05:17:04.081986 164605 storage/replica_proposal.go:222  [n4,s4,r14/2:/Table/1{7-8}] new range lease repl=(n4,s4):2 seq=3 start=1532236624.080691000,0 epo=1 pro=1532236624.080693473,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:05.067427 165893 storage/replica_raftstorage.go:520  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot 375937e7 at index 26\nI180722 05:17:05.068918 165893 storage/store_snapshot.go:605  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n4,s4):?: kv pairs: 8, log entries: 16, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:05.069281 165864 storage/replica_raftstorage.go:737  [n4,s4,r2/?:{-}] applying preemptive snapshot at index 26 (id=375937e7, encoded size=6629, 1 rocksdb batches, 16 log entries)\nI180722 05:17:05.069505 165864 storage/replica_raftstorage.go:743  [n4,s4,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:05.071031 165893 storage/replica_command.go:743  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, next=2]\nI180722 05:17:05.076919 165893 storage/replica.go:3613  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:05.079839 165932 storage/replica_range_lease.go:554  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] transferring lease to s4\nI180722 05:17:05.082693 165932 storage/replica_range_lease.go:617  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] done transferring lease to s4: <nil>\nI180722 05:17:05.664507 165910 storage/replica_range_lease.go:554  [replicate,n4,s4,r26/2:/Table/5{4-5}] transferring lease to s1\nI180722 05:17:05.665391 165910 storage/replica_range_lease.go:617  [replicate,n4,s4,r26/2:/Table/5{4-5}] done transferring lease to s1: <nil>\nI180722 05:17:05.666097 163688 storage/replica_proposal.go:222  [n1,s1,r26/1:/Table/5{4-5}] new range lease repl=(n1,s1):1 seq=4 start=1532236625.664529950,0 epo=1 pro=1532236625.664532882,0 following repl=(n4,s4):2 seq=3 start=1532236621.873820447,0 epo=1 pro=1532236621.873823604,0\nI180722 05:17:06.068209 165972 storage/replica_raftstorage.go:520  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot b92d380a at index 18\nI180722 05:17:06.068911 165972 storage/store_snapshot.go:605  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n4,s4):?: kv pairs: 10, log entries: 8, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:06.069283 165975 storage/replica_raftstorage.go:737  [n4,s4,r18/?:{-}] applying preemptive snapshot at index 18 (id=b92d380a, encoded size=2859, 1 rocksdb batches, 8 log entries)\nI180722 05:17:06.069488 165975 storage/replica_raftstorage.go:743  [n4,s4,r18/?:/Table/2{1-2}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:06.069943 165972 storage/replica_command.go:743  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, next=2]\nI180722 05:17:06.076706 165972 storage/replica.go:3613  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:06.080322 166001 storage/replica_range_lease.go:554  [replicate,n1,s1,r18/1:/Table/2{1-2}] transferring lease to s4\nI180722 05:17:06.081150 166001 storage/replica_range_lease.go:617  [replicate,n1,s1,r18/1:/Table/2{1-2}] done transferring lease to s4: <nil>\nI180722 05:17:06.082180 164788 storage/replica_proposal.go:222  [n4,s4,r18/2:/Table/2{1-2}] new range lease repl=(n4,s4):2 seq=3 start=1532236626.080352797,0 epo=1 pro=1532236626.080368561,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:07.067984 163593 storage/replica_proposal.go:222  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236627.067729898,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:07.068662 165979 storage/replica_raftstorage.go:520  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot ef8f6398 at index 17\nI180722 05:17:07.069282 165979 storage/store_snapshot.go:605  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n4,s4):?: kv pairs: 9, log entries: 7, rate-limit: 2.0 MiB/sec, 0ms\nI180722 05:17:07.069582 166037 storage/replica_raftstorage.go:737  [n4,s4,r12/?:{-}] applying preemptive snapshot at index 17 (id=ef8f6398, encoded size=2624, 1 rocksdb batches, 7 log entries)\nI180722 05:17:07.069764 166037 storage/replica_raftstorage.go:743  [n4,s4,r12/?:/Table/1{5-6}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:07.070126 165979 storage/replica_command.go:743  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, next=2]\nI180722 05:17:07.075274 163600 storage/replica_proposal.go:222  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236627.075024885,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:07.077208 165979 storage/replica.go:3613  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:07.084798 166115 storage/replica_range_lease.go:554  [replicate,n1,s1,r12/1:/Table/1{5-6}] transferring lease to s4\nI180722 05:17:07.085580 164609 storage/replica_proposal.go:222  [n4,s4,r12/2:/Table/1{5-6}] new range lease repl=(n4,s4):2 seq=4 start=1532236627.084841044,0 epo=1 pro=1532236627.084845024,0 following repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236627.067729898,0\nI180722 05:17:07.085594 166115 storage/replica_range_lease.go:617  [replicate,n1,s1,r12/1:/Table/1{5-6}] done transferring lease to s4: <nil>\nI180722 05:17:07.664939 166134 storage/replica_command.go:743  [replicate,n4,s4,r7/2:/Table/{SystemCon…-11}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:07.669204 166134 storage/replica.go:3613  [n4,s4,r7/2:/Table/{SystemCon…-11}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:07.670480 164979 storage/store.go:3585  [n1,s1,r7/1:/Table/{SystemCon…-11}] added to replica GC queue (peer suggestion)\nI180722 05:17:07.670672 166071 storage/store.go:2513  [replicaGC,n1,s1,r7/1:/Table/{SystemCon…-11}] removing replica\nI180722 05:17:07.671089 166071 storage/replica.go:836  [replicaGC,n1,s1,r7/1:/Table/{SystemCon…-11}] removed 72 (63+9) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:08.060416 163750 server/status/runtime.go:255  [n1] runtime stats: 228 MiB RSS, 1117 goroutines, 46 MiB/41 MiB/114 MiB GO alloc/idle/total, 37 MiB/72 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (1070x)\nI180722 05:17:08.070434 163692 storage/replica_proposal.go:222  [n1,s1,r25/1:/Table/5{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236628.069666907,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:08.070902 166165 storage/replica_command.go:743  [replicate,n1,s1,r25/1:/Table/5{3-4}] change replicas (REMOVE_REPLICA (n4,s4):2): read existing descriptor r25:/Table/5{3-4} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:08.077978 166165 storage/replica.go:3613  [n1,s1,r25/1:/Table/5{3-4}] proposing REMOVE_REPLICA((n4,s4):2): updated=[(n1,s1):1] next=3\nI180722 05:17:08.080709 166211 storage/store.go:2513  [replicaGC,n4,s4,r25/2:/Table/5{3-4}] removing replica\nI180722 05:17:08.080916 166211 storage/replica.go:836  [replicaGC,n4,s4,r25/2:/Table/5{3-4}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\nW180722 05:17:08.098794 163752 server/node.go:892  [n1,summaries] health alerts detected: {Alerts:[{StoreID:1 Category:METRICS Description:queue.replicate.process.failure Value:2}]}\nI180722 05:17:08.443717 164181 server/status/runtime.go:255  [n2] runtime stats: 230 MiB RSS, 1116 goroutines, 30 MiB/53 MiB/114 MiB GO alloc/idle/total, 38 MiB/74 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (1071x)\nI180722 05:17:08.558723 164414 server/status/runtime.go:255  [n3] runtime stats: 230 MiB RSS, 1138 goroutines, 39 MiB/45 MiB/114 MiB GO alloc/idle/total, 38 MiB/74 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (1071x)\nI180722 05:17:08.645050 164670 server/status/runtime.go:255  [n4] runtime stats: 230 MiB RSS, 1137 goroutines, 44 MiB/40 MiB/114 MiB GO alloc/idle/total, 38 MiB/74 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (1071x)\nI180722 05:17:08.721586 166291 storage/replica_command.go:743  [replicate,n4,s4,r8/2:/Table/1{1-2}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:08.725768 166291 storage/replica.go:3613  [n4,s4,r8/2:/Table/1{1-2}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:08.727500 164979 storage/store.go:3585  [n1,s1,r8/1:/Table/1{1-2}] added to replica GC queue (peer suggestion)\nI180722 05:17:08.727779 166268 storage/store.go:2513  [replicaGC,n1,s1,r8/1:/Table/1{1-2}] removing replica\nI180722 05:17:08.728012 166268 storage/replica.go:836  [replicaGC,n1,s1,r8/1:/Table/1{1-2}] removed 12 (3+9) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:09.071107 166311 storage/replica_raftstorage.go:520  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 467868f2 at index 35\nI180722 05:17:09.085257 166311 rpc/nodedialer/nodedialer.go:90  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] connection to n2 established\nI180722 05:17:09.085951 166311 storage/store_snapshot.go:605  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 20, log entries: 25, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:09.086263 166225 storage/replica_raftstorage.go:737  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 35 (id=467868f2, encoded size=7028, 1 rocksdb batches, 25 log entries)\nI180722 05:17:09.086974 166225 storage/replica_raftstorage.go:743  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=1ms]\nI180722 05:17:09.087283 166311 storage/replica_command.go:743  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, next=2]\nI180722 05:17:09.092054 166311 storage/replica.go:3613  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3\nI180722 05:17:09.095314 164054 rpc/nodedialer/nodedialer.go:90  [n2] connection to n1 established\nI180722 05:17:09.101541 166365 storage/replica_range_lease.go:554  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] transferring lease to s2\nI180722 05:17:09.102423 166365 storage/replica_range_lease.go:617  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] done transferring lease to s2: <nil>\nI180722 05:17:10.073640 163699 storage/replica_proposal.go:222  [n1,s1,r20/1:/Table/{23-50}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236630.073309015,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:10.074519 166325 storage/replica_raftstorage.go:520  [replicate,n1,s1,r20/1:/Table/{23-50}] generated preemptive snapshot 294dcc61 at index 16\nI180722 05:17:10.075370 166325 storage/store_snapshot.go:605  [replicate,n1,s1,r20/1:/Table/{23-50}] streamed snapshot to (n4,s4):?: kv pairs: 12, log entries: 6, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:10.075789 166422 storage/replica_raftstorage.go:737  [n4,s4,r20/?:{-}] applying preemptive snapshot at index 16 (id=294dcc61, encoded size=2379, 1 rocksdb batches, 6 log entries)\nI180722 05:17:10.076005 166422 storage/replica_raftstorage.go:743  [n4,s4,r20/?:/Table/{23-50}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:10.076420 166325 storage/replica_command.go:743  [replicate,n1,s1,r20/1:/Table/{23-50}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r20:/Table/{23-50} [(n1,s1):1, next=2]\nI180722 05:17:10.082267 166325 storage/replica.go:3613  [n1,s1,r20/1:/Table/{23-50}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:10.114536 166454 storage/replica_range_lease.go:554  [replicate,n1,s1,r20/1:/Table/{23-50}] transferring lease to s4\nI180722 05:17:10.122186 166454 storage/replica_range_lease.go:617  [replicate,n1,s1,r20/1:/Table/{23-50}] done transferring lease to s4: <nil>\nI180722 05:17:10.123041 164749 storage/replica_proposal.go:222  [n4,s4,r20/2:/Table/{23-50}] new range lease repl=(n4,s4):2 seq=4 start=1532236630.114557688,0 epo=1 pro=1532236630.114561056,0 following repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236630.073309015,0\nI180722 05:17:10.537628 166424 storage/replica_command.go:743  [replicate,n2,s2,r3/2:/System/NodeLiveness{-Max}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, (n2,s2):2, next=3]\nI180722 05:17:10.593055 166424 storage/replica.go:3613  [n2,s2,r3/2:/System/NodeLiveness{-Max}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n2,s2):2] next=3\nI180722 05:17:10.595112 166373 storage/store.go:3585  [n1,s1,r3/1:/System/NodeLiveness{-Max}] added to replica GC queue (peer suggestion)\nI180722 05:17:10.664025 166501 storage/store.go:2513  [replicaGC,n1,s1,r3/1:/System/NodeLiveness{-Max}] removing replica\nI180722 05:17:10.664341 166501 storage/replica.go:836  [replicaGC,n1,s1,r3/1:/System/NodeLiveness{-Max}] removed 11 (4+7) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:10.666755 164762 storage/replica_proposal.go:222  [n4,s4,r27/2:/{Table/55-Max}] new range lease repl=(n4,s4):2 seq=3 start=1532236627.056359920,1 epo=1 pro=1532236630.665563619,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nE180722 05:17:10.667255 166492 storage/queue.go:778  [replicate,n4,s4,r27/2:/{Table/55-Max}] no removable replicas from range that needs a removal: [raft progress unknown]\nI180722 05:17:11.074217 163679 storage/replica_proposal.go:222  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236631.073872305,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:11.075357 166506 storage/replica_raftstorage.go:520  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot 5f5793fc at index 18\nI180722 05:17:11.076222 166506 storage/store_snapshot.go:605  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n4,s4):?: kv pairs: 9, log entries: 8, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:11.076641 166578 storage/replica_raftstorage.go:737  [n4,s4,r11/?:{-}] applying preemptive snapshot at index 18 (id=5f5793fc, encoded size=2712, 1 rocksdb batches, 8 log entries)\nI180722 05:17:11.076880 166578 storage/replica_raftstorage.go:743  [n4,s4,r11/?:/Table/1{4-5}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:11.077277 166506 storage/replica_command.go:743  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, next=2]\nI180722 05:17:11.082089 166506 storage/replica.go:3613  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:11.089358 166587 storage/replica_range_lease.go:554  [replicate,n1,s1,r11/1:/Table/1{4-5}] transferring lease to s4\nI180722 05:17:11.090059 166587 storage/replica_range_lease.go:617  [replicate,n1,s1,r11/1:/Table/1{4-5}] done transferring lease to s4: <nil>\nI180722 05:17:11.090506 164780 storage/replica_proposal.go:222  [n4,s4,r11/2:/Table/1{4-5}] new range lease repl=(n4,s4):2 seq=4 start=1532236631.089369558,0 epo=1 pro=1532236631.089372664,0 following repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236631.073872305,0\nI180722 05:17:12.075066 163718 storage/replica_proposal.go:222  [n1,s1,r21/1:/Table/5{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236632.074775094,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:12.076146 166557 storage/replica_raftstorage.go:520  [replicate,n1,s1,r21/1:/Table/5{0-1}] generated preemptive snapshot c1f78298 at index 18\nI180722 05:17:12.076771 166557 storage/store_snapshot.go:605  [replicate,n1,s1,r21/1:/Table/5{0-1}] streamed snapshot to (n4,s4):?: kv pairs: 9, log entries: 8, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:12.077118 166605 storage/replica_raftstorage.go:737  [n4,s4,r21/?:{-}] applying preemptive snapshot at index 18 (id=c1f78298, encoded size=2520, 1 rocksdb batches, 8 log entries)\nI180722 05:17:12.077345 166605 storage/replica_raftstorage.go:743  [n4,s4,r21/?:/Table/5{0-1}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:12.077692 166557 storage/replica_command.go:743  [replicate,n1,s1,r21/1:/Table/5{0-1}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r21:/Table/5{0-1} [(n1,s1):1, next=2]\nI180722 05:17:12.083888 166557 storage/replica.go:3613  [n1,s1,r21/1:/Table/5{0-1}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:12.090604 166731 storage/replica_range_lease.go:554  [replicate,n1,s1,r21/1:/Table/5{0-1}] transferring lease to s4\nI180722 05:17:12.091495 166731 storage/replica_range_lease.go:617  [replicate,n1,s1,r21/1:/Table/5{0-1}] done transferring lease to s4: <nil>\nI180722 05:17:12.092219 164600 storage/replica_proposal.go:222  [n4,s4,r21/2:/Table/5{0-1}] new range lease repl=(n4,s4):2 seq=4 start=1532236632.090628984,0 epo=1 pro=1532236632.090631906,0 following repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236632.074775094,0\nI180722 05:17:13.075473 166718 storage/replica_raftstorage.go:520  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot 93f25f49 at index 94\nI180722 05:17:13.077820 166718 storage/store_snapshot.go:605  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n4,s4):?: kv pairs: 273, log entries: 2, rate-limit: 2.0 MiB/sec, 2ms\nI180722 05:17:13.078318 166883 storage/replica_raftstorage.go:737  [n4,s4,r10/?:{-}] applying preemptive snapshot at index 94 (id=93f25f49, encoded size=29389, 1 rocksdb batches, 2 log entries)\nI180722 05:17:13.078805 166883 storage/replica_raftstorage.go:743  [n4,s4,r10/?:/Table/1{3-4}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:13.079269 166718 storage/replica_command.go:743  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, next=2]\nI180722 05:17:13.086469 166718 storage/replica.go:3613  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:13.092628 166862 storage/replica_range_lease.go:554  [replicate,n1,s1,r10/1:/Table/1{3-4}] transferring lease to s4\nI180722 05:17:13.093426 166862 storage/replica_range_lease.go:617  [replicate,n1,s1,r10/1:/Table/1{3-4}] done transferring lease to s4: <nil>\nI180722 05:17:13.093620 164742 storage/replica_proposal.go:222  [n4,s4,r10/2:/Table/1{3-4}] new range lease repl=(n4,s4):2 seq=4 start=1532236633.092744928,0 epo=1 pro=1532236633.092747850,0 following repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236627.075024885,0\nI180722 05:17:14.075775 163683 storage/replica_proposal.go:222  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236634.075524394,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:14.076660 166996 storage/replica_raftstorage.go:520  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot 84a51cd3 at index 18\nI180722 05:17:14.077434 166996 storage/store_snapshot.go:605  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n4,s4):?: kv pairs: 9, log entries: 8, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:14.077857 166785 storage/replica_raftstorage.go:737  [n4,s4,r13/?:{-}] applying preemptive snapshot at index 18 (id=84a51cd3, encoded size=2551, 1 rocksdb batches, 8 log entries)\nI180722 05:17:14.078077 166785 storage/replica_raftstorage.go:743  [n4,s4,r13/?:/Table/1{6-7}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:14.078547 166996 storage/replica_command.go:743  [replicate,n1,s1,r13/1:/Table/1{6-7}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, next=2]\nI180722 05:17:14.143131 166996 storage/replica.go:3613  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:14.149894 166952 storage/replica_range_lease.go:554  [replicate,n1,s1,r13/1:/Table/1{6-7}] transferring lease to s4\nI180722 05:17:14.150683 166952 storage/replica_range_lease.go:617  [replicate,n1,s1,r13/1:/Table/1{6-7}] done transferring lease to s4: <nil>\nI180722 05:17:14.151098 164763 storage/replica_proposal.go:222  [n4,s4,r13/2:/Table/1{6-7}] new range lease repl=(n4,s4):2 seq=4 start=1532236634.149909747,0 epo=1 pro=1532236634.149912570,0 following repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236634.075524394,0\nI180722 05:17:14.719250 166954 storage/replica_command.go:743  [replicate,n4,s4,r12/2:/Table/1{5-6}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:14.777654 166954 storage/replica.go:3613  [n4,s4,r12/2:/Table/1{5-6}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:14.778982 164979 storage/store.go:3585  [n1,s1,r12/1:/Table/1{5-6}] added to replica GC queue (peer suggestion)\nI180722 05:17:14.836937 167122 storage/store.go:2513  [replicaGC,n1,s1,r12/1:/Table/1{5-6}] removing replica\nI180722 05:17:14.837160 167122 storage/replica.go:836  [replicaGC,n1,s1,r12/1:/Table/1{5-6}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:15.076291 163716 storage/replica_proposal.go:222  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236635.075991394,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:15.077406 167135 storage/replica_raftstorage.go:520  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 9383126e at index 41\nI180722 05:17:15.079042 167135 storage/store_snapshot.go:605  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n4,s4):?: kv pairs: 99, log entries: 31, rate-limit: 2.0 MiB/sec, 2ms\nI180722 05:17:15.079564 167139 storage/replica_raftstorage.go:737  [n4,s4,r9/?:{-}] applying preemptive snapshot at index 41 (id=9383126e, encoded size=26534, 1 rocksdb batches, 31 log entries)\nI180722 05:17:15.079996 167139 storage/replica_raftstorage.go:743  [n4,s4,r9/?:/Table/1{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:15.080492 167135 storage/replica_command.go:743  [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, next=2]\nI180722 05:17:15.088408 167135 storage/replica.go:3613  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:15.093100 167221 storage/replica_range_lease.go:554  [replicate,n1,s1,r9/1:/Table/1{2-3}] transferring lease to s4\nI180722 05:17:15.099101 167221 storage/replica_range_lease.go:617  [replicate,n1,s1,r9/1:/Table/1{2-3}] done transferring lease to s4: <nil>\nI180722 05:17:15.099658 164606 storage/replica_proposal.go:222  [n4,s4,r9/2:/Table/1{2-3}] new range lease repl=(n4,s4):2 seq=4 start=1532236635.093109537,0 epo=1 pro=1532236635.093111686,0 following repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236635.075991394,0\nI180722 05:17:15.649802 163728 storage/compactor/compactor.go:329  [n1,s1,compactor] purging suggested compaction for range /Min - /System/\"\" that contains live data\nI180722 05:17:15.650111 163728 storage/compactor/compactor.go:374  [n1,s1,compactor] processing compaction #1-7/7 (/System/NodeLiveness-/Table/53) for 77 KiB (reasons: size=false used=true avail=false)\nI180722 05:17:15.658104 163728 storage/compactor/compactor.go:390  [n1,s1,compactor] processed compaction #1-7/7 (/System/NodeLiveness-/Table/53) for 77 KiB in 0.0s\nI180722 05:17:15.674724 167104 storage/replica_command.go:743  [replicate,n4,s4,r14/2:/Table/1{7-8}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:15.678270 167104 storage/replica.go:3613  [n4,s4,r14/2:/Table/1{7-8}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:15.679751 164979 storage/store.go:3585  [n1,s1,r14/1:/Table/1{7-8}] added to replica GC queue (peer suggestion)\nI180722 05:17:15.681096 167268 storage/store.go:2513  [replicaGC,n1,s1,r14/1:/Table/1{7-8}] removing replica\nI180722 05:17:15.681470 167268 storage/replica.go:836  [replicaGC,n1,s1,r14/1:/Table/1{7-8}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:16.076818 163696 storage/replica_proposal.go:222  [n1,s1,r19/1:/Table/2{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236636.076390637,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:16.078953 167274 storage/replica_raftstorage.go:520  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot 9ff549fc at index 16\nI180722 05:17:16.079675 167274 storage/store_snapshot.go:605  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n4,s4):?: kv pairs: 8, log entries: 6, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:16.080161 167240 storage/replica_raftstorage.go:737  [n4,s4,r19/?:{-}] applying preemptive snapshot at index 16 (id=9ff549fc, encoded size=2251, 1 rocksdb batches, 6 log entries)\nI180722 05:17:16.080389 167240 storage/replica_raftstorage.go:743  [n4,s4,r19/?:/Table/2{2-3}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:16.081495 167274 storage/replica_command.go:743  [replicate,n1,s1,r19/1:/Table/2{2-3}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, next=2]\nI180722 05:17:16.089867 167274 storage/replica.go:3613  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:16.106770 167260 storage/replica_range_lease.go:554  [replicate,n1,s1,r19/1:/Table/2{2-3}] transferring lease to s4\nI180722 05:17:16.111563 167260 storage/replica_range_lease.go:617  [replicate,n1,s1,r19/1:/Table/2{2-3}] done transferring lease to s4: <nil>\nI180722 05:17:16.112089 164774 storage/replica_proposal.go:222  [n4,s4,r19/2:/Table/2{2-3}] new range lease repl=(n4,s4):2 seq=4 start=1532236636.106793968,0 epo=1 pro=1532236636.106797229,0 following repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236636.076390637,0\nI180722 05:17:17.077297 163704 storage/replica_proposal.go:222  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236637.076932364,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:17.077780 167288 storage/replica_raftstorage.go:520  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot f28764d4 at index 16\nI180722 05:17:17.079158 167288 storage/store_snapshot.go:605  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n4,s4):?: kv pairs: 8, log entries: 6, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:17.079535 167294 storage/replica_raftstorage.go:737  [n4,s4,r15/?:{-}] applying preemptive snapshot at index 16 (id=f28764d4, encoded size=2416, 1 rocksdb batches, 6 log entries)\nI180722 05:17:17.079742 167294 storage/replica_raftstorage.go:743  [n4,s4,r15/?:/Table/1{8-9}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:17.080159 167288 storage/replica_command.go:743  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, next=2]\nI180722 05:17:17.087063 167288 storage/replica.go:3613  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:17.101310 167624 storage/replica_range_lease.go:554  [replicate,n1,s1,r15/1:/Table/1{8-9}] transferring lease to s4\nI180722 05:17:17.102153 167624 storage/replica_range_lease.go:617  [replicate,n1,s1,r15/1:/Table/1{8-9}] done transferring lease to s4: <nil>\nI180722 05:17:17.102165 164605 storage/replica_proposal.go:222  [n4,s4,r15/2:/Table/1{8-9}] new range lease repl=(n4,s4):2 seq=4 start=1532236637.101347421,0 epo=1 pro=1532236637.101351570,0 following repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236637.076932364,0\nI180722 05:17:17.675560 167514 storage/replica_range_lease.go:554  [replicate,n4,s4,r27/2:/{Table/55-Max}] transferring lease to s1\nI180722 05:17:17.676840 163678 storage/replica_proposal.go:222  [n1,s1,r27/1:/{Table/55-Max}] new range lease repl=(n1,s1):1 seq=4 start=1532236637.675576544,0 epo=1 pro=1532236637.675580998,0 following repl=(n4,s4):2 seq=3 start=1532236627.056359920,1 epo=1 pro=1532236630.665563619,0\nI180722 05:17:17.678464 167514 storage/replica_range_lease.go:617  [replicate,n4,s4,r27/2:/{Table/55-Max}] done transferring lease to s1: <nil>\nI180722 05:17:18.062496 163750 server/status/runtime.go:255  [n1] runtime stats: 230 MiB RSS, 1176 goroutines, 30 MiB/51 MiB/114 MiB GO alloc/idle/total, 46 MiB/82 MiB CGO alloc/total, 776.44cgo/sec, 0.07/0.01 %(u/s)time, 0.00 %gc (3x)\nI180722 05:17:18.077890 163683 storage/replica_proposal.go:222  [n1,s1,r6/1:/{System/tse-Table/System…}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236638.077566474,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:18.078699 167520 storage/replica_raftstorage.go:520  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 919670cf at index 22\nI180722 05:17:18.080631 167520 storage/store_snapshot.go:605  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n4,s4):?: kv pairs: 8, log entries: 12, rate-limit: 2.0 MiB/sec, 2ms\nI180722 05:17:18.081058 167470 storage/replica_raftstorage.go:737  [n4,s4,r6/?:{-}] applying preemptive snapshot at index 22 (id=919670cf, encoded size=5821, 1 rocksdb batches, 12 log entries)\nI180722 05:17:18.081296 167470 storage/replica_raftstorage.go:743  [n4,s4,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:18.081690 167520 storage/replica_command.go:743  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, next=2]\nI180722 05:17:18.089423 167520 storage/replica.go:3613  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:18.092937 167740 storage/replica_range_lease.go:554  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] transferring lease to s4\nI180722 05:17:18.093812 167740 storage/replica_range_lease.go:617  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] done transferring lease to s4: <nil>\nI180722 05:17:18.094511 164761 storage/replica_proposal.go:222  [n4,s4,r6/2:/{System/tse-Table/System…}] new range lease repl=(n4,s4):2 seq=4 start=1532236638.093025888,0 epo=1 pro=1532236638.093029371,0 following repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236638.077566474,0\nI180722 05:17:18.443801 164181 server/status/runtime.go:255  [n2] runtime stats: 230 MiB RSS, 1177 goroutines, 39 MiB/43 MiB/114 MiB GO alloc/idle/total, 46 MiB/82 MiB CGO alloc/total, 792.29cgo/sec, 0.07/0.00 %(u/s)time, 0.00 %gc (2x)\nI180722 05:17:18.559275 164414 server/status/runtime.go:255  [n3] runtime stats: 230 MiB RSS, 1176 goroutines, 45 MiB/38 MiB/114 MiB GO alloc/idle/total, 46 MiB/82 MiB CGO alloc/total, 789.96cgo/sec, 0.07/0.01 %(u/s)time, 0.00 %gc (2x)\nI180722 05:17:18.645267 164670 server/status/runtime.go:255  [n4] runtime stats: 232 MiB RSS, 1176 goroutines, 51 MiB/32 MiB/114 MiB GO alloc/idle/total, 46 MiB/83 MiB CGO alloc/total, 792.88cgo/sec, 0.07/0.00 %(u/s)time, 0.00 %gc (2x)\nW180722 05:17:18.658752 164672 server/node.go:892  [n4,summaries] health alerts detected: {Alerts:[{StoreID:4 Category:METRICS Description:queue.replicate.process.failure Value:1}]}\nI180722 05:17:18.676347 167753 storage/replica_command.go:743  [replicate,n4,s4,r5/2:/System/ts{d-e}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:18.679551 167753 storage/replica.go:3613  [n4,s4,r5/2:/System/ts{d-e}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:18.681825 164979 storage/store.go:3585  [n1,s1,r5/1:/System/ts{d-e}] added to replica GC queue (peer suggestion)\nI180722 05:17:18.682732 167664 storage/store.go:2513  [replicaGC,n1,s1,r5/1:/System/ts{d-e}] removing replica\nI180722 05:17:18.684559 167664 storage/replica.go:836  [replicaGC,n1,s1,r5/1:/System/ts{d-e}] removed 1241 (1233+8) keys in 2ms [clear=2ms commit=0ms]\nI180722 05:17:18.757361 164983 storage/store.go:3604  [n4,s4,r5/2:/System/ts{d-e}] added to replica GC queue (contacted deleted peer)\nI180722 05:17:19.078417 163667 storage/replica_proposal.go:222  [n1,s1,r17/1:/Table/2{0-1}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236639.077976802,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:19.080394 167779 storage/replica_raftstorage.go:520  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot 3be54f34 at index 18\nI180722 05:17:19.081200 167779 storage/store_snapshot.go:605  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n4,s4):?: kv pairs: 9, log entries: 8, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:19.081581 167711 storage/replica_raftstorage.go:737  [n4,s4,r17/?:{-}] applying preemptive snapshot at index 18 (id=3be54f34, encoded size=2547, 1 rocksdb batches, 8 log entries)\nI180722 05:17:19.081818 167711 storage/replica_raftstorage.go:743  [n4,s4,r17/?:/Table/2{0-1}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:19.082736 167779 storage/replica_command.go:743  [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, next=2]\nI180722 05:17:19.090277 167779 storage/replica.go:3613  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:19.098442 167871 storage/replica_range_lease.go:554  [replicate,n1,s1,r17/1:/Table/2{0-1}] transferring lease to s4\nI180722 05:17:19.099343 167871 storage/replica_range_lease.go:617  [replicate,n1,s1,r17/1:/Table/2{0-1}] done transferring lease to s4: <nil>\nI180722 05:17:19.099580 164756 storage/replica_proposal.go:222  [n4,s4,r17/2:/Table/2{0-1}] new range lease repl=(n4,s4):2 seq=4 start=1532236639.098474642,0 epo=1 pro=1532236639.098477873,0 following repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236639.077976802,0\nI180722 05:17:20.084704 163690 storage/replica_proposal.go:222  [n1,s1,r16/1:/Table/{19-20}] new range lease repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236640.084398064,0 following repl=(n1,s1):1 seq=2 start=1532236618.056032419,0 exp=1532236627.056359920,0 pro=1532236618.056381736,0\nI180722 05:17:20.086072 167880 storage/replica_raftstorage.go:520  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot 1c3f714e at index 18\nI180722 05:17:20.086685 167880 storage/store_snapshot.go:605  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n4,s4):?: kv pairs: 9, log entries: 8, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:20.087072 167762 storage/replica_raftstorage.go:737  [n4,s4,r16/?:{-}] applying preemptive snapshot at index 18 (id=1c3f714e, encoded size=2551, 1 rocksdb batches, 8 log entries)\nI180722 05:17:20.087277 167762 storage/replica_raftstorage.go:743  [n4,s4,r16/?:/Table/{19-20}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:20.087636 167880 storage/replica_command.go:743  [replicate,n1,s1,r16/1:/Table/{19-20}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r16:/Table/{19-20} [(n1,s1):1, next=2]\nI180722 05:17:20.094569 167880 storage/replica.go:3613  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3\nI180722 05:17:20.106927 167968 storage/replica_range_lease.go:554  [replicate,n1,s1,r16/1:/Table/{19-20}] transferring lease to s4\nI180722 05:17:20.107808 164777 storage/replica_proposal.go:222  [n4,s4,r16/2:/Table/{19-20}] new range lease repl=(n4,s4):2 seq=4 start=1532236640.107033449,0 epo=1 pro=1532236640.107035632,0 following repl=(n1,s1):1 seq=3 start=1532236618.056032419,0 epo=1 pro=1532236640.084398064,0\nI180722 05:17:20.107863 167968 storage/replica_range_lease.go:617  [replicate,n1,s1,r16/1:/Table/{19-20}] done transferring lease to s4: <nil>\nI180722 05:17:21.689860 167946 storage/replica_command.go:743  [replicate,n4,s4,r20/2:/Table/{23-50}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r20:/Table/{23-50} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:21.692792 167946 storage/replica.go:3613  [n4,s4,r20/2:/Table/{23-50}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:21.696338 164979 storage/store.go:3585  [n1,s1,r20/1:/Table/{23-50}] added to replica GC queue (peer suggestion)\nI180722 05:17:21.710023 168103 storage/store.go:2513  [replicaGC,n1,s1,r20/1:/Table/{23-50}] removing replica\nI180722 05:17:21.710283 168103 storage/replica.go:836  [replicaGC,n1,s1,r20/1:/Table/{23-50}] removed 12 (4+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:22.690120 167919 storage/replica_command.go:743  [replicate,n4,s4,r18/2:/Table/2{1-2}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:22.693596 167919 storage/replica.go:3613  [n4,s4,r18/2:/Table/2{1-2}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:22.696693 164979 storage/store.go:3585  [n1,s1,r18/1:/Table/2{1-2}] added to replica GC queue (peer suggestion)\nI180722 05:17:22.696775 167887 storage/store.go:2513  [replicaGC,n1,s1,r18/1:/Table/2{1-2}] removing replica\nI180722 05:17:22.697002 167887 storage/replica.go:836  [replicaGC,n1,s1,r18/1:/Table/2{1-2}] removed 9 (0+9) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:23.691204 168074 storage/replica_command.go:743  [replicate,n4,s4,r2/2:/System/{-NodeLive…}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:23.694704 168074 storage/replica.go:3613  [n4,s4,r2/2:/System/{-NodeLive…}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:23.696796 164979 storage/store.go:3585  [n1,s1,r2/1:/System/{-NodeLive…}] added to replica GC queue (peer suggestion)\nI180722 05:17:23.696805 168133 storage/store.go:2513  [replicaGC,n1,s1,r2/1:/System/{-NodeLive…}] removing replica\nI180722 05:17:23.697057 168133 storage/replica.go:836  [replicaGC,n1,s1,r2/1:/System/{-NodeLive…}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:24.088571 168136 storage/replica_range_lease.go:554  [replicate,n1,s1,r27/1:/{Table/55-Max}] transferring lease to s4\nI180722 05:17:24.089776 168136 storage/replica_range_lease.go:617  [replicate,n1,s1,r27/1:/{Table/55-Max}] done transferring lease to s4: <nil>\nI180722 05:17:24.090218 164783 storage/replica_proposal.go:222  [n4,s4,r27/2:/{Table/55-Max}] new range lease repl=(n4,s4):2 seq=5 start=1532236644.088593303,0 epo=1 pro=1532236644.088596900,0 following repl=(n1,s1):1 seq=4 start=1532236637.675576544,0 epo=1 pro=1532236637.675580998,0\nI180722 05:17:24.186363 163572 gossip/gossip.go:1339  [n1] node has connected to cluster via gossip\nI180722 05:17:24.186565 163572 storage/stores.go:241  [n1] wrote 3 node addresses to persistent storage\nI180722 05:17:24.690791 168113 storage/replica_command.go:743  [replicate,n4,s4,r10/2:/Table/1{3-4}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:24.693845 168113 storage/replica.go:3613  [n4,s4,r10/2:/Table/1{3-4}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:24.694954 164979 storage/store.go:3585  [n1,s1,r10/1:/Table/1{3-4}] added to replica GC queue (peer suggestion)\nI180722 05:17:24.695469 168139 storage/store.go:2513  [replicaGC,n1,s1,r10/1:/Table/1{3-4}] removing replica\nI180722 05:17:24.695727 168139 storage/replica.go:836  [replicaGC,n1,s1,r10/1:/Table/1{3-4}] removed 348 (340+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:24.772054 164641 gossip/gossip.go:1339  [n4] node has connected to cluster via gossip\nI180722 05:17:24.772238 164641 storage/stores.go:241  [n4] wrote 3 node addresses to persistent storage\nI180722 05:17:27.691693 168245 storage/replica_command.go:743  [replicate,n4,s4,r11/2:/Table/1{4-5}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:27.694792 168245 storage/replica.go:3613  [n4,s4,r11/2:/Table/1{4-5}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:27.696777 164979 storage/store.go:3585  [n1,s1,r11/1:/Table/1{4-5}] added to replica GC queue (peer suggestion)\nI180722 05:17:27.696974 168248 storage/store.go:2513  [replicaGC,n1,s1,r11/1:/Table/1{4-5}] removing replica\nI180722 05:17:27.697182 168248 storage/replica.go:836  [replicaGC,n1,s1,r11/1:/Table/1{4-5}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:28.059692 163750 server/status/runtime.go:255  [n1] runtime stats: 234 MiB RSS, 1178 goroutines, 44 MiB/41 MiB/114 MiB GO alloc/idle/total, 48 MiB/86 MiB CGO alloc/total, 377.11cgo/sec, 0.04/0.01 %(u/s)time, 0.00 %gc (1x)\nI180722 05:17:28.090753 168264 storage/replica_range_lease.go:554  [replicate,n1,s1,r26/1:/Table/5{4-5}] transferring lease to s4\nI180722 05:17:28.091769 168264 storage/replica_range_lease.go:617  [replicate,n1,s1,r26/1:/Table/5{4-5}] done transferring lease to s4: <nil>\nI180722 05:17:28.092531 164764 storage/replica_proposal.go:222  [n4,s4,r26/2:/Table/5{4-5}] new range lease repl=(n4,s4):2 seq=5 start=1532236648.090777211,0 epo=1 pro=1532236648.090779985,0 following repl=(n1,s1):1 seq=4 start=1532236625.664529950,0 epo=1 pro=1532236625.664532882,0\nI180722 05:17:28.445837 164181 server/status/runtime.go:255  [n2] runtime stats: 234 MiB RSS, 1178 goroutines, 51 MiB/35 MiB/114 MiB GO alloc/idle/total, 48 MiB/86 MiB CGO alloc/total, 333.43cgo/sec, 0.04/0.01 %(u/s)time, 0.00 %gc (1x)\nI180722 05:17:28.449073 164090 rpc/nodedialer/nodedialer.go:90  [intExec=adopt-job] connection to n1 established\nI180722 05:17:28.449704 168312 rpc/nodedialer/nodedialer.go:90  [n1] connection to n2 established\nI180722 05:17:28.558728 164414 server/status/runtime.go:255  [n3] runtime stats: 236 MiB RSS, 1177 goroutines, 57 MiB/30 MiB/114 MiB GO alloc/idle/total, 48 MiB/86 MiB CGO alloc/total, 334.62cgo/sec, 0.04/0.01 %(u/s)time, 0.00 %gc (1x)\nI180722 05:17:28.565501 164363 rpc/nodedialer/nodedialer.go:90  [intExec=adopt-job] connection to n4 established\nI180722 05:17:28.566107 168341 rpc/nodedialer/nodedialer.go:90  [n4] connection to n3 established\nI180722 05:17:28.646510 164670 server/status/runtime.go:255  [n4] runtime stats: 238 MiB RSS, 1177 goroutines, 34 MiB/47 MiB/114 MiB GO alloc/idle/total, 48 MiB/86 MiB CGO alloc/total, 337.66cgo/sec, 0.04/0.01 %(u/s)time, 0.00 %gc (2x)\nI180722 05:17:28.760683 168355 storage/replica_command.go:743  [replicate,n4,s4,r6/2:/{System/tse-Table/System…}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:28.764035 168355 storage/replica.go:3613  [n4,s4,r6/2:/{System/tse-Table/System…}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:28.766246 164979 storage/store.go:3585  [n1,s1,r6/1:/{System/tse-Table/System…}] added to replica GC queue (peer suggestion)\nI180722 05:17:28.766542 168329 storage/store.go:2513  [replicaGC,n1,s1,r6/1:/{System/tse-Table/System…}] removing replica\nI180722 05:17:28.766809 168329 storage/replica.go:836  [replicaGC,n1,s1,r6/1:/{System/tse-Table/System…}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:29.745787 168242 storage/replica_command.go:743  [replicate,n4,s4,r16/2:/Table/{19-20}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r16:/Table/{19-20} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:29.749334 168242 storage/replica.go:3613  [n4,s4,r16/2:/Table/{19-20}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:29.752377 164979 storage/store.go:3585  [n1,s1,r16/1:/Table/{19-20}] added to replica GC queue (peer suggestion)\nI180722 05:17:29.797053 168435 storage/store.go:2513  [replicaGC,n1,s1,r16/1:/Table/{19-20}] removing replica\nI180722 05:17:29.797318 168435 storage/replica.go:836  [replicaGC,n1,s1,r16/1:/Table/{19-20}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:30.656486 164133 gossip/gossip.go:1339  [n2] node has connected to cluster via gossip\nI180722 05:17:30.656730 164133 storage/stores.go:241  [n2] wrote 3 node addresses to persistent storage\nI180722 05:17:31.699843 168447 storage/replica_command.go:743  [replicate,n4,s4,r17/2:/Table/2{0-1}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:31.706189 168447 storage/replica.go:3613  [n4,s4,r17/2:/Table/2{0-1}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:31.709263 164979 storage/store.go:3585  [n1,s1,r17/1:/Table/2{0-1}] added to replica GC queue (peer suggestion)\nI180722 05:17:31.709825 168450 storage/store.go:2513  [replicaGC,n1,s1,r17/1:/Table/2{0-1}] removing replica\nI180722 05:17:31.710155 168450 storage/replica.go:836  [replicaGC,n1,s1,r17/1:/Table/2{0-1}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:32.529042 164390 gossip/gossip.go:1339  [n3] node has connected to cluster via gossip\nI180722 05:17:32.529226 164390 storage/stores.go:241  [n3] wrote 3 node addresses to persistent storage\nI180722 05:17:33.686562 163728 storage/compactor/compactor.go:374  [n1,s1,compactor] processing compaction #1-10/10 (/System/\"\"-/Table/50) for 298 KiB (reasons: size=false used=true avail=false)\nI180722 05:17:33.694212 163728 storage/compactor/compactor.go:390  [n1,s1,compactor] processed compaction #1-10/10 (/System/\"\"-/Table/50) for 298 KiB in 0.0s\nI180722 05:17:35.701039 168547 storage/replica_range_lease.go:554  [replicate,n4,s4,r26/2:/Table/5{4-5}] transferring lease to s1\nI180722 05:17:35.702534 168547 storage/replica_range_lease.go:617  [replicate,n4,s4,r26/2:/Table/5{4-5}] done transferring lease to s1: <nil>\nI180722 05:17:35.702974 163714 storage/replica_proposal.go:222  [n1,s1,r26/1:/Table/5{4-5}] new range lease repl=(n1,s1):1 seq=6 start=1532236655.701063419,0 epo=1 pro=1532236655.701067751,0 following repl=(n4,s4):2 seq=5 start=1532236648.090777211,0 epo=1 pro=1532236648.090779985,0\nI180722 05:17:37.095889 168550 storage/replica_range_lease.go:554  [replicate,n1,s1,r26/1:/Table/5{4-5}] transferring lease to s4\nI180722 05:17:37.096943 168550 storage/replica_range_lease.go:617  [replicate,n1,s1,r26/1:/Table/5{4-5}] done transferring lease to s4: <nil>\nI180722 05:17:37.097646 164738 storage/replica_proposal.go:222  [n4,s4,r26/2:/Table/5{4-5}] new range lease repl=(n4,s4):2 seq=7 start=1532236657.095908122,0 epo=1 pro=1532236657.095910622,0 following repl=(n1,s1):1 seq=6 start=1532236655.701063419,0 epo=1 pro=1532236655.701067751,0\nI180722 05:17:38.059954 163750 server/status/runtime.go:255  [n1] runtime stats: 236 MiB RSS, 1176 goroutines, 47 MiB/37 MiB/114 MiB GO alloc/idle/total, 48 MiB/83 MiB CGO alloc/total, 183.49cgo/sec, 0.03/0.00 %(u/s)time, 0.00 %gc (1x)\nI180722 05:17:38.443860 164181 server/status/runtime.go:255  [n2] runtime stats: 236 MiB RSS, 1176 goroutines, 52 MiB/32 MiB/114 MiB GO alloc/idle/total, 48 MiB/83 MiB CGO alloc/total, 172.53cgo/sec, 0.03/0.00 %(u/s)time, 0.00 %gc (1x)\nI180722 05:17:38.558677 164414 server/status/runtime.go:255  [n3] runtime stats: 236 MiB RSS, 1176 goroutines, 31 MiB/51 MiB/114 MiB GO alloc/idle/total, 48 MiB/83 MiB CGO alloc/total, 170.20cgo/sec, 0.04/0.00 %(u/s)time, 0.00 %gc (2x)\nI180722 05:17:38.645485 164670 server/status/runtime.go:255  [n4] runtime stats: 236 MiB RSS, 1176 goroutines, 37 MiB/45 MiB/114 MiB GO alloc/idle/total, 48 MiB/83 MiB CGO alloc/total, 167.82cgo/sec, 0.03/0.00 %(u/s)time, 0.00 %gc (1x)\nI180722 05:17:38.702388 168576 storage/replica_command.go:743  [replicate,n4,s4,r27/2:/{Table/55-Max}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r27:/{Table/55-Max} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:38.705548 168576 storage/replica.go:3613  [n4,s4,r27/2:/{Table/55-Max}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:38.706595 164979 storage/store.go:3585  [n1,s1,r27/1:/{Table/55-Max}] added to replica GC queue (peer suggestion)\nI180722 05:17:38.706693 168615 storage/replica_raftstorage.go:520  [replicate,n4,s4,r27/2:/{Table/55-Max}] generated preemptive snapshot a4b2b613 at index 23\nI180722 05:17:38.706757 168615 rpc/nodedialer/nodedialer.go:90  [replicate,n4,s4,r27/2:/{Table/55-Max}] connection to n3 established\nI180722 05:17:38.707743 168615 storage/store_snapshot.go:605  [replicate,n4,s4,r27/2:/{Table/55-Max}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 13, rate-limit: 2.0 MiB/sec, 1ms\nI180722 05:17:38.707838 168476 storage/store.go:2513  [replicaGC,n1,s1,r27/1:/{Table/55-Max}] removing replica\nI180722 05:17:38.708049 168476 storage/replica.go:836  [replicaGC,n1,s1,r27/1:/{Table/55-Max}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:38.708084 168479 storage/replica_raftstorage.go:737  [n3,s3,r27/?:{-}] applying preemptive snapshot at index 23 (id=a4b2b613, encoded size=2633, 1 rocksdb batches, 13 log entries)\nI180722 05:17:38.708326 168479 storage/replica_raftstorage.go:743  [n3,s3,r27/?:/{Table/55-Max}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\nI180722 05:17:38.708661 168615 storage/replica_command.go:743  [replicate,n4,s4,r27/2:/{Table/55-Max}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r27:/{Table/55-Max} [(n4,s4):2, next=3]\nI180722 05:17:38.711299 168615 storage/replica.go:3613  [n4,s4,r27/2:/{Table/55-Max}] proposing ADD_REPLICA((n3,s3):3): updated=[(n4,s4):2 (n3,s3):3] next=4\nI180722 05:17:38.720746 164489 rpc/nodedialer/nodedialer.go:90  [n3] connection to n4 established\nI180722 05:17:38.721655 168632 storage/replica_range_lease.go:554  [replicate,n4,s4,r27/2:/{Table/55-Max}] transferring lease to s3\nI180722 05:17:38.722456 168632 storage/replica_range_lease.go:617  [replicate,n4,s4,r27/2:/{Table/55-Max}] done transferring lease to s3: <nil>\nI180722 05:17:38.722550 164493 storage/replica_proposal.go:222  [n3,s3,r27/3:/{Table/55-Max}] new range lease repl=(n3,s3):3 seq=6 start=1532236658.721669292,0 epo=1 pro=1532236658.721671241,0 following repl=(n4,s4):2 seq=5 start=1532236644.088593303,0 epo=1 pro=1532236644.088596900,0\nI180722 05:17:39.704299 168640 storage/replica_command.go:743  [replicate,n4,s4,r9/2:/Table/1{2-3}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:39.706933 168640 storage/replica.go:3613  [n4,s4,r9/2:/Table/1{2-3}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:39.708616 164979 storage/store.go:3585  [n1,s1,r9/1:/Table/1{2-3}] added to replica GC queue (peer suggestion)\nI180722 05:17:39.767858 168814 storage/store.go:2513  [replicaGC,n1,s1,r9/1:/Table/1{2-3}] removing replica\nI180722 05:17:39.768083 168814 storage/replica.go:836  [replicaGC,n1,s1,r9/1:/Table/1{2-3}] removed 98 (90+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:40.664660 168822 storage/replica_command.go:743  [replicate,n3,s3,r27/3:/{Table/55-Max}] change replicas (REMOVE_REPLICA (n4,s4):2): read existing descriptor r27:/{Table/55-Max} [(n4,s4):2, (n3,s3):3, next=4]\nI180722 05:17:40.671872 168822 storage/replica.go:3613  [n3,s3,r27/3:/{Table/55-Max}] proposing REMOVE_REPLICA((n4,s4):2): updated=[(n3,s3):3] next=4\nI180722 05:17:40.672984 168631 storage/store.go:3585  [n4,s4,r27/2:/{Table/55-Max}] added to replica GC queue (peer suggestion)\nI180722 05:17:40.673336 168871 storage/store.go:2513  [replicaGC,n4,s4,r27/2:/{Table/55-Max}] removing replica\nI180722 05:17:40.673599 168871 storage/replica.go:836  [replicaGC,n4,s4,r27/2:/{Table/55-Max}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\nI180722 05:17:41.759791 168902 storage/replica_command.go:743  [replicate,n4,s4,r15/2:/Table/1{8-9}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, (n4,s4):2, next=3]\nI180722 05:17:41.762741 168902 storage/replica.go:3613  [n4,s4,r15/2:/Table/1{8-9}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n4,s4):2] next=3\nI180722 05:17:41.763578 164979 storage/store.go:3585  [n1,s1,r15/1:/Table/1{8-9}] added to replica GC queue (peer suggestion)\nI180722 05:17:41.813957 168853 storage/store.go:2513  [replicaGC,n1,s1,r15/1:/Table/1{8-9}] removing replica\nI180722 05:17:41.814249 168853 storage/replica.go:836  [replicaGC,n1,s1,r15/1:/Table/1{8-9}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]\n    --- FAIL: TestShowTraceReplica/UPSERT_INTO_d.t2_VALUES_(1) (45.39s)\n    \tshow_trace_replica_test.go:101: condition failed to evaluate within 45s: UPSERT INTO d.t2 VALUES (1): got [[4 4]] expected [[2 2]]\n    \t\tgoroutine 165032 [running]:\n    \t\truntime/debug.Stack(0xa7a358200, 0xc423b19f78, 0x2958dc0)\n    \t\t\t/usr/local/go/src/runtime/debug/stack.go:24 +0xa7\n    \t\tgithub.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x29a60e0, 0xc420995680, 0xc423244f78)\n    \t\t\t/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:38 +0x7d\n    \t\tgithub.com/cockroachdb/cockroach/pkg/sql_test.TestShowTraceReplica.func2(0xc420995680)\n    \t\t\t/go/src/github.com/cockroachdb/cockroach/pkg/sql/show_trace_replica_test.go:101 +0x64\n    \t\ttesting.tRunner(0xc420995680, 0xc420930da0)\n    \t\t\t/usr/local/go/src/testing/testing.go:777 +0xd0\n    \t\tcreated by testing.(*T).Run\n    \t\t\t/usr/local/go/src/testing/testing.go:824 +0x2e0\n\n```"}}
{"actor":{"display_login":"benesch"}}