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

github.com/cockroachdb/cockroach/pkg/storage: TestReplicateQueueDownReplicate failed under stress #27736

Closed
cockroach-teamcity opened this issue Jul 19, 2018 · 1 comment
Closed

github.com/cockroachdb/cockroach/pkg/storage: TestReplicateQueueDownReplicate failed under stress #27736

cockroach-teamcity opened this issue Jul 19, 2018 · 1 comment
Assignees
@tbg
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone
2.1

Comments

@cockroach-teamcity
Copy link
Member

SHA: https://github.com/cockroachdb/cockroach/commits/6b49d8cf1b8130a21698c74f541964dfd6a4e3c8

Parameters:

TAGS=
GOFLAGS=

Failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=785908&tab=buildLog

I180719 05:31:41.410904 121776 storage/replica_raftstorage.go:520  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot de4a4390 at index 21
I180719 05:31:41.411944 121776 storage/store_snapshot.go:605  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n3,s3):?: kv pairs: 10, log entries: 11, rate-limit: 2.0 MiB/sec, 1ms
I180719 05:31:41.412400 121940 storage/replica_raftstorage.go:737  [n3,s3,r15/?:{-}] applying preemptive snapshot at index 21 (id=de4a4390, encoded size=4335, 1 rocksdb batches, 11 log entries)
I180719 05:31:41.413477 121940 storage/replica_raftstorage.go:743  [n3,s3,r15/?:/Table/1{8-9}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180719 05:31:41.413866 121776 storage/replica_command.go:743  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n3,s3):4): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, (n5,s5):2, (n4,s4):3, next=4]
I180719 05:31:41.420009 121776 storage/replica.go:3613  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n3,s3):4): updated=[(n1,s1):1 (n5,s5):2 (n4,s4):3 (n3,s3):4] next=5
I180719 05:31:41.428905 121897 storage/replica_range_lease.go:554  [replicate,n1,s1,r15/1:/Table/1{8-9}] transferring lease to s4
I180719 05:31:41.431875 120798 rpc/nodedialer/nodedialer.go:90  [n4] connection to n2 established
I180719 05:31:41.433645 120204 rpc/nodedialer/nodedialer.go:90  [n2] connection to n4 established
I180719 05:31:41.434420 121897 storage/replica_range_lease.go:617  [replicate,n1,s1,r15/1:/Table/1{8-9}] done transferring lease to s4: <nil>
I180719 05:31:41.434796 121925 storage/replica_raftstorage.go:520  [replicate,n1,s1,r20/1:/Table/{23-50}] generated preemptive snapshot df9875cf at index 21
I180719 05:31:41.435457 120761 storage/replica_proposal.go:222  [n4,s4,r15/3:/Table/1{8-9}] new range lease repl=(n4,s4):3 seq=3 start=1531978301.428922107,0 epo=1 pro=1531978301.428925915,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.445124 121925 storage/store_snapshot.go:605  [replicate,n1,s1,r20/1:/Table/{23-50}] streamed snapshot to (n3,s3):?: kv pairs: 14, log entries: 11, rate-limit: 2.0 MiB/sec, 10ms
I180719 05:31:41.449746 121857 storage/replica_raftstorage.go:737  [n3,s3,r20/?:{-}] applying preemptive snapshot at index 21 (id=df9875cf, encoded size=4298, 1 rocksdb batches, 11 log entries)
I180719 05:31:41.450378 121857 storage/replica_raftstorage.go:743  [n3,s3,r20/?:/Table/{23-50}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180719 05:31:41.450812 120204 rpc/nodedialer/nodedialer.go:90  [n2] connection to n3 established
I180719 05:31:41.451848 121925 storage/replica_command.go:743  [replicate,n1,s1,r20/1:/Table/{23-50}] change replicas (ADD_REPLICA (n3,s3):4): read existing descriptor r20:/Table/{23-50} [(n1,s1):1, (n2,s2):2, (n5,s5):3, next=4]
I180719 05:31:41.455247 122003 rpc/nodedialer/nodedialer.go:90  [replica consistency checker,n1,s1,r1/1:/{Min-System/}] connection to n1 established
I180719 05:31:41.456298 121925 storage/replica.go:3613  [n1,s1,r20/1:/Table/{23-50}] proposing ADD_REPLICA((n3,s3):4): updated=[(n1,s1):1 (n2,s2):2 (n5,s5):3 (n3,s3):4] next=5
I180719 05:31:41.457285 121983 storage/replica_range_lease.go:554  [replicate,n1,s1,r20/1:/Table/{23-50}] transferring lease to s2
I180719 05:31:41.458241 121983 storage/replica_range_lease.go:617  [replicate,n1,s1,r20/1:/Table/{23-50}] done transferring lease to s2: <nil>
I180719 05:31:41.458340 119888 storage/replica_proposal.go:222  [n2,s2,r20/2:/Table/{23-50}] new range lease repl=(n2,s2):2 seq=3 start=1531978301.457299312,0 epo=1 pro=1531978301.457301739,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.458681 122053 storage/replica_raftstorage.go:520  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot 7860afa6 at index 38
I180719 05:31:41.460382 122053 storage/store_snapshot.go:605  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 65, log entries: 28, rate-limit: 2.0 MiB/sec, 2ms
I180719 05:31:41.460761 122056 storage/replica_raftstorage.go:737  [n2,s2,r9/?:{-}] applying preemptive snapshot at index 38 (id=7860afa6, encoded size=23701, 1 rocksdb batches, 28 log entries)
I180719 05:31:41.463785 122056 storage/replica_raftstorage.go:743  [n2,s2,r9/?:/Table/1{2-3}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=3ms commit=0ms]
I180719 05:31:41.466298 122053 storage/replica_command.go:743  [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n2,s2):4): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, (n3,s3):2, (n4,s4):3, next=4]
I180719 05:31:41.468965 120421 rpc/nodedialer/nodedialer.go:90  [n3] connection to n2 established
I180719 05:31:41.471095 122053 storage/replica.go:3613  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n2,s2):4): updated=[(n1,s1):1 (n3,s3):2 (n4,s4):3 (n2,s2):4] next=5
I180719 05:31:41.472150 122075 storage/replica_range_lease.go:554  [replicate,n1,s1,r9/1:/Table/1{2-3}] transferring lease to s3
I180719 05:31:41.473291 122075 storage/replica_range_lease.go:617  [replicate,n1,s1,r9/1:/Table/1{2-3}] done transferring lease to s3: <nil>
I180719 05:31:41.473533 120441 storage/replica_proposal.go:222  [n3,s3,r9/2:/Table/1{2-3}] new range lease repl=(n3,s3):2 seq=3 start=1531978301.472162428,0 epo=1 pro=1531978301.472164782,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.475468 122043 storage/replica_raftstorage.go:520  [replicate,n1,s1,r22/1:/{Table/51-Max}] generated preemptive snapshot e02e2a0f at index 17
I180719 05:31:41.476037 122043 storage/store_snapshot.go:605  [replicate,n1,s1,r22/1:/{Table/51-Max}] streamed snapshot to (n3,s3):?: kv pairs: 9, log entries: 7, rate-limit: 2.0 MiB/sec, 0ms
I180719 05:31:41.476456 122046 storage/replica_raftstorage.go:737  [n3,s3,r22/?:{-}] applying preemptive snapshot at index 17 (id=e02e2a0f, encoded size=2466, 1 rocksdb batches, 7 log entries)
I180719 05:31:41.477098 122046 storage/replica_raftstorage.go:743  [n3,s3,r22/?:/{Table/51-Max}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180719 05:31:41.477592 122043 storage/replica_command.go:743  [replicate,n1,s1,r22/1:/{Table/51-Max}] change replicas (ADD_REPLICA (n3,s3):4): read existing descriptor r22:/{Table/51-Max} [(n1,s1):1, (n5,s5):2, (n4,s4):3, next=4]
I180719 05:31:41.482253 122043 storage/replica.go:3613  [n1,s1,r22/1:/{Table/51-Max}] proposing ADD_REPLICA((n3,s3):4): updated=[(n1,s1):1 (n5,s5):2 (n4,s4):3 (n3,s3):4] next=5
I180719 05:31:41.483294 122105 storage/replica_range_lease.go:554  [replicate,n1,s1,r22/1:/{Table/51-Max}] transferring lease to s5
I180719 05:31:41.484528 122105 storage/replica_range_lease.go:617  [replicate,n1,s1,r22/1:/{Table/51-Max}] done transferring lease to s5: <nil>
I180719 05:31:41.484760 121090 storage/replica_proposal.go:222  [n5,s5,r22/2:/{Table/51-Max}] new range lease repl=(n5,s5):2 seq=3 start=1531978301.483352691,0 epo=1 pro=1531978301.483355618,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.487642 122089 storage/replica_raftstorage.go:520  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot ad3bdba2 at index 21
I180719 05:31:41.492996 122089 storage/store_snapshot.go:605  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 11, rate-limit: 2.0 MiB/sec, 5ms
I180719 05:31:41.493351 122050 storage/replica_raftstorage.go:737  [n2,s2,r12/?:{-}] applying preemptive snapshot at index 21 (id=ad3bdba2, encoded size=4331, 1 rocksdb batches, 11 log entries)
I180719 05:31:41.494213 122050 storage/replica_raftstorage.go:743  [n2,s2,r12/?:/Table/1{5-6}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180719 05:31:41.494832 122089 storage/replica_command.go:743  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n2,s2):4): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, (n5,s5):2, (n4,s4):3, next=4]
I180719 05:31:41.499820 122089 storage/replica.go:3613  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n2,s2):4): updated=[(n1,s1):1 (n5,s5):2 (n4,s4):3 (n2,s2):4] next=5
I180719 05:31:41.500799 122132 storage/replica_range_lease.go:554  [replicate,n1,s1,r12/1:/Table/1{5-6}] transferring lease to s5
I180719 05:31:41.502577 121048 storage/replica_proposal.go:222  [n5,s5,r12/2:/Table/1{5-6}] new range lease repl=(n5,s5):2 seq=3 start=1531978301.500812279,0 epo=1 pro=1531978301.500814836,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.503107 122132 storage/replica_range_lease.go:617  [replicate,n1,s1,r12/1:/Table/1{5-6}] done transferring lease to s5: <nil>
I180719 05:31:41.503788 121904 storage/replica_raftstorage.go:520  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot e0aef0ba at index 34
I180719 05:31:41.504508 121904 storage/store_snapshot.go:605  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 61, log entries: 24, rate-limit: 2.0 MiB/sec, 1ms
I180719 05:31:41.504827 122180 storage/replica_raftstorage.go:737  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 34 (id=e0aef0ba, encoded size=17837, 1 rocksdb batches, 24 log entries)
I180719 05:31:41.506333 122180 storage/replica_raftstorage.go:743  [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180719 05:31:41.506721 121904 storage/replica_command.go:743  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n2,s2):4): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n4,s4):2, (n5,s5):3, next=4]
I180719 05:31:41.511507 121904 storage/replica.go:3613  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n2,s2):4): updated=[(n1,s1):1 (n4,s4):2 (n5,s5):3 (n2,s2):4] next=5
I180719 05:31:41.512512 122198 storage/replica_range_lease.go:554  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] transferring lease to s4
I180719 05:31:41.513682 122198 storage/replica_range_lease.go:617  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] done transferring lease to s4: <nil>
I180719 05:31:41.513911 120800 storage/replica_proposal.go:222  [n4,s4,r7/2:/Table/{SystemCon…-11}] new range lease repl=(n4,s4):2 seq=3 start=1531978301.512550110,0 epo=1 pro=1531978301.512552905,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.514016 122136 storage/replica_raftstorage.go:520  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 347ca1f2 at index 186
I180719 05:31:41.516389 122136 storage/store_snapshot.go:605  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n5,s5):?: kv pairs: 113, log entries: 14, rate-limit: 2.0 MiB/sec, 2ms
I180719 05:31:41.516717 122153 storage/replica_raftstorage.go:737  [n5,s5,r1/?:{-}] applying preemptive snapshot at index 186 (id=347ca1f2, encoded size=7699, 1 rocksdb batches, 14 log entries)
I180719 05:31:41.517629 122153 storage/replica_raftstorage.go:743  [n5,s5,r1/?:/{Min-System/}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180719 05:31:41.517990 122136 storage/replica_command.go:743  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n5,s5):4): read existing descriptor r1:/{Min-System/} [(n1,s1):1, (n2,s2):2, (n3,s3):3, next=4]
I180719 05:31:41.526726 122136 storage/replica.go:3613  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n5,s5):4): updated=[(n1,s1):1 (n2,s2):2 (n3,s3):3 (n5,s5):4] next=5
I180719 05:31:41.527817 122096 storage/replica_range_lease.go:554  [replicate,n1,s1,r1/1:/{Min-System/}] transferring lease to s2
I180719 05:31:41.529628 122096 storage/replica_range_lease.go:617  [replicate,n1,s1,r1/1:/{Min-System/}] done transferring lease to s2: <nil>
I180719 05:31:41.529995 122029 storage/replica_raftstorage.go:520  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot 716f5594 at index 21
I180719 05:31:41.530555 122029 storage/store_snapshot.go:605  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n5,s5):?: kv pairs: 10, log entries: 11, rate-limit: 2.0 MiB/sec, 0ms
I180719 05:31:41.530912 122291 storage/replica_raftstorage.go:737  [n5,s5,r18/?:{-}] applying preemptive snapshot at index 21 (id=716f5594, encoded size=4170, 1 rocksdb batches, 11 log entries)
I180719 05:31:41.531841 122291 storage/replica_raftstorage.go:743  [n5,s5,r18/?:/Table/2{1-2}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180719 05:31:41.532660 122029 storage/replica_command.go:743  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n5,s5):4): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4]
I180719 05:31:41.538691 119429 storage/replica_command.go:279  [n1,s1,r6/1:/{System/tse-Table/System…}] initiating a split of this range at key "m" [r23]
I180719 05:31:41.542649 122029 storage/replica.go:3613  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n5,s5):4): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3 (n5,s5):4] next=5
I180719 05:31:41.543813 122293 storage/replica_range_lease.go:554  [replicate,n1,s1,r18/1:/Table/2{1-2}] transferring lease to s3
I180719 05:31:41.545232 122293 storage/replica_range_lease.go:617  [replicate,n1,s1,r18/1:/Table/2{1-2}] done transferring lease to s3: <nil>
I180719 05:31:41.545677 122269 storage/replica_raftstorage.go:520  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot 8dc7c8c8 at index 21
I180719 05:31:41.545243 120454 storage/replica_proposal.go:222  [n3,s3,r18/2:/Table/2{1-2}] new range lease repl=(n3,s3):2 seq=3 start=1531978301.543823369,0 epo=1 pro=1531978301.543825973,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.547802 122269 storage/store_snapshot.go:605  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n5,s5):?: kv pairs: 10, log entries: 11, rate-limit: 2.0 MiB/sec, 2ms
I180719 05:31:41.548210 122252 storage/replica_raftstorage.go:737  [n5,s5,r13/?:{-}] applying preemptive snapshot at index 21 (id=8dc7c8c8, encoded size=4335, 1 rocksdb batches, 11 log entries)
I180719 05:31:41.549055 122252 storage/replica_raftstorage.go:743  [n5,s5,r13/?:/Table/1{6-7}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180719 05:31:41.549494 122269 storage/replica_command.go:743  [replicate,n1,s1,r13/1:/Table/1{6-7}] change replicas (ADD_REPLICA (n5,s5):4): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, (n4,s4):2, (n2,s2):3, next=4]
I180719 05:31:41.562686 122269 storage/replica.go:3613  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n5,s5):4): updated=[(n1,s1):1 (n4,s4):2 (n2,s2):3 (n5,s5):4] next=5
I180719 05:31:41.563747 122374 storage/replica_range_lease.go:554  [replicate,n1,s1,r13/1:/Table/1{6-7}] transferring lease to s4
I180719 05:31:41.564690 119429 storage/replica_raftstorage.go:520  [n1,s1,r23/1:{m-/Table/Syste…}] generated preemptive snapshot bfad7c9a at index 10
I180719 05:31:41.565908 119429 storage/store_snapshot.go:605  [n1,s1,r23/1:{m-/Table/Syste…}] streamed snapshot to (n2,s2):?: kv pairs: 7, log entries: 0, rate-limit: 2.0 MiB/sec, 1ms
I180719 05:31:41.566239 122374 storage/replica_range_lease.go:617  [replicate,n1,s1,r13/1:/Table/1{6-7}] done transferring lease to s4: <nil>
I180719 05:31:41.566279 122281 storage/replica_raftstorage.go:737  [n2,s2,r23/?:{-}] applying preemptive snapshot at index 10 (id=bfad7c9a, encoded size=378, 1 rocksdb batches, 0 log entries)
I180719 05:31:41.566453 122281 storage/replica_raftstorage.go:743  [n2,s2,r23/?:{m-/Table/Syste…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180719 05:31:41.566529 120772 storage/replica_proposal.go:222  [n4,s4,r13/2:/Table/1{6-7}] new range lease repl=(n4,s4):2 seq=3 start=1531978301.563766325,0 epo=1 pro=1531978301.563769045,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.566812 119429 storage/replica_command.go:743  [n1,s1,r23/1:{m-/Table/Syste…}] change replicas (ADD_REPLICA (n2,s2):4): read existing descriptor r23:{m-/Table/SystemConfigSpan/Start} [(n1,s1):1, (n5,s5):2, (n3,s3):3, next=4]
I180719 05:31:41.567433 122283 storage/replica_raftstorage.go:520  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 66b7bb52 at index 56
I180719 05:31:41.568793 122283 storage/store_snapshot.go:605  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n2,s2):?: kv pairs: 45, log entries: 14, rate-limit: 2.0 MiB/sec, 1ms
I180719 05:31:41.570682 122407 storage/replica_raftstorage.go:737  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 56 (id=66b7bb52, encoded size=143823, 1 rocksdb batches, 14 log entries)
I180719 05:31:41.572191 122407 storage/replica_raftstorage.go:743  [n2,s2,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180719 05:31:41.573178 122283 storage/replica_command.go:743  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n2,s2):4): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, (n4,s4):2, (n3,s3):3, next=4]
I180719 05:31:41.581766 119429 storage/replica.go:3613  [n1,s1,r23/1:{m-/Table/Syste…}] proposing ADD_REPLICA((n2,s2):4): updated=[(n1,s1):1 (n5,s5):2 (n3,s3):3 (n2,s2):4] next=5
I180719 05:31:41.589438 122283 storage/replica.go:3613  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n2,s2):4): updated=[(n1,s1):1 (n4,s4):2 (n3,s3):3 (n2,s2):4] next=5
I180719 05:31:41.590220 119429 storage/replica_raftstorage.go:520  [n1,s1,r23/1:{m-/Table/Syste…}] generated preemptive snapshot c1115035 at index 15
I180719 05:31:41.590975 122451 storage/replica_range_lease.go:554  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] transferring lease to s3
I180719 05:31:41.591895 119429 storage/store_snapshot.go:605  [n1,s1,r23/1:{m-/Table/Syste…}] streamed snapshot to (n4,s4):?: kv pairs: 8, log entries: 5, rate-limit: 2.0 MiB/sec, 2ms
I180719 05:31:41.592142 122451 storage/replica_range_lease.go:617  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] done transferring lease to s3: <nil>
I180719 05:31:41.592238 122436 storage/replica_raftstorage.go:737  [n4,s4,r23/?:{-}] applying preemptive snapshot at index 15 (id=c1115035, encoded size=1907, 1 rocksdb batches, 5 log entries)
I180719 05:31:41.592503 122439 storage/replica_raftstorage.go:520  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot ef467fa4 at index 165
I180719 05:31:41.592703 122436 storage/replica_raftstorage.go:743  [n4,s4,r23/?:{m-/Table/Syste…}] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180719 05:31:41.592843 120436 storage/replica_proposal.go:222  [n3,s3,r4/3:/System/{NodeLive…-tsd}] new range lease repl=(n3,s3):3 seq=3 start=1531978301.590983078,0 epo=1 pro=1531978301.590985669,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.593176 119429 storage/replica_command.go:743  [n1,s1,r23/1:{m-/Table/Syste…}] change replicas (ADD_REPLICA (n4,s4):5): read existing descriptor r23:{m-/Table/SystemConfigSpan/Start} [(n1,s1):1, (n5,s5):2, (n3,s3):3, (n2,s2):4, next=5]
I180719 05:31:41.596993 122439 storage/store_snapshot.go:605  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n5,s5):?: kv pairs: 442, log entries: 69, rate-limit: 2.0 MiB/sec, 4ms
I180719 05:31:41.597573 122418 storage/replica_raftstorage.go:737  [n5,s5,r10/?:{-}] applying preemptive snapshot at index 165 (id=ef467fa4, encoded size=101061, 1 rocksdb batches, 69 log entries)
I180719 05:31:41.602335 119429 storage/replica.go:3613  [n1,s1,r23/1:{m-/Table/Syste…}] proposing ADD_REPLICA((n4,s4):5): updated=[(n1,s1):1 (n5,s5):2 (n3,s3):3 (n2,s2):4 (n4,s4):5] next=6
I180719 05:31:41.604694 122418 storage/replica_raftstorage.go:743  [n5,s5,r10/?:/Table/1{3-4}] applied preemptive snapshot in 7ms [clear=0ms batch=0ms entries=6ms commit=1ms]
I180719 05:31:41.606020 122439 storage/replica_command.go:743  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n5,s5):4): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, (n4,s4):2, (n2,s2):3, next=4]
I180719 05:31:41.618670 122439 storage/replica.go:3613  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n5,s5):4): updated=[(n1,s1):1 (n4,s4):2 (n2,s2):3 (n5,s5):4] next=5
I180719 05:31:41.627240 122512 storage/replica_range_lease.go:554  [replicate,n1,s1,r10/1:/Table/1{3-4}] transferring lease to s2
I180719 05:31:41.630329 122512 storage/replica_range_lease.go:617  [replicate,n1,s1,r10/1:/Table/1{3-4}] done transferring lease to s2: <nil>
I180719 05:31:41.630672 120201 storage/replica_proposal.go:222  [n2,s2,r10/3:/Table/1{3-4}] new range lease repl=(n2,s2):3 seq=3 start=1531978301.627291711,0 epo=1 pro=1531978301.627295817,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.630824 122431 storage/replica_raftstorage.go:520  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot 9a53d238 at index 21
I180719 05:31:41.634194 122431 storage/store_snapshot.go:605  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n4,s4):?: kv pairs: 10, log entries: 11, rate-limit: 2.0 MiB/sec, 3ms
I180719 05:31:41.634696 122491 storage/replica_raftstorage.go:737  [n4,s4,r11/?:{-}] applying preemptive snapshot at index 21 (id=9a53d238, encoded size=4166, 1 rocksdb batches, 11 log entries)
I180719 05:31:41.635612 122491 storage/replica_raftstorage.go:743  [n4,s4,r11/?:/Table/1{4-5}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180719 05:31:41.636105 122431 storage/replica_command.go:743  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n4,s4):4): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, (n5,s5):2, (n2,s2):3, next=4]
I180719 05:31:41.646229 122431 storage/replica.go:3613  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n4,s4):4): updated=[(n1,s1):1 (n5,s5):2 (n2,s2):3 (n4,s4):4] next=5
I180719 05:31:41.647532 122572 storage/replica_range_lease.go:554  [replicate,n1,s1,r11/1:/Table/1{4-5}] transferring lease to s2
I180719 05:31:41.649291 122572 storage/replica_range_lease.go:617  [replicate,n1,s1,r11/1:/Table/1{4-5}] done transferring lease to s2: <nil>
I180719 05:31:41.649439 120248 storage/replica_proposal.go:222  [n2,s2,r11/3:/Table/1{4-5}] new range lease repl=(n2,s2):3 seq=3 start=1531978301.647582256,0 epo=1 pro=1531978301.647585185,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.650791 122573 storage/replica_raftstorage.go:520  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot ae0ac58e at index 28
I180719 05:31:41.651859 122573 storage/store_snapshot.go:605  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 15, log entries: 18, rate-limit: 2.0 MiB/sec, 1ms
I180719 05:31:41.652251 122576 storage/replica_raftstorage.go:737  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 28 (id=ae0ac58e, encoded size=7411, 1 rocksdb batches, 18 log entries)
I180719 05:31:41.653318 122576 storage/replica_raftstorage.go:743  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180719 05:31:41.654019 122573 storage/replica_command.go:743  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n2,s2):4): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, (n3,s3):2, (n4,s4):3, next=4]
I180719 05:31:41.668530 122573 storage/replica.go:3613  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n2,s2):4): updated=[(n1,s1):1 (n3,s3):2 (n4,s4):3 (n2,s2):4] next=5
I180719 05:31:41.669800 122650 storage/replica_range_lease.go:554  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] transferring lease to s3
I180719 05:31:41.672076 122650 storage/replica_range_lease.go:617  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] done transferring lease to s3: <nil>
I180719 05:31:41.672271 122590 storage/replica_range_lease.go:554  [replicate,n1,s1,r23/1:{m-/Table/Syste…}] transferring lease to s5
I180719 05:31:41.673274 122590 storage/replica_range_lease.go:617  [replicate,n1,s1,r23/1:{m-/Table/Syste…}] done transferring lease to s5: <nil>
I180719 05:31:41.673299 121072 storage/replica_proposal.go:222  [n5,s5,r23/2:{m-/Table/Syste…}] new range lease repl=(n5,s5):2 seq=3 start=1531978301.672277208,0 epo=1 pro=1531978301.672279983,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.673610 122617 storage/replica_raftstorage.go:520  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 6d552581 at index 21
I180719 05:31:41.674122 122617 storage/store_snapshot.go:605  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 11, rate-limit: 2.0 MiB/sec, 0ms
I180719 05:31:41.674469 122594 storage/replica_raftstorage.go:737  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 21 (id=6d552581, encoded size=4338, 1 rocksdb batches, 11 log entries)
I180719 05:31:41.675127 122594 storage/replica_raftstorage.go:743  [n2,s2,r14/?:/Table/1{7-8}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180719 05:31:41.675528 122617 storage/replica_command.go:743  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n2,s2):4): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, (n3,s3):2, (n4,s4):3, next=4]
I180719 05:31:41.685085 122617 storage/replica.go:3613  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n2,s2):4): updated=[(n1,s1):1 (n3,s3):2 (n4,s4):3 (n2,s2):4] next=5
I180719 05:31:41.687988 122608 storage/replica_range_lease.go:554  [replicate,n1,s1,r14/1:/Table/1{7-8}] transferring lease to s3
I180719 05:31:41.689327 122608 storage/replica_range_lease.go:617  [replicate,n1,s1,r14/1:/Table/1{7-8}] done transferring lease to s3: <nil>
I180719 05:31:41.689408 120448 storage/replica_proposal.go:222  [n3,s3,r14/2:/Table/1{7-8}] new range lease repl=(n3,s3):2 seq=3 start=1531978301.688004166,0 epo=1 pro=1531978301.688007215,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:41.689697 122634 storage/replica_raftstorage.go:520  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot d517b9b4 at index 28
I180719 05:31:41.690385 122634 storage/store_snapshot.go:605  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n5,s5):?: kv pairs: 10, log entries: 18, rate-limit: 2.0 MiB/sec, 1ms
I180719 05:31:41.690894 122637 storage/replica_raftstorage.go:737  [n5,s5,r2/?:{-}] applying preemptive snapshot at index 28 (id=d517b9b4, encoded size=58606, 1 rocksdb batches, 18 log entries)
I180719 05:31:41.692005 122637 storage/replica_raftstorage.go:743  [n5,s5,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180719 05:31:41.692389 122634 storage/replica_command.go:743  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n5,s5):4): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, (n4,s4):2, (n3,s3):3, next=4]
I180719 05:31:41.702382 122634 storage/replica.go:3613  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n5,s5):4): updated=[(n1,s1):1 (n4,s4):2 (n3,s3):3 (n5,s5):4] next=5
I180719 05:31:41.703570 122685 storage/replica_range_lease.go:554  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] transferring lease to s3
I180719 05:31:41.705155 122685 storage/replica_range_lease.go:617  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] done transferring lease to s3: <nil>
I180719 05:31:41.705541 122694 storage/replica_raftstorage.go:520  [replicate,n1,s1,r6/1:{/System/tse-m}] generated preemptive snapshot 40d0a6e4 at index 27
I180719 05:31:41.706415 122694 storage/store_snapshot.go:605  [replicate,n1,s1,r6/1:{/System/tse-m}] streamed snapshot to (n4,s4):?: kv pairs: 11, log entries: 17, rate-limit: 2.0 MiB/sec, 1ms
I180719 05:31:41.706773 122787 storage/replica_raftstorage.go:737  [n4,s4,r6/?:{-}] applying preemptive snapshot at index 27 (id=40d0a6e4, encoded size=7549, 1 rocksdb batches, 17 log entries)
I180719 05:31:41.707553 122787 storage/replica_raftstorage.go:743  [n4,s4,r6/?:{/System/tse-m}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180719 05:31:41.707969 122694 storage/replica_command.go:743  [replicate,n1,s1,r6/1:{/System/tse-m}] change replicas (ADD_REPLICA (n4,s4):4): read existing descriptor r6:{/System/tse-m} [(n1,s1):1, (n5,s5):2, (n3,s3):3, next=4]
I180719 05:31:41.719843 122694 storage/replica.go:3613  [n1,s1,r6/1:{/System/tse-m}] proposing ADD_REPLICA((n4,s4):4): updated=[(n1,s1):1 (n5,s5):2 (n3,s3):3 (n4,s4):4] next=5
I180719 05:31:41.720882 122746 storage/replica_range_lease.go:554  [replicate,n1,s1,r6/1:{/System/tse-m}] transferring lease to s5
I180719 05:31:41.722128 122746 storage/replica_range_lease.go:617  [replicate,n1,s1,r6/1:{/System/tse-m}] done transferring lease to s5: <nil>
I180719 05:31:41.722330 121109 storage/replica_proposal.go:222  [n5,s5,r6/2:{/System/tse-m}] new range lease repl=(n5,s5):2 seq=3 start=1531978301.720924398,0 epo=1 pro=1531978301.720927453,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:42.697176 122826 storage/replica_command.go:743  [replicate,n2,s2,r10/3:/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, (n2,s2):3, (n5,s5):4, next=5]
I180719 05:31:42.711463 122730 rpc/nodedialer/nodedialer.go:90  [replica consistency checker,n2,s2,r10/3:/Table/1{3-4}] connection to n2 established
I180719 05:31:42.752251 122826 storage/replica.go:3613  [n2,s2,r10/3:/Table/1{3-4}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n5,s5):4 (n4,s4):2 (n2,s2):3] next=5
I180719 05:31:42.753848 120949 storage/store.go:3585  [n1,s1,r10/1:/Table/1{3-4}] added to replica GC queue (peer suggestion)
I180719 05:31:42.754510 122769 storage/store.go:2513  [replicaGC,n1,s1,r10/1:/Table/1{3-4}] removing replica
I180719 05:31:42.754850 122769 storage/replica.go:836  [replicaGC,n1,s1,r10/1:/Table/1{3-4}] removed 480 (472+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:42.791796 122842 storage/replica_command.go:743  [replicate,n3,s3,r3/2:/System/NodeLiveness{-Max}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, (n3,s3):2, (n4,s4):3, (n2,s2):4, next=5]
I180719 05:31:42.799545 122887 rpc/nodedialer/nodedialer.go:90  [replica consistency checker,n3,s3,r3/2:/System/NodeLiveness{-Max}] connection to n3 established
I180719 05:31:42.804432 122842 storage/replica.go:3613  [n3,s3,r3/2:/System/NodeLiveness{-Max}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n2,s2):4 (n3,s3):2 (n4,s4):3] next=5
I180719 05:31:42.806100 120509 storage/store.go:3585  [n1,s1,r3/1:/System/NodeLiveness{-Max}] added to replica GC queue (peer suggestion)
I180719 05:31:42.865043 122935 storage/store.go:2513  [replicaGC,n1,s1,r3/1:/System/NodeLiveness{-Max}] removing replica
I180719 05:31:42.865373 122935 storage/replica.go:836  [replicaGC,n1,s1,r3/1:/System/NodeLiveness{-Max}] removed 13 (5+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:43.697718 122949 storage/replica_command.go:743  [replicate,n2,s2,r21/3:/Table/5{0-1}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r21:/Table/5{0-1} [(n1,s1):1, (n4,s4):2, (n2,s2):3, (n3,s3):4, next=5]
I180719 05:31:43.706998 122949 storage/replica.go:3613  [n2,s2,r21/3:/Table/5{0-1}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n3,s3):4 (n4,s4):2 (n2,s2):3] next=5
I180719 05:31:43.708502 120949 storage/store.go:3585  [n1,s1,r21/1:/Table/5{0-1}] added to replica GC queue (peer suggestion)
I180719 05:31:43.710284 120949 storage/store.go:3585  [n1,s1,r21/1:/Table/5{0-1}] added to replica GC queue (peer suggestion)
I180719 05:31:43.710481 122964 storage/store.go:2513  [replicaGC,n1,s1,r21/1:/Table/5{0-1}] removing replica
I180719 05:31:43.710751 122964 storage/replica.go:836  [replicaGC,n1,s1,r21/1:/Table/5{0-1}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:45.698151 123038 storage/replica_command.go:743  [replicate,n2,s2,r20/2:/Table/{23-50}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r20:/Table/{23-50} [(n1,s1):1, (n2,s2):2, (n5,s5):3, (n3,s3):4, next=5]
I180719 05:31:45.706925 123038 storage/replica.go:3613  [n2,s2,r20/2:/Table/{23-50}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n3,s3):4 (n2,s2):2 (n5,s5):3] next=5
I180719 05:31:45.707781 120949 storage/store.go:3585  [n1,s1,r20/1:/Table/{23-50}] added to replica GC queue (peer suggestion)
I180719 05:31:45.707855 120949 storage/store.go:3585  [n1,s1,r20/1:/Table/{23-50}] added to replica GC queue (peer suggestion)
I180719 05:31:45.708732 122921 storage/store.go:2513  [replicaGC,n1,s1,r20/1:/Table/{23-50}] removing replica
I180719 05:31:45.709076 122921 storage/replica.go:836  [replicaGC,n1,s1,r20/1:/Table/{23-50}] removed 12 (4+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:45.920774 123092 storage/replica_command.go:743  [replicate,n5,s5,r12/2:/Table/1{5-6}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, (n5,s5):2, (n4,s4):3, (n2,s2):4, next=5]
I180719 05:31:45.922135 123112 rpc/nodedialer/nodedialer.go:90  [replica consistency checker,n5,s5,r12/2:/Table/1{5-6}] connection to n5 established
I180719 05:31:45.929966 123092 storage/replica.go:3613  [n5,s5,r12/2:/Table/1{5-6}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n2,s2):4 (n5,s5):2 (n4,s4):3] next=5
I180719 05:31:45.931299 121290 storage/store.go:3585  [n1,s1,r12/1:/Table/1{5-6}] added to replica GC queue (peer suggestion)
I180719 05:31:45.933074 123141 storage/store.go:2513  [replicaGC,n1,s1,r12/1:/Table/1{5-6}] removing replica
I180719 05:31:45.933336 123141 storage/replica.go:836  [replicaGC,n1,s1,r12/1:/Table/1{5-6}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:48.698707 123160 storage/replica_command.go:743  [replicate,n2,s2,r1/2:/{Min-System/}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r1:/{Min-System/} [(n1,s1):1, (n2,s2):2, (n3,s3):3, (n5,s5):4, next=5]
I180719 05:31:48.707941 123160 storage/replica.go:3613  [n2,s2,r1/2:/{Min-System/}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n5,s5):4 (n2,s2):2 (n3,s3):3] next=5
I180719 05:31:48.710160 120949 storage/store.go:3585  [n1,s1,r1/1:/{Min-System/}] added to replica GC queue (peer suggestion)
I180719 05:31:48.710506 123190 storage/store.go:2513  [replicaGC,n1,s1,r1/1:/{Min-System/}] removing replica
I180719 05:31:48.711348 123190 storage/replica.go:836  [replicaGC,n1,s1,r1/1:/{Min-System/}] removed 33 (24+9) keys in 1ms [clear=0ms commit=0ms]
I180719 05:31:48.738127 123238 storage/replica_command.go:743  [replicate,n3,s3,r18/2:/Table/2{1-2}] change replicas (REMOVE_REPLICA (n5,s5):4): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, (n3,s3):2, (n2,s2):3, (n5,s5):4, next=5]
I180719 05:31:48.752866 123238 storage/replica.go:3613  [n3,s3,r18/2:/Table/2{1-2}] proposing REMOVE_REPLICA((n5,s5):4): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=5
I180719 05:31:48.757285 121803 storage/store.go:3585  [n5,s5,r18/4:/Table/2{1-2}] added to replica GC queue (peer suggestion)
I180719 05:31:48.758606 123244 storage/store.go:2513  [replicaGC,n5,s5,r18/4:/Table/2{1-2}] removing replica
I180719 05:31:48.758995 123244 storage/replica.go:836  [replicaGC,n5,s5,r18/4:/Table/2{1-2}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:48.865182 123214 storage/replica_command.go:743  [replicate,n5,s5,r19/2:/Table/2{2-3}] change replicas (REMOVE_REPLICA (n2,s2):3): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, (n5,s5):2, (n2,s2):3, (n3,s3):4, next=5]
I180719 05:31:48.879481 123214 storage/replica.go:3613  [n5,s5,r19/2:/Table/2{2-3}] proposing REMOVE_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n5,s5):2 (n3,s3):4] next=5
I180719 05:31:48.881052 121832 storage/store.go:3585  [n2,s2,r19/3:/Table/2{2-3}] added to replica GC queue (peer suggestion)
I180719 05:31:48.881503 121832 storage/store.go:3585  [n2,s2,r19/3:/Table/2{2-3}] added to replica GC queue (peer suggestion)
I180719 05:31:48.886309 123275 storage/store.go:2513  [replicaGC,n2,s2,r19/3:/Table/2{2-3}] removing replica
I180719 05:31:48.886584 123275 storage/replica.go:836  [replicaGC,n2,s2,r19/3:/Table/2{2-3}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:50.437438 119466 server/status/runtime.go:255  [n1] runtime stats: 252 MiB RSS, 1180 goroutines, 43 MiB/36 MiB/115 MiB GO alloc/idle/total, 60 MiB/97 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (1030x)
W180719 05:31:50.446260 119468 server/node.go:892  [n1,summaries] health alerts detected: {Alerts:[{StoreID:1 Category:METRICS Description:queue.replicate.process.failure Value:311}]}
I180719 05:31:50.677790 120138 server/status/runtime.go:255  [n2] runtime stats: 253 MiB RSS, 1179 goroutines, 52 MiB/27 MiB/115 MiB GO alloc/idle/total, 60 MiB/97 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (1030x)
I180719 05:31:50.699245 123413 storage/replica_command.go:743  [replicate,n2,s2,r11/3:/Table/1{4-5}] change replicas (REMOVE_REPLICA (n4,s4):4): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, (n5,s5):2, (n2,s2):3, (n4,s4):4, next=5]
I180719 05:31:50.718048 123413 storage/replica.go:3613  [n2,s2,r11/3:/Table/1{4-5}] proposing REMOVE_REPLICA((n4,s4):4): updated=[(n1,s1):1 (n5,s5):2 (n2,s2):3] next=5
I180719 05:31:50.719690 121825 storage/store.go:3585  [n4,s4,r11/4:/Table/1{4-5}] added to replica GC queue (peer suggestion)
I180719 05:31:50.720682 123435 storage/store.go:2513  [replicaGC,n4,s4,r11/4:/Table/1{4-5}] removing replica
I180719 05:31:50.720859 123435 storage/replica.go:836  [replicaGC,n4,s4,r11/4:/Table/1{4-5}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:50.733363 120398 server/status/runtime.go:255  [n3] runtime stats: 254 MiB RSS, 1182 goroutines, 60 MiB/20 MiB/115 MiB GO alloc/idle/total, 60 MiB/98 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (1030x)
I180719 05:31:50.797254 121958 storage/store.go:3604  [n2,s2,r11/3:/Table/1{4-5}] added to replica GC queue (contacted deleted peer)
I180719 05:31:50.797563 120670 server/status/runtime.go:255  [n4] runtime stats: 256 MiB RSS, 1180 goroutines, 66 MiB/14 MiB/115 MiB GO alloc/idle/total, 62 MiB/99 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (1030x)
I180719 05:31:50.820158 123477 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, (n3,s3):3, (n5,s5):4, next=5]
I180719 05:31:50.840919 123477 storage/replica.go:3613  [n4,s4,r16/2:/Table/{19-20}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n5,s5):4 (n4,s4):2 (n3,s3):3] next=5
I180719 05:31:50.845883 121201 storage/store.go:3585  [n1,s1,r16/1:/Table/{19-20}] added to replica GC queue (peer suggestion)
I180719 05:31:50.846962 123416 rpc/nodedialer/nodedialer.go:90  [replica consistency checker,n4,s4,r16/2:/Table/{19-20}] connection to n4 established
I180719 05:31:50.847858 123419 storage/store.go:2513  [replicaGC,n1,s1,r16/1:/Table/{19-20}] removing replica
I180719 05:31:50.848179 123419 storage/replica.go:836  [replicaGC,n1,s1,r16/1:/Table/{19-20}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:50.861481 120864 server/status/runtime.go:255  [n5] runtime stats: 258 MiB RSS, 1191 goroutines, 48 MiB/34 MiB/116 MiB GO alloc/idle/total, 63 MiB/101 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (1031x)
I180719 05:31:51.738629 123509 storage/replica_command.go:743  [replicate,n3,s3,r2/3:/System/{-NodeLive…}] change replicas (REMOVE_REPLICA (n4,s4):2): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, (n4,s4):2, (n3,s3):3, (n5,s5):4, next=5]
I180719 05:31:51.747842 123509 storage/replica.go:3613  [n3,s3,r2/3:/System/{-NodeLive…}] proposing REMOVE_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n5,s5):4 (n3,s3):3] next=5
I180719 05:31:51.749062 121707 storage/store.go:3585  [n4,s4,r2/2:/System/{-NodeLive…}] added to replica GC queue (peer suggestion)
I180719 05:31:51.749905 123424 storage/store.go:2513  [replicaGC,n4,s4,r2/2:/System/{-NodeLive…}] removing replica
I180719 05:31:51.750138 123424 storage/replica.go:836  [replicaGC,n4,s4,r2/2:/System/{-NodeLive…}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:51.866903 123573 storage/replica_command.go:743  [replicate,n5,s5,r22/2:/{Table/51-Max}] change replicas (REMOVE_REPLICA (n3,s3):4): read existing descriptor r22:/{Table/51-Max} [(n1,s1):1, (n5,s5):2, (n4,s4):3, (n3,s3):4, next=5]
I180719 05:31:51.877171 123573 storage/replica.go:3613  [n5,s5,r22/2:/{Table/51-Max}] proposing REMOVE_REPLICA((n3,s3):4): updated=[(n1,s1):1 (n5,s5):2 (n4,s4):3] next=5
I180719 05:31:51.878340 121877 storage/store.go:3585  [n3,s3,r22/4:/{Table/51-Max}] added to replica GC queue (peer suggestion)
I180719 05:31:51.881182 123603 storage/store.go:2513  [replicaGC,n3,s3,r22/4:/{Table/51-Max}] removing replica
I180719 05:31:51.881429 123603 storage/replica.go:836  [replicaGC,n3,s3,r22/4:/{Table/51-Max}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:52.738803 123637 storage/replica_range_lease.go:554  [replicate,n3,s3,r9/2:/Table/1{2-3}] transferring lease to s4
I180719 05:31:52.740140 123637 storage/replica_range_lease.go:617  [replicate,n3,s3,r9/2:/Table/1{2-3}] done transferring lease to s4: <nil>
I180719 05:31:52.740648 120654 storage/replica_proposal.go:222  [n4,s4,r9/3:/Table/1{2-3}] new range lease repl=(n4,s4):3 seq=4 start=1531978312.738817680,0 epo=1 pro=1531978312.738819980,0 following repl=(n3,s3):2 seq=3 start=1531978301.472162428,0 epo=1 pro=1531978301.472164782,0
I180719 05:31:52.819661 123613 storage/replica_range_lease.go:554  [replicate,n4,s4,r9/3:/Table/1{2-3}] transferring lease to s3
I180719 05:31:52.820750 120451 storage/replica_proposal.go:222  [n3,s3,r9/2:/Table/1{2-3}] new range lease repl=(n3,s3):2 seq=5 start=1531978312.819678207,0 epo=1 pro=1531978312.819680394,0 following repl=(n4,s4):3 seq=4 start=1531978312.738817680,0 epo=1 pro=1531978312.738819980,0
I180719 05:31:52.820808 123613 storage/replica_range_lease.go:617  [replicate,n4,s4,r9/3:/Table/1{2-3}] done transferring lease to s3: <nil>
I180719 05:31:52.865918 123644 storage/replica_range_lease.go:554  [replicate,n5,s5,r23/2:{m-/Table/Syste…}] transferring lease to s3
I180719 05:31:52.867442 120453 storage/replica_proposal.go:222  [n3,s3,r23/3:{m-/Table/Syste…}] new range lease repl=(n3,s3):3 seq=4 start=1531978312.865936119,0 epo=1 pro=1531978312.865938763,0 following repl=(n5,s5):2 seq=3 start=1531978301.672277208,0 epo=1 pro=1531978301.672279983,0
I180719 05:31:52.867605 123644 storage/replica_range_lease.go:617  [replicate,n5,s5,r23/2:{m-/Table/Syste…}] done transferring lease to s3: <nil>
I180719 05:31:53.739123 123681 storage/replica_range_lease.go:554  [replicate,n3,s3,r4/3:/System/{NodeLive…-tsd}] transferring lease to s2
I180719 05:31:53.740394 120234 storage/replica_proposal.go:222  [n2,s2,r4/4:/System/{NodeLive…-tsd}] new range lease repl=(n2,s2):4 seq=4 start=1531978313.739139854,0 epo=1 pro=1531978313.739143833,0 following repl=(n3,s3):3 seq=3 start=1531978301.590983078,0 epo=1 pro=1531978301.590985669,0
I180719 05:31:53.740541 123681 storage/replica_range_lease.go:617  [replicate,n3,s3,r4/3:/System/{NodeLive…-tsd}] done transferring lease to s2: <nil>
I180719 05:31:53.820176 123765 storage/replica_command.go:743  [replicate,n4,s4,r17/3:/Table/2{0-1}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, (n2,s2):2, (n4,s4):3, (n3,s3):4, next=5]
I180719 05:31:53.826062 123765 storage/replica.go:3613  [n4,s4,r17/3:/Table/2{0-1}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n3,s3):4 (n2,s2):2 (n4,s4):3] next=5
I180719 05:31:53.827060 121201 storage/store.go:3585  [n1,s1,r17/1:/Table/2{0-1}] added to replica GC queue (peer suggestion)
I180719 05:31:53.828196 123795 storage/store.go:2513  [replicaGC,n1,s1,r17/1:/Table/2{0-1}] removing replica
I180719 05:31:53.828403 123795 storage/replica.go:836  [replicaGC,n1,s1,r17/1:/Table/2{0-1}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:53.866330 123754 storage/replica_command.go:743  [replicate,n5,s5,r6/2:{/System/tse-m}] change replicas (REMOVE_REPLICA (n4,s4):4): read existing descriptor r6:{/System/tse-m} [(n1,s1):1, (n5,s5):2, (n3,s3):3, (n4,s4):4, next=5]
I180719 05:31:53.874856 123754 storage/replica.go:3613  [n5,s5,r6/2:{/System/tse-m}] proposing REMOVE_REPLICA((n4,s4):4): updated=[(n1,s1):1 (n5,s5):2 (n3,s3):3] next=5
I180719 05:31:53.876034 121783 storage/store.go:3585  [n4,s4,r6/4:{/System/tse-m}] added to replica GC queue (peer suggestion)
I180719 05:31:53.877463 123796 storage/store.go:2513  [replicaGC,n4,s4,r6/4:{/System/tse-m}] removing replica
I180719 05:31:53.877718 123796 storage/replica.go:836  [replicaGC,n4,s4,r6/4:{/System/tse-m}] removed 9 (0+9) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:55.442807 119633 storage/replica_proposal.go:222  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1531978300.435554252,0 epo=1 pro=1531978315.441887538,0 following repl=(n1,s1):1 seq=2 start=1531978300.435554252,0 exp=1531978309.435730229,0 pro=1531978300.435752670,0
I180719 05:31:55.739054 123864 storage/replica_range_lease.go:554  [replicate,n3,s3,r14/2:/Table/1{7-8}] transferring lease to s4
I180719 05:31:55.740105 123864 storage/replica_range_lease.go:617  [replicate,n3,s3,r14/2:/Table/1{7-8}] done transferring lease to s4: <nil>
I180719 05:31:55.740139 120790 storage/replica_proposal.go:222  [n4,s4,r14/3:/Table/1{7-8}] new range lease repl=(n4,s4):3 seq=4 start=1531978315.739075671,0 epo=1 pro=1531978315.739078479,0 following repl=(n3,s3):2 seq=3 start=1531978301.688004166,0 epo=1 pro=1531978301.688007215,0
I180719 05:31:55.821491 123824 storage/replica_command.go:743  [replicate,n4,s4,r15/3:/Table/1{8-9}] change replicas (REMOVE_REPLICA (n5,s5):2): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, (n5,s5):2, (n4,s4):3, (n3,s3):4, next=5]
I180719 05:31:55.827107 123824 storage/replica.go:3613  [n4,s4,r15/3:/Table/1{8-9}] proposing REMOVE_REPLICA((n5,s5):2): updated=[(n1,s1):1 (n3,s3):4 (n4,s4):3] next=5
I180719 05:31:55.828113 121868 storage/store.go:3585  [n5,s5,r15/2:/Table/1{8-9}] added to replica GC queue (peer suggestion)
I180719 05:31:55.828978 123898 storage/store.go:2513  [replicaGC,n5,s5,r15/2:/Table/1{8-9}] removing replica
I180719 05:31:55.829149 123898 storage/replica.go:836  [replicaGC,n5,s5,r15/2:/Table/1{8-9}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:56.821013 123904 storage/replica_command.go:743  [replicate,n4,s4,r7/2:/Table/{SystemCon…-11}] change replicas (REMOVE_REPLICA (n2,s2):4): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n4,s4):2, (n5,s5):3, (n2,s2):4, next=5]
I180719 05:31:56.829505 123904 storage/replica.go:3613  [n4,s4,r7/2:/Table/{SystemCon…-11}] proposing REMOVE_REPLICA((n2,s2):4): updated=[(n1,s1):1 (n4,s4):2 (n5,s5):3] next=5
I180719 05:31:56.830538 121958 storage/store.go:3585  [n2,s2,r7/4:/Table/{SystemCon…-11}] added to replica GC queue (peer suggestion)
I180719 05:31:56.831872 123991 storage/store.go:2513  [replicaGC,n2,s2,r7/4:/Table/{SystemCon…-11}] removing replica
I180719 05:31:56.832209 123991 storage/replica.go:836  [replicaGC,n2,s2,r7/4:/Table/{SystemCon…-11}] removed 57 (48+9) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:57.755167 119662 storage/compactor/compactor.go:329  [n1,s1,compactor] purging suggested compaction for range /Min - /System/"" that contains live data
I180719 05:31:57.755587 119662 storage/compactor/compactor.go:374  [n1,s1,compactor] processing compaction #1-7/7 (/System/NodeLiveness-/Table/51) for 55 KiB (reasons: size=false used=true avail=false)
I180719 05:31:57.763642 119662 storage/compactor/compactor.go:390  [n1,s1,compactor] processed compaction #1-7/7 (/System/NodeLiveness-/Table/51) for 55 KiB in 0.0s
I180719 05:31:58.821703 124068 storage/replica_command.go:743  [replicate,n4,s4,r5/3:/System/ts{d-e}] change replicas (REMOVE_REPLICA (n3,s3):4): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, (n5,s5):2, (n4,s4):3, (n3,s3):4, next=5]
I180719 05:31:58.827861 124068 storage/replica.go:3613  [n4,s4,r5/3:/System/ts{d-e}] proposing REMOVE_REPLICA((n3,s3):4): updated=[(n1,s1):1 (n5,s5):2 (n4,s4):3] next=5
I180719 05:31:58.829578 121845 storage/store.go:3585  [n3,s3,r5/4:/System/ts{d-e}] added to replica GC queue (peer suggestion)
I180719 05:31:58.831445 123966 storage/store.go:2513  [replicaGC,n3,s3,r5/4:/System/ts{d-e}] removing replica
I180719 05:31:58.831664 123966 storage/replica.go:836  [replicaGC,n3,s3,r5/4:/System/ts{d-e}] removed 444 (435+9) keys in 0ms [clear=0ms commit=0ms]
I180719 05:31:58.917315 123963 storage/replica_consistency.go:129  [replica consistency checker,n4,s4,r5/3:/System/ts{d-e}] triggering stats recomputation to resolve delta of {ContainsEstimates:true LastUpdateNanos:1531978310894687197 IntentAge:0 GCBytesAge:0 LiveBytes:-20864 LiveCount:-1740 KeyBytes:-80788 KeyCount:-1740 ValBytes:59924 ValCount:-1740 IntentBytes:0 IntentCount:0 SysBytes:0 SysCount:0}
I180719 05:31:59.822765 124103 storage/replica_command.go:743  [replicate,n4,s4,r13/2:/Table/1{6-7}] change replicas (REMOVE_REPLICA (n2,s2):3): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, (n4,s4):2, (n2,s2):3, (n5,s5):4, next=5]
I180719 05:31:59.827715 124103 storage/replica.go:3613  [n4,s4,r13/2:/Table/1{6-7}] proposing REMOVE_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n4,s4):2 (n5,s5):4] next=5
I180719 05:31:59.828747 121958 storage/store.go:3585  [n2,s2,r13/3:/Table/1{6-7}] added to replica GC queue (peer suggestion)
I180719 05:31:59.829677 124131 storage/store.go:2513  [replicaGC,n2,s2,r13/3:/Table/1{6-7}] removing replica
I180719 05:31:59.829932 124131 storage/replica.go:836  [replicaGC,n2,s2,r13/3:/Table/1{6-7}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:32:00.437136 119466 server/status/runtime.go:255  [n1] runtime stats: 252 MiB RSS, 1189 goroutines, 67 MiB/16 MiB/116 MiB GO alloc/idle/total, 60 MiB/95 MiB CGO alloc/total, 1712.14cgo/sec, 0.13/0.01 %(u/s)time, 0.00 %gc (2x)
I180719 05:32:00.677607 120138 server/status/runtime.go:255  [n2] runtime stats: 252 MiB RSS, 1189 goroutines, 42 MiB/41 MiB/116 MiB GO alloc/idle/total, 60 MiB/96 MiB CGO alloc/total, 1703.84cgo/sec, 0.13/0.01 %(u/s)time, 0.00 %gc (3x)
I180719 05:32:00.736735 120398 server/status/runtime.go:255  [n3] runtime stats: 255 MiB RSS, 1189 goroutines, 50 MiB/33 MiB/116 MiB GO alloc/idle/total, 61 MiB/96 MiB CGO alloc/total, 1658.73cgo/sec, 0.13/0.01 %(u/s)time, 0.00 %gc (3x)
I180719 05:32:00.800062 120670 server/status/runtime.go:255  [n4] runtime stats: 255 MiB RSS, 1189 goroutines, 53 MiB/30 MiB/116 MiB GO alloc/idle/total, 61 MiB/96 MiB CGO alloc/total, 1657.38cgo/sec, 0.13/0.01 %(u/s)time, 0.00 %gc (3x)
I180719 05:32:00.862463 120864 server/status/runtime.go:255  [n5] runtime stats: 260 MiB RSS, 1189 goroutines, 67 MiB/16 MiB/116 MiB GO alloc/idle/total, 63 MiB/101 MiB CGO alloc/total, 1611.16cgo/sec, 0.12/0.01 %(u/s)time, 0.00 %gc (2x)
I180719 05:32:03.982119 120355 gossip/gossip.go:1339  [n3] node has connected to cluster via gossip
I180719 05:32:03.982366 120355 storage/stores.go:241  [n3] wrote 4 node addresses to persistent storage
I180719 05:32:06.705315 124253 storage/replica_command.go:743  [replicate,n2,s2,r4/4:/System/{NodeLive…-tsd}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, (n4,s4):2, (n3,s3):3, (n2,s2):4, next=5]
I180719 05:32:06.718056 124253 storage/replica.go:3613  [n2,s2,r4/4:/System/{NodeLive…-tsd}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n2,s2):4 (n4,s4):2 (n3,s3):3] next=5
I180719 05:32:06.719674 120949 storage/store.go:3585  [n1,s1,r4/1:/System/{NodeLive…-tsd}] added to replica GC queue (peer suggestion)
I180719 05:32:06.720219 124140 storage/store.go:2513  [replicaGC,n1,s1,r4/1:/System/{NodeLive…-tsd}] removing replica
I180719 05:32:06.720669 124140 storage/replica.go:836  [replicaGC,n1,s1,r4/1:/System/{NodeLive…-tsd}] removed 31 (22+9) keys in 0ms [clear=0ms commit=0ms]
I180719 05:32:07.478155 120096 gossip/gossip.go:1339  [n2] node has connected to cluster via gossip
I180719 05:32:07.478470 120096 storage/stores.go:241  [n2] wrote 4 node addresses to persistent storage
I180719 05:32:09.747980 124391 storage/replica_command.go:743  [replicate,n3,s3,r9/2:/Table/1{2-3}] change replicas (REMOVE_REPLICA (n2,s2):4): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, (n3,s3):2, (n4,s4):3, (n2,s2):4, next=5]
I180719 05:32:09.755542 124391 storage/replica.go:3613  [n3,s3,r9/2:/Table/1{2-3}] proposing REMOVE_REPLICA((n2,s2):4): updated=[(n1,s1):1 (n3,s3):2 (n4,s4):3] next=5
I180719 05:32:09.756697 122019 storage/store.go:3585  [n2,s2,r9/4:/Table/1{2-3}] added to replica GC queue (peer suggestion)
I180719 05:32:09.757497 124410 storage/store.go:2513  [replicaGC,n2,s2,r9/4:/Table/1{2-3}] removing replica
I180719 05:32:09.757846 124410 storage/replica.go:836  [replicaGC,n2,s2,r9/4:/Table/1{2-3}] removed 63 (55+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:32:10.437185 119466 server/status/runtime.go:255  [n1] runtime stats: 261 MiB RSS, 1189 goroutines, 48 MiB/36 MiB/117 MiB GO alloc/idle/total, 67 MiB/104 MiB CGO alloc/total, 205.30cgo/sec, 0.05/0.01 %(u/s)time, 0.00 %gc (2x)
I180719 05:32:10.442618 119439 rpc/nodedialer/nodedialer.go:90  [intExec=adopt-job] connection to n5 established
I180719 05:32:10.444312 124423 rpc/nodedialer/nodedialer.go:90  [n5] connection to n1 established
I180719 05:32:10.677615 120138 server/status/runtime.go:255  [n2] runtime stats: 261 MiB RSS, 1189 goroutines, 57 MiB/28 MiB/117 MiB GO alloc/idle/total, 67 MiB/104 MiB CGO alloc/total, 211.70cgo/sec, 0.05/0.01 %(u/s)time, 0.00 %gc (1x)
I180719 05:32:10.682834 120076 rpc/nodedialer/nodedialer.go:90  [intExec=adopt-job] connection to n5 established
I180719 05:32:10.685746 124483 rpc/nodedialer/nodedialer.go:90  [n5] connection to n2 established
I180719 05:32:10.733105 120398 server/status/runtime.go:255  [n3] runtime stats: 263 MiB RSS, 1189 goroutines, 65 MiB/20 MiB/117 MiB GO alloc/idle/total, 67 MiB/104 MiB CGO alloc/total, 211.78cgo/sec, 0.05/0.01 %(u/s)time, 0.00 %gc (1x)
I180719 05:32:10.738370 120328 rpc/nodedialer/nodedialer.go:90  [intExec=adopt-job] connection to n1 established
I180719 05:32:10.738891 124491 rpc/nodedialer/nodedialer.go:90  [n1] connection to n3 established
I180719 05:32:10.747327 124508 storage/replica_range_lease.go:554  [replicate,n3,s3,r23/3:{m-/Table/Syste…}] transferring lease to s5
I180719 05:32:10.748262 124508 storage/replica_range_lease.go:617  [replicate,n3,s3,r23/3:{m-/Table/Syste…}] done transferring lease to s5: <nil>
I180719 05:32:10.748373 121067 storage/replica_proposal.go:222  [n5,s5,r23/2:{m-/Table/Syste…}] new range lease repl=(n5,s5):2 seq=5 start=1531978330.747345673,0 epo=1 pro=1531978330.747348360,0 following repl=(n3,s3):3 seq=4 start=1531978312.865936119,0 epo=1 pro=1531978312.865938763,0
I180719 05:32:10.797510 120670 server/status/runtime.go:255  [n4] runtime stats: 263 MiB RSS, 1189 goroutines, 69 MiB/17 MiB/117 MiB GO alloc/idle/total, 67 MiB/104 MiB CGO alloc/total, 228.66cgo/sec, 0.05/0.01 %(u/s)time, 0.00 %gc (1x)
I180719 05:32:10.798625 120586 rpc/nodedialer/nodedialer.go:90  [intExec=adopt-job] connection to n1 established
I180719 05:32:10.799191 124518 rpc/nodedialer/nodedialer.go:90  [n1] connection to n4 established
I180719 05:32:10.861517 120864 server/status/runtime.go:255  [n5] runtime stats: 266 MiB RSS, 1189 goroutines, 49 MiB/34 MiB/117 MiB GO alloc/idle/total, 68 MiB/105 MiB CGO alloc/total, 227.02cgo/sec, 0.06/0.01 %(u/s)time, 0.00 %gc (2x)
I180719 05:32:11.157022 119515 gossip/gossip.go:1339  [n1] node has connected to cluster via gossip
I180719 05:32:11.157298 119515 storage/stores.go:241  [n1] wrote 4 node addresses to persistent storage
I180719 05:32:11.828819 124556 storage/replica_range_lease.go:554  [replicate,n4,s4,r14/3:/Table/1{7-8}] transferring lease to s3
I180719 05:32:11.829850 124556 storage/replica_range_lease.go:617  [replicate,n4,s4,r14/3:/Table/1{7-8}] done transferring lease to s3: <nil>
I180719 05:32:11.830172 120436 storage/replica_proposal.go:222  [n3,s3,r14/2:/Table/1{7-8}] new range lease repl=(n3,s3):2 seq=5 start=1531978331.828834105,0 epo=1 pro=1531978331.828836145,0 following repl=(n4,s4):3 seq=4 start=1531978315.739075671,0 epo=1 pro=1531978315.739078479,0
I180719 05:32:13.832681 120492 storage/compactor/compactor.go:374  [n3,s3,compactor] processing compaction #1-2/2 (/System/tsd-/Max) for 201 KiB (reasons: size=false used=true avail=false)
I180719 05:32:13.835754 120492 storage/compactor/compactor.go:390  [n3,s3,compactor] processed compaction #1-2/2 (/System/tsd-/Max) for 201 KiB in 0.0s
I180719 05:32:13.919910 120612 gossip/gossip.go:1339  [n4] node has connected to cluster via gossip
I180719 05:32:13.920136 120612 storage/stores.go:241  [n4] wrote 4 node addresses to persistent storage
I180719 05:32:17.750637 124697 storage/replica_command.go:743  [replicate,n3,s3,r14/2:/Table/1{7-8}] change replicas (REMOVE_REPLICA (n4,s4):3): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, (n3,s3):2, (n4,s4):3, (n2,s2):4, next=5]
I180719 05:32:17.761172 124697 storage/replica.go:3613  [n3,s3,r14/2:/Table/1{7-8}] proposing REMOVE_REPLICA((n4,s4):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):4] next=5
I180719 05:32:17.762445 121707 storage/store.go:3585  [n4,s4,r14/3:/Table/1{7-8}] added to replica GC queue (peer suggestion)
I180719 05:32:17.763557 124654 storage/store.go:2513  [replicaGC,n4,s4,r14/3:/Table/1{7-8}] removing replica
I180719 05:32:17.763801 124654 storage/replica.go:836  [replicaGC,n4,s4,r14/3:/Table/1{7-8}] removed 8 (0+8) keys in 0ms [clear=0ms commit=0ms]
I180719 05:32:20.437405 119466 server/status/runtime.go:255  [n1] runtime stats: 266 MiB RSS, 1189 goroutines, 64 MiB/20 MiB/117 MiB GO alloc/idle/total, 67 MiB/107 MiB CGO alloc/total, 184.00cgo/sec, 0.06/0.00 %(u/s)time, 0.00 %gc (1x)
I180719 05:32:20.678034 120138 server/status/runtime.go:255  [n2] runtime stats: 266 MiB RSS, 1189 goroutines, 72 MiB/13 MiB/117 MiB GO alloc/idle/total, 67 MiB/107 MiB CGO alloc/total, 177.29cgo/sec, 0.06/0.00 %(u/s)time, 0.00 %gc (1x)
I180719 05:32:20.733290 120398 server/status/runtime.go:255  [n3] runtime stats: 267 MiB RSS, 1189 goroutines, 40 MiB/43 MiB/117 MiB GO alloc/idle/total, 67 MiB/107 MiB CGO alloc/total, 176.10cgo/sec, 0.06/0.00 %(u/s)time, 0.00 %gc (2x)
I180719 05:32:20.797388 120670 server/status/runtime.go:255  [n4] runtime stats: 267 MiB RSS, 1189 goroutines, 46 MiB/38 MiB/117 MiB GO alloc/idle/total, 67 MiB/107 MiB CGO alloc/total, 162.90cgo/sec, 0.06/0.00 %(u/s)time, 0.00 %gc (2x)
I180719 05:32:20.861433 120864 server/status/runtime.go:255  [n5] runtime stats: 265 MiB RSS, 1189 goroutines, 60 MiB/25 MiB/117 MiB GO alloc/idle/total, 68 MiB/105 MiB CGO alloc/total, 159.60cgo/sec, 0.05/0.00 %(u/s)time, 0.00 %gc (1x)
I180719 05:32:21.721244 119662 storage/compactor/compactor.go:374  [n1,s1,compactor] processing compaction #1/1 (/System/NodeLivenessMax-/System/tsd) for 84 KiB (reasons: size=false used=true avail=false)
I180719 05:32:21.740682 119662 storage/compactor/compactor.go:390  [n1,s1,compactor] processed compaction #1/1 (/System/NodeLivenessMax-/System/tsd) for 84 KiB in 0.0s
I180719 05:32:23.882689 124868 storage/replica_range_lease.go:554  [replicate,n5,s5,r23/2:{m-/Table/Syste…}] transferring lease to s2
I180719 05:32:23.883635 124868 storage/replica_range_lease.go:617  [replicate,n5,s5,r23/2:{m-/Table/Syste…}] done transferring lease to s2: <nil>
I180719 05:32:23.883740 120211 storage/replica_proposal.go:222  [n2,s2,r23/4:{m-/Table/Syste…}] new range lease repl=(n2,s2):4 seq=6 start=1531978343.882705666,0 epo=1 pro=1531978343.882709821,0 following repl=(n5,s5):2 seq=5 start=1531978330.747345673,0 epo=1 pro=1531978330.747348360,0
W180719 05:32:26.779840 121293 storage/raft_transport.go:575  [n5] while processing outgoing Raft queue to node 1: rpc error: code = Unavailable desc = transport is closing:
W180719 05:32:26.780016 121826 storage/raft_transport.go:575  [n2] while processing outgoing Raft queue to node 4: rpc error: code = Unavailable desc = transport is closing:
W180719 05:32:26.780265 121664 storage/raft_transport.go:575  [n5] while processing outgoing Raft queue to node 2: rpc error: code = Canceled desc = grpc: the client connection is closing:
W180719 05:32:26.780326 120907 gossip/gossip.go:1325  [n5] no incoming or outgoing connections
W180719 05:32:26.780371 121830 storage/raft_transport.go:575  [n2] while processing outgoing Raft queue to node 5: EOF:
W180719 05:32:26.780390 121892 storage/raft_transport.go:575  [n3] while processing outgoing Raft queue to node 5: EOF:
W180719 05:32:26.780429 121801 storage/raft_transport.go:575  [n5] while processing outgoing Raft queue to node 3: rpc error: code = Canceled desc = grpc: the client connection is closing:
W180719 05:32:26.780434 121781 storage/raft_transport.go:575  [n4] while processing outgoing Raft queue to node 5: EOF:
W180719 05:32:26.780497 121866 storage/raft_transport.go:575  [n5] while processing outgoing Raft queue to node 4: rpc error: code = Canceled desc = grpc: the client connection is closing:
W180719 05:32:26.780575 122006 storage/raft_transport.go:575  [n2] while processing outgoing Raft queue to node 3: rpc error: code = Canceled desc = grpc: the client connection is closing:
W180719 05:32:26.780584 121823 storage/raft_transport.go:575  [n4] while processing outgoing Raft queue to node 2: EOF:
W180719 05:32:26.780630 122041 storage/raft_transport.go:575  [n3] while processing outgoing Raft queue to node 2: EOF:
W180719 05:32:26.780650 120952 storage/raft_transport.go:575  [n2] while processing outgoing Raft queue to node 1: rpc error: code = Canceled desc = context canceled:
W180719 05:32:26.780693 120096 gossip/gossip.go:1325  [n2] no incoming or outgoing connections
W180719 05:32:26.780725 120612 gossip/gossip.go:1325  [n4] no incoming or outgoing connections
W180719 05:32:26.780729 120355 gossip/gossip.go:1325  [n3] no incoming or outgoing connections
W180719 05:32:26.780789 121268 storage/raft_transport.go:575  [n4] while processing outgoing Raft queue to node 1: EOF:
W180719 05:32:26.780804 120512 storage/raft_transport.go:575  [n3] while processing outgoing Raft queue to node 1: EOF:
W180719 05:32:26.780847 121705 storage/raft_transport.go:575  [n4] while processing outgoing Raft queue to node 3: EOF:
W180719 05:32:26.780953 121843 storage/raft_transport.go:575  [n3] while processing outgoing Raft queue to node 4: rpc error: code = Canceled desc = grpc: the client connection is closing:
W180719 05:32:26.781146 120507 storage/raft_transport.go:575  [n1] while processing outgoing Raft queue to node 3: rpc error: code = Canceled desc = grpc: the client connection is closing:
W180719 05:32:26.781171 121288 storage/raft_transport.go:575  [n1] while processing outgoing Raft queue to node 5: rpc error: code = Canceled desc = grpc: the client connection is closing:
--- FAIL: TestReplicateQueueDownReplicate (46.37s)
	replicate_queue_test.go:231: condition failed to evaluate within 45s: replica count, want 3, current 5
		goroutine 119429 [running]:
		runtime/debug.Stack(0xa7a358200, 0xc4241a3f20, 0x2a00640)
			/usr/local/go/src/runtime/debug/stack.go:24 +0xa7
		github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x2a4d3e0, 0xc420c5a000, 0xc423013f20)
			/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:38 +0x7d
		github.com/cockroachdb/cockroach/pkg/storage_test.TestReplicateQueueDownReplicate(0xc420c5a000)
			/go/src/github.com/cockroachdb/cockroach/pkg/storage/replicate_queue_test.go:231 +0x45d
		testing.tRunner(0xc420c5a000, 0x263b5a0)
			/usr/local/go/src/testing/testing.go:777 +0xd0
		created by testing.(*T).Run
			/usr/local/go/src/testing/testing.go:824 +0x2e0
@cockroach-teamcity cockroach-teamcity added this to the 2.1 milestone Jul 19, 2018
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Jul 19, 2018
@cockroach-teamcity
Copy link
Member Author

SHA: https://github.com/cockroachdb/cockroach/commits/6b49d8cf1b8130a21698c74f541964dfd6a4e3c8

Parameters:

TAGS=
GOFLAGS=

Failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=786338&tab=buildLog

@tbg tbg assigned tbg and unassigned vivekmenezes Jul 19, 2018
tbg added a commit to tbg/cockroach that referenced this issue Jul 19, 2018
@tbg
storage: really deflake TestReplicateQueueDownReplicateo
aafd08b 
Fixes cockroachdb#27736.

Release note: None
@tbg tbg mentioned this issue Jul 19, 2018
Merged
craig bot pushed a commit that referenced this issue Jul 19, 2018
@tbg
Merge #27740
a9410c5 
27740: storage: really deflake TestReplicateQueueDownReplicate r=a-robinson a=tschottdorf

Fixes #27736.

Release note: None

Co-authored-by: Tobias Schottdorf <[email protected]>
@craig craig bot closed this as completed in #27740 Jul 19, 2018
@vivekmenezes vivekmenezes mentioned this issue Jul 23, 2018
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@tbg tbg

Labels
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 @vivekmenezes @cockroach-teamcity