echo service not displaying in vmc service list

Mike Reeves

unread,

Oct 11, 2012, 1:53:48 PM10/11/12

to vcap...@cloudfoundry.org

I added the echo service and found that while it is started by cf with the "~/cloudfoundry/vcap/dev_setup/bin/vcap_dev restart" as per the docs (https://github.com/cloudfoundry/oss-docs/tree/master/vcap/adding_a_system_service) and it does not show up in the vmc service list and cannot be provisioned as a service.

cloud_controller : RUNNING
router : RUNNING
stager : RUNNING
health_manager : RUNNING
dea : RUNNING
uaa : RUNNING
redis_node : RUNNING
mysql_node : RUNNING
mongodb_node : RUNNING
rabbitmq_node : RUNNING
postgresql_node : RUNNING
vblob_node : RUNNING
redis_gateway : RUNNING
mysql_gateway : RUNNING
mongodb_gateway : RUNNING
rabbitmq_gateway : RUNNING
postgresql_gateway : RUNNING
vblob_gateway : RUNNING
filesystem_gateway : RUNNING
echo_node : RUNNING
echo_gateway : RUNNING
cfadmin@sclu128:~$ vmc target api.vcap.me
Successfully targeted to [http://api.vcap.me]

cfadmin@sclu128:~$ vmc services

============== System Services ==============

=========== Provisioned Services ============

cfadmin@sclu128:~$

When I issue the vmc create-service echo myecho i get -

cfadmin@sclu128:~$ vmc create-service echo myecho
Creating Service: Service [echo] is not a valid service choice

cfadmin@sclu128:~$

Nicholas Kushmerick

unread,

Oct 11, 2012, 2:03:18 PM10/11/12

to vcap...@cloudfoundry.org

Can you please inspect echo_{gateway,node} and cloud_controller logs to see if you find an error/warning/fatal messages?

Mike Reeves

unread,

Oct 15, 2012, 9:45:48 AM10/15/12

to vcap...@cloudfoundry.org

From the echo_gateway log -

[2012-10-11 12:11:28.832292] echo_gateway - pid=31462 tid=22c9 fid=09ef INFO -- Fetching handles from cloud controller @ http://api.vcap.me/services/v1/offerings/echo-1.0/handles

[2012-10-11 12:11:28.920515] echo_gateway - pid=31462 tid=22c9 fid=09ef ERROR -- Failed fetching handles, status=404

[2012-10-11 12:11:29.588243] echo_gateway - pid=31462 tid=22c9 fid=09ef DEBUG -- [EchoaaS-Provisioner] Received node announcement: {"available_capacity":200,"capacity_unit":1,"id":"echo_node_1","plan":"free","supported_versions":["1.0"]}

From the cloud-controller log -

[2012-10-15 09:43:09.665888] cc_events - pid=17127 tid=82e6 fid=77cd INFO -- [2012-10-15 09:43:09 -0400, :USER, "N/A", "POST:/services/v1/offerings", :SUCCEEDED]

[2012-10-15 09:43:09.666206] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Connection checked in (checked out: 2/4)

[2012-10-15 09:43:10.187237] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Connection checked out (checked out: 3/4)

[2012-10-15 09:43:10.190211] cc_events - pid=17127 tid=82e6 fid=77cd INFO -- [2012-10-15 09:43:10 -0400, :USER, "N/A", "GET:/services/v1/offerings/echo-1.0/handles", :FAILED, "Service not found"]

[2012-10-15 09:43:10.190569] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Connection checked in (checked out: 2/4)

[2012-10-15 09:43:11.358825] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Connection checked out (checked out: 3/4)

[2012-10-15 09:43:11.361746] cc_events - pid=17127 tid=82e6 fid=77cd INFO -- [2012-10-15 09:43:11 -0400, :USER, "N/A", "GET:/services/v1/offerings/echo-1.0/handles", :FAILED, "Service not found"]

[2012-10-15 09:43:11.362104] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Connection checked in (checked out: 2/4)

[2012-10-15 09:43:12.530138] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Connection checked out (checked out: 3/4)

[2012-10-15 09:43:12.533181] cc_events - pid=17127 tid=82e6 fid=77cd INFO -- [2012-10-15 09:43:12 -0400, :USER, "N/A", "GET:/services/v1/offerings/echo-1.0/handles", :FAILED, "Service not found"]

[2012-10-15 09:43:12.533540] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Connection checked in (checked out: 2/4)

[2012-10-15 09:43:13.701546] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Connection checked out (checked out: 3/4)

[2012-10-15 09:43:13.704563] cc_events - pid=17127 tid=82e6 fid=77cd INFO -- [2012-10-15 09:43:13 -0400, :USER, "N/A", "GET:/services/v1/offerings/echo-1.0/handles", :FAILED, "Service not found"]

[2012-10-15 09:43:13.704925] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Connection checked in (checked out: 2/4)

[2012-10-15 09:43:14.870785] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Connection checked out (checked out: 3/4)

[2012-10-15 09:43:14.873678] cc_events - pid=17127 tid=82e6 fid=77cd INFO -- [2012-10-15 09:43:14 -0400, :USER, "N/A", "GET:/services/v1/offerings/echo-1.0/handles", :FAILED, "Service not found"]

[2012-10-15 09:43:14.874038] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Connection checked in (checked out: 2/4)

[2012-10-15 09:43:15.357453] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Connection checked out (checked out: 3/4)

[2012-10-15 09:43:15.358787] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Create service request: {"label":"rabbitmq-2.4","url":"http://10.13.181.128:53789","plans":["free"],"cf_plan_id":null,"tags":["message-queue","amqp"],"active":true,"description":"RabbitMQ message queue","plan_options":null,"acls":null,"timeout":15,"provider":null,"default_plan":"free","supported_versions":["2.4"],"version_aliases":{"current":"2.4"}}

[2012-10-15 09:43:15.361555] cc - pid=17127 tid=82e6 fid=77cd DEBUG -- Found svc = #<Service id: 4, label: "rabbitmq-2.4", url: "http://10.13.181.128:53789", token: "changerabbitmqtoken", name: "rabbitmq", version: "2.4", description: "RabbitMQ message queue", info_url: ni

Nicholas Kushmerick

unread,

Oct 15, 2012, 11:08:50 AM10/15/12

to vcap...@cloudfoundry.org

i'm confused: the gateway logs are 4 days earlier than the CC logs. so I think that either

the logs really are garbled -- in that case can you get some from the same time; also please adjust logging level to DEBUG so we'll see some missing messages
echo_gateway and cloud_controller are running on different hosts with huge clock skew. But the "vcap.me" domain requires that gateways & cc (and other stuff) all run on a single host -- so you need to use a custom domain, something like this: https://github.com/cloudfoundry/vcap/blob/master/dev_setup/deployments/sample/multihost_router/rest.yml#L3

Mike Reeves

unread,

Oct 15, 2012, 11:56:39 AM10/15/12

to vcap...@cloudfoundry.org

These are running ont he same machine. The point is not the time difference but the errors. I restarted cf and synced the time.

cloud_controller log -

[2012-10-15 11:39:53.768782] cc - pid=2414 tid=0d40 fid=e8f5 ERROR -- Failure decoding service offering request: Field: supported_versions, Error: Missing field supported_versions, Field: version_aliases, Error: Missing field version_aliases

[2012-10-15 11:39:53.769587] cc_events - pid=2414 tid=0d40 fid=e8f5 INFO -- [2012-10-15 11:39:53 -0400, :USER, "N/A", "POST:/services/v1/offerings", :SUCCEEDED]

[2012-10-15 11:39:53.769819] cc - pid=2414 tid=0d40 fid=e8f5 DEBUG -- Connection checked in (checked out: 2/3)

[2012-10-15 11:39:53.770380] cc - pid=2414 tid=0d40 fid=e8f5 DEBUG -- Connection checked out (checked out: 3/3)

[2012-10-15 11:39:53.773011] cc_events - pid=2414 tid=0d40 fid=e8f5 INFO -- [2012-10-15 11:39:53 -0400, :USER, "N/A", "GET:/services/v1/offerings/echo-1.0/handles", :FAILED, "Service not found"]

[2012-10-15 11:39:53.773211] cc - pid=2414 tid=0d40 fid=e8f5 DEBUG -- Connection checked in (checked out: 2/3)

[2012-10-15 11:39:54.621453] cc - pid=2414 tid=0d40 fid=e8f5 DEBUG -- Connection checked out (checked out: 3/3)

[2012-10-15 11:39:54.623329] cc_events - pid=2414 tid=0d40 fid=e8f5 INFO -- [2012-10-15 11:39:54 -0400, :USER, "N/A", "GET:/services/v1/offerings/echo-1.0/handles", :FAILED, "Service not found"]

[2012-10-15 11:39:54.623534] cc - pid=2414 tid=0d40 fid=e8f5 DEBUG -- Connection checked in (checked out: 2/3)

[2012-10-15 11:39:55.790535] cc - pid=2414 tid=0d40 fid=e8f5 DEBUG -- Connection checked out (checked out: 3/3)

gateway log -

[2012-10-15 11:39:53.464144] echo_gateway - pid=4297 tid=658d fid=4131 INFO -- EchoaaS-Provisioner: Initializing
[2012-10-15 11:39:53.471642] echo_gateway - pid=4297 tid=658d fid=4131 DEBUG -- Register update handle callback with #<Proc:0x000000034a3cd0@/home/cfadmin/cloudfoundry/.deployments/devbox/deploy/rubies/ruby-1.9.2-p180/lib/ruby/gems/1.9.1/bundler/gems/vcap-services-base-e54a821c72f1/lib/base/asynchronous_service_gateway.rb:130>

>> Thin web server (v1.3.1 codename Triple Espresso)

>> Maximum connections set to 1024

>> Listening on 10.13.181.128:58103, CTRL+C to stop

[2012-10-15 11:39:53.570505] echo_gateway - pid=4297 tid=658d fid=4131 INFO -- Sending info to cloud controller: http://api.vcap.me/services/v1/offerings

[2012-10-15 11:39:53.656392] echo_gateway - pid=4297 tid=658d fid=4131 INFO -- Fetching handles from cloud controller @ http://api.vcap.me/services/v1/offerings/echo-1.0/handles

[2012-10-15 11:39:53.765393] echo_gateway - pid=4297 tid=658d fid=4131 DEBUG -- [EchoaaS-Provisioner] Connected to node mbus..

[2012-10-15 11:39:53.775066] echo_gateway - pid=4297 tid=658d fid=4131 ERROR -- Failed registering with cloud controller, status=400

[2012-10-15 11:39:53.775201] echo_gateway - pid=4297 tid=658d fid=4131 ERROR -- Failed fetching handles, status=404

[2012-10-15 11:39:53.815328] echo_gateway - pid=4297 tid=658d fid=4131 DEBUG -- [EchoaaS-Provisioner] Received node announcement: {"available_capacity":100,"capacity_unit":1,"id":"echo_node_0","plan":"free","supported_versions":["1.0"]}

[2012-10-15 11:39:54.536697] echo_gateway - pid=4297 tid=658d fid=4131 INFO -- Fetching handles from cloud controller @ http://api.vcap.me/services/v1/offerings/echo-1.0/handles

[2012-10-15 11:39:54.624074] echo_gateway - pid=4297 tid=658d fid=4131 ERROR -- Failed fetching handles, status=404

[2012-10-15 11:39:55.705840] echo_gateway - pid=4297 tid=658d fid=4131 INFO -- Fetching handles from cloud controller @ http://api.vcap.me/services/v1/offerings/echo-1.0/handles

[2012-10-15 11:39:55.793124] echo_gateway - pid=4297 tid=658d fid=4131 ERROR -- Failed fetching handles, status=404

[2012-10-15 11:39:56.874788] echo_gateway - pid=4297 tid=658d fid=4131 INFO -- Fetching handles from cloud controller @ http://api.vcap.me/services/v1/offerings/echo-1.0/handles

[2012-10-15 11:39:56.991443] echo_gateway - pid=4297 tid=658d fid=4131 ERROR -- Failed fetching handles, status=404

Nicholas Kushmerick

unread,

Oct 15, 2012, 12:41:56 PM10/15/12

to vcap...@cloudfoundry.org

ok, the error listed at the top is the log: recently, the CC/GW protocol was modified to require some new fields. echo_gateway was updated (https://github.com/cloudfoundry/vcap/commit/237eb7a758e38cafb2e8c7ebe40c5f9178d03897#L6R10) to support this new protocol, but it seems that your echo_gateway.yml does not have these properties? (I see that Step 4 in https://github.com/cloudfoundry/oss-docs/blob/master/vcap/adding_a_system_service/README.md is stale: the gateway config should look like this:

service:  
   name: echo  
   version: "1.0"  
   description: 'Echo key-value store service'  
   plans: ['free']  
   tags: ['echo', 'echo-1.0', 'echobased', 'demo']
   supported_versions: ["1.0']
   version_aliases:
     "current": "1.0"

)

--
Nick
phone +1.206.293.5186 · skype nicholaskushmerick

Mike Reeves

unread,

Oct 15, 2012, 1:19:47 PM10/15/12

to vcap...@cloudfoundry.org

Hmm! I get the followning when I put this in -

   supported_versions: ["1.0']
   version_aliases:
     "current": "1.0"

I also tried -

   supported_versions: ['1.0']
   version_aliases:
     "current": "1.0"

Same results.

/home/cfadmin/cloudfoundry/.deployments/devbox/deploy/rubies/ruby-1.9.2-p180/lib/ruby/1.9.1/syck.rb:135:in `load': syntax error on line 9, col 3: `   supported_versions: ["1.0']' (ArgumentError)
        from /home/cfadmin/cloudfoundry/.deployments/devbox/deploy/rubies/ruby-1.9.2-p180/lib/ruby/1.9.1/syck.rb:135:in `load'
        from /home/cfadmin/cloudfoundry/vcap/dev_setup/lib/vcap_components.rb:77:in `configuration'
        from /home/cfadmin/cloudfoundry/vcap/dev_setup/lib/vcap_components.rb:81:in `pid_file'
        from /home/cfadmin/cloudfoundry/vcap/dev_setup/lib/vcap_components.rb:296:in `pid_file'
        from /home/cfadmin/cloudfoundry/vcap/dev_setup/lib/vcap_components.rb:94:in `pid'
        from /home/cfadmin/cloudfoundry/vcap/dev_setup/lib/vcap_components.rb:103:in `running?'
        from /home/cfadmin/cloudfoundry/vcap/dev_setup/lib/vcap_components.rb:159:in `stop'
        from /home/cfadmin/cloudfoundry/vcap/dev_setup/bin/vcap:91:in `each'
        from /home/cfadmin/cloudfoundry/vcap/dev_setup/bin/vcap:91:in `stop'
        from /home/cfadmin/cloudfoundry/vcap/dev_setup/bin/vcap:96:in `restart'
        from /home/cfadmin/cloudfoundry/vcap/dev_setup/bin/vcap:357:in `<main>'

On Thursday, October 11, 2012 1:53:48 PM UTC-4, Mike Reeves wrote:

Mike Reeves

unread,

Oct 16, 2012, 10:13:36 AM10/16/12

to vcap...@cloudfoundry.org

Ok. the issue is resolved. I had to add the following code to both .deployments/devbox/config/echo_gateway.yml and /vcap/services/echo/config/echo_gateway.yml:

supported_versions: ['1.0']

version_aliases:

"current": "1.0"

Reply all

Reply to author

Forward