Hi, Tom,

Thanks for the logs. From the getaddrinfo error in the CC logs, it looks
like CC is unable to resolve the nsync-listener service via Consul DNS on
the expected nsync.service.cf.internal domain. So it could be a problem on
that CC VM, or on the CC-Bridge VM(s), or with the consul server cluster
itself. Here are some things to check next:

On that CC VM:
- Does monit report that the consul_agent job is running?
- Does running `netstat -anp | grep consul` show that the consul process
is listening on port 53, and that it has a connection established to port
8300 on one of the consul server VMs?
- Are there warnings or errors that look like they could be relevant in
`/var/vcap/sys/log/consul_agent/consul_agent.stdout.log` or
`/var/vcap/sys/log/consul_agent/consul_agent.stdout.log`?
- What's the output of `nslookup nsync.service.cf.internal` or `dig
nsync.service.cf.internal`?
- Does running `/var/vcap/packages/consul/bin/consul members` list a
cc-bridge agent node for each CC-Bridge VM in your deployment, and a consul
server node for each consul server in your deployment?

On each CC-Bridge VM (you may have only one):
- Does monit report that the nsync_listener and consul_agent jobs are both
running?
- Does running `netstat -anp | grep nsync` report that the nsync-listener
process is listening on port 8787?
- Does running `netstat -anp | grep consul` show that the consul process
is listening on port 53, and that it has a connection established to port
8300 on one of the consul server VMs?
- Does /var/vcap/jobs/consul_agent/config/service-nsync.json exist and
contain JSON like
`{"service":{"name":"nsync","check":{"script":"/var/vcap/jobs/nsync/bin/dns_health_check","interval":"3s"},"tags":["cc-bridge-z1-0"]}}`?
- Are there warnings or errors that look like they could be relevant in
`/var/vcap/sys/log/consul_agent/consul_agent.stdout.log` or
`/var/vcap/sys/log/consul_agent/consul_agent.stdout.log`?

On the consul server VMs:
- Does monit report that the consul_agent job is running?
- Are there warnings or errors that look like they could be relevant in
`/var/vcap/sys/log/consul_agent/consul_agent.stdout.log` or
`/var/vcap/sys/log/consul_agent/consul_agent.stdout.log`?

Thanks,
Eric


On Thu, Dec 10, 2015 at 5:01 AM, Tom Sherrod <tom.sherrod(a)gmail.com>
wrote:

Hi Eric,

Thanks for the pointers.

`bosh vms` -- all running

Only 1 api vm running. cloud_controller_ng.log is almost constantly being
updated.

Below is the 500 error capture:


{"timestamp":1449752019.6870825,"message":"desire.app.request","log_level":"info","source":"cc.nsync.listener.client","data":{"request_guid":"e046d57f-277a-4f81-452c-3b6fb892432e::53557eba-6212-4727-9b43-ebbb03426b76","process_guid":"9f528159-1a7b-4876-92c9-34d040e9824d-29fd370c-04fd-4481-b432-39431460a963"},"thread_id":69975079694320,"fiber_id":69975079888800,"process_id":6524,"file":"/var/vcap/data/packages/cloud_controller_ng/80b067d32996057a4fc88fe1c553764671e7e8e8.1-1ea6a37e7b427cc868c0727a4bfec391725a79ab/cloud_controller_ng/lib/cloud_controller/diego/nsync_client.rb","lineno":15,"method":"desire_app"}

{"timestamp":1449752019.6899576,"message":"Cannot communicate with diego
- tried to send
start","log_level":"error","source":"cc.diego.runner","data":{"request_guid":"e046d57f-277a-4f81-452c-3b6fb892432e::53557eba-6212-4727-9b43-ebbb03426b76"},"thread_id":69975079694320,"fiber_id":69975079888800,"process_id":6524,"file":"/var/vcap/data/packages/cloud_controller_ng/80b067d32996057a4fc88fe1c553764671e7e8e8.1-1ea6a37e7b427cc868c0727a4bfec391725a79ab/cloud_controller_ng/lib/cloud_controller/diego/runner.rb","lineno":43,"method":"rescue
in with_logging"}

{"timestamp":1449752019.6909509,"message":"Request failed: 500:
{\"code\"=>10001, \"description\"=>\"getaddrinfo: Name or service not
known\", \"error_code\"=>\"CF-CannotCommunicateWithDiegoError\",
\"backtrace\"=>[\"/var/vcap/data/packages/cloud_controller_ng/80b067d32996057a4fc88fe1c553764671e7e8e8.1-1ea6a37e7b427cc868c0727a4bfec391725a79ab/cloud_controller_ng/lib/cloud_controller/diego/runner.rb:44:in
`rescue in with_logging'\",
\"/var/vcap/data/packages/cloud_controller_ng/80b067d32996057a4fc88fe1c553764671e7e8e8.1-1ea6a37e7b427cc868c0727a4bfec391725a79ab/cloud_controller_ng/lib/cloud_controller/diego/runner.rb:40:in
`with_logging'\",
\"/var/vcap/data/packages/cloud_controller_ng/80b067d32996057a4fc88fe1c553764671e7e8e8.1-1ea6a37e7b427cc868c0727a4bfec391725a79ab/cloud_controller_ng/lib/cloud_controller/diego/runner.rb:19:in
`start'\",
\"/var/vcap/data/packages/cloud_controller_ng/80b067d32996057a4fc88fe1c553764671e7e8e8.1-1ea6a37e7b427cc868c0727a4bfec391725a79ab/cloud_controller_ng/lib/cloud_controller/app_observer.rb:63:in
`react_to_state_change'\",
\"/var/vcap/data/packages/cloud_controller_ng/80b067d32996057a4fc88fe1c553764671e7e8e8.1-1ea6a37e7b427cc868c0727a4bfec391725a79ab/cloud_controller_ng/lib/cloud_controller/app_observer.rb:31:in
`updated'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/app/models/runtime/app.rb:574:in
`after_commit'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.21.0/lib/sequel/model/base.rb:1920:in
`block in _save'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.21.0/lib/sequel/database/transactions.rb:280:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.21.0/lib/sequel/database/transactions.rb:280:in
`block in remove_transaction'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.21.0/lib/sequel/database/transactions.rb:280:in
`each'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.21.0/lib/sequel/database/transactions.rb:280:in
`remove_transaction'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.21.0/lib/sequel/database/transactions.rb:156:in
`_transaction'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.21.0/lib/sequel/database/transactions.rb:108:in
`block in transaction'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.21.0/lib/sequel/database/connecting.rb:250:in
`block in synchronize'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.21.0/lib/sequel/connection_pool/threaded.rb:98:in
`hold'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.21.0/lib/sequel/database/connecting.rb:250:in
`synchronize'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.21.0/lib/sequel/database/transactions.rb:97:in
`transaction'\",
\"/var/vcap/data/packages/cloud_controller_ng/80b067d32996057a4fc88fe1c553764671e7e8e8.1-1ea6a37e7b427cc868c0727a4bfec391725a79ab/cloud_controller_ng/app/controllers/base/model_controller.rb:66:in
`update'\",
\"/var/vcap/data/packages/cloud_controller_ng/80b067d32996057a4fc88fe1c553764671e7e8e8.1-1ea6a37e7b427cc868c0727a4bfec391725a79ab/cloud_controller_ng/app/controllers/base/base_controller.rb:78:in
`dispatch'\",
\"/var/vcap/data/packages/cloud_controller_ng/80b067d32996057a4fc88fe1c553764671e7e8e8.1-1ea6a37e7b427cc868c0727a4bfec391725a79ab/cloud_controller_ng/lib/cloud_controller/rest_controller/routes.rb:16:in
`block in define_route'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1609:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1609:in
`block in compile!'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in
`[]'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in
`block (3 levels) in route!'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:993:in
`route_eval'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in
`block (2 levels) in route!'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in
`block in process_route'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in
`catch'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in
`process_route'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:972:in
`block in route!'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in
`each'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in
`route!'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1084:in
`block in dispatch!'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in
`block in invoke'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in
`catch'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in
`invoke'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in
`dispatch!'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in
`block in call!'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in
`block in invoke'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in
`catch'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in
`invoke'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in
`call!'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/nulllogger.rb:9:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/head.rb:13:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/urlmap.rb:66:in
`block in call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in
`each'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/middleware/request_logs.rb:21:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/middleware/vcap_request_id.rb:14:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/middleware/cors.rb:47:in
`call_app'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/middleware/cors.rb:12:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/middleware/request_metrics.rb:12:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/builder.rb:153:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/thin-1.6.3/lib/thin/connection.rb:86:in
`block in pre_process'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/thin-1.6.3/lib/thin/connection.rb:84:in
`catch'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/thin-1.6.3/lib/thin/connection.rb:84:in
`pre_process'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/eventmachine-1.0.8/lib/eventmachine.rb:1062:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/eventmachine-1.0.8/lib/eventmachine.rb:1062:in
`block in
spawn_threadpool'\"]}","log_level":"error","source":"cc.api","data":{"request_guid":"e046d57f-277a-4f81-452c-3b6fb892432e::53557eba-6212-4727-9b43-ebbb03426b76"},"thread_id":69975079694320,"fiber_id":69975079888800,"process_id":6524,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/lib/sinatra/vcap.rb","lineno":53,"method":"block
in registered"}

{"timestamp":1449752019.691719,"message":"Completed 500 vcap-request-id:
e046d57f-277a-4f81-452c-3b6fb892432e::53557eba-6212-4727-9b43-ebbb03426b76","log_level":"info","source":"cc.api","data":{},"thread_id":69975079694320,"fiber_id":69975079888800,"process_id":6524,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/middleware/request_logs.rb","lineno":23,"method":"call"}

On Wed, Dec 9, 2015 at 5:53 PM, Eric Malm <emalm(a)pivotal.io> wrote:

Hi, Tom,

It may be that Cloud Controller is unable to resolve the consul-provided
DNS entries for the CC-Bridge components, as that '10001 Unknown Error' 500
response sounds like this bug in the Diego tracker:
https://www.pivotaltracker.com/story/show/104066600. That 500 response
should be reflected as some sort of error in the CC log file, located by
default in /var/vcap/sys/log/cloud_controller_ng/cloud_controller_ng.log on
your CC VMs. It may even be helpful to follow that log in real-time with
`tail -f` while you try starting the Diego-targeted app via the CLI. To be
sure you capture it, you should tail that log file on each CC in your
deployment. In any case, a stack trace associated to that error would
likely help us identify what to check next.

Also, does `bosh vms` report any failing VMs in either the CF or the
Diego deployments?

Best,
Eric

On Wed, Dec 9, 2015 at 2:27 PM, Tom Sherrod <tom.sherrod(a)gmail.com>
wrote:

I'm giving CF 225 and diego 0.1441.0 a run.
CF 225 is up and app deployed.
Stop app. cf enable-diego app. Start app:
FAILED
Server error, status code: 500, error code: 10001, message: An unknown
error occurred.
FAILED
Server error, status code: 500, error code: 10001, message: An unknown
error occurred.

CF_TRACE ends with:
REQUEST: [2015-12-09T17:17:37-05:00]
PUT
/v2/apps/02c68ddd-0596-4aab-8c05-a8f538d06712?async=true&inline-relations-depth=1
HTTP/1.1
Host: api.dev.foo.com
Accept: application/json
Authorization: [PRIVATE DATA HIDDEN]
Content-Type: application/json
User-Agent: go-cli 6.14.0+2654a47 / darwin

{"state":"STARTED"}

RESPONSE: [2015-12-09T17:17:37-05:00]
HTTP/1.1 500 Internal Server Error
Content-Length: 99
Content-Type: application/json;charset=utf-8
Date: Wed, 09 Dec 2015 22:17:36 GMT
Server: nginx
X-Cf-Requestid: 6edf0ac8-384f-4db3-576a-6744b7eb4b8c
X-Content-Type-Options: nosniff
X-Vcap-Request-Id:
860d73f9-9415-478f-6c60-13e2e5ddde8c::80a4a687-7f2d-44c5-9b09-4e3c9fa07b68

{
"error_code": "UnknownError",
"description": "An unknown error occurred.",
"code": 10001
}


Where next to look for the broken piece?