FAQ
Hi,

I just setup CF Multi-Nodes Environment by BOSH and get ready for usage
after solving some problems. Now DEA node is OK and I can vmc push apps
with Ruby and Java.

But I can create service mysql or redis. The following is the information
and your kindly help is appreciated. Thanks a lot.

After going through some attached logs, I found the key issue is by
service_gateway_client.rb which function perform_request issue 503 error.
I doubted gateway request or response because I use static ip not dns to
communicate with cc, gateway and node.(Already modify /etc/hosts in cc,
mysql_gateway and mysql_node by adding 10.10.1.21 api.cf.local)

def perform_request(http_method, path,
msg=VCAP::Services::Api::EMPTY_REQUEST)
result = nil
uri = URI.parse(@url)
if EM.reactor_running?
url = URI.parse(uri.to_s + path)
code, body = requester.request(url, @token, http_method, @timeout,
msg)
else
klass = METHODS_MAP[http_method]
req = klass.new(path, initheader=@hdrs)
req.body = msg.encode
* resp = Net::HTTP.new(uri.host, uri.port).start {|http|
http.request(req)}*
* code = resp.code.to_i*
* body = resp.body*
end
case code
when 200
body
when 404
err = ServiceErrorResponse.decode(body)
raise NotFoundResponse.new(err)
when 503
* err = ServiceErrorResponse.decode(body)*
* raise GatewayInternalResponse.new(err)*
else
begin
# try to decode the response
err = ServiceErrorResponse.decode(body)
rescue => e
raise UnexpectedResponse, "Can't decode gateway response. status
code:#{code}, response body:#{body}"
end
raise ErrorResponse.new(code, err)
end

=============== vmc client ===================

ubuntu@ubuntu:~$ vmc create-service
1: mysql 5.1
2: redis 2.2
3: redis 2.4
4: redis 2.6
What kind?> 1

Name?> mysql-d603

Creating service mysql-d603... FAILED
CFoundry::ServiceGatewayError: 503: Unexpected response from service gateway
For more information, see ~/.vmc/crash
ubuntu@ubuntu:~$


ubuntu@ubuntu:~$ more ~/.vmc/crash
Time of crash:
2013-03-06 08:26:12 +0800

CFoundry::ServiceGatewayError: 503: Unexpected response from service gateway

cfoundry-0.4.21/lib/cfoundry/v1/base.rb:113:in `handle_response'
cfoundry-0.4.21/lib/cfoundry/baseclient.rb:146:in `block in request_uri'
/home/ubuntu/.rvm/rubies/ruby-1.9.2-p320/lib/ruby/1.9.1/net/http.rb:627:in
`start'
cfoundry-0.4.21/lib/cfoundry/baseclient.rb:127:in `request_uri'
cfoundry-0.4.21/lib/cfoundry/baseclient.rb:48:in `request'
cfoundry-0.4.21/lib/cfoundry/baseclient.rb:44:in `request_path'
cfoundry-0.4.21/lib/cfoundry/baseclient.rb:193:in `request_with_options'
cfoundry-0.4.21/lib/cfoundry/baseclient.rb:205:in `post'
cfoundry-0.4.21/lib/cfoundry/v1/model_magic.rb:34:in `block (2 levels) in
define_client_methods'
cfoundry-0.4.21/lib/cfoundry/v1/model.rb:72:in `create!'
vmc-0.4.7/lib/vmc/cli/service/create.rb:94:in `block in create_service'
interact-0.5.2/lib/interact/progress.rb:98:in `with_progress'
vmc-0.4.7/lib/vmc/cli/service/create.rb:93:in `create_service'
mothership-0.3.5/lib/mothership/base.rb:61:in `run'
mothership-0.3.5/lib/mothership/command.rb:68:in `block in invoke'
mothership-0.3.5/lib/mothership/command.rb:82:in `instance_exec'
mothership-0.3.5/lib/mothership/command.rb:82:in `invoke'
mothership-0.3.5/lib/mothership/base.rb:50:in `execute'
vmc-0.4.7/lib/vmc/cli.rb:106:in `execute'
mothership-0.3.5/lib/mothership.rb:45:in `start'
vmc-0.4.7/bin/vmc:11:in `<top (required)>'
ruby-1.9.2-p320/bin/vmc:19:in `load'
ruby-1.9.2-p320/bin/vmc:19:in `<main>'
ruby-1.9.2-p320/bin/ruby_noexec_wrapper:14:in `eval'
ruby-1.9.2-p320/bin/ruby_noexec_wrapper:14:in `<main>'

=============== mysql gateway ===================

[2013-03-06 08:45:04.400024] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Create service request: {"label":"mysql-5.1","description":"MySQL
database","provider":"core","url":"http://10.10.3.28:49236","plans":["free"],"cf_plan_id":{"free":null},"default_plan":"free","tags":["relational"],"active":true,"acls":null,"supported_versions":["5.1"],"version_aliases":{"current":"5.1"},"timeout":10}
[2013-03-06 08:45:04.403634] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Found svc = #<Service id: 1, label: "mysql-5.1", url:
"http://10.10.3.28:49236", token: "aaaf4eaa8c1758f66d5cb7adcb24adb9d7",
name: "mysql", version: "5.1", description: "MySQL database", info_url:
nil, tags: ["relational"], plans: ["free"], plan_options: nil,
binding_options: nil, acls: nil, active: true, created_at: "2013-03-05
11:40:01", updated_at: "2013-03-05 11:40:01", timeout: 10, cf_plan_id:
{"free"=>nil}, provider: nil, supported_versions: ["5.1"], version_aliases:
{"current"=>"5.1"}, default_plan: "free">
[2013-03-06 08:45:04.422341] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Connection checked in (checked out: 2/4)
[2013-03-06 08:45:12.236773] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Connection checked out (checked out: 3/4)
[2013-03-06 08:45:12.238072] cc - pid=21928 tid=f312 fid=b92a DEBUG -- *Create
service request: *{"label":"redis-2.2","description":"Redis key-value
store","provider":"core","url":"http://10.10.3.32:54003","plans":["free"],"cf_plan_id":{"free":null},"default_plan":"free","tags":["key-value","nosql"],"active":true,"acls":null,"supported_versions":["2.2","2.4","2.6"],"version_aliases":{"current":"2.2","next":"2.6"},"timeout":10}
[2013-03-06 08:45:12.240621] cc - pid=21928 tid=f312 fid=b92a DEBUG -- *Found
svc *= #<Service id: 2, label: "redis-2.2", url: "http://10.10.3.32:54003",
token: "aaaf4eaa8c1758f66d5cb7adcb24adb9d7", name: "redis", version: "2.2",
description: "Redis key-value store", info_url: nil, tags: ["key-value",
"nosql"], plans: ["free"], plan_options: nil, binding_options: nil, acls:
nil, active: true, created_at: "2013-03-05 14:51:16", updated_at:
"2013-03-05 14:51:16", timeout: 10, cf_plan_id: {"free"=>nil}, provider:
nil, supported_versions: ["2.2", "2.4", "2.6"], version_aliases:
{"current"=>"2.2", "next"=>"2.6"}, default_plan: "free">
[2013-03-06 08:45:12.258452] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Connection checked in (checked out: 2/4)
[2013-03-06 08:45:24.176979] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Connection checked out (checked out: 3/4)
[2013-03-06 08:45:24.178369] cc - pid=21928 tid=f312 fid=b92a DEBUG --
user_email decoded from token is "test@xxx.cn"
[2013-03-06 08:45:27.415240] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Connection checked in (checked out: 2/4)
[2013-03-06 08:45:49.146324] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Connection checked out (checked out: 3/4)
[2013-03-06 08:45:49.148364] cc - pid=21928 tid=f312 fid=b92a DEBUG --
user_email decoded from token is "test@xxx.cn"
[2013-03-06 08:45:49.151511] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Global service listing found 2 services.
[2013-03-06 08:45:49.155587] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Connection checked in (checked out: 2/4)
[2013-03-06 08:45:52.235458] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Connection checked out (checked out: 3/4)
[2013-03-06 08:45:52.237222] cc - pid=21928 tid=f312 fid=b92a DEBUG --
user_email decoded from token is "test@xxx.cn"
[2013-03-06 08:45:52.238993] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Attempting to provision service:
{"name":"mysql-d603","type":"database","vendor":"mysql","version":"5.1","tier":"free"}
[2013-03-06 08:45:52.261906] cc - pid=21928 tid=f312 fid=b92a ERROR -- *Error
talking to gateway: Reponse status:503,error:[{:code=>30600,
:description=>"Service unavailable"}]*
[2013-03-06 08:45:52.262439] cc exception pid=21928 tid=f312 fid=b92a
ERROR --
VCAP::Services::Api::ServiceGatewayClient::GatewayInternalResponse<<Reponse
status:503,error:[{:code=>30600, :description=>"Service unavailable"}]:*
/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/vcap_common-2.0.7/lib/services/api/clients/service_gateway_client.rb:17
*2:in
`perform_request',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/vcap_common-2.0.7/lib/services/api/clients/service_gateway_client.rb:77:in
`provision',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/app/models/service_config.rb:61:in
`block in
provision',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/connection_adapters/abstract/database_statements.rb:139:in
`transaction',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/transactions.rb:207:in
`transaction',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/app/models/service_config.rb:42:in
`provision',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/app/controllers/legacy_services_controller.rb:64:in
`provision',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/implicit_render.rb:4:in
`send_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/base.rb:150:in
`process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/rendering.rb:11:in
`process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/callbacks.rb:18:in
`block in
process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/callbacks.rb:441:in
`_run__385464964305857824__process_action__2444828834671554956__callbacks',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/callbacks.rb:410:in
`_run_process_action_callbacks',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/callbacks.rb:94:in
`run_callbacks',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/callbacks.rb:17:in
`process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/rescue.rb:17:in
`process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/instrumentation.rb:30:in
`block in
process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/notifications.rb:52:in
`block in
instrument',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/notifications/instrumenter.rb:21:in
`instrument',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/notifications.rb:52:in
`instrument',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/instrumentation.rb:29:in
`process_action',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/app/controllers/application_controller.rb:16:in
`process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/base.rb:119:in
`process',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/rendering.rb:41:in
`process',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal.rb:138:in
`dispatch',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/rack_delegation.rb:14:in
`dispatch',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal.rb:178:in
`block in
action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/routing/route_set.rb:68:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/routing/route_set.rb:68:in
`dispatch',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/routing/route_set.rb:33:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/route_set.rb:148:in
`block in
call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/code_generation.rb:93:in
`block in
recognize',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/code_generation.rb:68:in
`optimized_each',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/code_generation.rb:92:in
`recognize',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/route_set.rb:139:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/routing/route_set.rb:499:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/best_standards_support.rb:17:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/head.rb:14:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-1.2.7/lib/rack/methodoverride.rb:24:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/params_parser.rb:21:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/cookies.rb:302:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/query_cache.rb:32:in
`block in
call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/connection_adapters/abstract/query_cache.rb:28:in
`cache',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/query_cache.rb:12:in
`cache',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/query_cache.rb:31:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/connection_adapters/abstract/connection_pool.rb:354:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/callbacks.rb:46:in
`block in
call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/callbacks.rb:416:in
`_run_call_callbacks',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/callbacks.rb:44:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-1.2.7/lib/rack/sendfile.rb:106:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/remote_ip.rb:48:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/show_exceptions.rb:47:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/railties-3.0.20/lib/rails/rack/logger.rb:13:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/rack/fiber_pool.rb:19:in
`block in
call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/fiber_pool.rb:48:in
`call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/fiber_pool.rb:48:in
`block (3 levels) in
initialize',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/fiber_pool.rb:47:in
`loop',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/fiber_pool.rb:47:in
`block (2 levels) in
initialize',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/config/initializers/fiber_connection_pool.rb:11:in
`call',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/config/initializers/fiber_connection_pool.rb:11:in
`block in initialize'>>
[2013-03-06 08:45:52.276929] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Connection checked in (checked out: 2/4)
[2013-03-06 08:46:04.489454] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Connection checked out (checked out: 3/4)
[2013-03-06 08:46:04.491304] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Create service request: {"label":"mysql-5.1","description":"MySQL
database","provider":"core","url":"http://10.10.3.28:49236","plans":["free"],"cf_plan_id":{"free":null},"default_plan":"free","tags":["relational"],"active":true,"acls":null,"supported_versions":["5.1"],"version_aliases":{"current":"5.1"},"timeout":10}
[2013-03-06 08:46:04.494864] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Found svc = #<Service id: 1, label: "mysql-5.1", url:
"http://10.10.3.28:49236", token: "aaaf4eaa8c1758f66d5cb7adcb24adb9d7",
name: "mysql", version: "5.1", description: "MySQL database", info_url:
nil, tags: ["relational"], plans: ["free"], plan_options: nil,
binding_options: nil, acls: nil, active: true, created_at: "2013-03-05
11:40:01", updated_at: "2013-03-05 11:40:01", timeout: 10, cf_plan_id:
{"free"=>nil}, provider: nil, supported_versions: ["5.1"], version_aliases:
{"current"=>"5.1"}, default_plan: "free">
[2013-03-06 08:46:04.510592] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Connection checked in (checked out: 2/4)
[2013-03-06 08:46:12.302670] cc - pid=21928 tid=f312 fid=b92a DEBUG --
Connection checked out (checked out: 3/4)

=============== mysql node ===================

[2013-03-06 09:02:01.347601] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
DEBUG -- MyaaS-Node: Sending announcement for everyone
[2013-03-06 09:02:31.381183] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
DEBUG -- MyaaS-Node: Sending announcement for everyone
[2013-03-06 09:03:01.448431] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
DEBUG -- MyaaS-Node: Sending announcement for everyone
[2013-03-06 09:03:31.521892] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
DEBUG -- MyaaS-Node: Sending announcement for everyone
[2013-03-06 09:04:01.591951] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
DEBUG -- MyaaS-Node: Sending announcement for everyone
[2013-03-06 09:04:31.670580] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
DEBUG -- MyaaS-Node: Sending announcement for everyone
[2013-03-06 09:05:01.742284] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
DEBUG -- MyaaS-Node: Sending announcement for everyone
[2013-03-06 09:05:31.813634] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
DEBUG -- MyaaS-Node: Sending announcement for everyone
[2013-03-06 09:06:01.874919] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
DEBUG -- MyaaS-Node: Sending announcement for everyone
[2013-03-06 09:06:31.932898] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
DEBUG -- MyaaS-Node: Sending announcement for everyone


Rice

Search Discussions

  • Nicholas Kushmerick at Mar 6, 2013 at 2:18 am
    thanks for the very detailed message. but I think you need to check the gateway log for some relevant errors/messages. (the log that you label 'mysql gateway' is actually your cloud_controller log.)

    ----- Original Message -----

    From: "zhengdao yang" <zhengdao.yang@gmail.com>
    To: vcap-dev@cloudfoundry.org
    Sent: Tuesday, March 5, 2013 5:14:33 PM
    Subject: [vcap-dev] CF BOSH Mult-Nodes: vmc create-service Error 503 Unexpected response from service gateway

    Hi,

    I just setup CF Multi-Nodes Environment by BOSH and get ready for usage after solving some problems. Now DEA node is OK and I can vmc push apps with Ruby and Java.

    But I can create service mysql or redis. The following is the information and your kindly help is appreciated. Thanks a lot.

    After going through some attached logs, I found the key issue is by service_gateway_client.rb which function perform_request issue 503 error. I doubted gateway request or response because I use static ip not dns to communicate with cc, gateway and node.(Already modify /etc/hosts in cc, mysql_gateway and mysql_node by adding 10.10.1.21 api.cf.local)

    def perform_request(http_method, path, msg=VCAP::Services::Api::EMPTY_REQUEST)
    result = nil
    uri = URI.parse(@url)
    if EM.reactor_running?
    url = URI.parse(uri.to_s + path)
    code, body = requester.request(url, @token, http_method, @timeout, msg)
    else
    klass = METHODS_MAP[http_method]
    req = klass.new(path, initheader=@hdrs)
    req.body = msg.encode
    resp = Net::HTTP.new(uri.host, uri.port).start {|http| http.request(req)}
    code = resp.code.to_i
    body = resp.body
    end
    case code
    when 200
    body
    when 404
    err = ServiceErrorResponse.decode(body)
    raise NotFoundResponse.new(err)
    when 503
    err = ServiceErrorResponse.decode(body)
    raise GatewayInternalResponse.new(err)
    else
    begin
    # try to decode the response
    err = ServiceErrorResponse.decode(body)
    rescue => e
    raise UnexpectedResponse, "Can't decode gateway response. status code:#{code}, response body:#{body}"
    end
    raise ErrorResponse.new(code, err)
    end

    =============== vmc client ===================

    ubuntu@ubuntu:~$ vmc create-service
    1: mysql 5.1
    2: redis 2.2
    3: redis 2.4
    4: redis 2.6
    What kind?> 1

    Name?> mysql-d603

    Creating service mysql-d603... FAILED
    CFoundry::ServiceGatewayError: 503: Unexpected response from service gateway
    For more information, see ~/.vmc/crash
    ubuntu@ubuntu:~$


    ubuntu@ubuntu:~$ more ~/.vmc/crash
    Time of crash:
    2013-03-06 08:26:12 +0800

    CFoundry::ServiceGatewayError: 503: Unexpected response from service gateway

    cfoundry-0.4.21/lib/cfoundry/v1/base.rb:113:in `handle_response'
    cfoundry-0.4.21/lib/cfoundry/baseclient.rb:146:in `block in request_uri'
    /home/ubuntu/.rvm/rubies/ruby-1.9.2-p320/lib/ruby/1.9.1/net/http.rb:627:in `start'
    cfoundry-0.4.21/lib/cfoundry/baseclient.rb:127:in `request_uri'
    cfoundry-0.4.21/lib/cfoundry/baseclient.rb:48:in `request'
    cfoundry-0.4.21/lib/cfoundry/baseclient.rb:44:in `request_path'
    cfoundry-0.4.21/lib/cfoundry/baseclient.rb:193:in `request_with_options'
    cfoundry-0.4.21/lib/cfoundry/baseclient.rb:205:in `post'
    cfoundry-0.4.21/lib/cfoundry/v1/model_magic.rb:34:in `block (2 levels) in define_client_methods'
    cfoundry-0.4.21/lib/cfoundry/v1/model.rb:72:in `create!'
    vmc-0.4.7/lib/vmc/cli/service/create.rb:94:in `block in create_service'
    interact-0.5.2/lib/interact/progress.rb:98:in `with_progress'
    vmc-0.4.7/lib/vmc/cli/service/create.rb:93:in `create_service'
    mothership-0.3.5/lib/mothership/base.rb:61:in `run'
    mothership-0.3.5/lib/mothership/command.rb:68:in `block in invoke'
    mothership-0.3.5/lib/mothership/command.rb:82:in `instance_exec'
    mothership-0.3.5/lib/mothership/command.rb:82:in `invoke'
    mothership-0.3.5/lib/mothership/base.rb:50:in `execute'
    vmc-0.4.7/lib/vmc/cli.rb:106:in `execute'
    mothership-0.3.5/lib/mothership.rb:45:in `start'
    vmc-0.4.7/bin/vmc:11:in `<top (required)>'
    ruby-1.9.2-p320/bin/vmc:19:in `load'
    ruby-1.9.2-p320/bin/vmc:19:in `<main>'
    ruby-1.9.2-p320/bin/ruby_noexec_wrapper:14:in `eval'
    ruby-1.9.2-p320/bin/ruby_noexec_wrapper:14:in `<main>'

    =============== mysql gateway ===================

    [2013-03-06 08:45:04.400024] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Create service request: {"label":"mysql-5.1","description":"MySQL database","provider":"core","url":"http://10.10.3.28:49236","plans":["free"],"cf_plan_id":{"free":null},"default_plan":"free","tags":["relational"],"active":true,"acls":null,"supported_versions":["5.1"],"version_aliases":{"current":"5.1"},"timeout":10}
    [2013-03-06 08:45:04.403634] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Found svc = #<Service id: 1, label: "mysql-5.1", url: "http://10.10.3.28:49236", token: "aaaf4eaa8c1758f66d5cb7adcb24adb9d7", name: "mysql", version: "5.1", description: "MySQL database", info_url: nil, tags: ["relational"], plans: ["free"], plan_options: nil, binding_options: nil, acls: nil, active: true, created_at: "2013-03-05 11:40:01", updated_at: "2013-03-05 11:40:01", timeout: 10, cf_plan_id: {"free"=>nil}, provider: nil, supported_versions: ["5.1"], version_aliases: {"current"=>"5.1"}, default_plan: "free">
    [2013-03-06 08:45:04.422341] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Connection checked in (checked out: 2/4)
    [2013-03-06 08:45:12.236773] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Connection checked out (checked out: 3/4)
    [2013-03-06 08:45:12.238072] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Create service request: {"label":"redis-2.2","description":"Redis key-value store","provider":"core","url":"http://10.10.3.32:54003","plans":["free"],"cf_plan_id":{"free":null},"default_plan":"free","tags":["key-value","nosql"],"active":true,"acls":null,"supported_versions":["2.2","2.4","2.6"],"version_aliases":{"current":"2.2","next":"2.6"},"timeout":10}
    [2013-03-06 08:45:12.240621] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Found svc = #<Service id: 2, label: "redis-2.2", url: "http://10.10.3.32:54003", token: "aaaf4eaa8c1758f66d5cb7adcb24adb9d7", name: "redis", version: "2.2", description: "Redis key-value store", info_url: nil, tags: ["key-value", "nosql"], plans: ["free"], plan_options: nil, binding_options: nil, acls: nil, active: true, created_at: "2013-03-05 14:51:16", updated_at: "2013-03-05 14:51:16", timeout: 10, cf_plan_id: {"free"=>nil}, provider: nil, supported_versions: ["2.2", "2.4", "2.6"], version_aliases: {"current"=>"2.2", "next"=>"2.6"}, default_plan: "free">
    [2013-03-06 08:45:12.258452] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Connection checked in (checked out: 2/4)
    [2013-03-06 08:45:24.176979] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Connection checked out (checked out: 3/4)
    [2013-03-06 08:45:24.178369] cc - pid=21928 tid=f312 fid=b92a DEBUG -- user_email decoded from token is "test@xxx.cn"
    [2013-03-06 08:45:27.415240] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Connection checked in (checked out: 2/4)
    [2013-03-06 08:45:49.146324] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Connection checked out (checked out: 3/4)
    [2013-03-06 08:45:49.148364] cc - pid=21928 tid=f312 fid=b92a DEBUG -- user_email decoded from token is "test@xxx.cn"
    [2013-03-06 08:45:49.151511] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Global service listing found 2 services.
    [2013-03-06 08:45:49.155587] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Connection checked in (checked out: 2/4)
    [2013-03-06 08:45:52.235458] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Connection checked out (checked out: 3/4)
    [2013-03-06 08:45:52.237222] cc - pid=21928 tid=f312 fid=b92a DEBUG -- user_email decoded from token is "test@xxx.cn"
    [2013-03-06 08:45:52.238993] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Attempting to provision service: {"name":"mysql-d603","type":"database","vendor":"mysql","version":"5.1","tier":"free"}
    [2013-03-06 08:45:52.261906] cc - pid=21928 tid=f312 fid=b92a ERROR -- Error talking to gateway: Reponse status:503,error:[{:code=>30600, :description=>"Service unavailable"}]
    [2013-03-06 08:45:52.262439] cc exception pid=21928 tid=f312 fid=b92a ERROR -- VCAP::Services::Api::ServiceGatewayClient::GatewayInternalResponse<<Reponse status:503,error:[{:code=>30600, :description=>"Service unavailable"}]: /var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/vcap_common-2.0.7/lib/services/api/clients/service_gateway_client.rb:17 2:in `perform_request',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/vcap_common-2.0.7/lib/services/api/clients/service_gateway_client.rb:77:in `provision',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/app/models/service_config.rb:61:in `block in provision',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/connection_adapters/abstract/database_statements.rb:139:in `transaction',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/transactions.rb:207:in `transaction',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/app/models/service_config.rb:42:in `provision',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/app/controllers/legacy_services_controller.rb:64:in `provision',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/implicit_render.rb:4:in `send_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/base.rb:150:in `process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/rendering.rb:11:in `process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/callbacks.rb:18:in `block in process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/callbacks.rb:441:in `_run__385464964305857824__process_action__2444828834671554956__callbacks',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/callbacks.rb:410:in `_run_process_action_callbacks',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/callbacks.rb:94:in `run_callbacks',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/callbacks.rb:17:in `process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/rescue.rb:17:in `process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/instrumentation.rb:30:in `block in process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/notifications.rb:52:in `block in instrument',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/notifications/instrumenter.rb:21:in `instrument',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/notifications.rb:52:in `instrument',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/instrumentation.rb:29:in `process_action',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/app/controllers/application_controller.rb:16:in `process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/base.rb:119:in `process',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/rendering.rb:41:in `process',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal.rb:138:in `dispatch',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal.rb:178:in `block in action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/routing/route_set.rb:68:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/routing/route_set.rb:68:in `dispatch',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/routing/route_set.rb:33:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/route_set.rb:148:in `block in call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/code_generation.rb:93:in `block in recognize',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/code_generation.rb:68:in `optimized_each',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/code_generation.rb:92:in `recognize',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/route_set.rb:139:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/routing/route_set.rb:499:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/head.rb:14:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-1.2.7/lib/rack/methodoverride.rb:24:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/params_parser.rb:21:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/cookies.rb:302:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/query_cache.rb:32:in `block in call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/connection_adapters/abstract/query_cache.rb:28:in `cache',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/query_cache.rb:12:in `cache',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/query_cache.rb:31:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/connection_adapters/abstract/connection_pool.rb:354:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/callbacks.rb:46:in `block in call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/callbacks.rb:416:in `_run_call_callbacks',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/callbacks.rb:44:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-1.2.7/lib/rack/sendfile.rb:106:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/remote_ip.rb:48:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/show_exceptions.rb:47:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/railties-3.0.20/lib/rails/rack/logger.rb:13:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/rack/fiber_pool.rb:19:in `block in call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/fiber_pool.rb:48:in `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/fiber_pool.rb:48:in `block (3 levels) in initialize',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/fiber_pool.rb:47:in `loop',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/fiber_pool.rb:47:in `block (2 levels) in initialize',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/config/initializers/fiber_connection_pool.rb:11:in `call',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/config/initializers/fiber_connection_pool.rb:11:in `block in initialize'>>
    [2013-03-06 08:45:52.276929] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Connection checked in (checked out: 2/4)
    [2013-03-06 08:46:04.489454] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Connection checked out (checked out: 3/4)
    [2013-03-06 08:46:04.491304] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Create service request: {"label":"mysql-5.1","description":"MySQL database","provider":"core","url":"http://10.10.3.28:49236","plans":["free"],"cf_plan_id":{"free":null},"default_plan":"free","tags":["relational"],"active":true,"acls":null,"supported_versions":["5.1"],"version_aliases":{"current":"5.1"},"timeout":10}
    [2013-03-06 08:46:04.494864] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Found svc = #<Service id: 1, label: "mysql-5.1", url: "http://10.10.3.28:49236", token: "aaaf4eaa8c1758f66d5cb7adcb24adb9d7", name: "mysql", version: "5.1", description: "MySQL database", info_url: nil, tags: ["relational"], plans: ["free"], plan_options: nil, binding_options: nil, acls: nil, active: true, created_at: "2013-03-05 11:40:01", updated_at: "2013-03-05 11:40:01", timeout: 10, cf_plan_id: {"free"=>nil}, provider: nil, supported_versions: ["5.1"], version_aliases: {"current"=>"5.1"}, default_plan: "free">
    [2013-03-06 08:46:04.510592] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Connection checked in (checked out: 2/4)
    [2013-03-06 08:46:12.302670] cc - pid=21928 tid=f312 fid=b92a DEBUG -- Connection checked out (checked out: 3/4)

    =============== mysql node ===================

    [2013-03-06 09:02:01.347601] mysql_node_1 - pid=3044 tid=1dc1 fid=f121 DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:02:31.381183] mysql_node_1 - pid=3044 tid=1dc1 fid=f121 DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:03:01.448431] mysql_node_1 - pid=3044 tid=1dc1 fid=f121 DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:03:31.521892] mysql_node_1 - pid=3044 tid=1dc1 fid=f121 DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:04:01.591951] mysql_node_1 - pid=3044 tid=1dc1 fid=f121 DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:04:31.670580] mysql_node_1 - pid=3044 tid=1dc1 fid=f121 DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:05:01.742284] mysql_node_1 - pid=3044 tid=1dc1 fid=f121 DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:05:31.813634] mysql_node_1 - pid=3044 tid=1dc1 fid=f121 DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:06:01.874919] mysql_node_1 - pid=3044 tid=1dc1 fid=f121 DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:06:31.932898] mysql_node_1 - pid=3044 tid=1dc1 fid=f121 DEBUG -- MyaaS-Node: Sending announcement for everyone


    Rice
  • Zhengdao Yang at Mar 7, 2013 at 8:07 am
    Hi,

    The following is our mysql gateway and explicitly error is "Validation
    Failure". Your kindly help is appreciated.

    ===================== mysql gateway ==========================

    [2013-03-06 09:49:37.378566] mysql_gateway - pid=26650 tid=7bf0 fid=a9f1
    DEBUG -- [MyaaS-Provisioner] Received node announcement:
    {"available_capacity":200,"capacity_unit":1,"id":"mysql_node_1","plan":"free","supported_versions":["5.1"]}
    [2013-03-06 09:50:07.382417] mysql_gateway - pid=26650 tid=7bf0 fid=a9f1
    DEBUG -- [MyaaS-Provisioner] Received node announcement:
    {"available_capacity":200,"capacity_unit":1,"id":"mysql_node_1","plan":"free","supported_versions":["5.1"]}
    [2013-03-06 09:50:08.014279] mysql_gateway - pid=26650 tid=7bf0 fid=fc04
    DEBUG -- CC Catalog Manager: Advertise service offering
    "{\"label\":\"mysql-5.1\",\"description\":\"MySQL
    database\",\"provider\":\"core\",\"url\":\"http://10.10.3.28:49236\",\"plans\":[\"free\"],\"cf_plan_id\":{\"free\":null},\"default_plan\":\"free\",\"tags\":[\"relational\"],\"active\":true,\"acls\":null,\"supported_versions\":[\"5.1\"],\"version_aliases\":{\"current\":\"5.1\"},\"timeout\":10}"
    to cloud_controller: http://api.cf.local/services/v1/offerings
    [2013-03-06 09:50:08.049717] mysql_gateway - pid=26650 tid=7bf0 fid=fc04
    INFO -- CC Catalog Manager: Successfully advertised offering:
    "{\"label\":\"mysql-5.1\",\"description\":\"MySQL
    database\",\"provider\":\"core\",\"url\":\"http://10.10.3.28:49236\",\"plans\":[\"free\"],\"cf_plan_id\":{\"free\":null},\"default_plan\":\"free\",\"tags\":[\"relational\"],\"active\":true,\"acls\":null,\"supported_versions\":[\"5.1\"],\"version_aliases\":{\"current\":\"5.1\"},\"timeout\":10}"
    [2013-03-06 09:50:37.442705] mysql_gateway - pid=26650 tid=7bf0 fid=a9f1
    DEBUG -- [MyaaS-Provisioner] Received node announcement:
    {"available_capacity":200,"capacity_unit":1,"id":"mysql_node_1","plan":"free","supported_versions":["5.1"]}
    *[2013-03-06 09:50:43.504720] mysql_gateway - pid=26650 tid=7bf0 fid=a9f1
    ERROR -- Validation failure: {"status"=>503, "msg"=>{"code"=>30600,
    "description"=>"Service unavailable"}}, handles not fetched*
    [2013-03-06 09:51:07.502679] mysql_gateway - pid=26650 tid=7bf0 fid=a9f1
    DEBUG -- [MyaaS-Provisioner] Received node announcement:
    {"available_capacity":200,"capacity_unit":1,"id":"mysql_node_1","plan":"free","supported_versions":["5.1"]}
    [2013-03-06 09:51:08.044441] mysql_gateway - pid=26650 tid=7bf0 fid=bb20
    DEBUG -- CC Catalog Manager: Advertise service offering
    "{\"label\":\"mysql-5.1\",\"description\":\"MySQL
    database\",\"provider\":\"core\",\"url\":\"http://10.10.3.28:49236\",\"plans\":[\"free\"],\"cf_plan_id\":{\"free\":null},\"default_plan\":\"free\",\"tags\":[\"relational\"],\"active\":true,\"acls\":null,\"supported_versions\":[\"5.1\"],\"version_aliases\":{\"current\":\"5.1\"},\"timeout\":10}"
    to cloud_controller: http://api.cf.local/services/v1/offerings
    [2013-03-06 09:51:08.070936] mysql_gateway - pid=26650 tid=7bf0 fid=bb20
    INFO -- CC Catalog Manager: Successfully advertised offering:
    "{\"label\":\"mysql-5.1\",\"description\":\"MySQL
    database\",\"provider\":\"core\",\"url\":\"http://10.10.3.28:49236\",\"plans\":[\"free\"],\"cf_plan_id\":{\"free\":null},\"default_plan\":\"free\",\"tags\":[\"relational\"],\"active\":true,\"acls\":null,\"supported_versions\":[\"5.1\"],\"version_aliases\":{\"current\":\"5.1\"},\"timeout\":10}"
    [2013-03-06 09:51:37.569770] mysql_gateway - pid=26650 tid=7bf0 fid=a9f1
    DEBUG -- [MyaaS-Provisioner] Received node announcement:
    {"available_capacity":200,"capacity_unit":1,"id":"mysql_node_1","plan":"free","supported_versions":["5.1"]}
    [2013-03-06 09:52:07.640446] mysql_gateway - pid=26650 tid=7bf0 fid=a9f1
    DEBUG -- [MyaaS-Provisioner] Received node announcement:
    {"available_capacity":200,"capacity_unit":1,"id":"mysql_node_1","plan":"free","supported_versions":["5.1"]}










    在 2013年3月6日星期三UTC+8上午10时18分26秒,Nicholas Kushmerick写道:
    thanks for the very detailed message. but I think you need to check the
    gateway log for some relevant errors/messages. (the log that you label
    'mysql gateway' is actually your cloud_controller log.)

    ------------------------------
    *From: *"zhengdao yang" <zhengd...@gmail.com <javascript:>>
    *To: *vcap...@cloudfoundry.org <javascript:>
    *Sent: *Tuesday, March 5, 2013 5:14:33 PM
    *Subject: *[vcap-dev] CF BOSH Mult-Nodes: vmc create-service Error 503
    Unexpected response from service gateway

    Hi,

    I just setup CF Multi-Nodes Environment by BOSH and get ready for usage
    after solving some problems. Now DEA node is OK and I can vmc push apps
    with Ruby and Java.

    But I can create service mysql or redis. The following is the information
    and your kindly help is appreciated. Thanks a lot.

    After going through some attached logs, I found the key issue is by
    service_gateway_client.rb which function perform_request issue 503 error.
    I doubted gateway request or response because I use static ip not dns to
    communicate with cc, gateway and node.(Already modify /etc/hosts in cc,
    mysql_gateway and mysql_node by adding 10.10.1.21 api.cf.local)

    def perform_request(http_method, path,
    msg=VCAP::Services::Api::EMPTY_REQUEST)
    result = nil
    uri = URI.parse(@url)
    if EM.reactor_running?
    url = URI.parse(uri.to_s + path)
    code, body = requester.request(url, @token, http_method, @timeout,
    msg)
    else
    klass = METHODS_MAP[http_method]
    req = klass.new(path, initheader=@hdrs)
    req.body = msg.encode
    * resp = Net::HTTP.new(uri.host, uri.port).start {|http|
    http.request(req)}*
    * code = resp.code.to_i*
    * body = resp.body*
    end
    case code
    when 200
    body
    when 404
    err = ServiceErrorResponse.decode(body)
    raise NotFoundResponse.new(err)
    when 503
    * err = ServiceErrorResponse.decode(body)*
    * raise GatewayInternalResponse.new(err)*
    else
    begin
    # try to decode the response
    err = ServiceErrorResponse.decode(body)
    rescue => e
    raise UnexpectedResponse, "Can't decode gateway response. status
    code:#{code}, response body:#{body}"
    end
    raise ErrorResponse.new(code, err)
    end

    =============== vmc client ===================

    ubuntu@ubuntu:~$ vmc create-service
    1: mysql 5.1
    2: redis 2.2
    3: redis 2.4
    4: redis 2.6
    What kind?> 1

    Name?> mysql-d603

    Creating service mysql-d603... FAILED
    CFoundry::ServiceGatewayError: 503: Unexpected response from service
    gateway
    For more information, see ~/.vmc/crash
    ubuntu@ubuntu:~$


    ubuntu@ubuntu:~$ more ~/.vmc/crash
    Time of crash:
    2013-03-06 08:26:12 +0800

    CFoundry::ServiceGatewayError: 503: Unexpected response from service
    gateway

    cfoundry-0.4.21/lib/cfoundry/v1/base.rb:113:in `handle_response'
    cfoundry-0.4.21/lib/cfoundry/baseclient.rb:146:in `block in request_uri'
    /home/ubuntu/.rvm/rubies/ruby-1.9.2-p320/lib/ruby/1.9.1/net/http.rb:627:in
    `start'
    cfoundry-0.4.21/lib/cfoundry/baseclient.rb:127:in `request_uri'
    cfoundry-0.4.21/lib/cfoundry/baseclient.rb:48:in `request'
    cfoundry-0.4.21/lib/cfoundry/baseclient.rb:44:in `request_path'
    cfoundry-0.4.21/lib/cfoundry/baseclient.rb:193:in `request_with_options'
    cfoundry-0.4.21/lib/cfoundry/baseclient.rb:205:in `post'
    cfoundry-0.4.21/lib/cfoundry/v1/model_magic.rb:34:in `block (2 levels) in
    define_client_methods'
    cfoundry-0.4.21/lib/cfoundry/v1/model.rb:72:in `create!'
    vmc-0.4.7/lib/vmc/cli/service/create.rb:94:in `block in create_service'
    interact-0.5.2/lib/interact/progress.rb:98:in `with_progress'
    vmc-0.4.7/lib/vmc/cli/service/create.rb:93:in `create_service'
    mothership-0.3.5/lib/mothership/base.rb:61:in `run'
    mothership-0.3.5/lib/mothership/command.rb:68:in `block in invoke'
    mothership-0.3.5/lib/mothership/command.rb:82:in `instance_exec'
    mothership-0.3.5/lib/mothership/command.rb:82:in `invoke'
    mothership-0.3.5/lib/mothership/base.rb:50:in `execute'
    vmc-0.4.7/lib/vmc/cli.rb:106:in `execute'
    mothership-0.3.5/lib/mothership.rb:45:in `start'
    vmc-0.4.7/bin/vmc:11:in `<top (required)>'
    ruby-1.9.2-p320/bin/vmc:19:in `load'
    ruby-1.9.2-p320/bin/vmc:19:in `<main>'
    ruby-1.9.2-p320/bin/ruby_noexec_wrapper:14:in `eval'
    ruby-1.9.2-p320/bin/ruby_noexec_wrapper:14:in `<main>'

    =============== mysql gateway ===================

    [2013-03-06 08:45:04.400024] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Create service request: {"label":"mysql-5.1","description":"MySQL
    database","provider":"core","url":"http://10.10.3.28:49236
    ","plans":["free"],"cf_plan_id":{"free":null},"default_plan":"free","tags":["relational"],"active":true,"acls":null,"supported_versions":["5.1"],"version_aliases":{"current":"5.1"},"timeout":10}
    [2013-03-06 08:45:04.403634] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Found svc = #<Service id: 1, label: "mysql-5.1", url: "
    http://10.10.3.28:49236", token: "aaaf4eaa8c1758f66d5cb7adcb24adb9d7",
    name: "mysql", version: "5.1", description: "MySQL database", info_url:
    nil, tags: ["relational"], plans: ["free"], plan_options: nil,
    binding_options: nil, acls: nil, active: true, created_at: "2013-03-05
    11:40:01", updated_at: "2013-03-05 11:40:01", timeout: 10, cf_plan_id:
    {"free"=>nil}, provider: nil, supported_versions: ["5.1"], version_aliases:
    {"current"=>"5.1"}, default_plan: "free">
    [2013-03-06 08:45:04.422341] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Connection checked in (checked out: 2/4)
    [2013-03-06 08:45:12.236773] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Connection checked out (checked out: 3/4)
    [2013-03-06 08:45:12.238072] cc - pid=21928 tid=f312 fid=b92a DEBUG -- *Create
    service request: *{"label":"redis-2.2","description":"Redis key-value
    store","provider":"core","url":"http://10.10.3.32:54003
    ","plans":["free"],"cf_plan_id":{"free":null},"default_plan":"free","tags":["key-value","nosql"],"active":true,"acls":null,"supported_versions":["2.2","2.4","2.6"],"version_aliases":{"current":"2.2","next":"2.6"},"timeout":10}
    [2013-03-06 08:45:12.240621] cc - pid=21928 tid=f312 fid=b92a DEBUG -- *Found
    svc *= #<Service id: 2, label: "redis-2.2", url: "http://10.10.3.32:54003",
    token: "aaaf4eaa8c1758f66d5cb7adcb24adb9d7", name: "redis", version: "2.2",
    description: "Redis key-value store", info_url: nil, tags: ["key-value",
    "nosql"], plans: ["free"], plan_options: nil, binding_options: nil, acls:
    nil, active: true, created_at: "2013-03-05 14:51:16", updated_at:
    "2013-03-05 14:51:16", timeout: 10, cf_plan_id: {"free"=>nil}, provider:
    nil, supported_versions: ["2.2", "2.4", "2.6"], version_aliases:
    {"current"=>"2.2", "next"=>"2.6"}, default_plan: "free">
    [2013-03-06 08:45:12.258452] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Connection checked in (checked out: 2/4)
    [2013-03-06 08:45:24.176979] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Connection checked out (checked out: 3/4)
    [2013-03-06 08:45:24.178369] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    user_email decoded from token is "te...@xxx.cn <javascript:>"
    [2013-03-06 08:45:27.415240] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Connection checked in (checked out: 2/4)
    [2013-03-06 08:45:49.146324] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Connection checked out (checked out: 3/4)
    [2013-03-06 08:45:49.148364] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    user_email decoded from token is "te...@xxx.cn <javascript:>"
    [2013-03-06 08:45:49.151511] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Global service listing found 2 services.
    [2013-03-06 08:45:49.155587] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Connection checked in (checked out: 2/4)
    [2013-03-06 08:45:52.235458] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Connection checked out (checked out: 3/4)
    [2013-03-06 08:45:52.237222] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    user_email decoded from token is "te...@xxx.cn <javascript:>"
    [2013-03-06 08:45:52.238993] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Attempting to provision service:
    {"name":"mysql-d603","type":"database","vendor":"mysql","version":"5.1","tier":"free"}
    [2013-03-06 08:45:52.261906] cc - pid=21928 tid=f312 fid=b92a ERROR -- *Error
    talking to gateway: Reponse status:503,error:[{:code=>30600,
    :description=>"Service unavailable"}]*
    [2013-03-06 08:45:52.262439] cc exception pid=21928 tid=f312 fid=b92a
    ERROR --
    VCAP::Services::Api::ServiceGatewayClient::GatewayInternalResponse<<Reponse
    status:503,error:[{:code=>30600, :description=>"Service unavailable"}]:*
    /var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/vcap_common-2.0.7/lib/services/api/clients/service_gateway_client.rb:17
    *2:in
    `perform_request',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/vcap_common-2.0.7/lib/services/api/clients/service_gateway_client.rb:77:in
    `provision',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/app/models/service_config.rb:61:in
    `block in
    provision',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/connection_adapters/abstract/database_statements.rb:139:in
    `transaction',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/transactions.rb:207:in
    `transaction',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/app/models/service_config.rb:42:in
    `provision',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/app/controllers/legacy_services_controller.rb:64:in
    `provision',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/implicit_render.rb:4:in
    `send_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/base.rb:150:in
    `process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/rendering.rb:11:in
    `process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/callbacks.rb:18:in
    `block in
    process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/callbacks.rb:441:in
    `_run__385464964305857824__process_action__2444828834671554956__callbacks',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/callbacks.rb:410:in
    `_run_process_action_callbacks',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/callbacks.rb:94:in
    `run_callbacks',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/callbacks.rb:17:in
    `process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/rescue.rb:17:in
    `process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/instrumentation.rb:30:in
    `block in
    process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/notifications.rb:52:in
    `block in
    instrument',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/notifications/instrumenter.rb:21:in
    `instrument',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/notifications.rb:52:in
    `instrument',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/instrumentation.rb:29:in
    `process_action',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/app/controllers/application_controller.rb:16:in
    `process_action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/base.rb:119:in
    `process',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/abstract_controller/rendering.rb:41:in
    `process',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal.rb:138:in
    `dispatch',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal/rack_delegation.rb:14:in
    `dispatch',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_controller/metal.rb:178:in
    `block in
    action',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/routing/route_set.rb:68:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/routing/route_set.rb:68:in
    `dispatch',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/routing/route_set.rb:33:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/route_set.rb:148:in
    `block in
    call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/code_generation.rb:93:in
    `block in
    recognize',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/code_generation.rb:68:in
    `optimized_each',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/code_generation.rb:92:in
    `recognize',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-mount-0.6.14/lib/rack/mount/route_set.rb:139:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/routing/route_set.rb:499:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/best_standards_support.rb:17:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/head.rb:14:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-1.2.7/lib/rack/methodoverride.rb:24:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/params_parser.rb:21:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/cookies.rb:302:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/query_cache.rb:32:in
    `block in
    call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/connection_adapters/abstract/query_cache.rb:28:in
    `cache',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/query_cache.rb:12:in
    `cache',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/query_cache.rb:31:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activerecord-3.0.20/lib/active_record/connection_adapters/abstract/connection_pool.rb:354:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/callbacks.rb:46:in
    `block in
    call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/activesupport-3.0.20/lib/active_support/callbacks.rb:416:in
    `_run_call_callbacks',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/callbacks.rb:44:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-1.2.7/lib/rack/sendfile.rb:106:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/remote_ip.rb:48:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/actionpack-3.0.20/lib/action_dispatch/middleware/show_exceptions.rb:47:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/railties-3.0.20/lib/rails/rack/logger.rb:13:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/rack/fiber_pool.rb:19:in
    `block in
    call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/fiber_pool.rb:48:in
    `call',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/fiber_pool.rb:48:in
    `block (3 levels) in
    initialize',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/fiber_pool.rb:47:in
    `loop',/var/vcap/packages/cloud_controller/cloud_controller/vendor/bundle/ruby/1.9.1/gems/rack-fiber_pool-0.9.1/lib/fiber_pool.rb:47:in
    `block (2 levels) in
    initialize',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/config/initializers/fiber_connection_pool.rb:11:in
    `call',/var/vcap/data/packages/cloud_controller/75.1-dev.1/cloud_controller/config/initializers/fiber_connection_pool.rb:11:in
    `block in initialize'>>
    [2013-03-06 08:45:52.276929] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Connection checked in (checked out: 2/4)
    [2013-03-06 08:46:04.489454] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Connection checked out (checked out: 3/4)
    [2013-03-06 08:46:04.491304] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Create service request: {"label":"mysql-5.1","description":"MySQL
    database","provider":"core","url":"http://10.10.3.28:49236
    ","plans":["free"],"cf_plan_id":{"free":null},"default_plan":"free","tags":["relational"],"active":true,"acls":null,"supported_versions":["5.1"],"version_aliases":{"current":"5.1"},"timeout":10}
    [2013-03-06 08:46:04.494864] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Found svc = #<Service id: 1, label: "mysql-5.1", url: "
    http://10.10.3.28:49236", token: "aaaf4eaa8c1758f66d5cb7adcb24adb9d7",
    name: "mysql", version: "5.1", description: "MySQL database", info_url:
    nil, tags: ["relational"], plans: ["free"], plan_options: nil,
    binding_options: nil, acls: nil, active: true, created_at: "2013-03-05
    11:40:01", updated_at: "2013-03-05 11:40:01", timeout: 10, cf_plan_id:
    {"free"=>nil}, provider: nil, supported_versions: ["5.1"], version_aliases:
    {"current"=>"5.1"}, default_plan: "free">
    [2013-03-06 08:46:04.510592] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Connection checked in (checked out: 2/4)
    [2013-03-06 08:46:12.302670] cc - pid=21928 tid=f312 fid=b92a DEBUG --
    Connection checked out (checked out: 3/4)

    =============== mysql node ===================

    [2013-03-06 09:02:01.347601] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
    DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:02:31.381183] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
    DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:03:01.448431] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
    DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:03:31.521892] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
    DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:04:01.591951] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
    DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:04:31.670580] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
    DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:05:01.742284] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
    DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:05:31.813634] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
    DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:06:01.874919] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
    DEBUG -- MyaaS-Node: Sending announcement for everyone
    [2013-03-06 09:06:31.932898] mysql_node_1 - pid=3044 tid=1dc1 fid=f121
    DEBUG -- MyaaS-Node: Sending announcement for everyone


    Rice

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupvcap-dev @
postedMar 6, '13 at 1:14a
activeMar 7, '13 at 8:07a
posts3
users2

People

Translate

site design / logo © 2021 Grokbase