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, acceptance/TestNodeRestart #24633

Closed
cockroach-teamcity opened this issue Apr 10, 2018 · 1 comment
Closed

teamcity: failed tests on master: testrace/TestBackupRestoreControlJob, test/TestBackupRestoreControlJob, acceptance/TestNodeRestart #24633

cockroach-teamcity opened this issue Apr 10, 2018 · 1 comment
Assignees
@dt
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

The following tests appear to have failed:

#595333:

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

------- Stdout: -------
E180410 16:42:21.071255 66409 storage/queue.go:778  [replicate,n1,s1,r82/1:/Table/51/1/5{40-60}] no removable replicas from range that needs a removal: [1*:29]
E180410 16:42:21.128332 66428 storage/queue.go:778  [replicate,n3,s3,r58/3:/Table/51/1/3{40-60}] no removable replicas from range that needs a removal: [3*:28]
I180410 16:42:21.244847 52642 server/status/runtime.go:219  [n2] runtime stats: 1.4 GiB RSS, 657 goroutines, 40 MiB/73 MiB/138 MiB GO alloc/idle/total, 114 MiB/154 MiB CGO alloc/total, 1466.13cgo/sec, 1.93/0.16 %(u/s)time, 0.01 %gc (11x)
I180410 16:42:21.270878 54261 sql/event_log.go:121  [n1,client=127.0.0.1:41282,user=root] Event: "create_database", target: 56, info: {DatabaseName:pause Statement:CREATE DATABASE pause User:root}
E180410 16:42:21.334535 66455 storage/queue.go:778  [replicate,n3,s3,r32/3:/Table/51/1/{60-80}] no removable replicas from range that needs a removal: [3*:31]
I180410 16:42:21.352605 52903 storage/replica_proposal.go:202  [n3,s3,r90/3:/Table/51/1/{680-700}] new range lease repl=(n3,s3):3 seq=8 start=1523378541.312061400,0 epo=1 pro=1523378541.312102426,0 following repl=(n1,s1):1 seq=7 start=1523378535.077330630,0 epo=1 pro=1523378535.077368214,0
I180410 16:42:21.747809 66622 ccl/storageccl/export.go:120  [n1,s1,r55/1:/Table/51/1/2{20-40}] export [/Table/51/1/220,/Table/51/1/240)
I180410 16:42:21.802397 66642 ccl/storageccl/export.go:120  [n3,s3,r29/3:/Table/51/1/{40-60}] export [/Table/51/1/40,/Table/51/1/60)
I180410 16:42:21.814793 66591 ccl/storageccl/export.go:120  [n3,s3,r35/3:/Table/51/1/{80-100}] export [/Table/51/1/80,/Table/51/1/100)
I180410 16:42:21.819233 66643 ccl/storageccl/export.go:120  [n3,s3,r22/3:/Table/51{-/1/20}] export [/Table/51/1,/Table/51/1/20)
I180410 16:42:21.823727 66541 ccl/storageccl/export.go:120  [n2,s2,r47/2:/Table/51/1/2{00-20}] export [/Table/51/1/200,/Table/51/1/220)
I180410 16:42:21.824312 66540 ccl/storageccl/export.go:120  [n2,s2,r51/2:/Table/51/1/{160-200}] export [/Table/51/1/160,/Table/51/1/200)
I180410 16:42:21.845645 66539 ccl/storageccl/export.go:120  [n2,s2,r26/2:/Table/51/1/{20-40}] export [/Table/51/1/20,/Table/51/1/40)
I180410 16:42:21.859881 66542 ccl/storageccl/export.go:120  [n2,s2,r40/2:/Table/51/1/1{20-40}] export [/Table/51/1/120,/Table/51/1/140)
I180410 16:42:21.873081 66632 ccl/storageccl/export.go:120  [n1,s1,r53/1:/Table/51/1/3{20-40}] export [/Table/51/1/320,/Table/51/1/340)
I180410 16:42:21.803378 66644 ccl/storageccl/export.go:120  [n3,s3,r50/3:/Table/51/1/3{00-20}] export [/Table/51/1/300,/Table/51/1/320)
I180410 16:42:21.901922 66593 ccl/storageccl/export.go:120  [n2,s2,r57/2:/Table/51/1/2{40-60}] export [/Table/51/1/240,/Table/51/1/260)
I180410 16:42:21.944518 66629 ccl/storageccl/export.go:120  [n1,s1,r38/1:/Table/51/1/1{00-20}] export [/Table/51/1/100,/Table/51/1/120)
I180410 16:42:22.003236 66560 ccl/storageccl/export.go:120  [n2,s2,r43/2:/Table/51/1/1{40-60}] export [/Table/51/1/140,/Table/51/1/160)
I180410 16:42:22.067935 52767 server/status/runtime.go:219  [n3] runtime stats: 1.4 GiB RSS, 696 goroutines, 62 MiB/54 MiB/138 MiB GO alloc/idle/total, 118 MiB/156 MiB CGO alloc/total, 1440.52cgo/sec, 1.90/0.16 %(u/s)time, 0.02 %gc (11x)
I180410 16:42:22.071600 66692 ccl/storageccl/export.go:120  [n3,s3,r32/3:/Table/51/1/{60-80}] export [/Table/51/1/60,/Table/51/1/80)
I180410 16:42:22.094143 66609 ccl/storageccl/export.go:120  [n3,s3,r63/3:/Table/51/1/{280-300}] export [/Table/51/1/280,/Table/51/1/300)
I180410 16:42:22.113205 66691 ccl/storageccl/export.go:120  [n3,s3,r60/3:/Table/51/1/2{60-80}] export [/Table/51/1/260,/Table/51/1/280)
E180410 16:42:22.164006 66754 storage/queue.go:778  [replicate,n2,s2,r84/2:/Table/51/1/5{60-80}] no removable replicas from range that needs a removal: [2*:26]
E180410 16:42:22.413838 66810 storage/queue.go:778  [replicate,n1,s1,r68/1:/Table/51/1/4{20-40}] no removable replicas from range that needs a removal: [1*:30]
E180410 16:42:22.569865 66811 storage/queue.go:778  [replicate,n2,s2,r87/2:/Table/51/1/{580-600}] no removable replicas from range that needs a removal: [2*:26]
E180410 16:42:22.798006 66887 storage/queue.go:778  [replicate,n3,s3,r31/3:/Table/51/1/8{30-50}] no removable replicas from range that needs a removal: [3*:29]
E180410 16:42:22.995301 66848 storage/queue.go:778  [replicate,n2,s2,r51/2:/Table/51/1/{160-200}] no removable replicas from range that needs a removal: [2*:32]
E180410 16:42:23.032798 66922 storage/queue.go:778  [replicate,n3,s3,r85/3:/Table/51/1/6{40-60}] no removable replicas from range that needs a removal: [3*:28]
I180410 16:42:23.060399 66785 ccl/storageccl/export.go:120  [n3,s3,r58/3:/Table/51/1/3{40-60}] export [/Table/51/1/340,/Table/51/1/360)
E180410 16:42:23.246241 66937 storage/queue.go:778  [replicate,n1,s1,r77/1:/Table/51/1/5{20-40}] no removable replicas from range that needs a removal: [1*:34]
W180410 16:42:23.614262 52164 sql/jobs/registry.go:553  job 338520117412790273: node 0 owns lease; canceling
E180410 16:42:23.642610 67052 storage/queue.go:778  [replicate,n3,s3,r35/3:/Table/51/1/{80-100}] no removable replicas from range that needs a removal: [3*:33]
E180410 16:42:23.846876 66974 storage/queue.go:778  [replicate,n3,s3,r92/3:/Table/51/1/7{00-20}] no removable replicas from range that needs a removal: [3*:27]
I180410 16:42:23.927987 52058 storage/replica_proposal.go:202  [n1,s1,r96/1:/Table/51/1/7{40-70}] new range lease repl=(n1,s1):1 seq=7 start=1523378543.849465582,0 epo=1 pro=1523378543.849508005,0 following repl=(n2,s2):2 seq=6 start=1523378537.331233248,0 epo=1 pro=1523378537.338643334,0
I180410 16:42:24.203608 67105 ccl/storageccl/export.go:120  [n3,s3,r35/3:/Table/51/1/{80-100}] export [/Table/51/1/80,/Table/51/1/100)
I180410 16:42:24.231377 67104 ccl/storageccl/export.go:120  [n3,s3,r29/3:/Table/51/1/{40-60}] export [/Table/51/1/40,/Table/51/1/60)
I180410 16:42:24.232719 67103 ccl/storageccl/export.go:120  [n2,s2,r26/2:/Table/51/1/{20-40}] export [/Table/51/1/20,/Table/51/1/40)
I180410 16:42:24.280445 67181 ccl/storageccl/export.go:120  [n2,s2,r47/2:/Table/51/1/2{00-20}] export [/Table/51/1/200,/Table/51/1/220)
I180410 16:42:24.281799 67299 ccl/storageccl/export.go:120  [n3,s3,r60/3:/Table/51/1/2{60-80}] export [/Table/51/1/260,/Table/51/1/280)
I180410 16:42:24.286719 67253 ccl/storageccl/export.go:120  [n2,s2,r51/2:/Table/51/1/{160-200}] export [/Table/51/1/160,/Table/51/1/200)
I180410 16:42:24.294426 67255 ccl/storageccl/export.go:120  [n3,s3,r50/3:/Table/51/1/3{00-20}] export [/Table/51/1/300,/Table/51/1/320)
I180410 16:42:24.297210 67254 ccl/storageccl/export.go:120  [n3,s3,r63/3:/Table/51/1/{280-300}] export [/Table/51/1/280,/Table/51/1/300)
E180410 16:42:24.299568 67163 storage/queue.go:778  [replicate,n3,s3,r37/3:/Table/51/1/8{70-90}] no removable replicas from range that needs a removal: [3*:33]
I180410 16:42:24.302422 67164 ccl/storageccl/export.go:120  [n2,s2,r57/2:/Table/51/1/2{40-60}] export [/Table/51/1/240,/Table/51/1/260)
I180410 16:42:24.303424 67302 ccl/storageccl/export.go:120  [n2,s2,r43/2:/Table/51/1/1{40-60}] export [/Table/51/1/140,/Table/51/1/160)
I180410 16:42:24.313904 67303 ccl/storageccl/export.go:120  [n3,s3,r32/3:/Table/51/1/{60-80}] export [/Table/51/1/60,/Table/51/1/80)
I180410 16:42:24.314817 67304 ccl/storageccl/export.go:120  [n3,s3,r22/3:/Table/51{-/1/20}] export [/Table/51/1,/Table/51/1/20)
I180410 16:42:24.322585 67166 ccl/storageccl/export.go:120  [n1,s1,r53/1:/Table/51/1/3{20-40}] export [/Table/51/1/320,/Table/51/1/340)
I180410 16:42:24.361448 67322 storage/replica_raftstorage.go:520  [replicate,n1,s1,r106/1:/Table/54/1/{7-8}] generated preemptive snapshot 5586951d at index 20
I180410 16:42:24.376656 67217 ccl/storageccl/export.go:120  [n2,s2,r40/2:/Table/51/1/1{20-40}] export [/Table/51/1/120,/Table/51/1/140)
I180410 16:42:24.381297 67308 ccl/storageccl/export.go:120  [n1,s1,r38/1:/Table/51/1/1{00-20}] export [/Table/51/1/100,/Table/51/1/120)
I180410 16:42:24.398628 67322 storage/store.go:3834  [replicate,n1,s1,r106/1:/Table/54/1/{7-8}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 10, rate-limit: 8.0 MiB/sec, 36ms
I180410 16:42:24.415321 67325 storage/replica_raftstorage.go:726  [n3,s3,r106/?:{-}] applying preemptive snapshot at index 20 (id=5586951d, encoded size=2645, 1 rocksdb batches, 10 log entries)
I180410 16:42:24.421181 67325 storage/replica_raftstorage.go:732  [n3,s3,r106/?:/Table/54/1/{7-8}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=3ms commit=0ms]
I180410 16:42:24.468094 67322 storage/replica_command.go:1779  [replicate,n1,s1,r106/1:/Table/54/1/{7-8}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r106:/Table/54/1/{7-8} [(n1,s1):1, (n2,s2):2, next=3]
E180410 16:42:24.488690 67289 storage/queue.go:778  [replicate,n3,s3,r29/3:/Table/51/1/{40-60}] no removable replicas from range that needs a removal: [3*:27]
E180410 16:42:24.491611 67364 storage/queue.go:778  [replicate,n2,s2,r66/2:/Table/51/1/4{00-20}] no removable replicas from range that needs a removal: [2*:35]
--- FAIL: testrace/TestBackupRestoreControlJob (0.000s)
Test ended in panic.

------- Stdout: -------
W180410 16:41:04.499569 51923 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180410 16:41:04.593771 51923 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180410 16:41:04.721996 51923 server/config.go:538  [n?] 1 storage engine initialized
I180410 16:41:04.722078 51923 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180410 16:41:04.722132 51923 server/config.go:541  [n?] store 0: in-memory, size 0 B
I180410 16:41:04.901858 51923 server/node.go:374  [n?] **** cluster a03ceadd-391a-4a17-a1e8-ede0ebafa975 has been created
I180410 16:41:04.902110 51923 server/server.go:1305  [n?] **** add additional nodes by specifying --join=127.0.0.1:45351
I180410 16:41:04.960669 51923 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=1, 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}
I180410 16:41:04.961132 51923 server/node.go:352  [n1] node ID 1 initialized
I180410 16:41:04.961585 51923 gossip/gossip.go:332  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:45351" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180410 16:41:04.962708 51923 storage/stores.go:309  [n1] read 0 node addresses from persistent storage
I180410 16:41:04.963303 51923 server/node.go:653  [n1] connecting to gossip network to verify cluster ID...
I180410 16:41:04.963511 51923 server/node.go:678  [n1] node connected via gossip and verified as part of cluster "a03ceadd-391a-4a17-a1e8-ede0ebafa975"
I180410 16:41:04.963968 51923 server/node.go:446  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180410 16:41:05.017707 51923 server/server.go:1431  [n1] starting https server at 127.0.0.1:36531
I180410 16:41:05.017931 51923 server/server.go:1432  [n1] starting grpc/postgres server at 127.0.0.1:45351
I180410 16:41:05.017986 51923 server/server.go:1433  [n1] advertising CockroachDB node at 127.0.0.1:45351
W180410 16:41:05.018317 51923 sql/jobs/registry.go:286  [n1] unable to get node liveness: node not in the liveness table
I180410 16:41:05.051538 52032 storage/replica_command.go:862  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I180410 16:41:05.297544 51889 storage/replica_command.go:862  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I180410 16:41:05.744452 52167 storage/replica_command.go:862  [split,n1,s1,r3/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
W180410 16:41:05.821481 52194 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "sql txn implicit" id=6a6f08e8 key=/Table/SystemConfigSpan/Start rw=true pri=0.02333419 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523378465.222180230,0 orig=1523378465.222180230,0 max=1523378465.222180230,0 wto=false rop=false seq=8
I180410 16:41:05.870700 51923 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}
I180410 16:41:06.123014 51923 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:node}
I180410 16:41:06.224318 52160 storage/replica_command.go:862  [split,n1,s1,r4/1:/{System/NodeL…-Max}] initiating a split of this range at key /System/tsd [r5]
I180410 16:41:06.397147 51923 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}
I180410 16:41:06.429570 52125 storage/replica_command.go:862  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
W180410 16:41:06.739379 52202 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=d6bbe8e6 key=/Local/Range/System/tsd/RangeDescriptor rw=true pri=0.00467175 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523378466.448567438,0 orig=1523378466.448567438,0 max=1523378466.448567438,0 wto=false rop=false seq=3
I180410 16:41:06.810158 52111 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]
I180410 16:41:07.030441 52292 storage/replica_command.go:862  [split,n1,s1,r7/1:/{Table/System…-Max}] initiating a split of this range at key /Table/11 [r8]
I180410 16:41:07.253858 52295 storage/replica_command.go:862  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I180410 16:41:07.390868 52309 storage/replica_command.go:862  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I180410 16:41:07.571292 51923 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:[]}
I180410 16:41:07.625445 51923 sql/lease.go:352  [n1] publish: descID=4 (users) version=2 mtime=2018-04-10 16:41:07.624472069 +0000 UTC
I180410 16:41:07.679998 52056 storage/replica_proposal.go:202  [n1,s1,r10/1:/{Table/13-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0 following repl=(n1,s1):1 seq=2 start=1523378464.906325751,0 exp=1523378473.937639155,0 pro=1523378464.937714344,0
I180410 16:41:07.725121 52241 storage/replica_command.go:862  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I180410 16:41:07.872149 52070 storage/replica_proposal.go:202  [n1,s1,r10/1:/{Table/13-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0 following repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0
I180410 16:41:07.884493 52341 storage/replica_command.go:862  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I180410 16:41:08.041592 52082 storage/replica_proposal.go:202  [n1,s1,r11/1:/{Table/14-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0 following repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0
I180410 16:41:08.052441 52356 storage/replica_command.go:862  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I180410 16:41:08.132572 51923 sql/lease.go:352  [n1] publish: descID=4 (users) version=3 mtime=2018-04-10 16:41:08.124964867 +0000 UTC
I180410 16:41:08.234874 52037 storage/replica_proposal.go:202  [n1,s1,r12/1:/{Table/15-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0 following repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0
I180410 16:41:08.254046 52350 storage/replica_command.go:862  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I180410 16:41:08.396769 51923 sql/backfill.go:134  [n1] Running backfill for "users", v=3, m=1
I180410 16:41:08.398128 52056 storage/replica_proposal.go:202  [n1,s1,r13/1:/{Table/16-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0 following repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0
I180410 16:41:08.423477 52254 storage/replica_command.go:862  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
W180410 16:41:08.550153 52434 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=aeef308f key=/Local/Range/Table/17/RangeDescriptor rw=true pri=0.01887404 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523378468.424388640,0 orig=1523378468.424388640,0 max=1523378468.424388640,0 wto=false rop=false seq=3
W180410 16:41:08.555811 52451 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=aeef308f key=/Local/Range/Table/17/RangeDescriptor rw=true pri=0.01887404 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523378468.424388640,0 orig=1523378468.424388640,0 max=1523378468.424388640,0 wto=false rop=false seq=3
I180410 16:41:08.567492 52079 storage/replica_proposal.go:202  [n1,s1,r14/1:/{Table/17-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0 following repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0
I180410 16:41:08.572460 52326 storage/replica_command.go:862  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
I180410 16:41:08.736307 52087 storage/replica_proposal.go:202  [n1,s1,r15/1:/{Table/18-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0 following repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0
I180410 16:41:08.762359 52441 storage/replica_command.go:862  [split,n1,s1,r16/1:/{Table/19-Max}] initiating a split of this range at key /Table/20 [r17]
W180410 16:41:08.867213 52442 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=5c70f91d key=/Local/Range/Table/19/RangeDescriptor rw=true pri=0.02372493 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523378468.762676529,0 orig=1523378468.762676529,0 max=1523378468.762676529,0 wto=false rop=false seq=3
I180410 16:41:08.892748 52044 storage/replica_proposal.go:202  [n1,s1,r16/1:/{Table/19-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0 following repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0
I180410 16:41:08.910092 52360 storage/replica_command.go:862  [split,n1,s1,r17/1:/{Table/20-Max}] initiating a split of this range at key /Table/21 [r18]
I180410 16:41:09.049051 52060 storage/replica_proposal.go:202  [n1,s1,r17/1:/{Table/20-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0 following repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0
I180410 16:41:09.098861 52362 storage/replica_command.go:862  [split,n1,s1,r18/1:/{Table/21-Max}] initiating a split of this range at key /Table/22 [r19]
I180410 16:41:09.112952 51923 sql/lease.go:352  [n1] publish: descID=4 (users) version=4 mtime=2018-04-10 16:41:09.111394684 +0000 UTC
I180410 16:41:09.282984 52068 storage/replica_proposal.go:202  [n1,s1,r18/1:/{Table/21-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0 following repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0
I180410 16:41:09.305826 52410 storage/replica_command.go:862  [split,n1,s1,r19/1:/{Table/22-Max}] initiating a split of this range at key /Table/23 [r20]
W180410 16:41:09.401754 52414 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=edcb72ab key=/Local/Range/Table/22/RangeDescriptor rw=true pri=0.00959747 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523378469.306028205,0 orig=1523378469.306028205,0 max=1523378469.306028205,0 wto=false rop=false seq=3
W180410 16:41:09.408928 52460 storage/intent_resolver.go:320  [n1,s1] failed to push during intent resolution: failed to push "split" id=edcb72ab key=/Local/Range/Table/22/RangeDescriptor rw=true pri=0.00959747 iso=SERIALIZABLE stat=PENDING epo=0 ts=1523378469.306028205,0 orig=1523378469.306028205,0 max=1523378469.306028205,0 wto=false rop=false seq=3
I180410 16:41:09.441537 52035 storage/replica_proposal.go:202  [n1,s1,r19/1:/{Table/22-Max}] new range lease repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0 following repl=(n1,s1):1 seq=3 start=1523378467.610996489,0 epo=1 pro=1523378467.616068448,0
I180410 16:41:09.493452 51923 sql/lease.go:352  [n1] publish: descID=4 (users) version=4 mtime=2018-04-10 16:41:09.134654704 +0000 UTC
I180410 16:41:09.654112 51923 sql/event_log.go:121  [n1] Event: "finish_schema_change", target: 4, info: {MutationID:1}
I180410 16:41:09.673053 52514 sql/lease.go:812  new lease: 4("users") ver=4:1523378781.675511613,0, refcount=0
I180410 16:41:09.689173 51923 sql/lease.go:275  publish (count leases): descID=4 name=users version=3 count=1
I180410 16:41:09.716861 51923 sql/lease.go:275  publish (count leases): descID=4 name=users version=3 count=1
I180410 16:41:10.438541 51923 sql/event_log.go:121  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:node}
I180410 16:41:10.532515 51923 server/server.go:1511  [n1] done ensuring all necessary migrations have run
I180410 16:41:10.532837 51923 server/server.go:1514  [n1] serving sql connections
I180410 16:41:10.572051 52502 sql/event_log.go:121  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:45351} Attrs: Locality: ServerVersion:2.0-3} ClusterID:a03ceadd-391a-4a17-a1e8-ede0ebafa975 StartedAt:1523378464963578173 LastUp:1523378464963578173}
W180410 16:41:10.750477 51923 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180410 16:41:10.867112 51923 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180410 16:41:10.906984 51923 server/config.go:538  [n?] 1 storage engine initialized
I180410 16:41:10.907172 51923 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180410 16:41:10.907223 51923 server/config.go:541  [n?] store 0: in-memory, size 0 B
W180410 16:41:10.907623 51923 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180410 16:41:10.945208 51923 server/server.go:1307  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180410 16:41:11.133993 52508 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:45351
I180410 16:41:11.136876 52570 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:39549}
I180410 16:41:11.145159 51923 storage/stores.go:309  [n?] read 0 node addresses from persistent storage
I180410 16:41:11.151153 51923 storage/stores.go:328  [n?] wrote 1 node addresses to persistent storage
I180410 16:41:11.151393 51923 server/node.go:653  [n?] connecting to gossip network to verify cluster ID...
I180410 16:41:11.151650 51923 server/node.go:678  [n?] node connected via gossip and verified as part of cluster "a03ceadd-391a-4a17-a1e8-ede0ebafa975"
I180410 16:41:11.187878 51923 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180410 16:41:11.200785 51923 server/node.go:345  [n?] new node allocated ID 2
I180410 16:41:11.201421 51923 gossip/gossip.go:332  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:39549" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180410 16:41:11.202312 51923 server/node.go:427  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180410 16:41:11.202889 51923 server/node.go:446  [n2] node=2: started with [] engine(s) and attributes []
I180410 16:41:11.205673 51923 server/server.go:1431  [n2] starting https server at 127.0.0.1:41445
I180410 16:41:11.213879 51923 server/server.go:1432  [n2] starting grpc/postgres server at 127.0.0.1:39549
I180410 16:41:11.214259 51923 server/server.go:1433  [n2] advertising CockroachDB node at 127.0.0.1:39549
W180410 16:41:11.216292 51923 sql/jobs/registry.go:286  [n2] unable to get node liveness: node not in the liveness table
I180410 16:41:11.288632 52511 storage/stores.go:328  [n1] wrote 1 node addresses to persistent storage
I180410 16:41:11.295828 51923 server/server.go:1511  [n2] done ensuring all necessary migrations have run
I180410 16:41:11.298734 51923 server/server.go:1514  [n2] serving sql connections
I180410 16:41:11.366827 52525 server/node.go:634  [n2] bootstrapped store [n2,s2]
I180410 16:41:11.479177 52738 sql/event_log.go:121  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:39549} Attrs: Locality: ServerVersion:2.0-3} ClusterID:a03ceadd-391a-4a17-a1e8-ede0ebafa975 StartedAt:1523378471202570545 LastUp:1523378471202570545}
W180410 16:41:11.501120 51923 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180410 16:41:11.551316 51923 server/server.go:735  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180410 16:41:11.573122 51923 server/config.go:538  [n?] 1 storage engine initialized
I180410 16:41:11.573306 51923 server/config.go:541  [n?] RocksDB cache size: 128 MiB
I180410 16:41:11.573390 51923 server/config.go:541  [n?] store 0: in-memory, size 0 B
W180410 16:41:11.573794 51923 gossip/gossip.go:1292  [n?] no incoming or outgoing connections
I180410 16:41:11.574432 51923 server/server.go:1307  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180410 16:41:11.786840 52814 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:45351
I180410 16:41:11.790191 52872 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:39573}
I180410 16:41:11.814932 51923 storage/stores.go:309  [n?] read 0 node addresses from persistent storage
I180410 16:41:11.819261 51923 storage/stores.go:328  [n?] wrote 2 node addresses to persistent storage
I180410 16:41:11.819474 51923 server/node.go:653  [n?] connecting to gossip network to verify cluster ID...
I180410 16:41:11.819756 51923 server/node.go:678  [n?] node connected via gossip and verified as part of cluster "a03ceadd-391a-4a17-a1e8-ede0ebafa975"
I180410 16:41:11.839742 51923 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180410 16:41:11.856304 51923 server/node.go:345  [n?] new node allocated ID 3
I180410 16:41:11.857048 51923 gossip/gossip.go:332  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:39573" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:3 > 
I180410 16:41:11.858168 51923 server/node.go:427  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180410 16:41:11.864100 51923 server/node.go:446  [n3] node=3: started with [] engine(s) and attributes []
I180410 16:41:11.862481 52873 storage/stores.go:328  [n1] wrote 2 node addresses to persistent storage
I180410 16:41:11.940184 51923 server/server.go:1431  [n3] starting https server at 127.0.0.1:37219
I180410 16:41:11.941908 52748 storage/stores.go:328  [n2] wrote 2 node addresses to persistent storage
I180410 16:41:11.952707 51923 server/server.go:1432  [n3] starting grpc/postgres server at 127.0.0.1:39573
I180410 16:41:11.953743 51923 server/server.go:1433  [n3] advertising CockroachDB node at 127.0.0.1:39573
I180410 16:41:11.964334 51923 server/server.go:1511  [n3] done ensuring all necessary migrations have run
I180410 16:41:11.964639 51923 server/server.go:1514  [n3] serving sql connections
I180410 16:41:12.069096 52889 server/node.go:634  [n3] bootstrapped store [n3,s3]
I180410 16:41:12.135307 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot c0388bc3 at index 17
I180410 16:41:12.170543 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:12.200355 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:12.259356 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:12.341755 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:12.379353 52895 sql/event_log.go:121  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:39573} Attrs: Locality: ServerVersion:2.0-3} ClusterID:a03ceadd-391a-4a17-a1e8-ede0ebafa975 StartedAt:1523378471863744434 LastUp:1523378471863744434}
I180410 16:41:12.432703 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:12.551088 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:12.556236 52154 storage/store.go:3834  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 7, rate-limit: 8.0 MiB/sec, 10ms
I180410 16:41:12.568573 53080 storage/replica_raftstorage.go:726  [n3,s3,r18/?:{-}] applying preemptive snapshot at index 17 (id=c0388bc3, encoded size=2183, 1 rocksdb batches, 7 log entries)
I180410 16:41:12.575029 53080 storage/replica_raftstorage.go:732  [n3,s3,r18/?:/Table/2{1-2}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180410 16:41:12.632879 52154 storage/replica_command.go:1779  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, next=2]
I180410 16:41:12.665125 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:12.765217 52154 storage/replica.go:3340  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180410 16:41:12.796653 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:12.812354 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r20/1:/{Table/23-Max}] generated preemptive snapshot 6f40c958 at index 12
I180410 16:41:12.860454 53113 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180410 16:41:12.915170 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:13.042553 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:13.117793 52154 storage/store.go:3834  [replicate,n1,s1,r20/1:/{Table/23-Max}] streamed snapshot to (n2,s2):?: kv pairs: 10, log entries: 2, rate-limit: 8.0 MiB/sec, 20ms
I180410 16:41:13.120518 53089 storage/replica_raftstorage.go:726  [n2,s2,r20/?:{-}] applying preemptive snapshot at index 12 (id=6f40c958, encoded size=677, 1 rocksdb batches, 2 log entries)
I180410 16:41:13.122730 53089 storage/replica_raftstorage.go:732  [n2,s2,r20/?:/{Table/23-Max}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180410 16:41:13.128136 52154 storage/replica_command.go:1779  [replicate,n1,s1,r20/1:/{Table/23-Max}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r20:/{Table/23-Max} [(n1,s1):1, next=2]
I180410 16:41:13.155295 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:13.231850 52154 storage/replica.go:3340  [n1,s1,r20/1:/{Table/23-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 16:41:13.256727 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot f5c00f48 at index 42
I180410 16:41:13.287552 52154 storage/store.go:3834  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 137, log entries: 32, rate-limit: 8.0 MiB/sec, 7ms
I180410 16:41:13.290098 53129 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180410 16:41:13.299715 53160 storage/replica_raftstorage.go:726  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 42 (id=f5c00f48, encoded size=31631, 1 rocksdb batches, 32 log entries)
I180410 16:41:13.342515 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:13.353590 53160 storage/replica_raftstorage.go:732  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 54ms [clear=0ms batch=0ms entries=45ms commit=8ms]
I180410 16:41:13.372949 52154 storage/replica_command.go:1779  [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]
I180410 16:41:13.455898 52054 storage/replica_proposal.go:202  [n1,s1,r7/1:/Table/{SystemCon…-11}] new range lease repl=(n1,s1):1 seq=3 start=1523378464.906325751,0 epo=1 pro=1523378473.450354603,0 following repl=(n1,s1):1 seq=2 start=1523378464.906325751,0 exp=1523378473.937639155,0 pro=1523378464.937714344,0
I180410 16:41:13.464120 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:13.562444 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:13.618563 52154 storage/replica.go:3340  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180410 16:41:13.625337 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot f5545a67 at index 17
I180410 16:41:13.642102 52154 storage/store.go:3834  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 7, rate-limit: 8.0 MiB/sec, 16ms
I180410 16:41:13.645023 53206 storage/replica_raftstorage.go:726  [n2,s2,r14/?:{-}] applying preemptive snapshot at index 17 (id=f5545a67, encoded size=2183, 1 rocksdb batches, 7 log entries)
I180410 16:41:13.647793 53206 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]
I180410 16:41:13.652474 52154 storage/replica_command.go:1779  [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]
I180410 16:41:13.680741 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:13.762115 52154 storage/replica.go:3340  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 16:41:13.792167 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:13.796260 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r12/1:/Table/1{5-6}] generated preemptive snapshot f7f2962b at index 26
I180410 16:41:13.804086 52154 storage/store.go:3834  [replicate,n1,s1,r12/1:/Table/1{5-6}] streamed snapshot to (n3,s3):?: kv pairs: 18, log entries: 16, rate-limit: 8.0 MiB/sec, 6ms
I180410 16:41:13.817669 53210 storage/replica_raftstorage.go:726  [n3,s3,r12/?:{-}] applying preemptive snapshot at index 26 (id=f7f2962b, encoded size=7654, 1 rocksdb batches, 16 log entries)
I180410 16:41:13.832726 53210 storage/replica_raftstorage.go:732  [n3,s3,r12/?:/Table/1{5-6}] applied preemptive snapshot in 15ms [clear=0ms batch=0ms entries=13ms commit=0ms]
I180410 16:41:13.837820 52154 storage/replica_command.go:1779  [replicate,n1,s1,r12/1:/Table/1{5-6}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r12:/Table/1{5-6} [(n1,s1):1, next=2]
I180410 16:41:13.909259 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:13.919009 52154 storage/replica.go:3340  [n1,s1,r12/1:/Table/1{5-6}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180410 16:41:13.941064 51823 storage/replica_proposal.go:202  [n1,s1,r9/1:/Table/1{2-3}] new range lease repl=(n1,s1):1 seq=3 start=1523378464.906325751,0 epo=1 pro=1523378473.929640648,0 following repl=(n1,s1):1 seq=2 start=1523378464.906325751,0 exp=1523378473.937639155,0 pro=1523378464.937714344,0
I180410 16:41:13.990380 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot c62179ac at index 32
I180410 16:41:13.998890 52154 storage/store.go:3834  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 53, log entries: 22, rate-limit: 8.0 MiB/sec, 7ms
I180410 16:41:14.001933 53268 storage/replica_raftstorage.go:726  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 32 (id=c62179ac, encoded size=18480, 1 rocksdb batches, 22 log entries)
I180410 16:41:14.009512 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:14.010700 53268 storage/replica_raftstorage.go:732  [n3,s3,r9/?:/Table/1{2-3}] applied preemptive snapshot in 8ms [clear=0ms batch=0ms entries=7ms commit=1ms]
I180410 16:41:14.015911 52154 storage/replica_command.go:1779  [replicate,n1,s1,r9/1:/Table/1{2-3}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r9:/Table/1{2-3} [(n1,s1):1, next=2]
I180410 16:41:14.071372 52154 storage/replica.go:3340  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180410 16:41:14.094451 52058 storage/replica_proposal.go:202  [n1,s1,r8/1:/Table/1{1-2}] new range lease repl=(n1,s1):1 seq=3 start=1523378464.906325751,0 epo=1 pro=1523378474.085414210,0 following repl=(n1,s1):1 seq=2 start=1523378464.906325751,0 exp=1523378473.937639155,0 pro=1523378464.937714344,0
I180410 16:41:14.107677 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r8/1:/Table/1{1-2}] generated preemptive snapshot 1535fad1 at index 26
I180410 16:41:14.118478 52154 storage/store.go:3834  [replicate,n1,s1,r8/1:/Table/1{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 11, log entries: 16, rate-limit: 8.0 MiB/sec, 7ms
I180410 16:41:14.121434 53284 storage/replica_raftstorage.go:726  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 26 (id=1535fad1, encoded size=6066, 1 rocksdb batches, 16 log entries)
I180410 16:41:14.163386 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:14.164126 53284 storage/replica_raftstorage.go:732  [n2,s2,r8/?:/Table/1{1-2}] applied preemptive snapshot in 9ms [clear=0ms batch=0ms entries=8ms commit=0ms]
I180410 16:41:14.171313 52154 storage/replica_command.go:1779  [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]
I180410 16:41:14.246641 52154 storage/replica.go:3340  [n1,s1,r8/1:/Table/1{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 16:41:14.281273 52071 storage/replica_proposal.go:202  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1523378464.906325751,0 epo=1 pro=1523378474.270806470,0 following repl=(n1,s1):1 seq=2 start=1523378464.906325751,0 exp=1523378473.937639155,0 pro=1523378464.937714344,0
I180410 16:41:14.281793 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:14.285743 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot f296fb5c at index 25
I180410 16:41:14.350732 52154 storage/store.go:3834  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n3,s3):?: kv pairs: 965, log entries: 15, rate-limit: 8.0 MiB/sec, 39ms
I180410 16:41:14.369839 53317 storage/replica_raftstorage.go:726  [n3,s3,r5/?:{-}] applying preemptive snapshot at index 25 (id=f296fb5c, encoded size=163086, 1 rocksdb batches, 15 log entries)
I180410 16:41:14.436915 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:14.460205 53317 storage/replica_raftstorage.go:732  [n3,s3,r5/?:/System/ts{d-e}] applied preemptive snapshot in 90ms [clear=0ms batch=1ms entries=87ms commit=1ms]
I180410 16:41:14.468347 52154 storage/replica_command.go:1779  [replicate,n1,s1,r5/1:/System/ts{d-e}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r5:/System/ts{d-e} [(n1,s1):1, next=2]
I180410 16:41:14.517603 52154 storage/replica.go:3340  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180410 16:41:14.525913 53289 storage/replica_raftstorage.go:520  [replicate,n1,s1,r18/1:/Table/2{1-2}] generated preemptive snapshot a7cfa368 at index 20
I180410 16:41:14.532101 53289 storage/store.go:3834  [replicate,n1,s1,r18/1:/Table/2{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 10, rate-limit: 8.0 MiB/sec, 5ms
I180410 16:41:14.544842 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:14.547104 53306 storage/replica_raftstorage.go:726  [n2,s2,r18/?:{-}] applying preemptive snapshot at index 20 (id=a7cfa368, encoded size=3211, 1 rocksdb batches, 10 log entries)
I180410 16:41:14.550313 53306 storage/replica_raftstorage.go:732  [n2,s2,r18/?:/Table/2{1-2}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I180410 16:41:14.597963 53289 storage/replica_command.go:1779  [replicate,n1,s1,r18/1:/Table/2{1-2}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r18:/Table/2{1-2} [(n1,s1):1, (n3,s3):2, next=3]
I180410 16:41:14.670801 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 20 underreplicated ranges
I180410 16:41:14.684408 53289 storage/replica.go:3340  [n1,s1,r18/1:/Table/2{1-2}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I180410 16:41:14.703194 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 05be7f5b at index 31
I180410 16:41:14.712503 52154 storage/store.go:3834  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n2,s2):?: kv pairs: 13, log entries: 21, rate-limit: 8.0 MiB/sec, 7ms
I180410 16:41:14.715907 53333 storage/replica_raftstorage.go:726  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 31 (id=05be7f5b, encoded size=7587, 1 rocksdb batches, 21 log entries)
I180410 16:41:14.722744 53333 storage/replica_raftstorage.go:732  [n2,s2,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 7ms [clear=0ms batch=0ms entries=5ms commit=0ms]
I180410 16:41:14.763761 52154 storage/replica_command.go:1779  [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]
I180410 16:41:14.803422 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:14.851657 52154 storage/replica.go:3340  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 16:41:14.858208 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 1918d634 at index 84
I180410 16:41:14.873084 52154 storage/store.go:3834  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n2,s2):?: kv pairs: 61, log entries: 74, rate-limit: 8.0 MiB/sec, 6ms
I180410 16:41:14.876792 53280 storage/replica_raftstorage.go:726  [n2,s2,r1/?:{-}] applying preemptive snapshot at index 84 (id=1918d634, encoded size=35443, 1 rocksdb batches, 74 log entries)
I180410 16:41:14.892637 53280 storage/replica_raftstorage.go:732  [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 16ms [clear=0ms batch=0ms entries=14ms commit=1ms]
I180410 16:41:14.900696 52154 storage/replica_command.go:1779  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r1:/{Min-System/} [(n1,s1):1, next=2]
I180410 16:41:14.922479 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:14.942912 52154 storage/replica.go:3340  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 16:41:14.955467 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r17/1:/Table/2{0-1}] generated preemptive snapshot 90619589 at index 17
I180410 16:41:14.986990 52137 server/status/runtime.go:219  [n1] runtime stats: 1.4 GiB RSS, 604 goroutines, 43 MiB/74 MiB/138 MiB GO alloc/idle/total, 86 MiB/124 MiB CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (308x)
I180410 16:41:15.003564 52154 storage/store.go:3834  [replicate,n1,s1,r17/1:/Table/2{0-1}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 7, rate-limit: 8.0 MiB/sec, 15ms
I180410 16:41:15.006884 53381 storage/replica_raftstorage.go:726  [n3,s3,r17/?:{-}] applying preemptive snapshot at index 17 (id=90619589, encoded size=2183, 1 rocksdb batches, 7 log entries)
I180410 16:41:15.009541 53381 storage/replica_raftstorage.go:732  [n3,s3,r17/?:/Table/2{0-1}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180410 16:41:15.017314 52154 storage/replica_command.go:1779  [replicate,n1,s1,r17/1:/Table/2{0-1}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r17:/Table/2{0-1} [(n1,s1):1, next=2]
I180410 16:41:15.044590 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:15.075215 52154 storage/replica.go:3340  [n1,s1,r17/1:/Table/2{0-1}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180410 16:41:15.081969 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r16/1:/Table/{19-20}] generated preemptive snapshot f52f75c7 at index 17
I180410 16:41:15.095868 52154 storage/store.go:3834  [replicate,n1,s1,r16/1:/Table/{19-20}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 7, rate-limit: 8.0 MiB/sec, 5ms
I180410 16:41:15.098537 53353 storage/replica_raftstorage.go:726  [n2,s2,r16/?:{-}] applying preemptive snapshot at index 17 (id=f52f75c7, encoded size=2183, 1 rocksdb batches, 7 log entries)
I180410 16:41:15.101423 53353 storage/replica_raftstorage.go:732  [n2,s2,r16/?:/Table/{19-20}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180410 16:41:15.142367 52154 storage/replica_command.go:1779  [replicate,n1,s1,r16/1:/Table/{19-20}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r16:/Table/{19-20} [(n1,s1):1, next=2]
I180410 16:41:15.183996 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:15.276104 52154 storage/replica.go:3340  [n1,s1,r16/1:/Table/{19-20}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 16:41:15.286609 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] generated preemptive snapshot 9eab965d at index 46
I180410 16:41:15.292590 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:15.318892 52154 storage/store.go:3834  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):?: kv pairs: 75, log entries: 36, rate-limit: 8.0 MiB/sec, 31ms
I180410 16:41:15.324213 53342 storage/replica_raftstorage.go:726  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 46 (id=9eab965d, encoded size=40144, 1 rocksdb batches, 36 log entries)
I180410 16:41:15.350283 53342 storage/replica_raftstorage.go:732  [n3,s3,r7/?:/Table/{SystemCon…-11}] applied preemptive snapshot in 26ms [clear=0ms batch=0ms entries=16ms commit=1ms]
I180410 16:41:15.368643 52154 storage/replica_command.go:1779  [replicate,n1,s1,r7/1:/Table/{SystemCon…-11}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, next=2]
I180410 16:41:15.393992 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:15.417622 52154 storage/replica.go:3340  [n1,s1,r7/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180410 16:41:15.443264 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r19/1:/Table/2{2-3}] generated preemptive snapshot cc67db96 at index 17
I180410 16:41:15.453347 52154 storage/store.go:3834  [replicate,n1,s1,r19/1:/Table/2{2-3}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 7, rate-limit: 8.0 MiB/sec, 9ms
I180410 16:41:15.456136 53343 storage/replica_raftstorage.go:726  [n2,s2,r19/?:{-}] applying preemptive snapshot at index 17 (id=cc67db96, encoded size=2183, 1 rocksdb batches, 7 log entries)
I180410 16:41:15.459642 53343 storage/replica_raftstorage.go:732  [n2,s2,r19/?:/Table/2{2-3}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180410 16:41:15.466503 52154 storage/replica_command.go:1779  [replicate,n1,s1,r19/1:/Table/2{2-3}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r19:/Table/2{2-3} [(n1,s1):1, next=2]
I180410 16:41:15.504430 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:15.553627 52154 storage/replica.go:3340  [n1,s1,r19/1:/Table/2{2-3}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 16:41:15.575528 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot 10948920 at index 17
I180410 16:41:15.582978 52154 storage/store.go:3834  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 7, rate-limit: 8.0 MiB/sec, 7ms
I180410 16:41:15.590804 53478 storage/replica_raftstorage.go:726  [n2,s2,r13/?:{-}] applying preemptive snapshot at index 17 (id=10948920, encoded size=2183, 1 rocksdb batches, 7 log entries)
I180410 16:41:15.602862 53478 storage/replica_raftstorage.go:732  [n2,s2,r13/?:/Table/1{6-7}] applied preemptive snapshot in 12ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180410 16:41:15.605421 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:15.618401 52154 storage/replica_command.go:1779  [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]
I180410 16:41:15.699946 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:15.702850 52154 storage/replica.go:3340  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 16:41:15.730698 52071 storage/replica_proposal.go:202  [n1,s1,r6/1:/{System/tse-Table/System…}] new range lease repl=(n1,s1):1 seq=3 start=1523378464.906325751,0 epo=1 pro=1523378475.708952690,0 following repl=(n1,s1):1 seq=2 start=1523378464.906325751,0 exp=1523378473.937639155,0 pro=1523378464.937714344,0
I180410 16:41:15.737977 52064 storage/replica_proposal.go:202  [n1,s1,r4/1:/System/{NodeLive…-tsd}] new range lease repl=(n1,s1):1 seq=3 start=1523378464.906325751,0 epo=1 pro=1523378475.730224314,0 following repl=(n1,s1):1 seq=2 start=1523378464.906325751,0 exp=1523378473.937639155,0 pro=1523378464.937714344,0
I180410 16:41:15.756393 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] generated preemptive snapshot 2454bcec at index 23
I180410 16:41:15.769551 52154 storage/store.go:3834  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 13, rate-limit: 8.0 MiB/sec, 12ms
I180410 16:41:15.772685 53434 storage/replica_raftstorage.go:726  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 23 (id=2454bcec, encoded size=5102, 1 rocksdb batches, 13 log entries)
I180410 16:41:15.818420 53434 storage/replica_raftstorage.go:732  [n2,s2,r6/?:/{System/tse-Table/System…}] applied preemptive snapshot in 45ms [clear=0ms batch=0ms entries=3ms commit=41ms]
I180410 16:41:15.929167 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:15.930011 52154 storage/replica_command.go:1779  [replicate,n1,s1,r6/1:/{System/tse-Table/System…}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r6:/{System/tse-Table/SystemConfigSpan/Start} [(n1,s1):1, next=2]
I180410 16:41:16.053263 52154 storage/replica.go:3340  [n1,s1,r6/1:/{System/tse-Table/System…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 16:41:16.072926 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r15/1:/Table/1{8-9}] generated preemptive snapshot 1a649978 at index 17
I180410 16:41:16.077135 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:16.094610 52154 storage/store.go:3834  [replicate,n1,s1,r15/1:/Table/1{8-9}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 7, rate-limit: 8.0 MiB/sec, 21ms
I180410 16:41:16.099420 53507 storage/replica_raftstorage.go:726  [n2,s2,r15/?:{-}] applying preemptive snapshot at index 17 (id=1a649978, encoded size=2183, 1 rocksdb batches, 7 log entries)
I180410 16:41:16.106068 53507 storage/replica_raftstorage.go:732  [n2,s2,r15/?:/Table/1{8-9}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=5ms commit=0ms]
I180410 16:41:16.138754 52154 storage/replica_command.go:1779  [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]
I180410 16:41:16.183488 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:16.250301 52154 storage/replica.go:3340  [n1,s1,r15/1:/Table/1{8-9}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 16:41:16.281672 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] generated preemptive snapshot b7073b2d at index 23
I180410 16:41:16.294256 52154 storage/store.go:3834  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 13, rate-limit: 8.0 MiB/sec, 9ms
I180410 16:41:16.297952 53467 storage/replica_raftstorage.go:726  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 23 (id=b7073b2d, encoded size=54818, 1 rocksdb batches, 13 log entries)
I180410 16:41:16.327356 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:16.360563 53467 storage/replica_raftstorage.go:732  [n2,s2,r2/?:/System/{-NodeLive…}] applied preemptive snapshot in 62ms [clear=0ms batch=0ms entries=61ms commit=1ms]
I180410 16:41:16.414485 52154 storage/replica_command.go:1779  [replicate,n1,s1,r2/1:/System/{-NodeLive…}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, next=2]
I180410 16:41:16.420050 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:16.563881 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:16.649853 52154 storage/replica.go:3340  [n1,s1,r2/1:/System/{-NodeLive…}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 16:41:16.663473 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] generated preemptive snapshot 6cc02fb4 at index 48
I180410 16:41:16.677945 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:16.680036 52154 storage/store.go:3834  [replicate,n1,s1,r4/1:/System/{NodeLive…-tsd}] streamed snapshot to (n3,s3):?: kv pairs: 39, log entries: 2, rate-limit: 8.0 MiB/sec, 16ms
I180410 16:41:16.687255 53471 storage/replica_raftstorage.go:726  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 48 (id=6cc02fb4, encoded size=69420, 1 rocksdb batches, 2 log entries)
I180410 16:41:16.751640 53471 storage/replica_raftstorage.go:732  [n3,s3,r4/?:/System/{NodeLive…-tsd}] applied preemptive snapshot in 64ms [clear=0ms batch=0ms entries=60ms commit=1ms]
I180410 16:41:16.762784 52154 storage/replica_command.go:1779  [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]
I180410 16:41:16.787897 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:16.833943 52154 storage/replica.go:3340  [n1,s1,r4/1:/System/{NodeLive…-tsd}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180410 16:41:16.874230 52154 storage/replica_raftstorage.go:520  [replicate,n1,s1,r11/1:/Table/1{4-5}] generated preemptive snapshot e12ba886 at index 18
I180410 16:41:16.883372 52154 storage/store.go:3834  [replicate,n1,s1,r11/1:/Table/1{4-5}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 8, rate-limit: 8.0 MiB/sec, 8ms
I180410 16:41:16.886469 53569 storage/replica_raftstorage.go:726  [n2,s2,r11/?:{-}] applying preemptive snapshot at index 18 (id=e12ba886, encoded size=3111, 1 rocksdb batches, 8 log entries)
I180410 16:41:16.897831 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:16.899483 53569 storage/replica_raftstorage.go:732  [n2,s2,r11/?:/Table/1{4-5}] applied preemptive snapshot in 13ms [clear=0ms batch=0ms entries=10ms commit=1ms]
I180410 16:41:16.904452 52154 storage/replica_command.go:1779  [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]
I180410 16:41:17.003946 52154 storage/replica.go:3340  [n1,s1,r11/1:/Table/1{4-5}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180410 16:41:17.015602 52154 storage/queue.go:847  [n1,replicate] purgatory is now empty
I180410 16:41:17.020421 51923 testutils/testcluster/testcluster.go:534  [n1,s1] has 19 underreplicated ranges
I180410 16:41:17.030924 53529 storage/replica_raftstorage.go:520  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot 268b6601 at index 30
I180410 16:41:17.115785 53529 storage/store.go:3834  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 966, log entries: 6, rate-limit: 8.0 MiB/sec, 84ms
I180410 16:41:17.126986 53575 storage/replica_raftstorage.go:726  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 30 (id=268b6601, encoded size=155747, 1 rocksdb batches, 6 log entries)
I180410 16:41:17.153227 51923 testutils/testcluster/te

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the 2.1 milestone Apr 10, 2018
@cockroach-teamcity cockroach-teamcity added O-robot Originated from a bot. C-test-failure Broken test (automatically or manually discovered). labels Apr 10, 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
2.1
Development

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