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/TestDistSQLRangeCachesIntegrationTest #25808

Closed
cockroach-teamcity opened this issue May 22, 2018 · 6 comments
Closed

teamcity: failed tests on master: testrace/TestDistSQLRangeCachesIntegrationTest #25808

cockroach-teamcity opened this issue May 22, 2018 · 6 comments
Assignees
@asubiotto
Labels
A-sql-execution Relating to SQL execution. 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:

#672666:

--- FAIL: testrace/TestDistSQLRangeCachesIntegrationTest (9.520s)
distsql_physical_planner_test.go:376: expected prefix "{\"nodeNames\":[\"1\",\"2\",\"3\",\"4\"]", but json is: {"nodeNames":["1","4"],"processors":[{"nodeIdx":0,"inputs":[],"core":{"title":"TableReader/0","details":["primary@left"]},"outputs":[],"stage":1},{"nodeIdx":0,"inputs":[],"core":{"title":"TableReader/1","details":["primary@right"]},"outputs":[],"stage":2},{"nodeIdx":0,"inputs":[{"title":"unordered","details":[]},{"title":"unordered","details":[]}],"core":{"title":"MergeJoiner/2","details":["left(@1+)=right(@1+)","Render: 1:::INT"]},"outputs":[],"stage":3},{"nodeIdx":0,"inputs":[],"core":{"title":"Aggregator/3","details":["COUNT(@1)"]},"outputs":[],"stage":4},{"nodeIdx":1,"inputs":[],"core":{"title":"No-op/4","details":[]},"outputs":[],"stage":5},{"nodeIdx":1,"inputs":[],"core":{"title":"Response","details":[]},"outputs":[],"stage":0}],"edges":[{"sourceProc":0,"sourceOutput":0,"destProc":2,"destInput":1},{"sourceProc":1,"sourceOutput":0,"destProc":2,"destInput":2},{"sourceProc":2,"sourceOutput":0,"destProc":3,"destInput":0},{"sourceProc":3,"sourceOutput":0,"destProc":4,"destInput":0},{"sourceProc":4,"sourceOutput":0,"destProc":5,"destInput":0}]}
------- Stdout: -------
I180522 16:15:55.836786 5818 server/server.go:783  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180522 16:15:55.878035 5818 server/config.go:539  [n?] 1 storage engine initialized
I180522 16:15:55.878195 5818 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180522 16:15:55.878281 5818 server/config.go:542  [n?] store 0: in-memory, size 0 B
I180522 16:15:55.955684 5818 server/node.go:376  [n?] **** cluster 2df383bd-817e-4a03-ac9a-12d87ceba32d has been created
I180522 16:15:55.955846 5818 server/server.go:1357  [n?] **** add additional nodes by specifying --join=127.0.0.1:46013
I180522 16:15:55.973913 5818 storage/store.go:1450  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180522 16:15:55.974648 5818 server/node.go:506  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=0, writes=0.00, bytesPerReplica={p10=7043.00 p25=7043.00 p50=7043.00 p75=7043.00 p90=7043.00 pMax=7043.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180522 16:15:55.974928 5818 server/node.go:354  [n1] node ID 1 initialized
I180522 16:15:55.975308 5818 gossip/gossip.go:333  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:46013" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:4 > 
I180522 16:15:55.977160 5818 storage/stores.go:222  [n1] read 0 node addresses from persistent storage
I180522 16:15:55.977902 5818 server/node.go:647  [n1] connecting to gossip network to verify cluster ID...
I180522 16:15:55.978125 5818 server/node.go:672  [n1] node connected via gossip and verified as part of cluster "2df383bd-817e-4a03-ac9a-12d87ceba32d"
I180522 16:15:55.978542 5818 server/node.go:440  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180522 16:15:55.981081 5818 server/server.go:1484  [n1] starting https server at 127.0.0.1:34813
I180522 16:15:55.981213 5818 server/server.go:1485  [n1] starting grpc/postgres server at 127.0.0.1:46013
I180522 16:15:55.981286 5818 server/server.go:1486  [n1] advertising CockroachDB node at 127.0.0.1:46013
W180522 16:15:55.981532 5818 sql/jobs/registry.go:287  [n1] unable to get node liveness: node not in the liveness table
I180522 16:15:56.443388 6130 sql/event_log.go:124  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180522 16:15:56.710608 6147 sql/event_log.go:124  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
I180522 16:15:56.814449 6162 sql/event_log.go:124  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180522 16:15:57.061166 6167 sql/event_log.go:124  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:root}
I180522 16:15:57.212323 6095 sql/event_log.go:124  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I180522 16:15:57.423760 6119 sql/event_log.go:124  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I180522 16:15:57.439335 5818 server/server.go:1563  [n1] done ensuring all necessary migrations have run
I180522 16:15:57.439512 5818 server/server.go:1566  [n1] serving sql connections
I180522 16:15:57.528177 6096 server/server_update.go:66  [n1] no need to upgrade, cluster already at the newest version
I180522 16:15:57.532286 6178 sql/event_log.go:124  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:46013} Attrs: Locality: ServerVersion:2.0-4} ClusterID:2df383bd-817e-4a03-ac9a-12d87ceba32d StartedAt:1527005755978182503 LastUp:1527005755978182503}
I180522 16:15:57.871567 5818 server/server.go:783  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180522 16:15:57.882749 5818 server/config.go:539  [n?] 1 storage engine initialized
I180522 16:15:57.883639 5818 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180522 16:15:57.883752 5818 server/config.go:542  [n?] store 0: in-memory, size 0 B
W180522 16:15:57.884221 5818 gossip/gossip.go:1293  [n?] no incoming or outgoing connections
I180522 16:15:57.902379 5818 server/server.go:1359  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180522 16:15:58.058486 5889 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:46013
I180522 16:15:58.061469 6155 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:41717}
I180522 16:15:58.139897 5818 storage/stores.go:222  [n?] read 0 node addresses from persistent storage
I180522 16:15:58.141257 5818 storage/stores.go:241  [n?] wrote 1 node addresses to persistent storage
I180522 16:15:58.141458 5818 server/node.go:647  [n?] connecting to gossip network to verify cluster ID...
I180522 16:15:58.141707 5818 server/node.go:672  [n?] node connected via gossip and verified as part of cluster "2df383bd-817e-4a03-ac9a-12d87ceba32d"
I180522 16:15:58.159196 5818 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180522 16:15:58.263952 5818 server/node.go:347  [n?] new node allocated ID 2
I180522 16:15:58.264495 5818 gossip/gossip.go:333  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:41717" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:4 > 
I180522 16:15:58.265280 5818 server/node.go:421  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180522 16:15:58.265988 5818 server/node.go:440  [n2] node=2: started with [] engine(s) and attributes []
I180522 16:15:58.268391 5818 server/server.go:1484  [n2] starting https server at 127.0.0.1:45811
I180522 16:15:58.268522 5818 server/server.go:1485  [n2] starting grpc/postgres server at 127.0.0.1:41717
I180522 16:15:58.268587 5818 server/server.go:1486  [n2] advertising CockroachDB node at 127.0.0.1:41717
I180522 16:15:58.274736 6290 storage/stores.go:241  [n1] wrote 1 node addresses to persistent storage
I180522 16:15:58.278496 5818 server/server.go:1563  [n2] done ensuring all necessary migrations have run
I180522 16:15:58.278741 5818 server/server.go:1566  [n2] serving sql connections
I180522 16:15:58.550611 6291 server/server_update.go:66  [n2] no need to upgrade, cluster already at the newest version
I180522 16:15:58.586572 6293 sql/event_log.go:124  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:41717} Attrs: Locality: ServerVersion:2.0-4} ClusterID:2df383bd-817e-4a03-ac9a-12d87ceba32d StartedAt:1527005758265482551 LastUp:1527005758265482551}
I180522 16:15:58.696090 5872 server/node.go:628  [n2] bootstrapped store [n2,s2]
I180522 16:15:59.159815 5818 server/server.go:783  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180522 16:15:59.209543 5818 server/config.go:539  [n?] 1 storage engine initialized
I180522 16:15:59.209704 5818 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180522 16:15:59.209750 5818 server/config.go:542  [n?] store 0: in-memory, size 0 B
W180522 16:15:59.210101 5818 gossip/gossip.go:1293  [n?] no incoming or outgoing connections
I180522 16:15:59.210570 5818 server/server.go:1359  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180522 16:15:59.503517 6473 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:46013
I180522 16:15:59.506541 6516 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:36989}
I180522 16:15:59.517605 5818 storage/stores.go:222  [n?] read 0 node addresses from persistent storage
I180522 16:15:59.518130 5818 storage/stores.go:241  [n?] wrote 1 node addresses to persistent storage
I180522 16:15:59.518200 5818 server/node.go:647  [n?] connecting to gossip network to verify cluster ID...
I180522 16:15:59.518377 5818 server/node.go:672  [n?] node connected via gossip and verified as part of cluster "2df383bd-817e-4a03-ac9a-12d87ceba32d"
I180522 16:15:59.524554 6517 storage/stores.go:241  [n?] wrote 2 node addresses to persistent storage
I180522 16:15:59.533616 5818 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180522 16:15:59.540936 5818 server/node.go:347  [n?] new node allocated ID 3
I180522 16:15:59.541471 5818 gossip/gossip.go:333  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:36989" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:4 > 
I180522 16:15:59.543048 5818 server/node.go:421  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180522 16:15:59.543609 5818 server/node.go:440  [n3] node=3: started with [] engine(s) and attributes []
I180522 16:15:59.551691 5818 server/server.go:1484  [n3] starting https server at 127.0.0.1:40139
I180522 16:15:59.551817 5818 server/server.go:1485  [n3] starting grpc/postgres server at 127.0.0.1:36989
I180522 16:15:59.551875 5818 server/server.go:1486  [n3] advertising CockroachDB node at 127.0.0.1:36989
I180522 16:15:59.552216 6546 storage/stores.go:241  [n1] wrote 2 node addresses to persistent storage
I180522 16:15:59.560985 6335 storage/stores.go:241  [n2] wrote 2 node addresses to persistent storage
I180522 16:15:59.568385 5818 server/server.go:1563  [n3] done ensuring all necessary migrations have run
I180522 16:15:59.568673 5818 server/server.go:1566  [n3] serving sql connections
I180522 16:15:59.783951 6485 server/node.go:628  [n3] bootstrapped store [n3,s3]
I180522 16:15:59.829890 6547 server/server_update.go:66  [n3] no need to upgrade, cluster already at the newest version
I180522 16:15:59.831329 6549 sql/event_log.go:124  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:36989} Attrs: Locality: ServerVersion:2.0-4} ClusterID:2df383bd-817e-4a03-ac9a-12d87ceba32d StartedAt:1527005759543260582 LastUp:1527005759543260582}
I180522 16:16:00.211700 5818 server/server.go:783  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180522 16:16:00.262837 5818 server/config.go:539  [n?] 1 storage engine initialized
I180522 16:16:00.262994 5818 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180522 16:16:00.263059 5818 server/config.go:542  [n?] store 0: in-memory, size 0 B
W180522 16:16:00.263456 5818 gossip/gossip.go:1293  [n?] no incoming or outgoing connections
I180522 16:16:00.268948 5818 server/server.go:1359  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180522 16:16:00.451141 6678 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:46013
I180522 16:16:00.454321 6720 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:35581}
I180522 16:16:00.508029 5818 storage/stores.go:222  [n?] read 0 node addresses from persistent storage
I180522 16:16:00.508516 5818 storage/stores.go:241  [n?] wrote 3 node addresses to persistent storage
I180522 16:16:00.508661 5818 server/node.go:647  [n?] connecting to gossip network to verify cluster ID...
I180522 16:16:00.508855 5818 server/node.go:672  [n?] node connected via gossip and verified as part of cluster "2df383bd-817e-4a03-ac9a-12d87ceba32d"
I180522 16:16:00.525039 5818 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180522 16:16:00.532674 5818 server/node.go:347  [n?] new node allocated ID 4
I180522 16:16:00.533320 5818 gossip/gossip.go:333  [n4] NodeDescriptor set to node_id:4 address:<network_field:"tcp" address_field:"127.0.0.1:35581" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:4 > 
I180522 16:16:00.534109 5818 server/node.go:421  [n4] node=4: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180522 16:16:00.534762 5818 server/node.go:440  [n4] node=4: started with [] engine(s) and attributes []
I180522 16:16:00.537612 5818 server/server.go:1484  [n4] starting https server at 127.0.0.1:42697
I180522 16:16:00.537792 5818 server/server.go:1485  [n4] starting grpc/postgres server at 127.0.0.1:35581
I180522 16:16:00.537943 5818 server/server.go:1486  [n4] advertising CockroachDB node at 127.0.0.1:35581
I180522 16:16:00.571789 6804 storage/stores.go:241  [n1] wrote 3 node addresses to persistent storage
I180522 16:16:00.578346 5818 server/server.go:1563  [n4] done ensuring all necessary migrations have run
I180522 16:16:00.578522 5818 server/server.go:1566  [n4] serving sql connections
I180522 16:16:00.591406 6728 storage/stores.go:241  [n3] wrote 3 node addresses to persistent storage
I180522 16:16:00.592409 6807 storage/stores.go:241  [n2] wrote 3 node addresses to persistent storage
I180522 16:16:00.760977 6787 server/node.go:628  [n4] bootstrapped store [n4,s4]
I180522 16:16:00.784916 6761 sql/event_log.go:124  [n4] Event: "node_join", target: 4, info: {Descriptor:{NodeID:4 Address:{NetworkField:tcp AddressField:127.0.0.1:35581} Attrs: Locality: ServerVersion:2.0-4} ClusterID:2df383bd-817e-4a03-ac9a-12d87ceba32d StartedAt:1527005760534483535 LastUp:1527005760534483535}
I180522 16:16:00.853655 6759 server/server_update.go:66  [n4] no need to upgrade, cluster already at the newest version
I180522 16:16:01.321611 6963 sql/event_log.go:124  [n1,client=127.0.0.1:44532,user=root] Event: "create_database", target: 52, info: {DatabaseName:test Statement:CREATE DATABASE IF NOT EXISTS test User:root}
I180522 16:16:01.420710 6963 sql/event_log.go:124  [n1,client=127.0.0.1:44532,user=root] Event: "create_table", target: 53, info: {TableName:test.public."left" Statement:CREATE TABLE test.public."left" (num INT PRIMARY KEY) User:root}
I180522 16:16:01.740740 6963 sql/event_log.go:124  [n1,client=127.0.0.1:44532,user=root] Event: "create_table", target: 54, info: {TableName:test.public."right" Statement:CREATE TABLE test.public."right" (num INT PRIMARY KEY) User:root}
I180522 16:16:02.581310 6963 storage/replica_command.go:863  [n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /Table/54/1/1 [r2]
I180522 16:16:02.880179 6963 storage/replica_command.go:863  [n1,s1,r2/1:/{Table/54/1/1-Max}] initiating a split of this range at key /Table/54/1/2 [r3]
I180522 16:16:03.077863 6963 storage/replica_command.go:863  [n1,s1,r3/1:/{Table/54/1/2-Max}] initiating a split of this range at key /Table/54/1/3 [r4]
I180522 16:16:03.223149 6963 storage/replica_raftstorage.go:520  [n1,s1,r2/1:/Table/54/1/{1-2}] generated preemptive snapshot e83ca358 at index 15
I180522 16:16:03.489250 6963 storage/store_snapshot.go:605  [n1,s1,r2/1:/Table/54/1/{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 5, rate-limit: 2.0 MiB/sec, 4ms
I180522 16:16:03.492492 7052 storage/replica_raftstorage.go:730  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 15 (id=e83ca358, encoded size=2027, 1 rocksdb batches, 5 log entries)
I180522 16:16:03.521561 7052 storage/replica_raftstorage.go:736  [n2,s2,r2/?:/Table/54/1/{1-2}] applied preemptive snapshot in 29ms [clear=0ms batch=0ms entries=1ms commit=26ms]
I180522 16:16:03.530574 6963 storage/replica_command.go:1777  [n1,s1,r2/1:/Table/54/1/{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r2:/Table/54/1/{1-2} [(n1,s1):1, next=2]
I180522 16:16:03.636637 6963 storage/replica.go:3320  [n1,s1,r2/1:/Table/54/1/{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180522 16:16:03.692483 7080 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180522 16:16:03.733975 6303 storage/replica_proposal.go:202  [n2,s2,r2/2:/Table/54/1/{1-2}] new range lease repl=(n2,s2):2 seq=3 start=1527005763.699329692,0 epo=1 pro=1527005763.699343217,0 following repl=(n1,s1):1 seq=2 start=1527005755.959783839,0 exp=1527005769.487482333,0 pro=1527005760.487560595,0
I180522 16:16:03.791392 7110 storage/replica_command.go:1777  [n2,s2,r2/2:/Table/54/1/{1-2}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r2:/Table/54/1/{1-2} [(n1,s1):1, (n2,s2):2, next=3]
I180522 16:16:03.958288 7141 storage/replica.go:3320  [n2,s2,r2/2:/Table/54/1/{1-2}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n2,s2):2] next=3
I180522 16:16:03.973469 7009 storage/store.go:3508  [n1,s1,r2/1:/Table/54/1/{1-2}] added to replica GC queue (peer suggestion)
I180522 16:16:03.991100 6963 storage/replica_raftstorage.go:520  [n1,s1,r4/1:/{Table/54/1/3-Max}] generated preemptive snapshot d6375b6e at index 13
I180522 16:16:04.011957 7030 storage/store.go:2492  [replicaGC,n1,s1,r2/1:/Table/54/1/{1-2}] removing replica
I180522 16:16:04.015666 7030 storage/replica.go:829  [replicaGC,n1,s1,r2/1:/Table/54/1/{1-2}] removed 8 (1+7) keys in 3ms [clear=0ms commit=3ms]
I180522 16:16:04.227575 6963 storage/store_snapshot.go:605  [n1,s1,r4/1:/{Table/54/1/3-Max}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 3, rate-limit: 2.0 MiB/sec, 6ms
I180522 16:16:04.230640 7040 storage/replica_raftstorage.go:730  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 13 (id=d6375b6e, encoded size=647, 1 rocksdb batches, 3 log entries)
I180522 16:16:04.233451 7040 storage/replica_raftstorage.go:736  [n3,s3,r4/?:/{Table/54/1/3-Max}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180522 16:16:04.237483 6963 storage/replica_command.go:1777  [n1,s1,r4/1:/{Table/54/1/3-Max}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r4:/{Table/54/1/3-Max} [(n1,s1):1, next=2]
I180522 16:16:04.287272 6963 storage/replica.go:3320  [n1,s1,r4/1:/{Table/54/1/3-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180522 16:16:04.345391 7131 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180522 16:16:04.374469 6458 storage/replica_proposal.go:202  [n3,s3,r4/2:/{Table/54/1/3-Max}] new range lease repl=(n3,s3):2 seq=3 start=1527005764.302290276,0 epo=1 pro=1527005764.302306136,0 following repl=(n1,s1):1 seq=2 start=1527005755.959783839,0 exp=1527005769.487482333,0 pro=1527005760.487560595,0
I180522 16:16:04.420367 7220 storage/replica_command.go:1777  [n3,s3,r4/2:/{Table/54/1/3-Max}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r4:/{Table/54/1/3-Max} [(n1,s1):1, (n3,s3):2, next=3]
I180522 16:16:04.549108 7191 storage/replica.go:3320  [n3,s3,r4/2:/{Table/54/1/3-Max}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n3,s3):2] next=3
I180522 16:16:04.630457 7099 storage/store.go:3508  [n1,s1,r4/1:/{Table/54/1/3-Max}] added to replica GC queue (peer suggestion)
I180522 16:16:04.637075 7145 storage/store.go:2492  [replicaGC,n1,s1,r4/1:/{Table/54/1/3-Max}] removing replica
I180522 16:16:04.641565 7145 storage/replica.go:829  [replicaGC,n1,s1,r4/1:/{Table/54/1/3-Max}] removed 8 (1+7) keys in 2ms [clear=0ms commit=2ms]
I180522 16:16:05.067619 7259 util/stop/stopper.go:471  quiescing; tasks left:
1      [async] transport racer
I180522 16:16:05.069550 5777 kv/transport_race.go:67  transport race promotion: ran 58 iterations on up to 621 requests
W180522 16:16:05.081284 7131 storage/raft_transport.go:465  [n3] raft transport stream to node 1 failed: EOF
W180522 16:16:05.085337 7080 storage/raft_transport.go:465  [n2] raft transport stream to node 1 failed: rpc error: code = Unavailable desc = transport is closing
W180522 16:16:05.086043 7007 storage/raft_transport.go:465  [n1] raft transport stream to node 2 failed: rpc error: code = FailedPrecondition desc = grpc: the client connection is closing
W180522 16:16:05.087411 7086 storage/raft_transport.go:465  [n1] raft transport stream to node 3 failed: rpc error: code = Unavailable desc = transport is closing
W180522 16:16:05.106118 6801 storage/node_liveness.go:465  [n4,hb] failed node liveness heartbeat: node unavailable; try another peer
--- FAIL: testrace/TestDistSQLRangeCachesIntegrationTest (10.220s)
distsql_physical_planner_test.go:376: expected prefix "{\"nodeNames\":[\"1\",\"2\",\"3\",\"4\"]", but json is: {"nodeNames":["1","4"],"processors":[{"nodeIdx":0,"inputs":[],"core":{"title":"TableReader/0","details":["primary@left"]},"outputs":[],"stage":1},{"nodeIdx":0,"inputs":[],"core":{"title":"TableReader/1","details":["primary@right"]},"outputs":[],"stage":2},{"nodeIdx":0,"inputs":[{"title":"unordered","details":[]},{"title":"unordered","details":[]}],"core":{"title":"MergeJoiner/2","details":["left(@1+)=right(@1+)","Render: 1:::INT"]},"outputs":[],"stage":3},{"nodeIdx":0,"inputs":[],"core":{"title":"Aggregator/3","details":["COUNT(@1)"]},"outputs":[],"stage":4},{"nodeIdx":1,"inputs":[],"core":{"title":"No-op/4","details":[]},"outputs":[],"stage":5},{"nodeIdx":1,"inputs":[],"core":{"title":"Response","details":[]},"outputs":[],"stage":0}],"edges":[{"sourceProc":0,"sourceOutput":0,"destProc":2,"destInput":1},{"sourceProc":1,"sourceOutput":0,"destProc":2,"destInput":2},{"sourceProc":2,"sourceOutput":0,"destProc":3,"destInput":0},{"sourceProc":3,"sourceOutput":0,"destProc":4,"destInput":0},{"sourceProc":4,"sourceOutput":0,"destProc":5,"destInput":0}]}
------- Stdout: -------
I180522 16:15:55.836786 5818 server/server.go:783  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180522 16:15:55.878035 5818 server/config.go:539  [n?] 1 storage engine initialized
I180522 16:15:55.878195 5818 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180522 16:15:55.878281 5818 server/config.go:542  [n?] store 0: in-memory, size 0 B
I180522 16:15:55.955684 5818 server/node.go:376  [n?] **** cluster 2df383bd-817e-4a03-ac9a-12d87ceba32d has been created
I180522 16:15:55.955846 5818 server/server.go:1357  [n?] **** add additional nodes by specifying --join=127.0.0.1:46013
I180522 16:15:55.973913 5818 storage/store.go:1450  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180522 16:15:55.974648 5818 server/node.go:506  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=0, writes=0.00, bytesPerReplica={p10=7043.00 p25=7043.00 p50=7043.00 p75=7043.00 p90=7043.00 pMax=7043.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180522 16:15:55.974928 5818 server/node.go:354  [n1] node ID 1 initialized
I180522 16:15:55.975308 5818 gossip/gossip.go:333  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:46013" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:4 > 
I180522 16:15:55.977160 5818 storage/stores.go:222  [n1] read 0 node addresses from persistent storage
I180522 16:15:55.977902 5818 server/node.go:647  [n1] connecting to gossip network to verify cluster ID...
I180522 16:15:55.978125 5818 server/node.go:672  [n1] node connected via gossip and verified as part of cluster "2df383bd-817e-4a03-ac9a-12d87ceba32d"
I180522 16:15:55.978542 5818 server/node.go:440  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180522 16:15:55.981081 5818 server/server.go:1484  [n1] starting https server at 127.0.0.1:34813
I180522 16:15:55.981213 5818 server/server.go:1485  [n1] starting grpc/postgres server at 127.0.0.1:46013
I180522 16:15:55.981286 5818 server/server.go:1486  [n1] advertising CockroachDB node at 127.0.0.1:46013
W180522 16:15:55.981532 5818 sql/jobs/registry.go:287  [n1] unable to get node liveness: node not in the liveness table
I180522 16:15:56.443388 6130 sql/event_log.go:124  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180522 16:15:56.710608 6147 sql/event_log.go:124  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
I180522 16:15:56.814449 6162 sql/event_log.go:124  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180522 16:15:57.061166 6167 sql/event_log.go:124  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:root}
I180522 16:15:57.212323 6095 sql/event_log.go:124  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I180522 16:15:57.423760 6119 sql/event_log.go:124  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I180522 16:15:57.439335 5818 server/server.go:1563  [n1] done ensuring all necessary migrations have run
I180522 16:15:57.439512 5818 server/server.go:1566  [n1] serving sql connections
I180522 16:15:57.528177 6096 server/server_update.go:66  [n1] no need to upgrade, cluster already at the newest version
I180522 16:15:57.532286 6178 sql/event_log.go:124  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:46013} Attrs: Locality: ServerVersion:2.0-4} ClusterID:2df383bd-817e-4a03-ac9a-12d87ceba32d StartedAt:1527005755978182503 LastUp:1527005755978182503}
I180522 16:15:57.871567 5818 server/server.go:783  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180522 16:15:57.882749 5818 server/config.go:539  [n?] 1 storage engine initialized
I180522 16:15:57.883639 5818 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180522 16:15:57.883752 5818 server/config.go:542  [n?] store 0: in-memory, size 0 B
W180522 16:15:57.884221 5818 gossip/gossip.go:1293  [n?] no incoming or outgoing connections
I180522 16:15:57.902379 5818 server/server.go:1359  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180522 16:15:58.058486 5889 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:46013
I180522 16:15:58.061469 6155 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:41717}
I180522 16:15:58.139897 5818 storage/stores.go:222  [n?] read 0 node addresses from persistent storage
I180522 16:15:58.141257 5818 storage/stores.go:241  [n?] wrote 1 node addresses to persistent storage
I180522 16:15:58.141458 5818 server/node.go:647  [n?] connecting to gossip network to verify cluster ID...
I180522 16:15:58.141707 5818 server/node.go:672  [n?] node connected via gossip and verified as part of cluster "2df383bd-817e-4a03-ac9a-12d87ceba32d"
I180522 16:15:58.159196 5818 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180522 16:15:58.263952 5818 server/node.go:347  [n?] new node allocated ID 2
I180522 16:15:58.264495 5818 gossip/gossip.go:333  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:41717" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:4 > 
I180522 16:15:58.265280 5818 server/node.go:421  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180522 16:15:58.265988 5818 server/node.go:440  [n2] node=2: started with [] engine(s) and attributes []
I180522 16:15:58.268391 5818 server/server.go:1484  [n2] starting https server at 127.0.0.1:45811
I180522 16:15:58.268522 5818 server/server.go:1485  [n2] starting grpc/postgres server at 127.0.0.1:41717
I180522 16:15:58.268587 5818 server/server.go:1486  [n2] advertising CockroachDB node at 127.0.0.1:41717
I180522 16:15:58.274736 6290 storage/stores.go:241  [n1] wrote 1 node addresses to persistent storage
I180522 16:15:58.278496 5818 server/server.go:1563  [n2] done ensuring all necessary migrations have run
I180522 16:15:58.278741 5818 server/server.go:1566  [n2] serving sql connections
I180522 16:15:58.550611 6291 server/server_update.go:66  [n2] no need to upgrade, cluster already at the newest version
I180522 16:15:58.586572 6293 sql/event_log.go:124  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:41717} Attrs: Locality: ServerVersion:2.0-4} ClusterID:2df383bd-817e-4a03-ac9a-12d87ceba32d StartedAt:1527005758265482551 LastUp:1527005758265482551}
I180522 16:15:58.696090 5872 server/node.go:628  [n2] bootstrapped store [n2,s2]
I180522 16:15:59.159815 5818 server/server.go:783  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180522 16:15:59.209543 5818 server/config.go:539  [n?] 1 storage engine initialized
I180522 16:15:59.209704 5818 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180522 16:15:59.209750 5818 server/config.go:542  [n?] store 0: in-memory, size 0 B
W180522 16:15:59.210101 5818 gossip/gossip.go:1293  [n?] no incoming or outgoing connections
I180522 16:15:59.210570 5818 server/server.go:1359  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180522 16:15:59.503517 6473 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:46013
I180522 16:15:59.506541 6516 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:36989}
I180522 16:15:59.517605 5818 storage/stores.go:222  [n?] read 0 node addresses from persistent storage
I180522 16:15:59.518130 5818 storage/stores.go:241  [n?] wrote 1 node addresses to persistent storage
I180522 16:15:59.518200 5818 server/node.go:647  [n?] connecting to gossip network to verify cluster ID...
I180522 16:15:59.518377 5818 server/node.go:672  [n?] node connected via gossip and verified as part of cluster "2df383bd-817e-4a03-ac9a-12d87ceba32d"
I180522 16:15:59.524554 6517 storage/stores.go:241  [n?] wrote 2 node addresses to persistent storage
I180522 16:15:59.533616 5818 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180522 16:15:59.540936 5818 server/node.go:347  [n?] new node allocated ID 3
I180522 16:15:59.541471 5818 gossip/gossip.go:333  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:36989" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:4 > 
I180522 16:15:59.543048 5818 server/node.go:421  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180522 16:15:59.543609 5818 server/node.go:440  [n3] node=3: started with [] engine(s) and attributes []
I180522 16:15:59.551691 5818 server/server.go:1484  [n3] starting https server at 127.0.0.1:40139
I180522 16:15:59.551817 5818 server/server.go:1485  [n3] starting grpc/postgres server at 127.0.0.1:36989
I180522 16:15:59.551875 5818 server/server.go:1486  [n3] advertising CockroachDB node at 127.0.0.1:36989
I180522 16:15:59.552216 6546 storage/stores.go:241  [n1] wrote 2 node addresses to persistent storage
I180522 16:15:59.560985 6335 storage/stores.go:241  [n2] wrote 2 node addresses to persistent storage
I180522 16:15:59.568385 5818 server/server.go:1563  [n3] done ensuring all necessary migrations have run
I180522 16:15:59.568673 5818 server/server.go:1566  [n3] serving sql connections
I180522 16:15:59.783951 6485 server/node.go:628  [n3] bootstrapped store [n3,s3]
I180522 16:15:59.829890 6547 server/server_update.go:66  [n3] no need to upgrade, cluster already at the newest version
I180522 16:15:59.831329 6549 sql/event_log.go:124  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:36989} Attrs: Locality: ServerVersion:2.0-4} ClusterID:2df383bd-817e-4a03-ac9a-12d87ceba32d StartedAt:1527005759543260582 LastUp:1527005759543260582}
I180522 16:16:00.211700 5818 server/server.go:783  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180522 16:16:00.262837 5818 server/config.go:539  [n?] 1 storage engine initialized
I180522 16:16:00.262994 5818 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180522 16:16:00.263059 5818 server/config.go:542  [n?] store 0: in-memory, size 0 B
W180522 16:16:00.263456 5818 gossip/gossip.go:1293  [n?] no incoming or outgoing connections
I180522 16:16:00.268948 5818 server/server.go:1359  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180522 16:16:00.451141 6678 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:46013
I180522 16:16:00.454321 6720 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:35581}
I180522 16:16:00.508029 5818 storage/stores.go:222  [n?] read 0 node addresses from persistent storage
I180522 16:16:00.508516 5818 storage/stores.go:241  [n?] wrote 3 node addresses to persistent storage
I180522 16:16:00.508661 5818 server/node.go:647  [n?] connecting to gossip network to verify cluster ID...
I180522 16:16:00.508855 5818 server/node.go:672  [n?] node connected via gossip and verified as part of cluster "2df383bd-817e-4a03-ac9a-12d87ceba32d"
I180522 16:16:00.525039 5818 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180522 16:16:00.532674 5818 server/node.go:347  [n?] new node allocated ID 4
I180522 16:16:00.533320 5818 gossip/gossip.go:333  [n4] NodeDescriptor set to node_id:4 address:<network_field:"tcp" address_field:"127.0.0.1:35581" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:4 > 
I180522 16:16:00.534109 5818 server/node.go:421  [n4] node=4: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180522 16:16:00.534762 5818 server/node.go:440  [n4] node=4: started with [] engine(s) and attributes []
I180522 16:16:00.537612 5818 server/server.go:1484  [n4] starting https server at 127.0.0.1:42697
I180522 16:16:00.537792 5818 server/server.go:1485  [n4] starting grpc/postgres server at 127.0.0.1:35581
I180522 16:16:00.537943 5818 server/server.go:1486  [n4] advertising CockroachDB node at 127.0.0.1:35581
I180522 16:16:00.571789 6804 storage/stores.go:241  [n1] wrote 3 node addresses to persistent storage
I180522 16:16:00.578346 5818 server/server.go:1563  [n4] done ensuring all necessary migrations have run
I180522 16:16:00.578522 5818 server/server.go:1566  [n4] serving sql connections
I180522 16:16:00.591406 6728 storage/stores.go:241  [n3] wrote 3 node addresses to persistent storage
I180522 16:16:00.592409 6807 storage/stores.go:241  [n2] wrote 3 node addresses to persistent storage
I180522 16:16:00.760977 6787 server/node.go:628  [n4] bootstrapped store [n4,s4]
I180522 16:16:00.784916 6761 sql/event_log.go:124  [n4] Event: "node_join", target: 4, info: {Descriptor:{NodeID:4 Address:{NetworkField:tcp AddressField:127.0.0.1:35581} Attrs: Locality: ServerVersion:2.0-4} ClusterID:2df383bd-817e-4a03-ac9a-12d87ceba32d StartedAt:1527005760534483535 LastUp:1527005760534483535}
I180522 16:16:00.853655 6759 server/server_update.go:66  [n4] no need to upgrade, cluster already at the newest version
I180522 16:16:01.321611 6963 sql/event_log.go:124  [n1,client=127.0.0.1:44532,user=root] Event: "create_database", target: 52, info: {DatabaseName:test Statement:CREATE DATABASE IF NOT EXISTS test User:root}
I180522 16:16:01.420710 6963 sql/event_log.go:124  [n1,client=127.0.0.1:44532,user=root] Event: "create_table", target: 53, info: {TableName:test.public."left" Statement:CREATE TABLE test.public."left" (num INT PRIMARY KEY) User:root}
I180522 16:16:01.740740 6963 sql/event_log.go:124  [n1,client=127.0.0.1:44532,user=root] Event: "create_table", target: 54, info: {TableName:test.public."right" Statement:CREATE TABLE test.public."right" (num INT PRIMARY KEY) User:root}
I180522 16:16:02.581310 6963 storage/replica_command.go:863  [n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /Table/54/1/1 [r2]
I180522 16:16:02.880179 6963 storage/replica_command.go:863  [n1,s1,r2/1:/{Table/54/1/1-Max}] initiating a split of this range at key /Table/54/1/2 [r3]
I180522 16:16:03.077863 6963 storage/replica_command.go:863  [n1,s1,r3/1:/{Table/54/1/2-Max}] initiating a split of this range at key /Table/54/1/3 [r4]
I180522 16:16:03.223149 6963 storage/replica_raftstorage.go:520  [n1,s1,r2/1:/Table/54/1/{1-2}] generated preemptive snapshot e83ca358 at index 15
I180522 16:16:03.489250 6963 storage/store_snapshot.go:605  [n1,s1,r2/1:/Table/54/1/{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 5, rate-limit: 2.0 MiB/sec, 4ms
I180522 16:16:03.492492 7052 storage/replica_raftstorage.go:730  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 15 (id=e83ca358, encoded size=2027, 1 rocksdb batches, 5 log entries)
I180522 16:16:03.521561 7052 storage/replica_raftstorage.go:736  [n2,s2,r2/?:/Table/54/1/{1-2}] applied preemptive snapshot in 29ms [clear=0ms batch=0ms entries=1ms commit=26ms]
I180522 16:16:03.530574 6963 storage/replica_command.go:1777  [n1,s1,r2/1:/Table/54/1/{1-2}] change replicas (ADD_REPLICA (n2,s2):2): read existing descriptor r2:/Table/54/1/{1-2} [(n1,s1):1, next=2]
I180522 16:16:03.636637 6963 storage/replica.go:3320  [n1,s1,r2/1:/Table/54/1/{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180522 16:16:03.692483 7080 storage/raft_transport.go:459  [n2] raft transport stream to node 1 established
I180522 16:16:03.733975 6303 storage/replica_proposal.go:202  [n2,s2,r2/2:/Table/54/1/{1-2}] new range lease repl=(n2,s2):2 seq=3 start=1527005763.699329692,0 epo=1 pro=1527005763.699343217,0 following repl=(n1,s1):1 seq=2 start=1527005755.959783839,0 exp=1527005769.487482333,0 pro=1527005760.487560595,0
I180522 16:16:03.791392 7110 storage/replica_command.go:1777  [n2,s2,r2/2:/Table/54/1/{1-2}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r2:/Table/54/1/{1-2} [(n1,s1):1, (n2,s2):2, next=3]
I180522 16:16:03.958288 7141 storage/replica.go:3320  [n2,s2,r2/2:/Table/54/1/{1-2}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n2,s2):2] next=3
I180522 16:16:03.973469 7009 storage/store.go:3508  [n1,s1,r2/1:/Table/54/1/{1-2}] added to replica GC queue (peer suggestion)
I180522 16:16:03.991100 6963 storage/replica_raftstorage.go:520  [n1,s1,r4/1:/{Table/54/1/3-Max}] generated preemptive snapshot d6375b6e at index 13
I180522 16:16:04.011957 7030 storage/store.go:2492  [replicaGC,n1,s1,r2/1:/Table/54/1/{1-2}] removing replica
I180522 16:16:04.015666 7030 storage/replica.go:829  [replicaGC,n1,s1,r2/1:/Table/54/1/{1-2}] removed 8 (1+7) keys in 3ms [clear=0ms commit=3ms]
I180522 16:16:04.227575 6963 storage/store_snapshot.go:605  [n1,s1,r4/1:/{Table/54/1/3-Max}] streamed snapshot to (n3,s3):?: kv pairs: 8, log entries: 3, rate-limit: 2.0 MiB/sec, 6ms
I180522 16:16:04.230640 7040 storage/replica_raftstorage.go:730  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 13 (id=d6375b6e, encoded size=647, 1 rocksdb batches, 3 log entries)
I180522 16:16:04.233451 7040 storage/replica_raftstorage.go:736  [n3,s3,r4/?:/{Table/54/1/3-Max}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I180522 16:16:04.237483 6963 storage/replica_command.go:1777  [n1,s1,r4/1:/{Table/54/1/3-Max}] change replicas (ADD_REPLICA (n3,s3):2): read existing descriptor r4:/{Table/54/1/3-Max} [(n1,s1):1, next=2]
I180522 16:16:04.287272 6963 storage/replica.go:3320  [n1,s1,r4/1:/{Table/54/1/3-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180522 16:16:04.345391 7131 storage/raft_transport.go:459  [n3] raft transport stream to node 1 established
I180522 16:16:04.374469 6458 storage/replica_proposal.go:202  [n3,s3,r4/2:/{Table/54/1/3-Max}] new range lease repl=(n3,s3):2 seq=3 start=1527005764.302290276,0 epo=1 pro=1527005764.302306136,0 following repl=(n1,s1):1 seq=2 start=1527005755.959783839,0 exp=1527005769.487482333,0 pro=1527005760.487560595,0
I180522 16:16:04.420367 7220 storage/replica_command.go:1777  [n3,s3,r4/2:/{Table/54/1/3-Max}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r4:/{Table/54/1/3-Max} [(n1,s1):1, (n3,s3):2, next=3]
I180522 16:16:04.549108 7191 storage/replica.go:3320  [n3,s3,r4/2:/{Table/54/1/3-Max}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n3,s3):2] next=3
I180522 16:16:04.630457 7099 storage/store.go:3508  [n1,s1,r4/1:/{Table/54/1/3-Max}] added to replica GC queue (peer suggestion)
I180522 16:16:04.637075 7145 storage/store.go:2492  [replicaGC,n1,s1,r4/1:/{Table/54/1/3-Max}] removing replica
I180522 16:16:04.641565 7145 storage/replica.go:829  [replicaGC,n1,s1,r4/1:/{Table/54/1/3-Max}] removed 8 (1+7) keys in 2ms [clear=0ms commit=2ms]
I180522 16:16:05.067619 7259 util/stop/stopper.go:471  quiescing; tasks left:
1      [async] transport racer
I180522 16:16:05.069550 5777 kv/transport_race.go:67  transport race promotion: ran 58 iterations on up to 621 requests
W180522 16:16:05.081284 7131 storage/raft_transport.go:465  [n3] raft transport stream to node 1 failed: EOF
W180522 16:16:05.085337 7080 storage/raft_transport.go:465  [n2] raft transport stream to node 1 failed: rpc error: code = Unavailable desc = transport is closing
W180522 16:16:05.086043 7007 storage/raft_transport.go:465  [n1] raft transport stream to node 2 failed: rpc error: code = FailedPrecondition desc = grpc: the client connection is closing
W180522 16:16:05.087411 7086 storage/raft_transport.go:465  [n1] raft transport stream to node 3 failed: rpc error: code = Unavailable desc = transport is closing
W180522 16:16:05.106118 6801 storage/node_liveness.go:465  [n4,hb] failed node liveness heartbeat: node unavailable; try another peer
------- Stdout: -------
I180522 16:06:25.106246 5244 server/server.go:783  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180522 16:06:25.113470 5244 server/config.go:539  [n?] 1 storage engine initialized
I180522 16:06:25.113500 5244 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180522 16:06:25.113511 5244 server/config.go:542  [n?] store 0: in-memory, size 0 B
I180522 16:06:25.120647 5244 server/node.go:376  [n?] **** cluster d62779e6-8d23-458d-97b3-bc46fd8bbd34 has been created
I180522 16:06:25.120680 5244 server/server.go:1357  [n?] **** add additional nodes by specifying --join=127.0.0.1:35769
I180522 16:06:25.121370 5244 storage/store.go:1450  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180522 16:06:25.121435 5244 server/node.go:506  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=0, writes=0.00, bytesPerReplica={p10=7043.00 p25=7043.00 p50=7043.00 p75=7043.00 p90=7043.00 pMax=7043.00}, writesPerReplica={p10=0.00 p25=0.00 p50=0.00 p75=0.00 p90=0.00 pMax=0.00}
I180522 16:06:25.121471 5244 server/node.go:354  [n1] node ID 1 initialized
I180522 16:06:25.121530 5244 gossip/gossip.go:333  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:35769" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:4 > 
I180522 16:06:25.124543 5244 storage/stores.go:222  [n1] read 0 node addresses from persistent storage
I180522 16:06:25.124682 5244 server/node.go:647  [n1] connecting to gossip network to verify cluster ID...
I180522 16:06:25.124731 5244 server/node.go:672  [n1] node connected via gossip and verified as part of cluster "d62779e6-8d23-458d-97b3-bc46fd8bbd34"
I180522 16:06:25.124795 5244 server/node.go:440  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180522 16:06:25.124951 5244 server/server.go:1484  [n1] starting https server at 127.0.0.1:40491
I180522 16:06:25.124993 5244 server/server.go:1485  [n1] starting grpc/postgres server at 127.0.0.1:35769
I180522 16:06:25.125019 5244 server/server.go:1486  [n1] advertising CockroachDB node at 127.0.0.1:35769
I180522 16:06:25.143404 5518 sql/event_log.go:124  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180522 16:06:25.158064 5521 sql/event_log.go:124  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
I180522 16:06:25.165669 5543 sql/event_log.go:124  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180522 16:06:25.178746 5553 sql/event_log.go:124  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:root}
I180522 16:06:25.186061 5559 sql/event_log.go:124  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I180522 16:06:25.190017 5563 sql/event_log.go:124  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I180522 16:06:25.190767 5244 server/server.go:1563  [n1] done ensuring all necessary migrations have run
I180522 16:06:25.190825 5244 server/server.go:1566  [n1] serving sql connections
I180522 16:06:25.196974 5567 server/server_update.go:66  [n1] no need to upgrade, cluster already at the newest version
I180522 16:06:25.197519 5569 sql/event_log.go:124  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:35769} Attrs: Locality: ServerVersion:2.0-4} ClusterID:d62779e6-8d23-458d-97b3-bc46fd8bbd34 StartedAt:1527005185124746323 LastUp:1527005185124746323}
I180522 16:06:25.204873 5244 server/server.go:783  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180522 16:06:25.214953 5244 server/config.go:539  [n?] 1 storage engine initialized
I180522 16:06:25.215028 5244 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180522 16:06:25.215059 5244 server/config.go:542  [n?] store 0: in-memory, size 0 B
W180522 16:06:25.215178 5244 gossip/gossip.go:1293  [n?] no incoming or outgoing connections
I180522 16:06:25.215256 5244 server/server.go:1359  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180522 16:06:25.227188 5578 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:35769
I180522 16:06:25.227788 5653 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:40965}
I180522 16:06:25.228659 5244 storage/stores.go:222  [n?] read 0 node addresses from persistent storage
I180522 16:06:25.228708 5244 server/node.go:647  [n?] connecting to gossip network to verify cluster ID...
I180522 16:06:25.228736 5244 server/node.go:672  [n?] node connected via gossip and verified as part of cluster "d62779e6-8d23-458d-97b3-bc46fd8bbd34"
I180522 16:06:25.228888 5658 storage/stores.go:241  [n?] wrote 1 node addresses to persistent storage
I180522 16:06:25.230982 5244 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180522 16:06:25.231967 5244 server/node.go:347  [n?] new node allocated ID 2
I180522 16:06:25.232040 5244 gossip/gossip.go:333  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:40965" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:4 > 
I180522 16:06:25.232116 5244 server/node.go:421  [n2] node=2: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180522 16:06:25.232172 5244 server/node.go:440  [n2] node=2: started with [] engine(s) and attributes []
I180522 16:06:25.232272 5244 server/server.go:1484  [n2] starting https server at 127.0.0.1:41673
I180522 16:06:25.232290 5244 server/server.go:1485  [n2] starting grpc/postgres server at 127.0.0.1:40965
I180522 16:06:25.232304 5244 server/server.go:1486  [n2] advertising CockroachDB node at 127.0.0.1:40965
I180522 16:06:25.237745 5695 storage/stores.go:241  [n1] wrote 1 node addresses to persistent storage
I180522 16:06:25.240958 5244 server/server.go:1563  [n2] done ensuring all necessary migrations have run
I180522 16:06:25.241400 5244 server/server.go:1566  [n2] serving sql connections
I180522 16:06:25.241242 5675 server/node.go:628  [n2] bootstrapped store [n2,s2]
I180522 16:06:25.300382 5128 sql/event_log.go:124  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:40965} Attrs: Locality: ServerVersion:2.0-4} ClusterID:d62779e6-8d23-458d-97b3-bc46fd8bbd34 StartedAt:1527005185232155803 LastUp:1527005185232155803}
I180522 16:06:25.304317 5244 server/server.go:783  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180522 16:06:25.304518 5126 server/server_update.go:66  [n2] no need to upgrade, cluster already at the newest version
I180522 16:06:25.306790 5244 server/config.go:539  [n?] 1 storage engine initialized
I180522 16:06:25.306856 5244 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180522 16:06:25.306891 5244 server/config.go:542  [n?] store 0: in-memory, size 0 B
W180522 16:06:25.306990 5244 gossip/gossip.go:1293  [n?] no incoming or outgoing connections
I180522 16:06:25.307060 5244 server/server.go:1359  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180522 16:06:25.325937 5838 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:35769
I180522 16:06:25.326389 5806 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:35529}
I180522 16:06:25.327265 5244 storage/stores.go:222  [n?] read 0 node addresses from persistent storage
I180522 16:06:25.327308 5244 server/node.go:647  [n?] connecting to gossip network to verify cluster ID...
I180522 16:06:25.327336 5244 server/node.go:672  [n?] node connected via gossip and verified as part of cluster "d62779e6-8d23-458d-97b3-bc46fd8bbd34"
I180522 16:06:25.327461 5926 storage/stores.go:241  [n?] wrote 1 node addresses to persistent storage
I180522 16:06:25.327653 5926 storage/stores.go:241  [n?] wrote 2 node addresses to persistent storage
I180522 16:06:25.331032 5244 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180522 16:06:25.332162 5244 server/node.go:347  [n?] new node allocated ID 3
I180522 16:06:25.332283 5244 gossip/gossip.go:333  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:35529" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:4 > 
I180522 16:06:25.332369 5244 server/node.go:421  [n3] node=3: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180522 16:06:25.332426 5244 server/node.go:440  [n3] node=3: started with [] engine(s) and attributes []
I180522 16:06:25.332594 5244 server/server.go:1484  [n3] starting https server at 127.0.0.1:33669
I180522 16:06:25.332663 5244 server/server.go:1485  [n3] starting grpc/postgres server at 127.0.0.1:35529
I180522 16:06:25.332698 5244 server/server.go:1486  [n3] advertising CockroachDB node at 127.0.0.1:35529
I180522 16:06:25.338352 5702 storage/stores.go:241  [n1] wrote 2 node addresses to persistent storage
I180522 16:06:25.338952 5941 server/node.go:628  [n3] bootstrapped store [n3,s3]
I180522 16:06:25.339095 5244 server/server.go:1563  [n3] done ensuring all necessary migrations have run
I180522 16:06:25.349235 5244 server/server.go:1566  [n3] serving sql connections
I180522 16:06:25.352647 6052 storage/stores.go:241  [n2] wrote 2 node addresses to persistent storage
I180522 16:06:25.355654 5135 storage/replica_consistency.go:129  [replica consistency checker,n1,s1,r1/1:/M{in-ax}] triggering stats recomputation to resolve delta of {ContainsEstimates:true LastUpdateNanos:1527005185242352540 IntentAge:0 GCBytesAge:0 LiveBytes:-32122 LiveCount:-694 KeyBytes:-31938 KeyCount:-694 ValBytes:-184 ValCount:-694 IntentBytes:0 IntentCount:0 SysBytes:0 SysCount:0}
I180522 16:06:25.380785 5244 server/server.go:783  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180522 16:06:25.392526 5706 server/server_update.go:66  [n3] no need to upgrade, cluster already at the newest version
I180522 16:06:25.392583 5244 server/config.go:539  [n?] 1 storage engine initialized
I180522 16:06:25.392602 5244 server/config.go:542  [n?] RocksDB cache size: 128 MiB
I180522 16:06:25.392613 5244 server/config.go:542  [n?] store 0: in-memory, size 0 B
I180522 16:06:25.392638 5708 sql/event_log.go:124  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:35529} Attrs: Locality: ServerVersion:2.0-4} ClusterID:d62779e6-8d23-458d-97b3-bc46fd8bbd34 StartedAt:1527005185332410694 LastUp:1527005185332410694}
W180522 16:06:25.392677 5244 gossip/gossip.go:1293  [n?] no incoming or outgoing connections
I180522 16:06:25.392728 5244 server/server.go:1359  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180522 16:06:25.406816 6118 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:35769
I180522 16:06:25.407329 6144 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:41263}
I180522 16:06:25.408333 5244 storage/stores.go:222  [n?] read 0 node addresses from persistent storage
I180522 16:06:25.408382 5244 server/node.go:647  [n?] connecting to gossip network to verify cluster ID...
I180522 16:06:25.408421 5244 server/node.go:672  [n?] node connected via gossip and verified as part of cluster "d62779e6-8d23-458d-97b3-bc46fd8bbd34"
I180522 16:06:25.409024 6145 storage/stores.go:241  [n?] wrote 1 node addresses to persistent storage
I180522 16:06:25.409165 6145 storage/stores.go:241  [n?] wrote 2 node addresses to persistent storage
I180522 16:06:25.409238 6145 storage/stores.go:241  [n?] wrote 3 node addresses to persistent storage
I180522 16:06:25.414982 5244 kv/dist_sender.go:368  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180522 16:06:25.415964 5244 server/node.go:347  [n?] new node allocated ID 4
I180522 16:06:25.416109 5244 gossip/gossip.go:333  [n4] NodeDescriptor set to node_id:4 address:<network_field:"tcp" address_field:"127.0.0.1:41263" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:4 > 
I180522 16:06:25.416787 6089 storage/stores.go:241  [n1] wrote 3 node addresses to persistent storage
I180522 16:06:25.417180 5968 storage/stores.go:241  [n2] wrote 3 node addresses to persistent storage
I180522 16:06:25.417219 5914 storage/stores.go:241  [n3] wrote 3 node addresses to persistent storage
I180522 16:06:25.417256 5244 server/node.go:421  [n4] node=4: asynchronously bootstrapping engine(s) [<no-attributes>=<in-mem>]
I180522 16:06:25.417291 5244 server/node.go:440  [n4] node=4: started with [] engine(s) and attributes []
I180522 16:06:25.418922 5244 server/server.go:1484  [n4] starting https server at 127.0.0.1:37569
I180522 16:06:25.418954 5244 server/server.go:1485  [n4] starting grpc/postgres server at 127.0.0.1:41263
I180522 16:06:25.418972 5244 server/server.go:1486  [n4] advertising CockroachDB node at 127.0.0.1:41263
I180522 16:06:25.419672 5244 server/server.go:1563  [n4] done ensuring all necessary migrations have run
I180522 16:06:25.419707 5244 server/server.go:1566  [n4] serving sql connections
I180522 16:06:25.418467 6179 server/node.go:628  [n4] bootstrapped store [n4,s4]
I180522 16:06:25.465388 6283 sql/event_log.go:124  [n1,client=127.0.0.1:60920,user=root] Event: "create_database", target: 52, info: {DatabaseName:test Statement:CREATE DATABASE IF NOT EXISTS test User:root}
I180522 16:06:25.470468 6185 sql/event_log.go:124  [n4] Event: "node_join", target: 4, info: {Descriptor:{NodeID:4 Address:{NetworkField:tcp AddressField:127.0.0.1:41263} Attrs: Locality: ServerVersion:2.0-4} ClusterID:d62779e6-8d23-458d-97b3-bc46fd8bbd34 StartedAt:1527005185417274513 LastUp:1527005185417274513}
I180522 16:06:25.475362 6183 server/server_update.go:66  [n4] no need to upgrade, cluster already at the newest version
I180522 16:06:25.479800 6283 sql/event_log.go:124  [n1,client=127.0.0.1:60920,user=root] Event: "create_table", target: 53, info: {TableName:test.public."left" Statement:CREATE TABLE test.public."left" (num INT PRIMARY KEY) User:root}
I180522 16:06:25.488830 6283 sql/event_log.go:124  [n1,client=127.0.0.1:60920,user=root] Event: "create_table", target: 54, info: {TableName:test.public."right" Statement:CREATE TABLE test.public."right" (num INT PRIMARY KEY) User:root}
I180522 16:06:25.530027 6283 storage/replica_command.go:863  [n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /Table/54/1/1 [r2]
I180522 16:06:25.545017 6283 storage/replica_command.go:863  [n1,s1,r2/1:/{Table/54/1/1-Max}] initiating a split of this range at key /Table/54/1/2 [r3]
I180522 16:06:25.550291 6283 storage/replica_command.go:863  [n1,s1,r3/1:/{Table/54/1/2-Max}] initiating a split of this range at key /Table/54/1/3 [r4]
I180522 16:06:25.557750 6283 storage/replica_raftstorage.go:520  [n1,s1,r2/1:/Table/54/1/{1-2}] generated preemptive snapshot 4b8e8b15 at index 15
I180522 16:06:25.573935 6283 storage/store_snapshot.go:605  [n1,s1,r2/1:/Table/54/1/{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 5, rate-limit: 2.0 MiB/sec, 1ms
I180522 16:06:25.574250 6383 storage/replica_raftstorage.go:730  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 15 (id=4b8e8b15, encoded size=2027, 1 rocksdb batches, 5 log entries)
I18

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the 2.1 milestone May 22, 2018
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels May 22, 2018
@tbg tbg added the A-sql-execution Relating to SQL execution. label May 22, 2018
@jordanlewis jordanlewis assigned asubiotto and unassigned jordanlewis Oct 9, 2018
@jordanlewis jordanlewis mentioned this issue Oct 9, 2018
Closed
@asubiotto
Copy link
Contributor

Attempts to reproduce this on a gceworker running stressrace on either master or release-2.1 haven't succeeded so far (running for 20 mins).

@asubiotto
Copy link
Contributor

Still haven't managed to reproduce this.

So it seems that this test is testing that misplanned TableReaders return metadata about misplanned ranges and that's taken into account in a subsequent query. My suspicion is that in very rare cases we're not "misplanning" tableReaders because the EXPERIMENTAL_RELOCATE hasn't happened yet. We've seen other instances of certain planning expectations breaking because of some race with EXPERIMENTAL_RELOCATE. @RaduBerinde, what are the guarantees of EXPERIMENTAL_RELOCATE? I can't find any documentation on it.

The flakiness in this test could be fixed by verifying data placement before running the first query.

@RaduBerinde
Copy link
Member

RELOCATE is supposed to return only after things have been relocated. We have various logic tests that rely on this: https://github.com/cockroachdb/cockroach/blob/master/pkg/sql/logictest/testdata/planner_test/distsql_agg#L14

CCing @tschottdorf @a-robinson who might know of some caveats here. Also CC @m-schneider who was asking the same thing.

@RaduBerinde
Copy link
Member

Also see #31068.

@a-robinson
Copy link
Contributor

Sorry for missing this. The RelocateRange mini-rewrite from #29684 seems to have made it so that the new range locations aren't always cached in the DistSender when the RELOCATE is done. The ranges and leases are all in the right places, but the locations may not be cached yet. Some of the logic tests have been fixed by adding a "verification" query that ensures all ranges/leases are in the right place, which has the nice side effect of also caching them all in the DistSender.

See #31068 and #31013 for additional detail.

@jordanlewis
Copy link
Member

The flakiness in this test could be fixed by verifying data placement before running the first query.

Seems like this is the way to go.

@jordanlewis jordanlewis mentioned this issue Oct 11, 2018
Merged
craig bot pushed a commit that referenced this issue Oct 11, 2018
@tbg @jordanlewis
Merge #30913 #31239
cb0246b 
30913: server: add a configuration to enable GC of system.rangelog r=tschottdorf a=mvijaykarthik

system.rangelog table currently grows unboundedly. The rate of
growth is slow (as long as there is no replica rebalancing
thrashing), but it can still become a problem in long running
clusters.

This commit adds cluster settings to specify interval and TTL
for rows in system.rangelog.
By default, TTL of system.rangelog is set to 30 days.

Fixes #21260

Release note: Add configuration to enable GC of system.rangelog

31239: sql: attempt to deflake distsql physical planner tests r=tschottdorf a=jordanlewis

Make sure the range cache is populated before verifying things about it.

This seems like a hack, but otherwise I think these will just keep flaking.

Closes #25808.
Closes #31235.

Release note: None

Co-authored-by: Tobias Schottdorf <[email protected]>
Co-authored-by: Jordan Lewis <[email protected]>
@craig craig bot closed this as completed in #31239 Oct 11, 2018
@asubiotto asubiotto mentioned this issue Oct 11, 2018
Closed
@tbg tbg mentioned this issue Oct 11, 2018
Merged
craig bot pushed a commit that referenced this issue Oct 11, 2018
@jordanlewis
Merge #31285
00413b0 
31285: backport-2.1: sql: attempt to deflake distsql physical planner tests r=jordanlewis a=tschottdorf

Backport 1/1 commits from #31239.

Flaky as hell on release-2.1. Someone please ~~bors~~merge this for me with the LGTM.

/cc @cockroachdb/release

---

Make sure the range cache is populated before verifying things about it.

This seems like a hack, but otherwise I think these will just keep flaking.

Closes #25808.
Closes #31235.

Release note: None


Co-authored-by: Jordan Lewis <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@asubiotto asubiotto

Labels
A-sql-execution Relating to SQL execution. 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
6 participants
@jordanlewis @tbg @a-robinson @asubiotto @RaduBerinde @cockroach-teamcity