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 #28491

Closed
cockroach-teamcity opened this issue Aug 11, 2018 · 1 comment
Closed

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

cockroach-teamcity opened this issue Aug 11, 2018 · 1 comment
Assignees
@jordanlewis
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:

#830114:

--- FAIL: testrace/TestDistSQLRangeCachesIntegrationTest (10.110s)
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+)","ON @1 = @2","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: -------
W180811 20:02:27.483681 5655 server/status/runtime.go:287  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180811 20:02:27.670140 5655 server/server.go:812  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180811 20:02:27.679933 5655 server/config.go:492  [n?] 1 storage engine initialized
I180811 20:02:27.680076 5655 server/config.go:495  [n?] RocksDB cache size: 128 MiB
I180811 20:02:27.680124 5655 server/config.go:495  [n?] store 0: in-memory, size 0 B
I180811 20:02:27.823831 5655 server/node.go:373  [n?] **** cluster 52b78f9b-105b-4d7d-85f1-cabed3ff25e9 has been created
I180811 20:02:27.824015 5655 server/server.go:1387  [n?] **** add additional nodes by specifying --join=127.0.0.1:44173
I180811 20:02:27.825071 5655 gossip/gossip.go:363  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:44173" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:11 > build_tag:"v2.1.0-alpha.20180702-1439-g3dcc979" started_at:1534017747824715992 
I180811 20:02:27.843682 5655 storage/store.go:1501  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180811 20:02:27.846161 5655 server/node.go:475  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=0, queries=0.00, 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}
I180811 20:02:27.846616 5655 storage/stores.go:222  [n1] read 0 node addresses from persistent storage
I180811 20:02:27.847186 5655 server/node.go:696  [n1] connecting to gossip network to verify cluster ID...
I180811 20:02:27.847384 5655 server/node.go:721  [n1] node connected via gossip and verified as part of cluster "52b78f9b-105b-4d7d-85f1-cabed3ff25e9"
I180811 20:02:27.847817 5655 server/node.go:545  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180811 20:02:27.849007 5655 server/status/recorder.go:652  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:27.849091 5655 server/server.go:1818  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180811 20:02:27.851483 5655 server/server.go:1523  [n1] starting https server at 127.0.0.1:37361
I180811 20:02:27.855050 5655 server/server.go:1524  [n1] starting grpc/postgres server at 127.0.0.1:44173
I180811 20:02:27.855164 5655 server/server.go:1525  [n1] advertising CockroachDB node at 127.0.0.1:44173
W180811 20:02:27.855520 5655 jobs/registry.go:299  [n1] unable to get node liveness: node not in the liveness table
I180811 20:02:27.857134 5880 server/status/recorder.go:652  [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:28.259086 5865 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180811 20:02:28.587385 5645 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
I180811 20:02:28.813538 5776 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180811 20:02:29.151977 5894 rpc/nodedialer/nodedialer.go:92  [replica consistency checker,n1,s1,r1/1:/M{in-ax}] connection to n1 established
I180811 20:02:29.163681 5672 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:1534017748912203925 IntentAge:0 GCBytesAge:0 LiveBytes:-21820 LiveCount:-456 KeyBytes:-21238 KeyCount:-456 ValBytes:-582 ValCount:-456 IntentBytes:0 IntentCount:0 SysBytes:0 SysCount:0}
I180811 20:02:29.206196 5869 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:root}
I180811 20:02:29.363087 5872 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I180811 20:02:29.517103 5930 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I180811 20:02:29.563733 5655 server/server.go:1607  [n1] done ensuring all necessary migrations have run
I180811 20:02:29.563955 5655 server/server.go:1610  [n1] serving sql connections
I180811 20:02:29.627435 5913 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:44173} Attrs: Locality: ServerVersion:2.0-11 BuildTag:v2.1.0-alpha.20180702-1439-g3dcc979 StartedAt:1534017747824715992} ClusterID:52b78f9b-105b-4d7d-85f1-cabed3ff25e9 StartedAt:1534017747824715992 LastUp:1534017747824715992}
I180811 20:02:29.630419 5911 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
W180811 20:02:29.811937 5655 server/status/runtime.go:287  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180811 20:02:30.152742 5655 server/server.go:812  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180811 20:02:30.158775 5655 server/config.go:492  [n?] 1 storage engine initialized
I180811 20:02:30.173217 5655 server/config.go:495  [n?] RocksDB cache size: 128 MiB
I180811 20:02:30.173358 5655 server/config.go:495  [n?] store 0: in-memory, size 0 B
W180811 20:02:30.173898 5655 gossip/gossip.go:1325  [n?] no incoming or outgoing connections
I180811 20:02:30.180905 5655 server/server.go:1389  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180811 20:02:30.348217 6005 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:45399}
I180811 20:02:30.350549 5898 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:44173
I180811 20:02:30.357274 5655 server/node.go:696  [n?] connecting to gossip network to verify cluster ID...
I180811 20:02:30.357550 5655 server/node.go:721  [n?] node connected via gossip and verified as part of cluster "52b78f9b-105b-4d7d-85f1-cabed3ff25e9"
I180811 20:02:30.360321 6008 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:30.377587 6007 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:30.382840 5655 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:30.401197 5655 server/node.go:427  [n?] new node allocated ID 2
I180811 20:02:30.401753 5655 gossip/gossip.go:363  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:45399" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:11 > build_tag:"v2.1.0-alpha.20180702-1439-g3dcc979" started_at:1534017750401358843 
I180811 20:02:30.402681 5655 storage/stores.go:222  [n2] read 0 node addresses from persistent storage
I180811 20:02:30.403031 5655 storage/stores.go:241  [n2] wrote 1 node addresses to persistent storage
I180811 20:02:30.408263 5678 storage/stores.go:241  [n1] wrote 1 node addresses to persistent storage
I180811 20:02:30.484717 5655 server/node.go:671  [n2] bootstrapped store [n2,s2]
I180811 20:02:30.487199 5655 server/node.go:545  [n2] node=2: started with [] engine(s) and attributes []
I180811 20:02:30.495347 5655 server/status/recorder.go:652  [n2] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:30.495550 5655 server/server.go:1818  [n2] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180811 20:02:30.497032 6155 server/status/recorder.go:652  [n2,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:30.499154 5655 server/server.go:1523  [n2] starting https server at 127.0.0.1:36605
I180811 20:02:30.501194 5655 server/server.go:1524  [n2] starting grpc/postgres server at 127.0.0.1:45399
I180811 20:02:30.501293 5655 server/server.go:1525  [n2] advertising CockroachDB node at 127.0.0.1:45399
I180811 20:02:30.550724 5655 server/server.go:1607  [n2] done ensuring all necessary migrations have run
I180811 20:02:30.550960 5655 server/server.go:1610  [n2] serving sql connections
I180811 20:02:30.792721 5679 server/server_update.go:67  [n2] no need to upgrade, cluster already at the newest version
I180811 20:02:30.808390 5681 sql/event_log.go:126  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:45399} Attrs: Locality: ServerVersion:2.0-11 BuildTag:v2.1.0-alpha.20180702-1439-g3dcc979 StartedAt:1534017750401358843} ClusterID:52b78f9b-105b-4d7d-85f1-cabed3ff25e9 StartedAt:1534017750401358843 LastUp:1534017750401358843}
W180811 20:02:30.837452 5655 server/status/runtime.go:287  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180811 20:02:31.120011 5655 server/server.go:812  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180811 20:02:31.147055 5655 server/config.go:492  [n?] 1 storage engine initialized
I180811 20:02:31.147187 5655 server/config.go:495  [n?] RocksDB cache size: 128 MiB
I180811 20:02:31.147226 5655 server/config.go:495  [n?] store 0: in-memory, size 0 B
W180811 20:02:31.147510 5655 gossip/gossip.go:1325  [n?] no incoming or outgoing connections
I180811 20:02:31.197418 5655 server/server.go:1389  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180811 20:02:31.433887 6199 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:44173
I180811 20:02:31.434749 6207 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:36631}
I180811 20:02:31.447782 5655 server/node.go:696  [n?] connecting to gossip network to verify cluster ID...
I180811 20:02:31.448092 5655 server/node.go:721  [n?] node connected via gossip and verified as part of cluster "52b78f9b-105b-4d7d-85f1-cabed3ff25e9"
I180811 20:02:31.453760 6274 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:31.462040 6209 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:31.468383 5655 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:31.485467 5655 server/node.go:427  [n?] new node allocated ID 3
I180811 20:02:31.486171 5655 gossip/gossip.go:363  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:36631" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:11 > build_tag:"v2.1.0-alpha.20180702-1439-g3dcc979" started_at:1534017751485760454 
I180811 20:02:31.487106 5655 storage/stores.go:222  [n3] read 0 node addresses from persistent storage
I180811 20:02:31.487511 5655 storage/stores.go:241  [n3] wrote 2 node addresses to persistent storage
I180811 20:02:31.493024 6293 storage/stores.go:241  [n1] wrote 2 node addresses to persistent storage
I180811 20:02:31.500036 6176 storage/stores.go:241  [n2] wrote 2 node addresses to persistent storage
I180811 20:02:31.584993 5655 server/node.go:671  [n3] bootstrapped store [n3,s3]
I180811 20:02:31.586842 5655 server/node.go:545  [n3] node=3: started with [] engine(s) and attributes []
I180811 20:02:31.588211 5655 server/status/recorder.go:652  [n3] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:31.588316 5655 server/server.go:1818  [n3] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180811 20:02:31.605307 6352 server/status/recorder.go:652  [n3,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:31.607782 5655 server/server.go:1523  [n3] starting https server at 127.0.0.1:37769
I180811 20:02:31.613360 5655 server/server.go:1524  [n3] starting grpc/postgres server at 127.0.0.1:36631
I180811 20:02:31.613470 5655 server/server.go:1525  [n3] advertising CockroachDB node at 127.0.0.1:36631
I180811 20:02:31.635847 5655 server/server.go:1607  [n3] done ensuring all necessary migrations have run
I180811 20:02:31.636001 5655 server/server.go:1610  [n3] serving sql connections
W180811 20:02:32.001082 5655 server/status/runtime.go:287  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180811 20:02:32.039044 6420 sql/event_log.go:126  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:36631} Attrs: Locality: ServerVersion:2.0-11 BuildTag:v2.1.0-alpha.20180702-1439-g3dcc979 StartedAt:1534017751485760454} ClusterID:52b78f9b-105b-4d7d-85f1-cabed3ff25e9 StartedAt:1534017751485760454 LastUp:1534017751485760454}
I180811 20:02:32.091223 6418 server/server_update.go:67  [n3] no need to upgrade, cluster already at the newest version
I180811 20:02:32.220318 5655 server/server.go:812  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180811 20:02:32.233148 5655 server/config.go:492  [n?] 1 storage engine initialized
I180811 20:02:32.240910 5655 server/config.go:495  [n?] RocksDB cache size: 128 MiB
I180811 20:02:32.241076 5655 server/config.go:495  [n?] store 0: in-memory, size 0 B
W180811 20:02:32.241464 5655 gossip/gossip.go:1325  [n?] no incoming or outgoing connections
I180811 20:02:32.243093 5655 server/server.go:1389  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180811 20:02:32.518350 6471 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:44173
I180811 20:02:32.521741 6548 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:44115}
I180811 20:02:32.535491 5655 server/node.go:696  [n?] connecting to gossip network to verify cluster ID...
I180811 20:02:32.542922 5655 server/node.go:721  [n?] node connected via gossip and verified as part of cluster "52b78f9b-105b-4d7d-85f1-cabed3ff25e9"
I180811 20:02:32.546265 6570 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:32.552183 6569 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:32.582936 5655 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:32.616608 5655 server/node.go:427  [n?] new node allocated ID 4
I180811 20:02:32.617321 5655 gossip/gossip.go:363  [n4] NodeDescriptor set to node_id:4 address:<network_field:"tcp" address_field:"127.0.0.1:44115" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:11 > build_tag:"v2.1.0-alpha.20180702-1439-g3dcc979" started_at:1534017752616868381 
I180811 20:02:32.618309 5655 storage/stores.go:222  [n4] read 0 node addresses from persistent storage
I180811 20:02:32.618697 5655 storage/stores.go:241  [n4] wrote 3 node addresses to persistent storage
I180811 20:02:32.643802 6480 storage/stores.go:241  [n1] wrote 3 node addresses to persistent storage
I180811 20:02:32.670270 6533 storage/stores.go:241  [n3] wrote 3 node addresses to persistent storage
I180811 20:02:32.677806 6610 storage/stores.go:241  [n2] wrote 3 node addresses to persistent storage
I180811 20:02:32.692245 5655 server/node.go:671  [n4] bootstrapped store [n4,s4]
I180811 20:02:32.714654 5655 server/node.go:545  [n4] node=4: started with [] engine(s) and attributes []
I180811 20:02:32.718801 5655 server/status/recorder.go:652  [n4] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:32.719033 5655 server/server.go:1818  [n4] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180811 20:02:32.731547 6683 server/status/recorder.go:652  [n4,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:32.745227 5655 server/server.go:1523  [n4] starting https server at 127.0.0.1:36131
I180811 20:02:32.751202 5655 server/server.go:1524  [n4] starting grpc/postgres server at 127.0.0.1:44115
I180811 20:02:32.751345 5655 server/server.go:1525  [n4] advertising CockroachDB node at 127.0.0.1:44115
I180811 20:02:32.760151 5655 server/server.go:1607  [n4] done ensuring all necessary migrations have run
I180811 20:02:32.760331 5655 server/server.go:1610  [n4] serving sql connections
I180811 20:02:32.956023 6414 sql/event_log.go:126  [n4] Event: "node_join", target: 4, info: {Descriptor:{NodeID:4 Address:{NetworkField:tcp AddressField:127.0.0.1:44115} Attrs: Locality: ServerVersion:2.0-11 BuildTag:v2.1.0-alpha.20180702-1439-g3dcc979 StartedAt:1534017752616868381} ClusterID:52b78f9b-105b-4d7d-85f1-cabed3ff25e9 StartedAt:1534017752616868381 LastUp:1534017752616868381}
I180811 20:02:32.964884 6412 server/server_update.go:67  [n4] no need to upgrade, cluster already at the newest version
I180811 20:02:33.174318 6540 sql/event_log.go:126  [n1,client=127.0.0.1:60092,user=root] Event: "create_database", target: 52, info: {DatabaseName:test Statement:CREATE DATABASE IF NOT EXISTS test User:root}
I180811 20:02:33.360612 6540 sql/event_log.go:126  [n1,client=127.0.0.1:60092,user=root] Event: "create_table", target: 53, info: {TableName:test.public."left" Statement:CREATE TABLE test.public."left" (num INT PRIMARY KEY) User:root}
I180811 20:02:33.653888 6540 sql/event_log.go:126  [n1,client=127.0.0.1:60092,user=root] Event: "create_table", target: 54, info: {TableName:test.public."right" Statement:CREATE TABLE test.public."right" (num INT PRIMARY KEY) User:root}
I180811 20:02:34.229198 6455 rpc/nodedialer/nodedialer.go:92  [intExec=get-table-statistics] connection to n1 established
I180811 20:02:34.610731 6779 rpc/nodedialer/nodedialer.go:92  [n1] connection to n4 established
I180811 20:02:34.618388 6456 rpc/nodedialer/nodedialer.go:92  [n4,client=127.0.0.1:57702,user=root] connection to n1 established
I180811 20:02:34.623029 6720 rpc/nodedialer/nodedialer.go:92  [n1] connection to n4 established
I180811 20:02:34.669762 6540 storage/replica_command.go:280  [n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /Table/54/1/1 [r2]
I180811 20:02:34.951031 6540 storage/replica_command.go:280  [n1,s1,r2/1:/{Table/54/1/1-Max}] initiating a split of this range at key /Table/54/1/2 [r3]
I180811 20:02:35.141546 6540 storage/replica_command.go:280  [n1,s1,r3/1:/{Table/54/1/2-Max}] initiating a split of this range at key /Table/54/1/3 [r4]
I180811 20:02:35.273693 6540 storage/replica_raftstorage.go:521  [n1,s1,r2/1:/Table/54/1/{1-2}] generated preemptive snapshot cc1da9ad at index 16
I180811 20:02:35.538113 6540 rpc/nodedialer/nodedialer.go:92  [n1,s1,r2/1:/Table/54/1/{1-2}] connection to n2 established
I180811 20:02:35.567462 6540 storage/store_snapshot.go:641  [n1,s1,r2/1:/Table/54/1/{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 6, rate-limit: 2.0 MiB/sec, 29ms
I180811 20:02:35.570127 6892 storage/replica_raftstorage.go:758  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 16 (id=cc1da9ad, encoded size=2048, 1 rocksdb batches, 6 log entries)
I180811 20:02:35.572985 6892 storage/replica_raftstorage.go:764  [n2,s2,r2/?:/Table/54/1/{1-2}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180811 20:02:35.576864 6540 storage/replica_command.go:750  [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, gen=842353421504]
I180811 20:02:35.637734 6540 storage/replica.go:3637  [n1,s1,r2/1:/Table/54/1/{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180811 20:02:35.643287 6540 storage/replica_range_lease.go:554  [n1,s1,r2/1:/Table/54/1/{1-2}] transferring lease to s2
I180811 20:02:35.679597 6060 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180811 20:02:35.697172 6061 storage/replica_proposal.go:214  [n2,s2,r2/2:/Table/54/1/{1-2}] new range lease repl=(n2,s2):2 seq=3 start=1534017755.646021796,0 epo=1 pro=1534017755.646047560,0 following repl=(n1,s1):1 seq=2 start=1534017747.828825219,0 exp=1534017761.360786243,0 pro=1534017752.360839933,0
I180811 20:02:35.700543 6540 storage/replica_range_lease.go:617  [n1,s1,r2/1:/Table/54/1/{1-2}] done transferring lease to s2: <nil>
I180811 20:02:35.775085 6918 storage/replica_range_lease.go:554  [n2,s2,r2/2:/Table/54/1/{1-2}] transferring lease to s2
I180811 20:02:35.802610 6822 storage/replica_command.go:750  [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, gen=842369462984]
I180811 20:02:36.071086 6822 storage/replica.go:3637  [n2,s2,r2/2:/Table/54/1/{1-2}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n2,s2):2] next=3
I180811 20:02:36.089069 6869 storage/store.go:3648  [n1,s1,r2/1:/Table/54/1/{1-2}] added to replica GC queue (peer suggestion)
I180811 20:02:36.108143 6729 storage/store.go:2585  [replicaGC,n1,s1,r2/1:/Table/54/1/{1-2}] removing replica
I180811 20:02:36.111973 6729 storage/replica.go:846  [replicaGC,n1,s1,r2/1:/Table/54/1/{1-2}] removed 7 (1+6) keys in 3ms [clear=2ms commit=1ms]
I180811 20:02:36.121954 6540 storage/replica_range_lease.go:554  [n1,s1,r3/1:/Table/54/1/{2-3}] transferring lease to s1
I180811 20:02:36.125201 6540 storage/replica_raftstorage.go:521  [n1,s1,r4/1:/{Table/54/1/3-Max}] generated preemptive snapshot 135cf1ca at index 12
I180811 20:02:36.223914 6540 rpc/nodedialer/nodedialer.go:92  [n1,s1,r4/1:/{Table/54/1/3-Max}] connection to n3 established
I180811 20:02:36.228390 6540 storage/store_snapshot.go:641  [n1,s1,r4/1:/{Table/54/1/3-Max}] streamed snapshot to (n3,s3):?: kv pairs: 7, log entries: 2, rate-limit: 2.0 MiB/sec, 4ms
I180811 20:02:36.234482 6736 storage/replica_raftstorage.go:758  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 12 (id=135cf1ca, encoded size=355, 1 rocksdb batches, 2 log entries)
I180811 20:02:36.236537 6736 storage/replica_raftstorage.go:764  [n3,s3,r4/?:/{Table/54/1/3-Max}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180811 20:02:36.240608 6540 storage/replica_command.go:750  [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, gen=0]
I180811 20:02:36.361021 6540 storage/replica.go:3637  [n1,s1,r4/1:/{Table/54/1/3-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180811 20:02:36.391130 6540 storage/replica_range_lease.go:554  [n1,s1,r4/1:/{Table/54/1/3-Max}] transferring lease to s3
I180811 20:02:36.412332 6279 rpc/nodedialer/nodedialer.go:92  [n3] connection to n1 established
I180811 20:02:36.436248 6540 storage/replica_range_lease.go:617  [n1,s1,r4/1:/{Table/54/1/3-Max}] done transferring lease to s3: <nil>
I180811 20:02:36.448371 6281 storage/replica_proposal.go:214  [n3,s3,r4/2:/{Table/54/1/3-Max}] new range lease repl=(n3,s3):2 seq=3 start=1534017756.391315463,0 epo=1 pro=1534017756.391333750,0 following repl=(n1,s1):1 seq=2 start=1534017747.828825219,0 exp=1534017761.360786243,0 pro=1534017752.360839933,0
I180811 20:02:36.451425 6969 storage/replica_range_lease.go:554  [n3,s3,r4/2:/{Table/54/1/3-Max}] transferring lease to s3
I180811 20:02:36.493712 6926 storage/replica_command.go:750  [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, gen=0]
I180811 20:02:36.710358 6926 storage/replica.go:3637  [n3,s3,r4/2:/{Table/54/1/3-Max}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n3,s3):2] next=3
I180811 20:02:36.743529 6964 storage/store.go:3648  [n1,s1,r4/1:/{Table/54/1/3-Max}] added to replica GC queue (peer suggestion)
I180811 20:02:36.754015 6830 storage/store.go:2585  [replicaGC,n1,s1,r4/1:/{Table/54/1/3-Max}] removing replica
I180811 20:02:36.756920 6830 storage/replica.go:846  [replicaGC,n1,s1,r4/1:/{Table/54/1/3-Max}] removed 7 (1+6) keys in 1ms [clear=0ms commit=1ms]
I180811 20:02:37.161492 6457 rpc/nodedialer/nodedialer.go:92  [intExec=get-table-statistics] connection to n1 established
I180811 20:02:37.169986 7058 rpc/nodedialer/nodedialer.go:92  [n1] connection to n4 established
I180811 20:02:37.210062 6458 rpc/nodedialer/nodedialer.go:92  [n4,client=127.0.0.1:57702,user=root] connection to n1 established
I180811 20:02:37.215830 7049 rpc/nodedialer/nodedialer.go:92  [n1] connection to n4 established
I180811 20:02:37.303061 7012 util/stop/stopper.go:537  quiescing; tasks left:
1      node.Node: batch
1      [async] transport racer
I180811 20:02:37.324194 5659 kv/transport_race.go:67  transport race promotion: ran 19 iterations on up to 672 requests
W180811 20:02:37.332481 6870 storage/raft_transport.go:574  [n2] while processing outgoing Raft queue to node 1: rpc error: code = Unavailable desc = transport is closing:
W180811 20:02:37.348246 6940 storage/raft_transport.go:574  [n3] while processing outgoing Raft queue to node 1: rpc error: code = Canceled desc = grpc: the client connection is closing:
W180811 20:02:37.352487 6706 internal/client/txn.go:514  [n4,hb] failure aborting transaction: node unavailable; try another peer; abort caused by: node unavailable; try another peer
W180811 20:02:37.352893 6706 storage/node_liveness.go:494  [n4,hb] failed node liveness heartbeat: node unavailable; try another peer
--- FAIL: testrace/TestDistSQLRangeCachesIntegrationTest (10.850s)
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+)","ON @1 = @2","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: -------
W180811 20:02:27.483681 5655 server/status/runtime.go:287  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180811 20:02:27.670140 5655 server/server.go:812  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180811 20:02:27.679933 5655 server/config.go:492  [n?] 1 storage engine initialized
I180811 20:02:27.680076 5655 server/config.go:495  [n?] RocksDB cache size: 128 MiB
I180811 20:02:27.680124 5655 server/config.go:495  [n?] store 0: in-memory, size 0 B
I180811 20:02:27.823831 5655 server/node.go:373  [n?] **** cluster 52b78f9b-105b-4d7d-85f1-cabed3ff25e9 has been created
I180811 20:02:27.824015 5655 server/server.go:1387  [n?] **** add additional nodes by specifying --join=127.0.0.1:44173
I180811 20:02:27.825071 5655 gossip/gossip.go:363  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:44173" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:11 > build_tag:"v2.1.0-alpha.20180702-1439-g3dcc979" started_at:1534017747824715992 
I180811 20:02:27.843682 5655 storage/store.go:1501  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180811 20:02:27.846161 5655 server/node.go:475  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=0, queries=0.00, 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}
I180811 20:02:27.846616 5655 storage/stores.go:222  [n1] read 0 node addresses from persistent storage
I180811 20:02:27.847186 5655 server/node.go:696  [n1] connecting to gossip network to verify cluster ID...
I180811 20:02:27.847384 5655 server/node.go:721  [n1] node connected via gossip and verified as part of cluster "52b78f9b-105b-4d7d-85f1-cabed3ff25e9"
I180811 20:02:27.847817 5655 server/node.go:545  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180811 20:02:27.849007 5655 server/status/recorder.go:652  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:27.849091 5655 server/server.go:1818  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180811 20:02:27.851483 5655 server/server.go:1523  [n1] starting https server at 127.0.0.1:37361
I180811 20:02:27.855050 5655 server/server.go:1524  [n1] starting grpc/postgres server at 127.0.0.1:44173
I180811 20:02:27.855164 5655 server/server.go:1525  [n1] advertising CockroachDB node at 127.0.0.1:44173
W180811 20:02:27.855520 5655 jobs/registry.go:299  [n1] unable to get node liveness: node not in the liveness table
I180811 20:02:27.857134 5880 server/status/recorder.go:652  [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:28.259086 5865 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180811 20:02:28.587385 5645 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
I180811 20:02:28.813538 5776 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180811 20:02:29.151977 5894 rpc/nodedialer/nodedialer.go:92  [replica consistency checker,n1,s1,r1/1:/M{in-ax}] connection to n1 established
I180811 20:02:29.163681 5672 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:1534017748912203925 IntentAge:0 GCBytesAge:0 LiveBytes:-21820 LiveCount:-456 KeyBytes:-21238 KeyCount:-456 ValBytes:-582 ValCount:-456 IntentBytes:0 IntentCount:0 SysBytes:0 SysCount:0}
I180811 20:02:29.206196 5869 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:root}
I180811 20:02:29.363087 5872 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I180811 20:02:29.517103 5930 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I180811 20:02:29.563733 5655 server/server.go:1607  [n1] done ensuring all necessary migrations have run
I180811 20:02:29.563955 5655 server/server.go:1610  [n1] serving sql connections
I180811 20:02:29.627435 5913 sql/event_log.go:126  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:44173} Attrs: Locality: ServerVersion:2.0-11 BuildTag:v2.1.0-alpha.20180702-1439-g3dcc979 StartedAt:1534017747824715992} ClusterID:52b78f9b-105b-4d7d-85f1-cabed3ff25e9 StartedAt:1534017747824715992 LastUp:1534017747824715992}
I180811 20:02:29.630419 5911 server/server_update.go:67  [n1] no need to upgrade, cluster already at the newest version
W180811 20:02:29.811937 5655 server/status/runtime.go:287  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180811 20:02:30.152742 5655 server/server.go:812  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180811 20:02:30.158775 5655 server/config.go:492  [n?] 1 storage engine initialized
I180811 20:02:30.173217 5655 server/config.go:495  [n?] RocksDB cache size: 128 MiB
I180811 20:02:30.173358 5655 server/config.go:495  [n?] store 0: in-memory, size 0 B
W180811 20:02:30.173898 5655 gossip/gossip.go:1325  [n?] no incoming or outgoing connections
I180811 20:02:30.180905 5655 server/server.go:1389  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180811 20:02:30.348217 6005 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:45399}
I180811 20:02:30.350549 5898 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:44173
I180811 20:02:30.357274 5655 server/node.go:696  [n?] connecting to gossip network to verify cluster ID...
I180811 20:02:30.357550 5655 server/node.go:721  [n?] node connected via gossip and verified as part of cluster "52b78f9b-105b-4d7d-85f1-cabed3ff25e9"
I180811 20:02:30.360321 6008 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:30.377587 6007 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:30.382840 5655 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:30.401197 5655 server/node.go:427  [n?] new node allocated ID 2
I180811 20:02:30.401753 5655 gossip/gossip.go:363  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:45399" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:11 > build_tag:"v2.1.0-alpha.20180702-1439-g3dcc979" started_at:1534017750401358843 
I180811 20:02:30.402681 5655 storage/stores.go:222  [n2] read 0 node addresses from persistent storage
I180811 20:02:30.403031 5655 storage/stores.go:241  [n2] wrote 1 node addresses to persistent storage
I180811 20:02:30.408263 5678 storage/stores.go:241  [n1] wrote 1 node addresses to persistent storage
I180811 20:02:30.484717 5655 server/node.go:671  [n2] bootstrapped store [n2,s2]
I180811 20:02:30.487199 5655 server/node.go:545  [n2] node=2: started with [] engine(s) and attributes []
I180811 20:02:30.495347 5655 server/status/recorder.go:652  [n2] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:30.495550 5655 server/server.go:1818  [n2] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180811 20:02:30.497032 6155 server/status/recorder.go:652  [n2,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:30.499154 5655 server/server.go:1523  [n2] starting https server at 127.0.0.1:36605
I180811 20:02:30.501194 5655 server/server.go:1524  [n2] starting grpc/postgres server at 127.0.0.1:45399
I180811 20:02:30.501293 5655 server/server.go:1525  [n2] advertising CockroachDB node at 127.0.0.1:45399
I180811 20:02:30.550724 5655 server/server.go:1607  [n2] done ensuring all necessary migrations have run
I180811 20:02:30.550960 5655 server/server.go:1610  [n2] serving sql connections
I180811 20:02:30.792721 5679 server/server_update.go:67  [n2] no need to upgrade, cluster already at the newest version
I180811 20:02:30.808390 5681 sql/event_log.go:126  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:45399} Attrs: Locality: ServerVersion:2.0-11 BuildTag:v2.1.0-alpha.20180702-1439-g3dcc979 StartedAt:1534017750401358843} ClusterID:52b78f9b-105b-4d7d-85f1-cabed3ff25e9 StartedAt:1534017750401358843 LastUp:1534017750401358843}
W180811 20:02:30.837452 5655 server/status/runtime.go:287  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180811 20:02:31.120011 5655 server/server.go:812  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180811 20:02:31.147055 5655 server/config.go:492  [n?] 1 storage engine initialized
I180811 20:02:31.147187 5655 server/config.go:495  [n?] RocksDB cache size: 128 MiB
I180811 20:02:31.147226 5655 server/config.go:495  [n?] store 0: in-memory, size 0 B
W180811 20:02:31.147510 5655 gossip/gossip.go:1325  [n?] no incoming or outgoing connections
I180811 20:02:31.197418 5655 server/server.go:1389  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180811 20:02:31.433887 6199 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:44173
I180811 20:02:31.434749 6207 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:36631}
I180811 20:02:31.447782 5655 server/node.go:696  [n?] connecting to gossip network to verify cluster ID...
I180811 20:02:31.448092 5655 server/node.go:721  [n?] node connected via gossip and verified as part of cluster "52b78f9b-105b-4d7d-85f1-cabed3ff25e9"
I180811 20:02:31.453760 6274 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:31.462040 6209 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:31.468383 5655 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:31.485467 5655 server/node.go:427  [n?] new node allocated ID 3
I180811 20:02:31.486171 5655 gossip/gossip.go:363  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:36631" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:11 > build_tag:"v2.1.0-alpha.20180702-1439-g3dcc979" started_at:1534017751485760454 
I180811 20:02:31.487106 5655 storage/stores.go:222  [n3] read 0 node addresses from persistent storage
I180811 20:02:31.487511 5655 storage/stores.go:241  [n3] wrote 2 node addresses to persistent storage
I180811 20:02:31.493024 6293 storage/stores.go:241  [n1] wrote 2 node addresses to persistent storage
I180811 20:02:31.500036 6176 storage/stores.go:241  [n2] wrote 2 node addresses to persistent storage
I180811 20:02:31.584993 5655 server/node.go:671  [n3] bootstrapped store [n3,s3]
I180811 20:02:31.586842 5655 server/node.go:545  [n3] node=3: started with [] engine(s) and attributes []
I180811 20:02:31.588211 5655 server/status/recorder.go:652  [n3] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:31.588316 5655 server/server.go:1818  [n3] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180811 20:02:31.605307 6352 server/status/recorder.go:652  [n3,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:31.607782 5655 server/server.go:1523  [n3] starting https server at 127.0.0.1:37769
I180811 20:02:31.613360 5655 server/server.go:1524  [n3] starting grpc/postgres server at 127.0.0.1:36631
I180811 20:02:31.613470 5655 server/server.go:1525  [n3] advertising CockroachDB node at 127.0.0.1:36631
I180811 20:02:31.635847 5655 server/server.go:1607  [n3] done ensuring all necessary migrations have run
I180811 20:02:31.636001 5655 server/server.go:1610  [n3] serving sql connections
W180811 20:02:32.001082 5655 server/status/runtime.go:287  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180811 20:02:32.039044 6420 sql/event_log.go:126  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:36631} Attrs: Locality: ServerVersion:2.0-11 BuildTag:v2.1.0-alpha.20180702-1439-g3dcc979 StartedAt:1534017751485760454} ClusterID:52b78f9b-105b-4d7d-85f1-cabed3ff25e9 StartedAt:1534017751485760454 LastUp:1534017751485760454}
I180811 20:02:32.091223 6418 server/server_update.go:67  [n3] no need to upgrade, cluster already at the newest version
I180811 20:02:32.220318 5655 server/server.go:812  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180811 20:02:32.233148 5655 server/config.go:492  [n?] 1 storage engine initialized
I180811 20:02:32.240910 5655 server/config.go:495  [n?] RocksDB cache size: 128 MiB
I180811 20:02:32.241076 5655 server/config.go:495  [n?] store 0: in-memory, size 0 B
W180811 20:02:32.241464 5655 gossip/gossip.go:1325  [n?] no incoming or outgoing connections
I180811 20:02:32.243093 5655 server/server.go:1389  [n?] no stores bootstrapped and --join flag specified, awaiting init command.
I180811 20:02:32.518350 6471 gossip/client.go:129  [n?] started gossip client to 127.0.0.1:44173
I180811 20:02:32.521741 6548 gossip/server.go:219  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:44115}
I180811 20:02:32.535491 5655 server/node.go:696  [n?] connecting to gossip network to verify cluster ID...
I180811 20:02:32.542922 5655 server/node.go:721  [n?] node connected via gossip and verified as part of cluster "52b78f9b-105b-4d7d-85f1-cabed3ff25e9"
I180811 20:02:32.546265 6570 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:32.552183 6569 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:32.582936 5655 kv/dist_sender.go:342  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I180811 20:02:32.616608 5655 server/node.go:427  [n?] new node allocated ID 4
I180811 20:02:32.617321 5655 gossip/gossip.go:363  [n4] NodeDescriptor set to node_id:4 address:<network_field:"tcp" address_field:"127.0.0.1:44115" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:11 > build_tag:"v2.1.0-alpha.20180702-1439-g3dcc979" started_at:1534017752616868381 
I180811 20:02:32.618309 5655 storage/stores.go:222  [n4] read 0 node addresses from persistent storage
I180811 20:02:32.618697 5655 storage/stores.go:241  [n4] wrote 3 node addresses to persistent storage
I180811 20:02:32.643802 6480 storage/stores.go:241  [n1] wrote 3 node addresses to persistent storage
I180811 20:02:32.670270 6533 storage/stores.go:241  [n3] wrote 3 node addresses to persistent storage
I180811 20:02:32.677806 6610 storage/stores.go:241  [n2] wrote 3 node addresses to persistent storage
I180811 20:02:32.692245 5655 server/node.go:671  [n4] bootstrapped store [n4,s4]
I180811 20:02:32.714654 5655 server/node.go:545  [n4] node=4: started with [] engine(s) and attributes []
I180811 20:02:32.718801 5655 server/status/recorder.go:652  [n4] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:32.719033 5655 server/server.go:1818  [n4] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180811 20:02:32.731547 6683 server/status/recorder.go:652  [n4,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 20:02:32.745227 5655 server/server.go:1523  [n4] starting https server at 127.0.0.1:36131
I180811 20:02:32.751202 5655 server/server.go:1524  [n4] starting grpc/postgres server at 127.0.0.1:44115
I180811 20:02:32.751345 5655 server/server.go:1525  [n4] advertising CockroachDB node at 127.0.0.1:44115
I180811 20:02:32.760151 5655 server/server.go:1607  [n4] done ensuring all necessary migrations have run
I180811 20:02:32.760331 5655 server/server.go:1610  [n4] serving sql connections
I180811 20:02:32.956023 6414 sql/event_log.go:126  [n4] Event: "node_join", target: 4, info: {Descriptor:{NodeID:4 Address:{NetworkField:tcp AddressField:127.0.0.1:44115} Attrs: Locality: ServerVersion:2.0-11 BuildTag:v2.1.0-alpha.20180702-1439-g3dcc979 StartedAt:1534017752616868381} ClusterID:52b78f9b-105b-4d7d-85f1-cabed3ff25e9 StartedAt:1534017752616868381 LastUp:1534017752616868381}
I180811 20:02:32.964884 6412 server/server_update.go:67  [n4] no need to upgrade, cluster already at the newest version
I180811 20:02:33.174318 6540 sql/event_log.go:126  [n1,client=127.0.0.1:60092,user=root] Event: "create_database", target: 52, info: {DatabaseName:test Statement:CREATE DATABASE IF NOT EXISTS test User:root}
I180811 20:02:33.360612 6540 sql/event_log.go:126  [n1,client=127.0.0.1:60092,user=root] Event: "create_table", target: 53, info: {TableName:test.public."left" Statement:CREATE TABLE test.public."left" (num INT PRIMARY KEY) User:root}
I180811 20:02:33.653888 6540 sql/event_log.go:126  [n1,client=127.0.0.1:60092,user=root] Event: "create_table", target: 54, info: {TableName:test.public."right" Statement:CREATE TABLE test.public."right" (num INT PRIMARY KEY) User:root}
I180811 20:02:34.229198 6455 rpc/nodedialer/nodedialer.go:92  [intExec=get-table-statistics] connection to n1 established
I180811 20:02:34.610731 6779 rpc/nodedialer/nodedialer.go:92  [n1] connection to n4 established
I180811 20:02:34.618388 6456 rpc/nodedialer/nodedialer.go:92  [n4,client=127.0.0.1:57702,user=root] connection to n1 established
I180811 20:02:34.623029 6720 rpc/nodedialer/nodedialer.go:92  [n1] connection to n4 established
I180811 20:02:34.669762 6540 storage/replica_command.go:280  [n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /Table/54/1/1 [r2]
I180811 20:02:34.951031 6540 storage/replica_command.go:280  [n1,s1,r2/1:/{Table/54/1/1-Max}] initiating a split of this range at key /Table/54/1/2 [r3]
I180811 20:02:35.141546 6540 storage/replica_command.go:280  [n1,s1,r3/1:/{Table/54/1/2-Max}] initiating a split of this range at key /Table/54/1/3 [r4]
I180811 20:02:35.273693 6540 storage/replica_raftstorage.go:521  [n1,s1,r2/1:/Table/54/1/{1-2}] generated preemptive snapshot cc1da9ad at index 16
I180811 20:02:35.538113 6540 rpc/nodedialer/nodedialer.go:92  [n1,s1,r2/1:/Table/54/1/{1-2}] connection to n2 established
I180811 20:02:35.567462 6540 storage/store_snapshot.go:641  [n1,s1,r2/1:/Table/54/1/{1-2}] streamed snapshot to (n2,s2):?: kv pairs: 8, log entries: 6, rate-limit: 2.0 MiB/sec, 29ms
I180811 20:02:35.570127 6892 storage/replica_raftstorage.go:758  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 16 (id=cc1da9ad, encoded size=2048, 1 rocksdb batches, 6 log entries)
I180811 20:02:35.572985 6892 storage/replica_raftstorage.go:764  [n2,s2,r2/?:/Table/54/1/{1-2}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I180811 20:02:35.576864 6540 storage/replica_command.go:750  [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, gen=842353421504]
I180811 20:02:35.637734 6540 storage/replica.go:3637  [n1,s1,r2/1:/Table/54/1/{1-2}] proposing ADD_REPLICA((n2,s2):2): updated=[(n1,s1):1 (n2,s2):2] next=3
I180811 20:02:35.643287 6540 storage/replica_range_lease.go:554  [n1,s1,r2/1:/Table/54/1/{1-2}] transferring lease to s2
I180811 20:02:35.679597 6060 rpc/nodedialer/nodedialer.go:92  [n2] connection to n1 established
I180811 20:02:35.697172 6061 storage/replica_proposal.go:214  [n2,s2,r2/2:/Table/54/1/{1-2}] new range lease repl=(n2,s2):2 seq=3 start=1534017755.646021796,0 epo=1 pro=1534017755.646047560,0 following repl=(n1,s1):1 seq=2 start=1534017747.828825219,0 exp=1534017761.360786243,0 pro=1534017752.360839933,0
I180811 20:02:35.700543 6540 storage/replica_range_lease.go:617  [n1,s1,r2/1:/Table/54/1/{1-2}] done transferring lease to s2: <nil>
I180811 20:02:35.775085 6918 storage/replica_range_lease.go:554  [n2,s2,r2/2:/Table/54/1/{1-2}] transferring lease to s2
I180811 20:02:35.802610 6822 storage/replica_command.go:750  [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, gen=842369462984]
I180811 20:02:36.071086 6822 storage/replica.go:3637  [n2,s2,r2/2:/Table/54/1/{1-2}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n2,s2):2] next=3
I180811 20:02:36.089069 6869 storage/store.go:3648  [n1,s1,r2/1:/Table/54/1/{1-2}] added to replica GC queue (peer suggestion)
I180811 20:02:36.108143 6729 storage/store.go:2585  [replicaGC,n1,s1,r2/1:/Table/54/1/{1-2}] removing replica
I180811 20:02:36.111973 6729 storage/replica.go:846  [replicaGC,n1,s1,r2/1:/Table/54/1/{1-2}] removed 7 (1+6) keys in 3ms [clear=2ms commit=1ms]
I180811 20:02:36.121954 6540 storage/replica_range_lease.go:554  [n1,s1,r3/1:/Table/54/1/{2-3}] transferring lease to s1
I180811 20:02:36.125201 6540 storage/replica_raftstorage.go:521  [n1,s1,r4/1:/{Table/54/1/3-Max}] generated preemptive snapshot 135cf1ca at index 12
I180811 20:02:36.223914 6540 rpc/nodedialer/nodedialer.go:92  [n1,s1,r4/1:/{Table/54/1/3-Max}] connection to n3 established
I180811 20:02:36.228390 6540 storage/store_snapshot.go:641  [n1,s1,r4/1:/{Table/54/1/3-Max}] streamed snapshot to (n3,s3):?: kv pairs: 7, log entries: 2, rate-limit: 2.0 MiB/sec, 4ms
I180811 20:02:36.234482 6736 storage/replica_raftstorage.go:758  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 12 (id=135cf1ca, encoded size=355, 1 rocksdb batches, 2 log entries)
I180811 20:02:36.236537 6736 storage/replica_raftstorage.go:764  [n3,s3,r4/?:/{Table/54/1/3-Max}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I180811 20:02:36.240608 6540 storage/replica_command.go:750  [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, gen=0]
I180811 20:02:36.361021 6540 storage/replica.go:3637  [n1,s1,r4/1:/{Table/54/1/3-Max}] proposing ADD_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n3,s3):2] next=3
I180811 20:02:36.391130 6540 storage/replica_range_lease.go:554  [n1,s1,r4/1:/{Table/54/1/3-Max}] transferring lease to s3
I180811 20:02:36.412332 6279 rpc/nodedialer/nodedialer.go:92  [n3] connection to n1 established
I180811 20:02:36.436248 6540 storage/replica_range_lease.go:617  [n1,s1,r4/1:/{Table/54/1/3-Max}] done transferring lease to s3: <nil>
I180811 20:02:36.448371 6281 storage/replica_proposal.go:214  [n3,s3,r4/2:/{Table/54/1/3-Max}] new range lease repl=(n3,s3):2 seq=3 start=1534017756.391315463,0 epo=1 pro=1534017756.391333750,0 following repl=(n1,s1):1 seq=2 start=1534017747.828825219,0 exp=1534017761.360786243,0 pro=1534017752.360839933,0
I180811 20:02:36.451425 6969 storage/replica_range_lease.go:554  [n3,s3,r4/2:/{Table/54/1/3-Max}] transferring lease to s3
I180811 20:02:36.493712 6926 storage/replica_command.go:750  [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, gen=0]
I180811 20:02:36.710358 6926 storage/replica.go:3637  [n3,s3,r4/2:/{Table/54/1/3-Max}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n3,s3):2] next=3
I180811 20:02:36.743529 6964 storage/store.go:3648  [n1,s1,r4/1:/{Table/54/1/3-Max}] added to replica GC queue (peer suggestion)
I180811 20:02:36.754015 6830 storage/store.go:2585  [replicaGC,n1,s1,r4/1:/{Table/54/1/3-Max}] removing replica
I180811 20:02:36.756920 6830 storage/replica.go:846  [replicaGC,n1,s1,r4/1:/{Table/54/1/3-Max}] removed 7 (1+6) keys in 1ms [clear=0ms commit=1ms]
I180811 20:02:37.161492 6457 rpc/nodedialer/nodedialer.go:92  [intExec=get-table-statistics] connection to n1 established
I180811 20:02:37.169986 7058 rpc/nodedialer/nodedialer.go:92  [n1] connection to n4 established
I180811 20:02:37.210062 6458 rpc/nodedialer/nodedialer.go:92  [n4,client=127.0.0.1:57702,user=root] connection to n1 established
I180811 20:02:37.215830 7049 rpc/nodedialer/nodedialer.go:92  [n1] connection to n4 established
I180811 20:02:37.303061 7012 util/stop/stopper.go:537  quiescing; tasks left:
1      node.Node: batch
1      [async] transport racer
I180811 20:02:37.324194 5659 kv/transport_race.go:67  transport race promotion: ran 19 iterations on up to 672 requests
W180811 20:02:37.332481 6870 storage/raft_transport.go:574  [n2] while processing outgoing Raft queue to node 1: rpc error: code = Unavailable desc = transport is closing:
W180811 20:02:37.348246 6940 storage/raft_transport.go:574  [n3] while processing outgoing Raft queue to node 1: rpc error: code = Canceled desc = grpc: the client connection is closing:
W180811 20:02:37.352487 6706 internal/client/txn.go:514  [n4,hb] failure aborting transaction: node unavailable; try another peer; abort caused by: node unavailable; try another peer
W180811 20:02:37.352893 6706 storage/node_liveness.go:494  [n4,hb] failed node liveness heartbeat: node unavailable; try another peer
------- Stdout: -------
W180811 19:56:32.607919 5165 server/status/runtime.go:287  [n?] Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I180811 19:56:32.627962 5165 server/server.go:812  [n?] monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I180811 19:56:32.630856 5165 server/config.go:492  [n?] 1 storage engine initialized
I180811 19:56:32.630887 5165 server/config.go:495  [n?] RocksDB cache size: 128 MiB
I180811 19:56:32.630899 5165 server/config.go:495  [n?] store 0: in-memory, size 0 B
I180811 19:56:32.636239 5165 server/node.go:373  [n?] **** cluster 9d6d9129-8561-4f24-bea3-ebd61d723bc9 has been created
I180811 19:56:32.636278 5165 server/server.go:1387  [n?] **** add additional nodes by specifying --join=127.0.0.1:37987
I180811 19:56:32.636515 5165 gossip/gossip.go:363  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:37987" > attrs:<> locality:<> ServerVersion:<major_val:2 minor_val:0 patch:0 unstable:11 > build_tag:"v2.1.0-alpha.20180702-1439-g3dcc979" started_at:1534017392636431924 
I180811 19:56:32.638026 5165 storage/store.go:1501  [n1,s1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I180811 19:56:32.638143 5165 server/node.go:475  [n1] initialized store [n1,s1]: disk (capacity=512 MiB, available=512 MiB, used=0 B, logicalBytes=6.9 KiB), ranges=1, leases=0, queries=0.00, 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}
I180811 19:56:32.638212 5165 storage/stores.go:222  [n1] read 0 node addresses from persistent storage
I180811 19:56:32.638360 5165 server/node.go:696  [n1] connecting to gossip network to verify cluster ID...
I180811 19:56:32.643535 5165 server/node.go:721  [n1] node connected via gossip and verified as part of cluster "9d6d9129-8561-4f24-bea3-ebd61d723bc9"
I180811 19:56:32.643577 5165 server/node.go:545  [n1] node=1: started with [<no-attributes>=<in-mem>] engine(s) and attributes []
I180811 19:56:32.645048 5165 server/status/recorder.go:652  [n1] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 19:56:32.645110 5165 server/server.go:1818  [n1] Could not start heap profiler worker due to: directory to store profiles could not be determined
I180811 19:56:32.645214 5165 server/server.go:1523  [n1] starting https server at 127.0.0.1:38481
I180811 19:56:32.645361 5165 server/server.go:1524  [n1] starting grpc/postgres server at 127.0.0.1:37987
I180811 19:56:32.645392 5165 server/server.go:1525  [n1] advertising CockroachDB node at 127.0.0.1:37987
I180811 19:56:32.650561 5455 server/status/recorder.go:652  [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180811 19:56:32.667788 5486 sql/event_log.go:126  [n1,intExec=optInToDiagnosticsStatReporting] Event: "set_cluster_setting", target: 0, info: {SettingName:diagnostics.reporting.enabled Value:true User:root}
I180811 19:56:32.687027 5470 sql/event_log.go:126  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:$1 User:root}
I180811 19:56:32.694837 5508 sql/event_log.go:126  [n1,intExec=disableNetTrace] Event: "set_cluster_setting", target: 0, info: {SettingName:trace.debug.enable Value:false User:root}
I180811 19:56:32.725238 5521 sql/event_log.go:126  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:gen_random_uuid()::STRING User:root}
I180811 19:56:32.733200 5527 sql/event_log.go:126  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I180811 19:56:32.749961 5531

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the 2.1 milestone Aug 11, 2018
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Aug 11, 2018
@tbg tbg added the A-sql-execution Relating to SQL execution. label Aug 14, 2018
@jordanlewis
Copy link
Member

Dupe of #25808

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

@jordanlewis jordanlewis

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
3 participants
@jordanlewis @tbg @cockroach-teamcity