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/TestSystemZoneConfigs #19180

Closed
cockroach-teamcity opened this issue Oct 11, 2017 · 3 comments
Closed

teamcity: failed tests on master: testrace/TestSystemZoneConfigs #19180

cockroach-teamcity opened this issue Oct 11, 2017 · 3 comments
Assignees
@a6802739 @a-robinson
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:

#374985:

--- FAIL: testrace/TestSystemZoneConfigs (0.000s)
Race detected!

------- Stdout: -------
W171011 15:52:01.887552 81999 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I171011 15:52:01.894122 81999 server/config.go:507  [n?] 1 storage engine initialized
I171011 15:52:01.894179 81999 server/config.go:510  [n?] RocksDB cache size: 128 MiB
I171011 15:52:01.894208 81999 server/config.go:510  [n?] store 0: in-memory, size 0 B
I171011 15:52:01.934701 81999 server/node.go:347  [n?] **** cluster 6bd7cdee-7071-4646-b26e-dd56d1ca6473 has been created
I171011 15:52:01.934958 81999 server/server.go:882  [n?] **** add additional nodes by specifying --join=127.0.0.1:36996
I171011 15:52:01.970097 81999 storage/store.go:1209  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I171011 15:52:01.970793 81999 server/node.go:472  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=3.2 KiB), ranges=1, leases=1, writes=0.00, bytesPerReplica={p10=3234.00 p25=3234.00 p50=3234.00 p75=3234.00 p90=3234.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00}
I171011 15:52:01.971144 81999 server/node.go:329  [n1] node ID 1 initialized
I171011 15:52:01.971857 81999 gossip/gossip.go:331  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:36996" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:3 > 
I171011 15:52:01.975289 81999 storage/stores.go:332  [n1] read 0 node addresses from persistent storage
I171011 15:52:01.976348 81999 server/node.go:617  [n1] connecting to gossip network to verify cluster ID...
I171011 15:52:01.976531 81999 server/node.go:642  [n1] node connected via gossip and verified as part of cluster "6bd7cdee-7071-4646-b26e-dd56d1ca6473"
I171011 15:52:01.976957 81999 server/node.go:414  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I171011 15:52:01.979584 81999 sql/executor.go:408  [n1] creating distSQLPlanner with address {tcp 127.0.0.1:36996}
I171011 15:52:01.995181 82407 storage/replica_command.go:2792  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I171011 15:52:01.999113 81999 server/server.go:987  [n1] starting https server at 127.0.0.1:60743
I171011 15:52:01.999241 81999 server/server.go:988  [n1] starting grpc/postgres server at 127.0.0.1:36996
I171011 15:52:01.999284 81999 server/server.go:989  [n1] advertising CockroachDB node at 127.0.0.1:36996
W171011 15:52:01.999550 81999 sql/jobs/registry.go:156  [n1] unable to get node liveness: node not in the liveness table
I171011 15:52:02.104928 82407 storage/replica_command.go:2792  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/NodeLiveness [r3]
I171011 15:52:02.172139 81999 sql/event_log.go:103  [n1] Event: "alter_table", target: 12, info: {TableName:eventlog Statement:ALTER TABLE system.eventlog ALTER COLUMN "uniqueID" SET DEFAULT uuid_v4() User:node MutationID:0 CascadeDroppedViews:[]}
I171011 15:52:02.291278 82407 storage/replica_command.go:2792  [split,n1,s1,r3/1:/{System/NodeL���-Max}] initiating a split of this range at key /System/NodeLivenessMax [r4]
I171011 15:52:02.374039 81999 sql/lease.go:341  [n1] publish: descID=12 (eventlog) version=2 mtime=2017-10-11 15:52:02.371851059 +0000 UTC
I171011 15:52:02.407266 82407 storage/replica_command.go:2792  [split,n1,s1,r4/1:/{System/NodeL���-Max}] initiating a split of this range at key /System/tsd [r5]
I171011 15:52:02.516486 82407 storage/replica_command.go:2792  [split,n1,s1,r5/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r6]
W171011 15:52:02.598766 82651 storage/intent_resolver.go:332  [n1,s1,r1/1:/{Min-System/}]: failed to push during intent resolution: failed to push "split" id=254f5686 key=/Local/Range/System/tsd/RangeDescriptor rw=true pri=0.01230310 iso=SERIALIZABLE stat=PENDING epo=0 ts=1507737122.516628291,0 orig=1507737122.516628291,0 max=1507737122.516628291,0 wto=false rop=false seq=3
I171011 15:52:02.653911 82407 storage/replica_command.go:2792  [split,n1,s1,r6/1:/{System/tse-Max}] initiating a split of this range at key /Table/SystemConfigSpan/Start [r7]
I171011 15:52:02.768546 82407 storage/replica_command.go:2792  [split,n1,s1,r7/1:/{Table/System���-Max}] initiating a split of this range at key /Table/11 [r8]
I171011 15:52:02.776548 81999 sql/event_log.go:103  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:node}
I171011 15:52:02.909132 82407 storage/replica_command.go:2792  [split,n1,s1,r8/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r9]
I171011 15:52:02.998584 82407 storage/replica_command.go:2792  [split,n1,s1,r9/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r10]
I171011 15:52:03.049901 81999 sql/event_log.go:103  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:1.1-3 User:node}
I171011 15:52:03.166282 82407 storage/replica_command.go:2792  [split,n1,s1,r10/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r11]
I171011 15:52:03.191457 81999 sql/event_log.go:103  [n1] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:node}
I171011 15:52:03.199755 81999 server/server.go:1131  [n1] done ensuring all necessary migrations have run
I171011 15:52:03.199935 81999 server/server.go:1133  [n1] serving sql connections
I171011 15:52:03.266199 82833 sql/event_log.go:103  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:36996} Attrs: Locality: ServerVersion:1.1-3} ClusterID:6bd7cdee-7071-4646-b26e-dd56d1ca6473 StartedAt:1507737121976616117 LastUp:1507737121976616117}
I171011 15:52:03.361713 82407 storage/replica_command.go:2792  [split,n1,s1,r11/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r12]
I171011 15:52:03.461881 82407 storage/replica_command.go:2792  [split,n1,s1,r12/1:/{Table/15-Max}] initiating a split of this range at key /Table/16 [r13]
I171011 15:52:03.573954 82407 storage/replica_command.go:2792  [split,n1,s1,r13/1:/{Table/16-Max}] initiating a split of this range at key /Table/17 [r14]
I171011 15:52:03.696023 82407 storage/replica_command.go:2792  [split,n1,s1,r14/1:/{Table/17-Max}] initiating a split of this range at key /Table/18 [r15]
I171011 15:52:03.772765 82407 storage/replica_command.go:2792  [split,n1,s1,r15/1:/{Table/18-Max}] initiating a split of this range at key /Table/19 [r16]
W171011 15:52:03.950621 81999 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
W171011 15:52:03.958759 81999 gossip/gossip.go:1277  [n?] no incoming or outgoing connections
I171011 15:52:03.964131 81999 server/config.go:507  [n?] 1 storage engine initialized
I171011 15:52:03.964250 81999 server/config.go:510  [n?] RocksDB cache size: 128 MiB
I171011 15:52:03.964297 81999 server/config.go:510  [n?] store 0: in-memory, size 0 B
I171011 15:52:03.965748 81999 server/server.go:884  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I171011 15:52:04.028024 82863 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:36996
I171011 15:52:04.031099 83206 gossip/server.go:232  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:37703}
I171011 15:52:04.035147 81999 storage/stores.go:332  [n?] read 0 node addresses from persistent storage
I171011 15:52:04.035581 81999 storage/stores.go:351  [n?] wrote 1 node addresses to persistent storage
I171011 15:52:04.035701 81999 server/node.go:617  [n?] connecting to gossip network to verify cluster ID...
I171011 15:52:04.035813 81999 server/node.go:642  [n?] node connected via gossip and verified as part of cluster "6bd7cdee-7071-4646-b26e-dd56d1ca6473"
I171011 15:52:04.041347 83103 kv/dist_sender.go:355  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I171011 15:52:04.047424 83102 kv/dist_sender.go:355  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I171011 15:52:04.053071 81999 kv/dist_sender.go:355  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I171011 15:52:04.061033 81999 server/node.go:322  [n?] new node allocated ID 2
I171011 15:52:04.061581 81999 gossip/gossip.go:331  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:37703" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:3 > 
I171011 15:52:04.065086 83132 storage/stores.go:351  [n1] wrote 1 node addresses to persistent storage
I171011 15:52:04.067263 81999 server/node.go:400  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I171011 15:52:04.067830 81999 server/node.go:414  [n2] node=2: started with [] engine(s) and attributes []
I171011 15:52:04.086639 81999 sql/executor.go:408  [n2] creating distSQLPlanner with address {tcp 127.0.0.1:37703}
I171011 15:52:04.135160 81999 server/server.go:987  [n2] starting https server at 127.0.0.1:60239
I171011 15:52:04.135308 81999 server/server.go:988  [n2] starting grpc/postgres server at 127.0.0.1:37703
I171011 15:52:04.135351 81999 server/server.go:989  [n2] advertising CockroachDB node at 127.0.0.1:37703
W171011 15:52:04.135598 81999 sql/jobs/registry.go:156  [n2] unable to get node liveness: node not in the liveness table
I171011 15:52:04.147621 81999 server/server.go:1131  [n2] done ensuring all necessary migrations have run
I171011 15:52:04.147788 81999 server/server.go:1133  [n2] serving sql connections
I171011 15:52:04.165056 83219 server/node.go:598  [n2] bootstrapped store [n2,s2]
I171011 15:52:04.244846 83378 sql/event_log.go:103  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:37703} Attrs: Locality: ServerVersion:1.1-3} ClusterID:6bd7cdee-7071-4646-b26e-dd56d1ca6473 StartedAt:1507737124067615094 LastUp:1507737124067615094}
W171011 15:52:04.308816 81999 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
W171011 15:52:04.313806 81999 gossip/gossip.go:1277  [n?] no incoming or outgoing connections
I171011 15:52:04.322808 81999 server/config.go:507  [n?] 1 storage engine initialized
I171011 15:52:04.323119 81999 server/config.go:510  [n?] RocksDB cache size: 128 MiB
I171011 15:52:04.326754 81999 server/config.go:510  [n?] store 0: in-memory, size 0 B
I171011 15:52:04.326996 81999 server/server.go:884  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I171011 15:52:04.389436 83116 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:36996
I171011 15:52:04.391303 83430 gossip/server.go:232  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:59868}
I171011 15:52:04.396840 81999 storage/stores.go:332  [n?] read 0 node addresses from persistent storage
I171011 15:52:04.397097 81999 server/node.go:617  [n?] connecting to gossip network to verify cluster ID...
I171011 15:52:04.397224 81999 server/node.go:642  [n?] node connected via gossip and verified as part of cluster "6bd7cdee-7071-4646-b26e-dd56d1ca6473"
I171011 15:52:04.397957 83393 storage/stores.go:351  [n?] wrote 1 node addresses to persistent storage
I171011 15:52:04.398535 83393 storage/stores.go:351  [n?] wrote 2 node addresses to persistent storage
I171011 15:52:04.404552 83472 kv/dist_sender.go:355  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I171011 15:52:04.413213 83471 kv/dist_sender.go:355  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I171011 15:52:04.418217 81999 kv/dist_sender.go:355  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I171011 15:52:04.425390 81999 server/node.go:322  [n?] new node allocated ID 3
I171011 15:52:04.425998 81999 gossip/gossip.go:331  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:59868" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:3 > 
I171011 15:52:04.426589 81999 server/node.go:400  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I171011 15:52:04.427049 81999 server/node.go:414  [n3] node=3: started with [] engine(s) and attributes []
I171011 15:52:04.429614 83432 storage/stores.go:351  [n1] wrote 2 node addresses to persistent storage
I171011 15:52:04.430828 81999 sql/executor.go:408  [n3] creating distSQLPlanner with address {tcp 127.0.0.1:59868}
I171011 15:52:04.434125 83456 storage/stores.go:351  [n2] wrote 2 node addresses to persistent storage
I171011 15:52:04.467910 81999 server/server.go:987  [n3] starting https server at 127.0.0.1:47171
I171011 15:52:04.468106 81999 server/server.go:988  [n3] starting grpc/postgres server at 127.0.0.1:59868
I171011 15:52:04.468174 81999 server/server.go:989  [n3] advertising CockroachDB node at 127.0.0.1:59868
W171011 15:52:04.468501 81999 sql/jobs/registry.go:156  [n3] unable to get node liveness: node not in the liveness table
I171011 15:52:04.491597 81999 server/server.go:1131  [n3] done ensuring all necessary migrations have run
I171011 15:52:04.491759 81999 server/server.go:1133  [n3] serving sql connections
I171011 15:52:04.520151 83491 server/node.go:598  [n3] bootstrapped store [n3,s3]
I171011 15:52:04.554481 82505 storage/replica_raftstorage.go:526  [replicate,n1,s1,r5/1:/System/ts{d-e}] generated preemptive snapshot fd672fb1 at index 22
I171011 15:52:04.583353 83345 sql/event_log.go:103  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:59868} Attrs: Locality: ServerVersion:1.1-3} ClusterID:6bd7cdee-7071-4646-b26e-dd56d1ca6473 StartedAt:1507737124426815978 LastUp:1507737124426815978}
W171011 15:52:04.604973 81999 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
W171011 15:52:04.632081 81999 gossip/gossip.go:1277  [n?] no incoming or outgoing connections
I171011 15:52:04.638910 81999 server/config.go:507  [n?] 1 storage engine initialized
I171011 15:52:04.639037 81999 server/config.go:510  [n?] RocksDB cache size: 128 MiB
I171011 15:52:04.639072 81999 server/config.go:510  [n?] store 0: in-memory, size 0 B
I171011 15:52:04.639219 81999 server/server.go:884  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I171011 15:52:04.667276 82505 storage/store.go:3506  [replicate,n1,s1,r5/1:/System/ts{d-e}] streamed snapshot to (n2,s2):?: kv pairs: 668, log entries: 12, rate-limit: 8.0 MiB/sec, 16ms
I171011 15:52:04.669055 83483 storage/replica_raftstorage.go:732  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 22 (id=fd672fb1, encoded size=102350, 1 rocksdb batches, 12 log entries)
I171011 15:52:04.681992 83483 storage/replica_raftstorage.go:738  [n2,s2,r5/?:/System/ts{d-e}] applied preemptive snapshot in 13ms [clear=0ms batch=0ms entries=8ms commit=4ms]
I171011 15:52:04.687520 82505 storage/replica_command.go:3736  [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]
I171011 15:52:04.697226 83404 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:36996
I171011 15:52:04.698787 83661 gossip/server.go:232  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:37949}
I171011 15:52:04.733463 81999 storage/stores.go:332  [n?] read 0 node addresses from persistent storage
I171011 15:52:04.734064 81999 storage/stores.go:351  [n?] wrote 3 node addresses to persistent storage
I171011 15:52:04.734119 81999 server/node.go:617  [n?] connecting to gossip network to verify cluster ID...
I171011 15:52:04.734235 81999 server/node.go:642  [n?] node connected via gossip and verified as part of cluster "6bd7cdee-7071-4646-b26e-dd56d1ca6473"
I171011 15:52:04.736182 83738 kv/dist_sender.go:355  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I171011 15:52:04.752546 83737 kv/dist_sender.go:355  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I171011 15:52:04.757348 81999 kv/dist_sender.go:355  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I171011 15:52:04.758409 83688 storage/replica.go:3071  [n1,s1,r5/1:/System/ts{d-e}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I171011 15:52:04.763448 81999 server/node.go:322  [n?] new node allocated ID 4
I171011 15:52:04.763948 81999 gossip/gossip.go:331  [n4] NodeDescriptor set to node_id:4 address:<network_field:"tcp" address_field:"127.0.0.1:37949" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:3 > 
I171011 15:52:04.764597 81999 server/node.go:400  [n4] node=4: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I171011 15:52:04.766646 81999 server/node.go:414  [n4] node=4: started with [] engine(s) and attributes []
I171011 15:52:04.767599 82505 storage/replica_raftstorage.go:526  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot c406304d at index 35
I171011 15:52:04.771966 81999 sql/executor.go:408  [n4] creating distSQLPlanner with address {tcp 127.0.0.1:37949}
I171011 15:52:04.777796 83764 storage/stores.go:351  [n1] wrote 3 node addresses to persistent storage
I171011 15:52:04.780343 83765 storage/stores.go:351  [n2] wrote 3 node addresses to persistent storage
I171011 15:52:04.783617 83766 storage/stores.go:351  [n3] wrote 3 node addresses to persistent storage
I171011 15:52:04.818469 83767 storage/raft_transport.go:455  [n2] raft transport stream to node 1 established
I171011 15:52:04.877489 81999 server/server.go:987  [n4] starting https server at 127.0.0.1:36009
I171011 15:52:04.877647 81999 server/server.go:988  [n4] starting grpc/postgres server at 127.0.0.1:37949
I171011 15:52:04.877701 81999 server/server.go:989  [n4] advertising CockroachDB node at 127.0.0.1:37949
W171011 15:52:04.877988 81999 sql/jobs/registry.go:156  [n4] unable to get node liveness: node not in the liveness table
I171011 15:52:04.899060 83746 server/node.go:598  [n4] bootstrapped store [n4,s4]
I171011 15:52:04.916772 82505 storage/store.go:3506  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):?: kv pairs: 110, log entries: 25, rate-limit: 8.0 MiB/sec, 20ms
I171011 15:52:04.918367 83954 storage/replica_raftstorage.go:732  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 35 (id=c406304d, encoded size=33142, 1 rocksdb batches, 25 log entries)
I171011 15:52:04.926698 83954 storage/replica_raftstorage.go:738  [n3,s3,r10/?:/Table/1{3-4}] applied preemptive snapshot in 8ms [clear=0ms batch=0ms entries=7ms commit=0ms]
I171011 15:52:04.933157 82505 storage/replica_command.go:3736  [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]
I171011 15:52:04.949964 81999 server/server.go:1131  [n4] done ensuring all necessary migrations have run
I171011 15:52:04.950154 81999 server/server.go:1133  [n4] serving sql connections
I171011 15:52:04.991491 83607 storage/store.go:2165  [replicaGC,n3,s3,r10/?:/Table/1{3-4}] removing replica
I171011 15:52:04.995958 83607 storage/replica.go:763  [replicaGC,n3,s3,r10/?:/Table/1{3-4}] removed 104 (95+9) keys in 4ms [clear=0ms commit=4ms]
I171011 15:52:05.042695 82505 storage/replica_command.go:3736  [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]
I171011 15:52:05.068226 83488 sql/event_log.go:103  [n4] Event: "node_join", target: 4, info: {Descriptor:{NodeID:4 Address:{NetworkField:tcp AddressField:127.0.0.1:37949} Attrs: Locality: ServerVersion:1.1-3} ClusterID:6bd7cdee-7071-4646-b26e-dd56d1ca6473 StartedAt:1507737124766401385 LastUp:1507737124766401385}
I171011 15:52:05.086947 84020 storage/replica.go:3071  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I171011 15:52:05.095109 82408 storage/replica_raftstorage.go:526  [replicate,n1,s1,r13/1:/Table/1{6-7}] generated preemptive snapshot b49c49bf at index 19
W171011 15:52:05.099928 81999 server/status/runtime.go:109  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
W171011 15:52:05.104324 81999 gossip/gossip.go:1277  [n?] no incoming or outgoing connections
I171011 15:52:05.105722 84013 storage/raft_transport.go:455  [n3] raft transport stream to node 1 established
I171011 15:52:05.108984 82411 storage/replica_raftstorage.go:526  [raftsnapshot,n1,s1,r10/1:/Table/1{3-4}] generated Raft snapshot 1ac3b84e at index 42
I171011 15:52:05.122927 82411 storage/store.go:3506  [raftsnapshot,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n3,s3):2: kv pairs: 112, log entries: 32, rate-limit: 8.0 MiB/sec, 5ms
I171011 15:52:05.125754 83965 storage/replica_raftstorage.go:732  [n3,s3,r10/2:{-}] applying Raft snapshot at index 42 (id=1ac3b84e, encoded size=38783, 1 rocksdb batches, 32 log entries)
I171011 15:52:05.128947 81999 server/config.go:507  [n?] 1 storage engine initialized
I171011 15:52:05.129088 81999 server/config.go:510  [n?] RocksDB cache size: 128 MiB
I171011 15:52:05.129137 81999 server/config.go:510  [n?] store 0: in-memory, size 0 B
I171011 15:52:05.129356 81999 server/server.go:884  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I171011 15:52:05.138325 83965 storage/replica_raftstorage.go:738  [n3,s3,r10/2:/Table/1{3-4}] applied Raft snapshot in 12ms [clear=0ms batch=0ms entries=11ms commit=1ms]
I171011 15:52:05.190233 82408 storage/store.go:3506  [replicate,n1,s1,r13/1:/Table/1{6-7}] streamed snapshot to (n4,s4):?: kv pairs: 10, log entries: 9, rate-limit: 8.0 MiB/sec, 5ms
I171011 15:52:05.190865 83917 storage/replica_raftstorage.go:732  [n4,s4,r13/?:{-}] applying preemptive snapshot at index 19 (id=b49c49bf, encoded size=3626, 1 rocksdb batches, 9 log entries)
I171011 15:52:05.192023 83960 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:36996
I171011 15:52:05.193354 84088 gossip/server.go:232  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:54766}
I171011 15:52:05.195339 83917 storage/replica_raftstorage.go:738  [n4,s4,r13/?:/Table/1{6-7}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I171011 15:52:05.223689 81999 storage/stores.go:332  [n?] read 0 node addresses from persistent storage
I171011 15:52:05.224153 81999 storage/stores.go:351  [n?] wrote 4 node addresses to persistent storage
I171011 15:52:05.224265 81999 server/node.go:617  [n?] connecting to gossip network to verify cluster ID...
I171011 15:52:05.224396 81999 server/node.go:642  [n?] node connected via gossip and verified as part of cluster "6bd7cdee-7071-4646-b26e-dd56d1ca6473"
I171011 15:52:05.223768 82408 storage/replica_command.go:3736  [replicate,n1,s1,r13/1:/Table/1{6-7}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r13:/Table/1{6-7} [(n1,s1):1, next=2]
I171011 15:52:05.240331 84137 kv/dist_sender.go:355  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I171011 15:52:05.252263 84136 kv/dist_sender.go:355  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I171011 15:52:05.258923 81999 kv/dist_sender.go:355  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I171011 15:52:05.269673 81999 server/node.go:322  [n?] new node allocated ID 5
I171011 15:52:05.270465 81999 gossip/gossip.go:331  [n5] NodeDescriptor set to node_id:5 address:<network_field:"tcp" address_field:"127.0.0.1:54766" > attrs:<> locality:<> ServerVersion:<major_val:1 minor_val:1 patch:0 unstable:3 > 
I171011 15:52:05.271180 81999 server/node.go:400  [n5] node=5: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I171011 15:52:05.272474 81999 server/node.go:414  [n5] node=5: started with [] engine(s) and attributes []
I171011 15:52:05.273306 84059 storage/replica.go:3071  [n1,s1,r13/1:/Table/1{6-7}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3
I171011 15:52:05.277048 81999 sql/executor.go:408  [n5] creating distSQLPlanner with address {tcp 127.0.0.1:54766}
I171011 15:52:05.294038 84088 gossip/server.go:282  [n1] refusing gossip from node 5 (max 3 conns); forwarding to 4 ({tcp 127.0.0.1:37949})
I171011 15:52:05.295549 83960 gossip/client.go:134  [n5] closing client to node 1 (127.0.0.1:36996): received forward from node 1 to 4 (127.0.0.1:37949)
I171011 15:52:05.296313 84149 storage/stores.go:351  [n1] wrote 4 node addresses to persistent storage
I171011 15:52:05.300819 84150 storage/stores.go:351  [n4] wrote 4 node addresses to persistent storage
I171011 15:52:05.302903 84151 storage/stores.go:351  [n2] wrote 4 node addresses to persistent storage
I171011 15:52:05.305793 84046 gossip/gossip.go:1291  [n5] node has connected to cluster via gossip
I171011 15:52:05.306490 84046 storage/stores.go:351  [n5] wrote 4 node addresses to persistent storage
I171011 15:52:05.309130 84141 storage/stores.go:351  [n3] wrote 4 node addresses to persistent storage
I171011 15:52:05.324713 84126 storage/raft_transport.go:455  [n4] raft transport stream to node 1 established
I171011 15:52:05.329125 82505 storage/replica_raftstorage.go:526  [replicate,n1,s1,r16/1:/{Table/19-Max}] generated preemptive snapshot 1433b074 at index 11
I171011 15:52:05.361727 82505 storage/store.go:3506  [replicate,n1,s1,r16/1:/{Table/19-Max}] streamed snapshot to (n2,s2):?: kv pairs: 9, log entries: 1, rate-limit: 8.0 MiB/sec, 32ms
I171011 15:52:05.365430 84244 storage/replica_raftstorage.go:732  [n2,s2,r16/?:{-}] applying preemptive snapshot at index 11 (id=1433b074, encoded size=523, 1 rocksdb batches, 1 log entries)
I171011 15:52:05.377148 84001 server/node.go:598  [n5] bootstrapped store [n5,s5]
I171011 15:52:05.384169 84244 storage/replica_raftstorage.go:738  [n2,s2,r16/?:/{Table/19-Max}] applied preemptive snapshot in 18ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I171011 15:52:05.400095 81999 server/server.go:987  [n5] starting https server at 127.0.0.1:46541
I171011 15:52:05.400277 81999 server/server.go:988  [n5] starting grpc/postgres server at 127.0.0.1:54766
I171011 15:52:05.400328 81999 server/server.go:989  [n5] advertising CockroachDB node at 127.0.0.1:54766
W171011 15:52:05.400643 81999 sql/jobs/registry.go:156  [n5] unable to get node liveness: node not in the liveness table
I171011 15:52:05.406346 84164 gossip/client.go:129  [n5] started gossip client to 127.0.0.1:37949
I171011 15:52:05.439395 82505 storage/replica_command.go:3736  [replicate,n1,s1,r16/1:/{Table/19-Max}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r16:/{Table/19-Max} [(n1,s1):1, next=2]
I171011 15:52:05.439935 81999 server/server.go:1131  [n5] done ensuring all necessary migrations have run
I171011 15:52:05.440097 81999 server/server.go:1133  [n5] serving sql connections
I171011 15:52:05.483166 83213 storage/store.go:2165  [replicaGC,n2,s2,r16/?:/{Table/19-Max}] removing replica
I171011 15:52:05.487360 83213 storage/replica.go:763  [replicaGC,n2,s2,r16/?:/{Table/19-Max}] removed 9 (0+9) keys in 1ms [clear=0ms commit=1ms]
I171011 15:52:05.525762 84328 sql/event_log.go:103  [n5] Event: "node_join", target: 5, info: {Descriptor:{NodeID:5 Address:{NetworkField:tcp AddressField:127.0.0.1:54766} Attrs: Locality: ServerVersion:1.1-3} ClusterID:6bd7cdee-7071-4646-b26e-dd56d1ca6473 StartedAt:1507737125272261799 LastUp:1507737125272261799}
W171011 15:52:05.549488 84435 storage/intent_resolver.go:332  [n1,s1,r1/1:/{Min-System/}]: failed to push during intent resolution: failed to push "change-replica" id=2fb62dba key=/Local/Range/Table/19/RangeDescriptor rw=true pri=0.00409670 iso=SERIALIZABLE stat=PENDING epo=0 ts=1507737125.481206757,1 orig=1507737125.415747833,0 max=1507737125.415747833,0 wto=false rop=false seq=4
I171011 15:52:05.549917 82505 storage/replica_command.go:3736  [replicate,n1,s1,r16/1:/{Table/19-Max}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r16:/{Table/19-Max} [(n1,s1):1, next=2]
W171011 15:52:05.562838 84334 storage/intent_resolver.go:332  [n1,s1,r1/1:/{Min-System/}]: failed to push during intent resolution: failed to push "change-replica" id=2fb62dba key=/Local/Range/Table/19/RangeDescriptor rw=true pri=0.00409670 iso=SERIALIZABLE stat=PENDING epo=0 ts=1507737125.481206757,1 orig=1507737125.415747833,0 max=1507737125.415747833,0 wto=false rop=false seq=4
I171011 15:52:05.592498 84441 storage/replica.go:3071  [n1,s1,r16/1:/{Table/19-Max}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I171011 15:52:05.602279 82505 storage/replica_raftstorage.go:526  [replicate,n1,s1,r14/1:/Table/1{7-8}] generated preemptive snapshot 512ac508 at index 16
I171011 15:52:05.618341 82411 storage/replica_raftstorage.go:526  [raftsnapshot,n1,s1,r16/1:/{Table/19-Max}] generated Raft snapshot 1da1e02f at index 15
I171011 15:52:05.625731 82411 storage/store.go:3506  [raftsnapshot,n1,s1,r16/1:/{Table/19-Max}] streamed snapshot to (n2,s2):2: kv pairs: 11, log entries: 5, rate-limit: 8.0 MiB/sec, 6ms
I171011 15:52:05.626983 84336 storage/replica_raftstorage.go:732  [n2,s2,r16/2:{-}] applying Raft snapshot at index 15 (id=1da1e02f, encoded size=2634, 1 rocksdb batches, 5 log entries)
I171011 15:52:05.634145 84336 storage/replica_raftstorage.go:738  [n2,s2,r16/2:/{Table/19-Max}] applied Raft snapshot in 7ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I171011 15:52:05.688076 82505 storage/store.go:3506  [replicate,n1,s1,r14/1:/Table/1{7-8}] streamed snapshot to (n5,s5):?: kv pairs: 10, log entries: 6, rate-limit: 8.0 MiB/sec, 5ms
I171011 15:52:05.691126 84489 storage/replica_raftstorage.go:732  [n5,s5,r14/?:{-}] applying preemptive snapshot at index 16 (id=512ac508, encoded size=2745, 1 rocksdb batches, 6 log entries)
I171011 15:52:05.693393 84489 storage/replica_raftstorage.go:738  [n5,s5,r14/?:/Table/1{7-8}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I171011 15:52:05.698354 82505 storage/replica_command.go:3736  [replicate,n1,s1,r14/1:/Table/1{7-8}] change replicas (ADD_REPLICA (n5,s5):2): read existing descriptor r14:/Table/1{7-8} [(n1,s1):1, next=2]
I171011 15:52:05.742988 84546 storage/replica.go:3071  [n1,s1,r14/1:/Table/1{7-8}] proposing ADD_REPLICA((n5,s5):2): updated=[(n1,s1):1 (n5,s5):2] next=3
I171011 15:52:05.752037 82408 storage/replica_raftstorage.go:526  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot a07e66a2 at index 25
I171011 15:52:05.755533 82408 storage/store.go:3506  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n5,s5):?: kv pairs: 15, log entries: 15, rate-limit: 8.0 MiB/sec, 3ms
I171011 15:52:05.763590 84476 storage/replica_raftstorage.go:732  [n5,s5,r3/?:{-}] applying preemptive snapshot at index 25 (id=a07e66a2, encoded size=7680, 1 rocksdb batches, 15 log entries)
I171011 15:52:05.775115 84476 storage/replica_raftstorage.go:738  [n5,s5,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 11ms [clear=0ms batch=0ms entries=10ms commit=0ms]
I171011 15:52:05.775733 84565 storage/raft_transport.go:455  [n5] raft transport stream to node 1 established
I171011 15:52:05.780671 82408 storage/replica_command.go:3736  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n5,s5):2): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, next=2]
I171011 15:52:05.857544 84518 storage/replica.go:3071  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n5,s5):2): updated=[(n1,s1):1 (n5,s5):2] next=3
I171011 15:52:05.871208 82505 storage/replica_raftstorage.go:526  [replicate,n1,s1,r2/1:/System/{-NodeLive���}] generated preemptive snapshot d06bdd81 at index 22
I171011 15:52:05.876805 82505 storage/store.go:3506  [replicate,n1,s1,r2/1:/System/{-NodeLive���}] streamed snapshot to (n4,s4):?: kv pairs: 10, log entries: 12, rate-limit: 8.0 MiB/sec, 5ms
I171011 15:52:05.880498 84579 storage/replica_raftstorage.go:732  [n4,s4,r2/?:{-}] applying preemptive snapshot at index 22 (id=d06bdd81, encoded size=53658, 1 rocksdb batches, 12 log entries)
I171011 15:52:05.893538 84579 storage/replica_raftstorage.go:738  [n4,s4,r2/?:/System/{-NodeLive���}] applied preemptive snapshot in 13ms [clear=0ms batch=0ms entries=12ms commit=0ms]
I171011 15:52:05.898499 82505 storage/replica_command.go:3736  [replicate,n1,s1,r2/1:/System/{-NodeLive���}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r2:/System/{-NodeLiveness} [(n1,s1):1, next=2]
I171011 15:52:05.935495 84527 storage/replica.go:3071  [n1,s1,r2/1:/System/{-NodeLive���}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3
I171011 15:52:05.944838 82505 storage/replica_raftstorage.go:526  [replicate,n1,s1,r7/1:/Table/{SystemCon���-11}] generated preemptive snapshot 6f894ee1 at index 28
I171011 15:52:05.948960 82505 storage/store.go:3506  [replicate,n1,s1,r7/1:/Table/{SystemCon���-11}] streamed snapshot to (n5,s5):?: kv pairs: 44, log entries: 18, rate-limit: 8.0 MiB/sec, 3ms
I171011 15:52:05.955582 84583 storage/replica_raftstorage.go:732  [n5,s5,r7/?:{-}] applying preemptive snapshot at index 28 (id=6f894ee1, encoded size=15949, 1 rocksdb batches, 18 log entries)
I171011 15:52:05.986718 84583 storage/replica_raftstorage.go:738  [n5,s5,r7/?:/Table/{SystemCon���-11}] applied preemptive snapshot in 31ms [clear=0ms batch=0ms entries=15ms commit=15ms]
I171011 15:52:05.990575 82505 storage/replica_command.go:3736  [replicate,n1,s1,r7/1:/Table/{SystemCon���-11}] change replicas (ADD_REPLICA (n5,s5):2): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, next=2]
I171011 15:52:06.034852 84321 storage/store.go:2165  [replicaGC,n5,s5,r7/?:/Table/{SystemCon���-11}] removing replica
I171011 15:52:06.035900 84321 storage/replica.go:763  [replicaGC,n5,s5,r7/?:/Table/{SystemCon���-11}] removed 38 (28+10) keys in 0ms [clear=0ms commit=0ms]
I171011 15:52:06.055682 82505 storage/replica_command.go:3736  [replicate,n1,s1,r7/1:/Table/{SystemCon���-11}] change replicas (ADD_REPLICA (n5,s5):2): read existing descriptor r7:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, next=2]
I171011 15:52:06.092956 84645 storage/replica.go:3071  [n1,s1,r7/1:/Table/{SystemCon���-11}] proposing ADD_REPLICA((n5,s5):2): updated=[(n1,s1):1 (n5,s5):2] next=3
I171011 15:52:06.103292 82408 storage/replica_raftstorage.go:526  [replicate,n1,s1,r10/1:/Table/1{3-4}] generated preemptive snapshot a4ab9bee at index 57
I171011 15:52:06.108849 82408 storage/store.go:3506  [replicate,n1,s1,r10/1:/Table/1{3-4}] streamed snapshot to (n2,s2):?: kv pairs: 156, log entries: 47, rate-limit: 8.0 MiB/sec, 5ms
I171011 15:52:06.110962 84632 storage/replica_raftstorage.go:732  [n2,s2,r10/?:{-}] applying preemptive snapshot at index 57 (id=a4ab9bee, encoded size=59559, 1 rocksdb batches, 47 log entries)
I171011 15:52:06.120172 82411 storage/replica_raftstorage.go:526  [raftsnapshot,n1,s1,r7/1:/Table/{SystemCon���-11}] generated Raft snapshot bfe3af8f at index 32
I171011 15:52:06.124616 82411 storage/store.go:3506  [raftsnapshot,n1,s1,r7/1:/Table/{SystemCon���-11}] streamed snapshot to (n5,s5):2: kv pairs: 46, log entries: 22, rate-limit: 8.0 MiB/sec, 3ms
I171011 15:52:06.125293 84560 storage/replica_raftstorage.go:732  [n5,s5,r7/2:{-}] applying Raft snapshot at index 32 (id=bfe3af8f, encoded size=18054, 1 rocksdb batches, 22 log entries)
I171011 15:52:06.132562 84632 storage/replica_raftstorage.go:738  [n2,s2,r10/?:/Table/1{3-4}] applied preemptive snapshot in 21ms [clear=0ms batch=0ms entries=20ms commit=1ms]
I171011 15:52:06.133118 84560 storage/replica_raftstorage.go:738  [n5,s5,r7/2:/Table/{SystemCon���-11}] applied Raft snapshot in 8ms [clear=0ms batch=0ms entries=6ms commit=0ms]
I171011 15:52:06.141270 82408 storage/replica_command.go:3736  [replicate,n1,s1,r10/1:/Table/1{3-4}] change replicas (ADD_REPLICA (n2,s2):3): read existing descriptor r10:/Table/1{3-4} [(n1,s1):1, (n3,s3):2, next=3]
I171011 15:52:06.212711 84664 storage/replica.go:3071  [n1,s1,r10/1:/Table/1{3-4}] proposing ADD_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I171011 15:52:06.221859 82408 storage/allocator_scorer.go:623  [replicate,n1,s1,r10/1:/Table/1{3-4}] s1: should-rebalance(ranges-overfull): rangeCount=16, mean=5.00, overfull-threshold=6
I171011 15:52:06.225556 82505 storage/replica_raftstorage.go:526  [replicate,n1,s1,r9/1:/Table/1{2-3}] generated preemptive snapshot be32bc40 at index 30
I171011 15:52:06.233443 82505 storage/store.go:3506  [replicate,n1,s1,r9/1:/Table/1{2-3}] streamed snapshot to (n3,s3):?: kv pairs: 55, log entries: 20, rate-limit: 8.0 MiB/sec, 6ms
I171011 15:52:06.236131 84666 storage/replica_raftstorage.go:732  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 30 (id=be32bc40, encoded size=22320, 1 rocksdb batches, 20 log entries)
I171011 15:52:06.253904 84666 storage/replica_raftstorage.go:738  [n3,s3,r9/?:/Table/1{2-3}] applied preemptive snapshot in 18ms [clear=1ms batch=0ms entries=14ms commit=0ms]
I171011 15:52:06.257685 82505 storage/replica_command.go:3736  [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]
I171011 15:52:06.268974 82414 storage/allocator_scorer.go:623  [replicate,n1,s1,r10/1:/Table/1{3-4}] s1: should-rebalance(ranges-overfull): rangeCount=16, mean=5.20, overfull-threshold=6
I171011 15:52:06.298549 84669 storage/replica.go:3071  [n1,s1,r9/1:/Table/1{2-3}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I171011 15:52:06.304485 82505 storage/replica_raftstorage.go:526  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 2b9c5bb8 at index 95
I171011 15:52:06.312309 82505 storage/store.go:3506  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot to (n4,s4):?: kv pairs: 56, log entries: 85, rate-limit: 8.0 MiB/sec, 5ms
I171011 15:52:06.313998 82414 storage/allocator_scorer.go:623  [replicate,n1,s1,r10/1:/Table/1{3-4}] s1: should-rebalance(ranges-overfull): rangeCount=16, mean=5.20, overfull-threshold=6
I171011 15:52:06.314250 84694 storage/replica_raftstorage.go:732  [n4,s4,r1/?:{-}] applying preemptive snapshot at index 95 (id=2b9c5bb8, encoded size=40950, 1 rocksdb batches, 85 log entries)
I171011 15:52:06.350245 82414 storage/allocator_scorer.go:623  [replicate,n1,s1,r10/1:/Table/1{3-4}] s1: should-rebalance(ranges-overfull): rangeCount=16, mean=5.20, overfull-threshold=6
I171011 15:52:06.361266 84694 storage/replica_raftstorage.go:738  [n4,s4,r1/?:/{Min-System/}] applied preemptive snapshot in 47ms [clear=0ms batch=0ms entries=46ms commit=0ms]
I171011 15:52:06.365112 82505 storage/replica_command.go:3736  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA (n4,s4):2): read existing descriptor r1:/{Min-System/} [(n1,s1):1, next=2]
I171011 15:52:06.401008 84624 storage/replica.go:3071  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA((n4,s4):2): updated=[(n1,s1):1 (n4,s4):2] next=3
I171011 15:52:06.412135 82408 storage/replica_raftstorage.go:526  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] generated preemptive snapshot 65ac0ebd at index 29
I171011 15:52:06.413081 82414 storage/allocator_scorer.go:623  [replicate,n1,s1,r10/1:/Table/1{3-4}] s1: should-rebalance(ranges-overfull): rangeCount=16, mean=5.40, overfull-threshold=6
I171011 15:52:06.430956 82408 storage/store.go:3506  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] streamed snapshot to (n3,s3):?: kv pairs: 16, log entries: 19, rate-limit: 8.0 MiB/sec, 9ms
I171011 15:52:06.442529 84724 storage/replica_raftstorage.go:732  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 29 (id=65ac0ebd, encoded size=9292, 1 rocksdb batches, 19 log entries)
I171011 15:52:06.452327 84724 storage/replica_raftstorage.go:738  [n3,s3,r3/?:/System/NodeLiveness{-Max}] applied preemptive snapshot in 10ms [clear=3ms batch=0ms entries=4ms commit=0ms]
I171011 15:52:06.464147 82408 storage/replica_command.go:3736  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, (n5,s5):2, next=3]
I171011 15:52:06.492280 83607 storage/store.go:2165  [replicaGC,n3,s3,r3/?:/System/NodeLiveness{-Max}] removing replica
I171011 15:52:06.497118 82414 storage/allocator_scorer.go:623  [replicate,n1,s1,r10/1:/Table/1{3-4}] s1: should-rebalance(ranges-overfull): rangeCount=16, mean=5.60, overfull-threshold=6
I171011 15:52:06.514727 83607 storage/replica.go:763  [replicaGC,n3,s3,r3/?:/System/NodeLiveness{-Max}] removed 14 (5+9) keys in 8ms [clear=0ms commit=8ms]
I171011 15:52:06.657298 82408 storage/replica_command.go:3736  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] change replicas (ADD_REPLICA (n3,s3):3): read existing descriptor r3:/System/NodeLiveness{-Max} [(n1,s1):1, (n5,s5):2, next=3]
I171011 15:52:06.683715 82414 storage/allocator_scorer.go:623  [replicate,n1,s1,r10/1:/Table/1{3-4}] s1: should-rebalance(ranges-overfull): rangeCount=16, mean=5.40, overfull-threshold=6
I171011 15:52:06.717319 84727 storage/replica.go:3071  [n1,s1,r3/1:/System/NodeLiveness{-Max}] proposing ADD_REPLICA((n3,s3):3): updated=[(n1,s1):1 (n5,s5):2 (n3,s3):3] next=4
I171011 15:52:06.725786 82408 storage/allocator_scorer.go:623  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] s1: should-rebalance(ranges-overfull): rangeCount=16, mean=5.40, overfull-threshold=6
I171011 15:52:06.736185 82505 storage/allocator_scorer.go:623  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] s1: should-rebalance(ranges-overfull): rangeCount=16, mean=5.40, overfull-threshold=6
I171011 15:52:06.739651 82414 storage/allocator_scorer.go:623  [replicate,n1,s1,r3/1:/System/NodeLiveness{-Max}] s1: should-rebalance(ranges-overfull): rangeCount=16, mean=5.40, overfull-threshold=6
==================
Write at 0x00c42126c238 by goroutine 100:
  github.com/cockroachdb/cockroach/pkg/storage.Allocator.RebalanceTarget()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/allocator.go:530 +0x858
  github.com/cockroachdb/cockroach/pkg/storage.(*replicateQueue).shouldQueue()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/replicate_queue.go:187 +0x77f
  github.com/cockroachdb/cockroach/pkg/storage.(*baseQueue).MaybeAdd()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:378 +0x2d0
  github.com/cockroachdb/cockroach/pkg/storage.(*replicateQueue).MaybeAdd()
      <autogenerated>:1 +0x6e
  github.com/cockroachdb/cockroach/pkg/storage.(*replicaScanner).waitAndProcess()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/scanner.go:222 +0x3a7
  github.com/cockroachdb/cockroach/pkg/storage.(*replicaScanner).scanLoop.func1.1()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/scanner.go:270 +0x163
  github.com/cockroachdb/cockroach/pkg/storage.(*storeReplicaVisitor).Visit()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:315 +0x2f4
  github.com/cockroachdb/cockroach/pkg/storage.(*replicaScanner).scanLoop.func1()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/scanner.go:268 +0x3f2
  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1()
      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:198 +0x160

Previous write at 0x00c42126c238 by goroutine 114:
  github.com/cockroachdb/cockroach/pkg/storage.Allocator.RebalanceTarget()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/allocator.go:530 +0x858
  github.com/cockroachdb/cockroach/pkg/storage.(*replicateQueue).processOneChange()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/replicate_queue.go:463 +0x1a58
  github.com/cockroachdb/cockroach/pkg/storage.(*replicateQueue).process()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/replicate_queue.go:222 +0x2aa
  github.com/cockroachdb/cockroach/pkg/storage.(*baseQueue).processReplica()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:631 +0x4d7
  github.com/cockroachdb/cockroach/pkg/storage.(*baseQueue).maybeAddToPurgatory.func2.1()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:714 +0x86
  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTask()
      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:231 +0x104
  github.com/cockroachdb/cockroach/pkg/storage.(*baseQueue).maybeAddToPurgatory.func2()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:711 +0xcff
  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1()
      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:198 +0x160

Goroutine 100 (running) created at:
  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker()
      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:191 +0xba
  github.com/cockroachdb/cockroach/pkg/storage.(*replicaScanner).scanLoop()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/scanner.go:253 +0x165
  github.com/cockroachdb/cockroach/pkg/storage.(*replicaScanner).Start()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/scanner.go:121 +0xd4
  github.com/cockroachdb/cockroach/pkg/storage.(*Store).Start.func3()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:1201 +0x1df
  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1()
      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:198 +0x160

Goroutine 114 (running) created at:
  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker()
      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:191 +0xba
  github.com/cockroachdb/cockroach/pkg/storage.(*baseQueue).maybeAddToPurgatory()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:690 +0x7a0
  github.com/cockroachdb/cockroach/pkg/storage.(*baseQueue).processLoop.func1.2()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:532 +0x342
  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTask()
      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:231 +0x104
  github.com/cockroachdb/cockroach/pkg/storage.(*baseQueue).processLoop.func1()
      /go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:526 +0x538
  github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1()
      /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:198 +0x160
==================

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added O-robot Originated from a bot. C-test-failure Broken test (automatically or manually discovered). labels Oct 11, 2017
@benesch
Copy link
Contributor

benesch commented Oct 11, 2017

@a-robinson can you triage?

@a-robinson
Copy link
Contributor

@a6802739 would you like to fix this, or should I? It looks like it got introduced by #18364

@lgo lgo mentioned this issue Oct 11, 2017
Merged
@a6802739
Copy link
Contributor

a6802739 commented Oct 12, 2017 via email

@a-robinson a-robinson mentioned this issue Oct 12, 2017
Closed
@a6802739 a6802739 mentioned this issue Oct 12, 2017
Merged
a-robinson pushed a commit to a-robinson/cockroach that referenced this issue Dec 20, 2017
@a6802739 @a-robinson
storage : fix bug for the testrace of TestSystemZoneConfigs
21d4cd9 
Fixes cockroachdb#19180.
Fixes cockroachdb#19207.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@a6802739 a6802739

@a-robinson a-robinson

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
@benesch @a6802739 @a-robinson @cockroach-teamcity