Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

teamcity: failed tests on master: testrace/TestBackupRestoreControlJob, test/TestBackupRestoreControlJob #24163

Closed
cockroach-teamcity opened this issue Mar 22, 2018 · 1 comment
Closed

teamcity: failed tests on master: testrace/TestBackupRestoreControlJob, test/TestBackupRestoreControlJob #24163

cockroach-teamcity opened this issue Mar 22, 2018 · 1 comment
Assignees
@dt
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed:

#582612:

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

------- Stdout: -------
I180322 20:55:28.857761 55576 sql/event_log.go:121  [n1,client=127.0.0.1:46268,user=root] Event: "create_database", target: 53, info: {DatabaseName:orig_fkdb Statement:CREATE DATABASE orig_fkdb User:root}
I180322 20:55:29.190074 53053 gossip/gossip.go:1306  [n3] node has connected to cluster via gossip
I180322 20:55:29.191172 53053 storage/stores.go:350  [n3] wrote 2 node addresses to persistent storage
I180322 20:55:29.256124 55175 sql/event_log.go:121  [n1,client=127.0.0.1:46262,user=root] Event: "create_database", target: 54, info: {DatabaseName:restore_fkdb Statement:CREATE DATABASE restore_fkdb User:root}
I180322 20:55:29.298093 52308 server/status/runtime.go:219  [n1] runtime stats: 1.4 GiB RSS, 647 goroutines, 53 MiB/62 MiB/137 MiB GO alloc/idle/total, 96 MiB/138 MiB CGO alloc/total, 2134.99cgo/sec, 1.73/0.11 %(u/s)time, 0.03 %gc (11x)
I180322 20:55:30.059992 55576 sql/event_log.go:121  [n1,client=127.0.0.1:46268,user=root] Event: "create_table", target: 55, info: {TableName:orig_fkdb.public.fk Statement:CREATE TABLE orig_fkdb.public.fk (i INT, FOREIGN KEY (i) REFERENCES data.public.bank) User:root}
I180322 20:55:30.135005 52916 storage/replica_proposal.go:201  [n2,s2,r13/2:/Table/1{6-7}] new range lease repl=(n2,s2):2 seq=4 start=1521752130.013344995,0 epo=1 pro=1521752130.013379710,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752109.517034485,0
I180322 20:55:30.215622 52895 storage/replica_proposal.go:201  [n2,s2,r22/2:/Table/5{1-2/1/20}] new range lease repl=(n2,s2):2 seq=6 start=1521752130.069938853,0 epo=1 pro=1521752130.069971187,0 following repl=(n3,s3):3 seq=5 start=1521752125.001206696,0 epo=1 pro=1521752125.001238733,0
I180322 20:55:30.669696 53178 storage/replica_proposal.go:201  [n3,s3,r22/3:/Table/5{1-2/1/20}] new range lease repl=(n3,s3):3 seq=7 start=1521752130.608123060,0 epo=1 pro=1521752130.608157156,0 following repl=(n2,s2):2 seq=6 start=1521752130.069938853,0 epo=1 pro=1521752130.069971187,0
I180322 20:55:30.816341 55576 sql/lease.go:352  [n1,client=127.0.0.1:46268,user=root] publish: descID=52 (bank) version=2 mtime=2018-03-22 20:55:30.731851496 +0000 UTC
I180322 20:55:31.167289 55576 sql/lease.go:275  publish (count leases): descID=52 name=bank version=1 count=1
I180322 20:55:31.195539 57649 sql/lease.go:812  new lease: 52("bank") ver=2:1521752491.048978566,0, refcount=0
I180322 20:55:31.293793 53161 storage/replica_proposal.go:201  [n3,s3,r14/3:/Table/1{7-8}] new range lease repl=(n3,s3):3 seq=4 start=1521752131.280398383,0 epo=1 pro=1521752131.280438635,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752109.858780514,0
I180322 20:55:31.413414 55576 sql/lease.go:275  publish (count leases): descID=52 name=bank version=1 count=1
I180322 20:55:32.295331 55576 sql/lease.go:352  [n1,client=127.0.0.1:46268,user=root] publish: descID=55 (fk) version=2 mtime=2018-03-22 20:55:32.288026014 +0000 UTC
I180322 20:55:32.357529 52804 gossip/gossip.go:1306  [n2] node has connected to cluster via gossip
I180322 20:55:32.358708 52804 storage/stores.go:350  [n2] wrote 2 node addresses to persistent storage
I180322 20:55:32.707882 55576 sql/lease.go:352  [n1,client=127.0.0.1:46268,user=root] publish: descID=55 (fk) version=3 mtime=2018-03-22 20:55:32.673000848 +0000 UTC
I180322 20:55:32.804158 52934 storage/replica_proposal.go:201  [n2,s2,r28/2:/Table/52/1/{400-500}] new range lease repl=(n2,s2):2 seq=4 start=1521752132.759716218,0 epo=1 pro=1521752132.759752661,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:33.906594 58403 storage/replica_command.go:862  [n1,s1,r33/1:/{Table/52/1/9…-Max}] initiating a split of this range at key /Table/55/1/0 [r34]
I180322 20:55:34.190644 52927 storage/replica_proposal.go:201  [n2,s2,r30/2:/Table/52/1/{600-700}] new range lease repl=(n2,s2):2 seq=4 start=1521752134.172793051,0 epo=1 pro=1521752134.172830783,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:34.209181 52258 storage/replica_proposal.go:201  [n1,s1,r33/1:/{Table/52/1/9…-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:34.792952 58571 storage/replica_command.go:862  [n1,s1,r34/1:/{Table/55/1/0-Max}] initiating a split of this range at key /Table/55/1/1 [r35]
I180322 20:55:34.983542 52888 storage/replica_proposal.go:201  [n2,s2,r22/2:/Table/5{1-2/1/20}] new range lease repl=(n2,s2):2 seq=8 start=1521752134.950555218,0 epo=1 pro=1521752134.950588767,0 following repl=(n3,s3):3 seq=7 start=1521752130.608123060,0 epo=1 pro=1521752130.608157156,0
I180322 20:55:35.420470 52264 storage/replica_proposal.go:201  [n1,s1,r34/1:/{Table/55/1/0-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:35.436555 52855 server/status/runtime.go:219  [n2] runtime stats: 1.4 GiB RSS, 656 goroutines, 46 MiB/69 MiB/137 MiB GO alloc/idle/total, 99 MiB/139 MiB CGO alloc/total, 1525.80cgo/sec, 1.61/0.10 %(u/s)time, 0.02 %gc (10x)
I180322 20:55:35.626693 53146 storage/replica_proposal.go:201  [n3,s3,r34/3:/Table/55/1/{0-1}] new range lease repl=(n3,s3):3 seq=4 start=1521752135.461603877,0 epo=1 pro=1521752135.461653227,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:36.045132 58869 storage/replica_command.go:862  [n1,s1,r35/1:/{Table/55/1/1-Max}] initiating a split of this range at key /Table/55/1/2 [r36]
I180322 20:55:36.437509 52231 storage/replica_proposal.go:201  [n1,s1,r35/1:/{Table/55/1/1-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:36.704192 53108 server/status/runtime.go:219  [n3] runtime stats: 1.4 GiB RSS, 657 goroutines, 36 MiB/77 MiB/137 MiB GO alloc/idle/total, 99 MiB/139 MiB CGO alloc/total, 1482.72cgo/sec, 1.61/0.11 %(u/s)time, 0.02 %gc (11x)
I180322 20:55:37.029609 59022 storage/replica_command.go:862  [n1,s1,r36/1:/{Table/55/1/2-Max}] initiating a split of this range at key /Table/55/1/3 [r37]
I180322 20:55:37.584427 52288 storage/replica_proposal.go:201  [n1,s1,r36/1:/{Table/55/1/2-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:38.267935 59260 storage/replica_command.go:862  [n1,s1,r37/1:/{Table/55/1/3-Max}] initiating a split of this range at key /Table/55/1/4 [r38]
I180322 20:55:38.587009 52258 storage/replica_proposal.go:201  [n1,s1,r37/1:/{Table/55/1/3-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:38.727518 53205 storage/replica_proposal.go:201  [n3,s3,r37/3:/Table/55/1/{3-4}] new range lease repl=(n3,s3):3 seq=4 start=1521752138.654185950,0 epo=1 pro=1521752138.654220910,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:39.215007 59496 storage/replica_command.go:862  [n1,s1,r38/1:/{Table/55/1/4-Max}] initiating a split of this range at key /Table/55/1/5 [r39]
I180322 20:55:39.277005 52308 server/status/runtime.go:219  [n1] runtime stats: 1.4 GiB RSS, 652 goroutines, 34 MiB/79 MiB/137 MiB GO alloc/idle/total, 98 MiB/139 MiB CGO alloc/total, 1302.35cgo/sec, 1.60/0.11 %(u/s)time, 0.02 %gc (11x)
I180322 20:55:39.521909 52288 storage/replica_proposal.go:201  [n1,s1,r38/1:/{Table/55/1/4-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:40.112296 53140 storage/replica_proposal.go:201  [n3,s3,r11/3:/Table/1{4-5}] new range lease repl=(n3,s3):3 seq=4 start=1521752140.094434510,0 epo=1 pro=1521752140.094474747,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752108.528893660,0
I180322 20:55:40.128536 59748 storage/replica_command.go:862  [n1,s1,r39/1:/{Table/55/1/5-Max}] initiating a split of this range at key /Table/55/1/6 [r40]
I180322 20:55:40.513008 52288 storage/replica_proposal.go:201  [n1,s1,r39/1:/{Table/55/1/5-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:40.533148 59816 storage/replica_command.go:1784  [replicate,n2,s2,r22/2:/Table/5{1-2/1/20}] change replicas (REMOVE_REPLICA (n3,s3):3): read existing descriptor r22:/Table/5{1-2/1/20} [(n3,s3):3, (n2,s2):2, next=4]
I180322 20:55:40.864427 59900 storage/replica.go:3218  [n2,s2,r22/2:/Table/5{1-2/1/20}] proposing REMOVE_REPLICA((n3,s3):3): updated=[(n2,s2):2] next=4
E180322 20:55:40.882269 59926 storage/queue.go:778  [replicate,n2,s2,r22/2:/Table/5{1-2/1/20}] no removable replicas from range that needs a removal: [2*:47]
I180322 20:55:40.926121 53547 storage/store.go:3543  [n3,s3,r22/3:/Table/5{1-2/1/20}] added to replica GC queue (peer suggestion)
I180322 20:55:40.977450 59852 storage/store.go:2414  [replicaGC,n3,s3,r22/3:/Table/5{1-2/1/20}] removing replica
I180322 20:55:40.988553 59852 storage/replica.go:836  [replicaGC,n3,s3,r22/3:/Table/5{1-2/1/20}] removed 33 (20+13) keys in 1ms [clear=0ms commit=1ms]
I180322 20:55:41.214210 59962 storage/replica_command.go:862  [n1,s1,r40/1:/{Table/55/1/6-Max}] initiating a split of this range at key /Table/55/1/7 [r41]
I180322 20:55:41.489748 52250 storage/replica_proposal.go:201  [n1,s1,r40/1:/{Table/55/1/6-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:41.800349 53088 storage/replica_proposal.go:201  [n3,s3,r40/3:/Table/55/1/{6-7}] new range lease repl=(n3,s3):3 seq=4 start=1521752141.570325137,0 epo=1 pro=1521752141.570387782,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:42.221196 60218 storage/replica_command.go:862  [n1,s1,r41/1:/{Table/55/1/7-Max}] initiating a split of this range at key /Table/55/1/8 [r42]
I180322 20:55:42.613049 52252 storage/replica_proposal.go:201  [n1,s1,r41/1:/{Table/55/1/7-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:43.129873 52764 storage/replica_proposal.go:201  [n2,s2,r35/2:/Table/55/1/{1-2}] new range lease repl=(n2,s2):2 seq=4 start=1521752143.095221900,0 epo=1 pro=1521752143.095255306,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:43.178507 60320 storage/replica_command.go:862  [n1,s1,r42/1:/{Table/55/1/8-Max}] initiating a split of this range at key /Table/55/1/9 [r43]
I180322 20:55:43.701238 52230 storage/replica_proposal.go:201  [n1,s1,r42/1:/{Table/55/1/8-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:44.383141 53142 storage/replica_proposal.go:201  [n3,s3,r23/3:/Table/52/1/{20-100}] new range lease repl=(n3,s3):3 seq=4 start=1521752144.354366915,0 epo=1 pro=1521752144.354408108,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:44.833743 60758 ccl/storageccl/export.go:118  [n1,s1,r38/1:/Table/55/1/{4-5}] export [/Table/55/1/4,/Table/55/1/5)
I180322 20:55:44.860397 60720 ccl/storageccl/export.go:118  [n1,s1,r33/1:/Table/5{2/1/900-5/1/0}] export [/Table/55/1,/Table/55/1/0)
I180322 20:55:44.869372 60772 ccl/storageccl/export.go:118  [n1,s1,r39/1:/Table/55/1/{5-6}] export [/Table/55/1/5,/Table/55/1/6)
I180322 20:55:44.874631 60834 ccl/storageccl/export.go:118  [n2,s2,r35/2:/Table/55/1/{1-2}] export [/Table/55/1/1,/Table/55/1/2)
I180322 20:55:44.876646 60773 ccl/storageccl/export.go:118  [n1,s1,r41/1:/Table/55/1/{7-8}] export [/Table/55/1/7,/Table/55/1/8)
I180322 20:55:44.877009 60855 ccl/storageccl/export.go:118  [n3,s3,r34/3:/Table/55/1/{0-1}] export [/Table/55/1/0,/Table/55/1/1)
I180322 20:55:44.877731 60852 ccl/storageccl/export.go:118  [n3,s3,r40/3:/Table/55/1/{6-7}] export [/Table/55/1/6,/Table/55/1/7)
I180322 20:55:44.879267 60854 ccl/storageccl/export.go:118  [n3,s3,r37/3:/Table/55/1/{3-4}] export [/Table/55/1/3,/Table/55/1/4)
I180322 20:55:44.884359 60789 ccl/storageccl/export.go:118  [n1,s1,r42/1:/Table/55/1/{8-9}] export [/Table/55/1/8,/Table/55/1/9)
I180322 20:55:44.897720 60777 ccl/storageccl/export.go:118  [n1,s1,r36/1:/Table/55/1/{2-3}] export [/Table/55/1/2,/Table/55/1/3)
I180322 20:55:44.899903 60858 ccl/storageccl/export.go:118  [n1,s1,r43/1:/{Table/55/1/9-Max}] export [/Table/55/2,/Table/55/3)
I180322 20:55:44.901875 60859 ccl/storageccl/export.go:118  [n1,s1,r43/1:/{Table/55/1/9-Max}] export [/Table/55/1/9,/Table/55/2)
I180322 20:55:45.427254 52855 server/status/runtime.go:219  [n2] runtime stats: 1.4 GiB RSS, 684 goroutines, 49 MiB/65 MiB/137 MiB GO alloc/idle/total, 102 MiB/142 MiB CGO alloc/total, 1501.70cgo/sec, 1.79/0.13 %(u/s)time, 0.03 %gc (11x)
I180322 20:55:46.700772 53108 server/status/runtime.go:219  [n3] runtime stats: 1.4 GiB RSS, 653 goroutines, 36 MiB/78 MiB/137 MiB GO alloc/idle/total, 100 MiB/143 MiB CGO alloc/total, 1355.26cgo/sec, 1.78/0.14 %(u/s)time, 0.02 %gc (11x)
I180322 20:55:47.553944 61436 ccl/storageccl/export.go:118  [n3,s3,r34/3:/Table/55/1/{0-1}] export [/Table/55/1/0,/Table/55/1/1)
I180322 20:55:47.557051 61445 ccl/storageccl/export.go:118  [n1,s1,r36/1:/Table/55/1/{2-3}] export [/Table/55/1/2,/Table/55/1/3)
I180322 20:55:47.600294 61371 ccl/storageccl/export.go:118  [n2,s2,r35/2:/Table/55/1/{1-2}] export [/Table/55/1/1,/Table/55/1/2)
I180322 20:55:47.567831 61447 ccl/storageccl/export.go:118  [n1,s1,r38/1:/Table/55/1/{4-5}] export [/Table/55/1/4,/Table/55/1/5)
I180322 20:55:47.616479 61464 ccl/storageccl/export.go:118  [n3,s3,r37/3:/Table/55/1/{3-4}] export [/Table/55/1/3,/Table/55/1/4)
I180322 20:55:47.640937 61408 ccl/storageccl/export.go:118  [n3,s3,r40/3:/Table/55/1/{6-7}] export [/Table/55/1/6,/Table/55/1/7)
I180322 20:55:47.642622 61492 ccl/storageccl/export.go:118  [n1,s1,r43/1:/{Table/55/1/9-Max}] export [/Table/55/2,/Table/55/3)
I180322 20:55:47.657329 61494 ccl/storageccl/export.go:118  [n1,s1,r43/1:/{Table/55/1/9-Max}] export [/Table/55/1/9,/Table/55/2)
I180322 20:55:47.662263 61493 ccl/storageccl/export.go:118  [n1,s1,r41/1:/Table/55/1/{7-8}] export [/Table/55/1/7,/Table/55/1/8)
I180322 20:55:47.665398 61495 ccl/storageccl/export.go:118  [n1,s1,r33/1:/Table/5{2/1/900-5/1/0}] export [/Table/55/1,/Table/55/1/0)
I180322 20:55:47.667274 61498 ccl/storageccl/export.go:118  [n1,s1,r42/1:/Table/55/1/{8-9}] export [/Table/55/1/8,/Table/55/1/9)
I180322 20:55:47.668533 61496 ccl/storageccl/export.go:118  [n1,s1,r39/1:/Table/55/1/{5-6}] export [/Table/55/1/5,/Table/55/1/6)
E180322 20:55:47.802529 52327 sql/jobs/registry.go:272  error while adopting jobs: unable to acquire lease: current lease node_id:2 epoch:1  did not match expected lease 
E180322 20:55:48.203693 53097 sql/jobs/registry.go:272  error while adopting jobs: unable to acquire lease: current lease node_id:2 epoch:1  did not match expected lease 
I180322 20:55:49.299519 52308 server/status/runtime.go:219  [n1] runtime stats: 1.4 GiB RSS, 666 goroutines, 49 MiB/68 MiB/137 MiB GO alloc/idle/total, 104 MiB/146 MiB CGO alloc/total, 1244.80cgo/sec, 1.80/0.15 %(u/s)time, 0.02 %gc (11x)
E180322 20:55:51.190414 62364 storage/queue.go:778  [replicate,n2,s2,r22/2:/Table/5{1-2/1/20}] no removable replicas from range that needs a removal: [2*:48]
I180322 20:55:53.336850 62942 storage/replica_command.go:862  [n1,s1,r43/1:/{Table/55/1/9-Max}] initiating a split of this range at key /Table/56 [r44]
I180322 20:55:53.654628 52240 storage/replica_proposal.go:201  [n1,s1,r43/1:/{Table/55/1/9-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:53.756155 52917 storage/replica_proposal.go:201  [n2,s2,r43/2:/Table/5{5/1/9-6}] new range lease repl=(n2,s2):2 seq=4 start=1521752153.704229643,0 epo=1 pro=1521752153.704261846,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:53.829457 63080 storage/replica_command.go:862  [n1,s1,r44/1:/{Table/56-Max}] initiating a split of this range at key /Table/56/1/9 [r45]
I180322 20:55:54.533734 52234 storage/replica_proposal.go:201  [n1,s1,r44/1:/{Table/56-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:54.670421 63315 storage/replica_command.go:862  [n1,s1,r45/1:/{Table/56/1/9-Max}] initiating a split of this range at key /Table/56/2 [r46]
I180322 20:55:55.160293 52242 storage/replica_proposal.go:201  [n1,s1,r45/1:/{Table/56/1/9-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:55.402320 52879 storage/replica_proposal.go:201  [n2,s2,r20/2:/Table/{23-50}] new range lease repl=(n2,s2):2 seq=4 start=1521752155.354946076,0 epo=1 pro=1521752155.354977386,0 following repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0
I180322 20:55:55.436293 52855 server/status/runtime.go:219  [n2] runtime stats: 1.4 GiB RSS, 668 goroutines, 34 MiB/77 MiB/137 MiB GO alloc/idle/total, 105 MiB/147 MiB CGO alloc/total, 1139.77cgo/sec, 1.85/0.18 %(u/s)time, 0.02 %gc (12x)
I180322 20:55:56.754523 53108 server/status/runtime.go:219  [n3] runtime stats: 1.4 GiB RSS, 656 goroutines, 40 MiB/73 MiB/137 MiB GO alloc/idle/total, 104 MiB/147 MiB CGO alloc/total, 1142.44cgo/sec, 1.83/0.17 %(u/s)time, 0.02 %gc (11x)
E180322 20:55:57.167408 53097 sql/jobs/registry.go:272  error while adopting jobs: unable to acquire lease: current lease node_id:2 epoch:1  did not match expected lease 
E180322 20:55:57.171368 63767 storage/queue.go:778  [replicate,n2,s2,r22/2:/Table/5{1-2/1/20}] no removable replicas from range that needs a removal: [2*:48]
I180322 20:55:59.268755 51921 gossip/gossip.go:487  [n1] gossip status (ok, 3 nodes)
gossip client (0/3 cur/max conns)
gossip server (2/3 cur/max conns, infos 875/166 sent/received, bytes 395148B/149010B sent/received)
  2: 127.0.0.1:46757 (54s)
  3: 127.0.0.1:33751 (53s)
I180322 20:55:59.301830 52308 server/status/runtime.go:219  [n1] runtime stats: 1.4 GiB RSS, 653 goroutines, 37 MiB/76 MiB/137 MiB GO alloc/idle/total, 105 MiB/149 MiB CGO alloc/total, 1097.44cgo/sec, 1.80/0.17 %(u/s)time, 0.04 %gc (11x)
--- FAIL: testrace/TestBackupRestoreControlJob (0.000s)
Test ended in panic.

------- Stdout: -------
W180322 20:54:59.017237 52085 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180322 20:54:59.079219 52085 server/server.go:734  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180322 20:54:59.094271 52085 server/config.go:538  [n?] 1 storage engine initialized
I180322 20:54:59.094513 52085 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180322 20:54:59.094577 52085 server/config.go:541  [n?] store 0: in-memory, size 0 B
I180322 20:54:59.181799 52085 server/node.go:374  [n?] **** cluster 25ddc89b-79cf-4fd5-88fa-c858a17adbec has been created
I180322 20:54:59.182021 52085 server/server.go:1304  [n?] **** add additional nodes by specifying --join=127.0.0.1:35367
I180322 20:54:59.213191 52085 storage/store.go:1394  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180322 20:54:59.231959 52085 server/node.go:512  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=4.9 KiB), ranges=1, leases=0, writes=0.00, bytesPerReplica={p10=5043.00 p25=5043.00 p50=5043.00 p75=5043.00 p90=5043.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00}
I180322 20:54:59.242236 52085 server/node.go:352  [n1] node ID 1 initialized
I180322 20:54:59.242844 52085 gossip/gossip.go:332  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:35367" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:1 > 
I180322 20:54:59.243917 52085 storage/stores.go:331  [n1] read 0 node addresses from persistent storage
I180322 20:54:59.244579 52085 server/node.go:653  [n1] connecting to gossip network to verify cluster ID...
I180322 20:54:59.244836 52085 server/node.go:678  [n1] node connected via gossip and verified as part of cluster "25ddc89b-79cf-4fd5-88fa-c858a17adbec"
I180322 20:54:59.266800 52085 server/node.go:446  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180322 20:54:59.274506 52085 server/server.go:1430  [n1] starting https server at 127.0.0.1:39311
I180322 20:54:59.274689 52085 server/server.go:1431  [n1] starting grpc/postgres server at 127.0.0.1:35367
I180322 20:54:59.274736 52085 server/server.go:1432  [n1] advertising CockroachDB node at 127.0.0.1:35367
W180322 20:54:59.275531 52085 sql/jobs/registry.go:286  [n1] unable to get node liveness: node not in the liveness table
I180322 20:54:59.328466 52331 storage/replica_command.go:862  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180322 20:54:59.572976 52320 storage/replica_command.go:862  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180322 20:54:59.784216 52085 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}
I180322 20:54:59.959323 52223 storage/replica_command.go:862  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I180322 20:55:00.284483 52394 storage/replica_command.go:862  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
W180322 20:55:00.507654 52397 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=79372bf8 key=/Local/Range/System/NodeLivenessMax/RangeDescriptor rw=true pri=0.03090226 iso=SERIALIZABLE stat=PENDING epo=0 ts=1521752100.284726654,0 orig=1521752100.284726654,0 max=1521752100.284726654,0 wto=false rop=false seq=3
I180322 20:55:00.582970 52350 storage/replica_command.go:862  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
W180322 20:55:00.594906 52399 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=1641c422 key=/Table/SystemConfigSpan/Start rw=true pri=0.02204119 iso=SERIALIZABLE stat=PENDING epo=0 ts=1521752100.339711896,0 orig=1521752100.339711896,0 max=1521752100.339711896,0 wto=false rop=false seq=13
I180322 20:55:00.805700 52085 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:node}
I180322 20:55:00.860817 52466 storage/replica_command.go:862  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I180322 20:55:01.050149 52366 storage/replica_command.go:862  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180322 20:55:01.125702 52085 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}
I180322 20:55:01.335010 52459 storage/replica_command.go:862  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180322 20:55:01.524427 52379 storage/replica_command.go:862  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180322 20:55:01.612415 52487 storage/replica_command.go:862  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180322 20:55:01.818970 52384 storage/replica_command.go:862  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180322 20:55:01.979363 52432 storage/replica_command.go:862  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180322 20:55:02.124762 52085 sql/event_log.go:121  [n1] Event: "alter_table", target: 4, info: {TableName:system.public.users Statement:ALTER TABLE system.public.users ADD COLUMN IF NOT EXISTS "isRole" BOOL NOT NULL DEFAULT false User:node MutationID:1 CascadeDroppedViews:[]}
I180322 20:55:02.268991 52579 storage/replica_command.go:862  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180322 20:55:02.306144 52085 sql/lease.go:352  [n1] publish: descID=4 (users) version=2 mtime=2018-03-22 20:55:02.299752806 +0000 UTC
I180322 20:55:02.489546 52556 storage/replica_command.go:862  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I180322 20:55:02.656360 52085 sql/lease.go:352  [n1] publish: descID=4 (users) version=3 mtime=2018-03-22 20:55:02.654736888 +0000 UTC
I180322 20:55:02.684309 52559 storage/replica_command.go:862  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180322 20:55:02.860971 52600 storage/replica_command.go:862  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
I180322 20:55:02.906763 52085 sql/backfill.go:134  [n1] Running backfill for "users", v=3, m=1
I180322 20:55:02.985670 52591 storage/replica_command.go:862  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180322 20:55:03.163662 52571 storage/replica_command.go:862  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180322 20:55:03.378856 52674 storage/replica_command.go:862  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
I180322 20:55:03.492325 52085 sql/lease.go:352  [n1] publish: descID=4 (users) version=4 mtime=2018-03-22 20:55:03.491092651 +0000 UTC
W180322 20:55:03.574338 52651 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=83953fb6 key=/Local/Range/Table/22/RangeDescriptor rw=true pri=0.05947915 iso=SERIALIZABLE stat=PENDING epo=0 ts=1521752103.380556923,0 orig=1521752103.380556923,0 max=1521752103.380556923,0 wto=false rop=false seq=3
I180322 20:55:03.773996 52085 sql/lease.go:352  [n1] publish: descID=4 (users) version=4 mtime=2018-03-22 20:55:03.534396166 +0000 UTC
I180322 20:55:03.881920 52085 sql/event_log.go:121  [n1] Event: "finish_schema_change", target: 4, info: {MutationID:1}
I180322 20:55:03.940674 52085 sql/lease.go:275  publish (count leases): descID=4 name=users version=3 count=1
I180322 20:55:03.954936 52693 sql/lease.go:812  new lease: 4("users") ver=4:1521752452.567025574,0, refcount=0
I180322 20:55:03.973781 52085 sql/lease.go:275  publish (count leases): descID=4 name=users version=3 count=1
I180322 20:55:04.706849 52085 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:node}
I180322 20:55:04.772000 52085 server/server.go:1510  [n1] done ensuring all necessary migrations have run
I180322 20:55:04.772336 52085 server/server.go:1513  [n1] serving sql connections
I180322 20:55:04.818609 52718 sql/event_log.go:121  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:35367} Attrs: Locality: ServerVersion:2.0-1} ClusterID:25ddc89b-79cf-4fd5-88fa-c858a17adbec StartedAt:1521752099244897236 LastUp:1521752099244897236}
W180322 20:55:04.941057 52085 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180322 20:55:05.081043 52085 server/server.go:734  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180322 20:55:05.119739 52085 server/config.go:538  [n?] 1 storage engine initialized
I180322 20:55:05.119931 52085 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180322 20:55:05.119978 52085 server/config.go:541  [n?] store 0: in-memory, size 0 B
W180322 20:55:05.132389 52085 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180322 20:55:05.137676 52085 server/server.go:1306  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180322 20:55:05.317493 52753 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:46757}
I180322 20:55:05.320821 52806 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:35367
I180322 20:55:05.335326 52085 storage/stores.go:331  [n?] read 0 node addresses from persistent storage
I180322 20:55:05.336063 52085 storage/stores.go:350  [n?] wrote 1 node addresses to persistent storage
I180322 20:55:05.336163 52085 server/node.go:653  [n?] connecting to gossip network to verify cluster ID...
I180322 20:55:05.336391 52085 server/node.go:678  [n?] node connected via gossip and verified as part of cluster "25ddc89b-79cf-4fd5-88fa-c858a17adbec"
I180322 20:55:05.340241 52846 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180322 20:55:05.348088 52845 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180322 20:55:05.375158 52085 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180322 20:55:05.385278 52085 server/node.go:345  [n?] new node allocated ID 2
I180322 20:55:05.387293 52085 gossip/gossip.go:332  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:46757" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:1 > 
I180322 20:55:05.395900 52820 storage/stores.go:350  [n1] wrote 1 node addresses to persistent storage
I180322 20:55:05.398000 52085 server/node.go:427  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180322 20:55:05.417380 52085 server/node.go:446  [n2] node=2: started with [] engine(s) and attributes []
I180322 20:55:05.459846 52085 server/server.go:1430  [n2] starting https server at 127.0.0.1:43443
I180322 20:55:05.460053 52085 server/server.go:1431  [n2] starting grpc/postgres server at 127.0.0.1:46757
I180322 20:55:05.460106 52085 server/server.go:1432  [n2] advertising CockroachDB node at 127.0.0.1:46757
I180322 20:55:05.512080 52085 server/server.go:1510  [n2] done ensuring all necessary migrations have run
I180322 20:55:05.512306 52085 server/server.go:1513  [n2] serving sql connections
I180322 20:55:05.770331 52850 server/node.go:634  [n2] bootstrapped store [n2,s2]
I180322 20:55:05.773382 52949 sql/event_log.go:121  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:46757} Attrs: Locality: ServerVersion:2.0-1} ClusterID:25ddc89b-79cf-4fd5-88fa-c858a17adbec StartedAt:1521752105416542521 LastUp:1521752105416542521}
W180322 20:55:05.996423 52085 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180322 20:55:06.115446 52085 server/server.go:734  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180322 20:55:06.150645 52085 server/config.go:538  [n?] 1 storage engine initialized
I180322 20:55:06.150852 52085 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180322 20:55:06.150902 52085 server/config.go:541  [n?] store 0: in-memory, size 0 B
W180322 20:55:06.151358 52085 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180322 20:55:06.152162 52085 server/server.go:1306  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180322 20:55:06.502570 53020 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:35367
I180322 20:55:06.525044 52827 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:33751}
I180322 20:55:06.558748 52085 storage/stores.go:331  [n?] read 0 node addresses from persistent storage
I180322 20:55:06.559229 52085 storage/stores.go:350  [n?] wrote 2 node addresses to persistent storage
I180322 20:55:06.560405 52085 server/node.go:653  [n?] connecting to gossip network to verify cluster ID...
I180322 20:55:06.560623 52085 server/node.go:678  [n?] node connected via gossip and verified as part of cluster "25ddc89b-79cf-4fd5-88fa-c858a17adbec"
I180322 20:55:06.569178 53091 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180322 20:55:06.588854 53090 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180322 20:55:06.608166 52085 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180322 20:55:06.645991 52085 server/node.go:345  [n?] new node allocated ID 3
I180322 20:55:06.646801 52085 gossip/gossip.go:332  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:33751" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:1 > 
I180322 20:55:06.647967 52085 server/node.go:427  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180322 20:55:06.649781 52085 server/node.go:446  [n3] node=3: started with [] engine(s) and attributes []
I180322 20:55:06.666217 52085 server/server.go:1430  [n3] starting https server at 127.0.0.1:33183
I180322 20:55:06.666437 52085 server/server.go:1431  [n3] starting grpc/postgres server at 127.0.0.1:33751
I180322 20:55:06.666511 52085 server/server.go:1432  [n3] advertising CockroachDB node at 127.0.0.1:33751
W180322 20:55:06.666904 52085 sql/jobs/registry.go:286  [n3] unable to get node liveness: node not in the liveness table
I180322 20:55:06.689395 52085 server/server.go:1510  [n3] done ensuring all necessary migrations have run
I180322 20:55:06.689714 52085 server/server.go:1513  [n3] serving sql connections
I180322 20:55:06.708164 53116 storage/stores.go:350  [n1] wrote 2 node addresses to persistent storage
I180322 20:55:06.744087 52687 server/node.go:634  [n3] bootstrapped store [n3,s3]
I180322 20:55:06.751731 53186 storage/stores.go:350  [n2] wrote 2 node addresses to persistent storage
I180322 20:55:06.792329 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot 6c38ca4e at index 17
I180322 20:55:06.846324 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:06.882192 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:06.943512 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:06.944388 53124 sql/event_log.go:121  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:33751} Attrs: Locality: ServerVersion:2.0-1} ClusterID:25ddc89b-79cf-4fd5-88fa-c858a17adbec StartedAt:1521752106648275095 LastUp:1521752106648275095}
I180322 20:55:06.978726 52304 storage/store.go:3828  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 11, log entries: 7, rate-limit: 8.0 MiB/sec, 6ms
I180322 20:55:06.981052 53300 storage/replica_raftstorage.go:726  [n3,s3,r19/?:{-}] applying preemptive snapshot at index 17 (id=6c38ca4e, encoded size=2687, 1 rocksdb batches, 7 log entries)
I180322 20:55:06.984271 53300 storage/replica_raftstorage.go:732  [n3,s3,r19/?:/Table/2{2-3}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180322 20:55:06.989309 52304 storage/replica_command.go:1784  [replicate,n1,s1,r19/1:/Table/2{2-3}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, next=2]
I180322 20:55:07.002657 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:07.161545 52304 storage/replica.go:3218  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180322 20:55:07.161784 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:07.211735 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 076dfbf3 at index 44
I180322 20:55:07.264469 52304 storage/store.go:3828  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 41, log entries: 34, rate-limit: 8.0 MiB/sec, 33ms
I180322 20:55:07.276897 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:07.280224 53307 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180322 20:55:07.311331 53274 storage/replica_raftstorage.go:726  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 44 (id=076dfbf3, encoded size=103840, 1 rocksdb batches, 34 log entries)
I180322 20:55:07.404039 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:07.422044 53274 storage/replica_raftstorage.go:732  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 110ms [clear=0ms batch=0ms entries=101ms commit=4ms]
I180322 20:55:07.430754 52304 storage/replica_command.go:1784  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, next=2]
I180322 20:55:07.522335 52304 storage/replica.go:3218  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180322 20:55:07.573045 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot e5fb2a3b at index 17
I180322 20:55:07.601681 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:07.713333 52304 storage/store.go:3828  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 7, rate-limit: 8.0 MiB/sec, 6ms
I180322 20:55:07.716245 53353 storage/replica_raftstorage.go:726  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 17 (id=e5fb2a3b, encoded size=2687, 1 rocksdb batches, 7 log entries)
I180322 20:55:07.719245 53353 storage/replica_raftstorage.go:732  [n2,s2,r15/?:/Table/1{8-9}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180322 20:55:07.733250 52286 storage/replica_proposal.go:201  [n1,s1,r15/1:/Table/1{8-9}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.729265087,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:07.735100 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:07.745197 52246 storage/replica_proposal.go:201  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.722821438,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:07.754120 52304 storage/replica_command.go:1784  [replicate,n1,s1,r15/1:/Table/1{8-9}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r15:/Table/1{8-9} [(n1,s1):1, next=2]
I180322 20:55:07.793237 52284 storage/replica_proposal.go:201  [n1,s1,r10/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.788885318,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:07.802819 52253 storage/replica_proposal.go:201  [n1,s1,r12/1:/Table/1{5-6}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.791414863,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:07.857361 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:07.893398 52256 storage/replica_proposal.go:201  [n1,s1,r20/1:/{Table/23-Max}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.889285797,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:07.933574 52304 storage/replica.go:3218  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180322 20:55:07.955994 52234 storage/replica_proposal.go:201  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752107.939904928,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:07.964212 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:07.969142 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot 98e4ec41 at index 26
I180322 20:55:07.990835 52304 storage/store.go:3828  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 14, log entries: 16, rate-limit: 8.0 MiB/sec, 13ms
I180322 20:55:07.993666 53337 storage/replica_raftstorage.go:726  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 26 (id=98e4ec41, encoded size=6038, 1 rocksdb batches, 16 log entries)
I180322 20:55:07.999294 53337 storage/replica_raftstorage.go:732  [n2,s2,r8/?:/Table/1{1-2}] applied preemptive snapshot in 5ms [clear=0ms batch=0ms entries=4ms commit=0ms]
I180322 20:55:08.021265 52304 storage/replica_command.go:1784  [replicate,n1,s1,r8/1:/Table/1{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r8:/Table/1{1-2} [(n1,s1):1, next=2]
I180322 20:55:08.029149 53390 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180322 20:55:08.134837 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:08.192574 52304 storage/replica.go:3218  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180322 20:55:08.225387 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot 30db4c74 at index 44
I180322 20:55:08.240426 52304 storage/store.go:3828  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 150, log entries: 34, rate-limit: 8.0 MiB/sec, 11ms
I180322 20:55:08.243453 53445 storage/replica_raftstorage.go:726  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 44 (id=30db4c74, encoded size=35728, 1 rocksdb batches, 34 log entries)
I180322 20:55:08.243715 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:08.253252 53445 storage/replica_raftstorage.go:732  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 9ms [clear=0ms batch=0ms entries=8ms commit=0ms]
I180322 20:55:08.269964 52304 storage/replica_command.go:1784  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, next=2]
I180322 20:55:08.386953 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:08.402442 53150 storage/replica_proposal.go:201  [n3,s3,r19/2:/Table/2{2-3}] new range lease repl=(n3,s3):2 seq=3 start=1521752108.222385597,1 epo=1 pro=1521752108.386655845,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:08.434539 53419 storage/replica_raftstorage.go:520  [replicate,n3,s3,r19/2:/Table/2{2-3}] generated preemptive snapshot 2a6a530c at index 21
I180322 20:55:08.500863 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:08.510911 52304 storage/replica.go:3218  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180322 20:55:08.533097 52253 storage/replica_proposal.go:201  [n1,s1,r11/1:/Table/1{4-5}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752108.528893660,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:08.556247 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot ff3334c1 at index 19
I180322 20:55:08.563303 52304 storage/store.go:3828  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 9, rate-limit: 8.0 MiB/sec, 6ms
I180322 20:55:08.574813 53509 storage/replica_raftstorage.go:726  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 19 (id=ff3334c1, encoded size=3379, 1 rocksdb batches, 9 log entries)
I180322 20:55:08.582509 53509 storage/replica_raftstorage.go:732  [n2,s2,r11/?:/Table/1{4-5}] applied preemptive snapshot in 7ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180322 20:55:08.589326 52304 storage/replica_command.go:1784  [replicate,n1,s1,r11/1:/Table/1{4-5}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r11:/Table/1{4-5} [(n1,s1):1, next=2]
I180322 20:55:08.622049 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:08.730956 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:08.735130 52304 storage/replica.go:3218  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180322 20:55:08.754673 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot b6699b12 at index 57
I180322 20:55:08.765158 52304 storage/store.go:3828  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):?: kv pairs: 79, log entries: 47, rate-limit: 8.0 MiB/sec, 9ms
I180322 20:55:08.769238 53480 storage/replica_raftstorage.go:726  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 57 (id=b6699b12, encoded size=44451, 1 rocksdb batches, 47 log entries)
I180322 20:55:08.883310 53419 storage/store.go:3828  [replicate,n3,s3,r19/2:/Table/2{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 12, log entries: 11, rate-limit: 8.0 MiB/sec, 79ms
I180322 20:55:08.888233 53480 storage/replica_raftstorage.go:732  [n2,s2,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 113ms [clear=0ms batch=0ms entries=108ms commit=1ms]
I180322 20:55:08.892783 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:08.902431 52304 storage/replica_command.go:1784  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, next=2]
I180322 20:55:08.938829 53525 storage/replica_raftstorage.go:726  [n2,s2,r19/?:{-}] applying preemptive snapshot at index 21 (id=2a6a530c, encoded size=3885, 1 rocksdb batches, 11 log entries)
I180322 20:55:08.942416 53525 storage/replica_raftstorage.go:732  [n2,s2,r19/?:/Table/2{2-3}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180322 20:55:08.960672 53419 storage/replica_command.go:1784  [replicate,n3,s3,r19/2:/Table/2{2-3}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, (n3,s3):2, next=3]
I180322 20:55:09.018151 52304 storage/replica.go:3218  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180322 20:55:09.110911 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:09.121108 52282 storage/replica_proposal.go:201  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752109.107730619,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:09.136001 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot d863cba6 at index 24
I180322 20:55:09.293813 52308 server/status/runtime.go:219  [n1] runtime stats: 1.4 GiB RSS, 612 goroutines, 29 MiB/85 MiB/137 MiB GO alloc/idle/total, 87 MiB/127 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (313x)
I180322 20:55:09.296622 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:09.303816 52304 storage/store.go:3828  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 967, log entries: 14, rate-limit: 8.0 MiB/sec, 167ms
I180322 20:55:09.309086 53342 storage/replica_raftstorage.go:726  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 24 (id=d863cba6, encoded size=163152, 1 rocksdb batches, 14 log entries)
I180322 20:55:09.373830 53342 storage/replica_raftstorage.go:732  [n2,s2,r5/?:/System/ts{d-e}] applied preemptive snapshot in 59ms [clear=0ms batch=1ms entries=56ms commit=2ms]
I180322 20:55:09.381474 52304 storage/replica_command.go:1784  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, next=2]
I180322 20:55:09.415569 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180322 20:55:09.442060 53556 storage/replica.go:3218  [n3,s3,r19/2:/Table/2{2-3}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180322 20:55:09.497513 53212 storage/replica_proposal.go:201  [n3,s3,r4/2:/System/{NodeLive…-tsd}] new range lease repl=(n3,s3):2 seq=3 start=1521752108.222385597,1 epo=1 pro=1521752109.463959134,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:09.500695 52304 storage/replica.go:3218  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180322 20:55:09.514917 53520 storage/replica_raftstorage.go:520  [replicate,n3,s3,r4/2:/System/{NodeLive…-tsd}] generated preemptive snapshot 98ee31d4 at index 50
I180322 20:55:09.525897 52249 storage/replica_proposal.go:201  [n1,s1,r13/1:/Table/1{6-7}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752109.517034485,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:09.531556 53520 storage/store.go:3828  [replicate,n3,s3,r4/2:/System/{NodeLive…-tsd}] streamed snapshot to (n2,s2):?: kv pairs: 42, log entries: 7, rate-limit: 8.0 MiB/sec, 8ms
I180322 20:55:09.535918 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot ba420a9a at index 19
I180322 20:55:09.536523 53592 storage/replica_raftstorage.go:726  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 50 (id=98ee31d4, encoded size=87620, 1 rocksdb batches, 7 log entries)
I180322 20:55:09.568228 52304 storage/store.go:3828  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 9, rate-limit: 8.0 MiB/sec, 31ms
I180322 20:55:09.587530 53607 storage/replica_raftstorage.go:726  [n2,s2,r13/?:{-}] applying preemptive snapshot at index 19 (id=ba420a9a, encoded size=2909, 1 rocksdb batches, 9 log entries)
I180322 20:55:09.590915 53607 storage/replica_raftstorage.go:732  [n2,s2,r13/?:/Table/1{6-7}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180322 20:55:09.593402 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180322 20:55:09.595781 53592 storage/replica_raftstorage.go:732  [n2,s2,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 59ms [clear=0ms batch=0ms entries=19ms commit=8ms]
I180322 20:55:09.656875 52304 storage/replica_command.go:1784  [replicate,n1,s1,r13/1:/Table/1{6-7}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, next=2]
I180322 20:55:09.698580 53520 storage/replica_command.go:1784  [replicate,n3,s3,r4/2:/System/{NodeLive…-tsd}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r4:/System/{NodeLivenessMax-tsd} [(n1,s1):1, (n3,s3):2, next=3]
I180322 20:55:09.730601 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180322 20:55:09.777135 53622 storage/raft_transport.go:459  [n2] raft transport stream to node 3 established
I180322 20:55:09.788124 52304 storage/replica.go:3218  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180322 20:55:09.897218 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180322 20:55:09.898463 52275 storage/replica_proposal.go:201  [n1,s1,r14/1:/Table/1{7-8}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752109.858780514,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:09.909560 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot a6fe6f38 at index 19
I180322 20:55:09.921169 52304 storage/store.go:3828  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 9, rate-limit: 8.0 MiB/sec, 11ms
I180322 20:55:09.924417 53703 storage/replica_raftstorage.go:726  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 19 (id=a6fe6f38, encoded size=2909, 1 rocksdb batches, 9 log entries)
I180322 20:55:09.927221 53703 storage/replica_raftstorage.go:732  [n2,s2,r14/?:/Table/1{7-8}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180322 20:55:09.972797 52304 storage/replica_command.go:1784  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, next=2]
I180322 20:55:09.996492 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180322 20:55:10.034038 53689 storage/replica.go:3218  [n3,s3,r4/2:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180322 20:55:10.114930 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180322 20:55:10.177023 52304 storage/replica.go:3218  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180322 20:55:10.208457 52264 storage/replica_proposal.go:201  [n1,s1,r18/1:/Table/2{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752110.203250072,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:10.223461 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot c2a81eb5 at index 18
I180322 20:55:10.245189 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180322 20:55:10.273620 52304 storage/store.go:3828  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 8, rate-limit: 8.0 MiB/sec, 44ms
I180322 20:55:10.288474 53693 storage/replica_raftstorage.go:726  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 18 (id=c2a81eb5, encoded size=2847, 1 rocksdb batches, 8 log entries)
I180322 20:55:10.295926 53693 storage/replica_raftstorage.go:732  [n2,s2,r18/?:/Table/2{1-2}] applied preemptive snapshot in 7ms [clear=0ms batch=0ms entries=5ms commit=0ms]
I180322 20:55:10.311107 52304 storage/replica_command.go:1784  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, next=2]
I180322 20:55:10.375515 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180322 20:55:10.397524 52304 storage/replica.go:3218  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180322 20:55:10.427006 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot e74102cc at index 28
I180322 20:55:10.432982 52304 storage/store.go:3828  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 16, log entries: 18, rate-limit: 8.0 MiB/sec, 5ms
I180322 20:55:10.435821 53676 storage/replica_raftstorage.go:726  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 28 (id=e74102cc, encoded size=5976, 1 rocksdb batches, 18 log entries)
I180322 20:55:10.454541 53676 storage/replica_raftstorage.go:732  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 18ms [clear=0ms batch=0ms entries=7ms commit=0ms]
I180322 20:55:10.459166 52304 storage/replica_command.go:1784  [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]
I180322 20:55:10.473584 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180322 20:55:10.581086 52304 storage/replica.go:3218  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180322 20:55:10.632561 52252 storage/replica_proposal.go:201  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1521752099.186213075,0 epo=1 pro=1521752110.595197471,0 following repl=(n1,s1):1 seq=2 start=1521752099.186213075,0 exp=1521752108.222385597,0 pro=1521752099.222565739,0
I180322 20:55:10.633251 52085 testutils/testcluster/testcluster.go:534  [n1,s1] has 18 underreplicated ranges
I180322 20:55:10.667147 52304 storage/replica_raftstorage.go:520  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot e42c71e5 at index 32
I180322 20:55:10.687215 52304 storage/store.go:3828  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n2,s2):?:

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the 2.0 milestone Mar 22, 2018
@cockroach-teamcity cockroach-teamcity added O-robot Originated from a bot. C-test-failure Broken test (automatically or manually discovered). labels Mar 22, 2018
@petermattis petermattis modified the milestones: 2.0, 2.0.x Apr 5, 2018
@tbg tbg assigned dt Apr 18, 2018
@a-robinson
Copy link
Contributor

Dupe of #24136

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

@dt dt

Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@dt @petermattis @a-robinson @cockroach-teamcity