Warning - Instances information unavailable

[pako-grape]

Hi, I am using Diego v0.1460.0 witch CF v233, stemcell v3215 on AWS.
After pushing docker image (cloudfoundry/lattice-app), when executing:

cf restart lattice-app

I have following warning (several times):

Could not fetch instance count: Server error, status code: 503, error code: 220002, message: Instances information unavailable: getaddrinfo: No address associated with hostname

App is working, but from time to time it turns down and starts again.
Have you any idea what can be wrong?

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this. You can view the current status of your issue at: https://www.pivotaltracker.com/story/show/117134161.

[pako-grape]

Hmm... It looks rather like CF CLI issue...
Using veritas to monitor this app for over 20 minutes and it's working non stop.
When execute 'cf apps' there are above errors.
If no one has different ideas, issue can be closed...

[emalm]

Hi, @pako-grape,

If you're getting errors from Cloud Controller with getaddrinfo in the error message, it likely means that Cloud Controller is unable to resolve the CC-Bridge components via consul DNS. If this issue is ongoing, do you have any failing jobs in the deployment? The output from bosh instances --ps would be particularly useful. Could you also provide logs from the consul-agent jobs on the VMs that host CC and the CC-Bridge components? Those logs are located at /var/vcap/sys/log/consul_agent/consul_agent.stdout.log.

Thanks,
Eric, CF Runtime Diego PM

[pako-grape]

@ematpl Thanks for reply.
'bosh instances --ps' on cf deployment:

+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| Instance                                                                   | State   | AZ  | VM Type   | IPs         |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| api_z1/0 (6c1572dd-2ebf-486c-af55-e29347fe9e15)*                           | running | n/a | small_z1  | 10.10.3.5   |
|   cloud_controller_ng                                                      | running |     |           |             |
|   cloud_controller_worker_local_1                                          | running |     |           |             |
|   cloud_controller_worker_local_2                                          | running |     |           |             |
|   nginx_cc                                                                 | running |     |           |             |
|   cloud_controller_migration                                               | running |     |           |             |
|   cloud_controller_worker_1                                                | running |     |           |             |
|   cloud_controller_clock                                                   | running |     |           |             |
|   metron_agent                                                             | running |     |           |             |
|   route_registrar                                                          | running |     |           |             |
|   consul_agent                                                             | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| blobstore_z1/0 (6ed731ef-4d92-45e8-8c89-76667ee33deb)*                     | running | n/a | small_z1  | 10.10.3.4   |
|   blobstore_nginx                                                          | running |     |           |             |
|   blobstore_url_signer                                                     | running |     |           |             |
|   metron_agent                                                             | running |     |           |             |
|   route_registrar                                                          | running |     |           |             |
|   consul_agent                                                             | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| consul_z1/0 (7a23ea0c-5a29-45ee-9c86-c77dd2397e0c)*                        | running | n/a | small_z1  | 10.10.3.105 |
|   metron_agent                                                             | running |     |           |             |
|   consul_agent                                                             | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| doppler_z1/0 (186488de-808d-4375-abce-04609bd68a0a)*                       | running | n/a | small_z1  | 10.10.3.7   |
|   doppler                                                                  | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| etcd_z1/0 (d1f8fd9f-aa33-4035-a8a6-4b062e96b168)*                          | running | n/a | small_z1  | 10.10.3.104 |
|   etcd                                                                     | running |     |           |             |
|   etcd_metrics_server                                                      | running |     |           |             |
|   metron_agent                                                             | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| ha_proxy_z1/0 (b35645c9-160e-43c7-a851-625f97f34129)*                      | running | n/a | small_z1  | ########### |
|                                                                            |         |     |           | 10.10.2.11  |
|   haproxy                                                                  | running |     |           |             |
|   metron_agent                                                             | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| hm9000_z1/0 (946ad92a-6a18-486d-99c1-95125bf87ee6)*                        | running | n/a | small_z1  | 10.10.3.6   |
|   consul_agent                                                             | running |     |           |             |
|   hm9000_listener                                                          | running |     |           |             |
|   hm9000_fetcher                                                           | running |     |           |             |
|   hm9000_analyzer                                                          | running |     |           |             |
|   hm9000_sender                                                            | running |     |           |             |
|   hm9000_api_server                                                        | running |     |           |             |
|   hm9000_evacuator                                                         | running |     |           |             |
|   hm9000_shredder                                                          | running |     |           |             |
|   metron_agent                                                             | running |     |           |             |
|   route_registrar                                                          | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| loggregator_trafficcontroller_z1/0 (348c5956-41ea-41fc-b5c8-9638aed9bb91)* | running | n/a | small_z1  | 10.10.3.8   |
|   loggregator_trafficcontroller                                            | running |     |           |             |
|   metron_agent                                                             | running |     |           |             |
|   route_registrar                                                          | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| nats_z1/0 (db2895e7-96ec-44b6-8bfb-17f4852d9549)*                          | running | n/a | small_z1  | 10.10.3.103 |
|   nats                                                                     | running |     |           |             |
|   nats_stream_forwarder                                                    | running |     |           |             |
|   metron_agent                                                             | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| postgres_z1/0 (3c1f7f70-51d1-4d0d-865f-bcc3f86caeb0)*                      | running | n/a | small_z1  | 10.10.3.101 |
|   postgres                                                                 | running |     |           |             |
|   metron_agent                                                             | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| router_z1/0 (31c06994-10de-4021-9ffb-ee52fbce28f4)*                        | running | n/a | small_z1  | 10.10.3.102 |
|   gorouter                                                                 | running |     |           |             |
|   metron_agent                                                             | running |     |           |             |
|   consul_agent                                                             | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| runner_z1/0 (910ca2ef-203c-409e-b43e-ff714383fd08)*                        | running | n/a | runner_z1 | 10.10.3.10  |
|   consul_agent                                                             | running |     |           |             |
|   warden                                                                   | running |     |           |             |
|   dea_next                                                                 | running |     |           |             |
|   dir_server                                                               | running |     |           |             |
|   dea_logging_agent                                                        | running |     |           |             |
|   metron_agent                                                             | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+
| uaa_z1/0 (0179dd90-3b9d-4452-b24e-5f29e3e8bb01)*                           | running | n/a | small_z1  | 10.10.3.9   |
|   uaa                                                                      | running |     |           |             |
|   metron_agent                                                             | running |     |           |             |
|   route_registrar                                                          | running |     |           |             |
+----------------------------------------------------------------------------+---------+-----+-----------+-------------+

on diego deployment:

+------------------------------------------------------------+---------+-----+------------------+-----------+
| Instance                                                   | State   | AZ  | VM Type          | IPs       |
+------------------------------------------------------------+---------+-----+------------------+-----------+
| access_z1/0 (3395cbf4-884c-4c11-ac22-9752a36c8c33)*        | running | n/a | access_z1        | 10.10.5.9 |
|   consul_agent                                             | running |     |                  |           |
|   ssh_proxy                                                | running |     |                  |           |
|   metron_agent                                             | running |     |                  |           |
|   file_server                                              | running |     |                  |           |
+------------------------------------------------------------+---------+-----+------------------+-----------+
| brain_z1/0 (d771578c-f881-4742-9ef5-a0d734d306ae)*         | running | n/a | brain_z1         | 10.10.5.5 |
|   consul_agent                                             | running |     |                  |           |
|   auctioneer                                               | running |     |                  |           |
|   converger                                                | running |     |                  |           |
|   metron_agent                                             | running |     |                  |           |
+------------------------------------------------------------+---------+-----+------------------+-----------+
| cc_bridge_z1/0 (7fdfbbfe-d7d0-481f-85e7-0559bc2d6a02)*     | running | n/a | cc_bridge_z1     | 10.10.5.7 |
|   consul_agent                                             | running |     |                  |           |
|   stager                                                   | running |     |                  |           |
|   nsync_listener                                           | running |     |                  |           |
|   nsync_bulker                                             | running |     |                  |           |
|   tps_listener                                             | running |     |                  |           |
|   tps_watcher                                              | running |     |                  |           |
|   cc_uploader                                              | running |     |                  |           |
|   metron_agent                                             | running |     |                  |           |
+------------------------------------------------------------+---------+-----+------------------+-----------+
| cell_z1/0 (201df1fc-3ba6-444f-872c-c712c127027c)*          | running | n/a | cell_z1          | 10.10.5.6 |
|   consul_agent                                             | running |     |                  |           |
|   rep                                                      | running |     |                  |           |
|   garden                                                   | running |     |                  |           |
|   metron_agent                                             | running |     |                  |           |
+------------------------------------------------------------+---------+-----+------------------+-----------+
| database_z1/0 (67c516b3-3543-4d0a-9907-43cc46604d2d)*      | running | n/a | database_z1      | 10.10.5.4 |
|   consul_agent                                             | running |     |                  |           |
|   etcd                                                     | running |     |                  |           |
|   bbs                                                      | running |     |                  |           |
|   metron_agent                                             | running |     |                  |           |
+------------------------------------------------------------+---------+-----+------------------+-----------+
| route_emitter_z1/0 (651c18d2-c18e-4339-a153-14599f80f611)* | running | n/a | route_emitter_z1 | 10.10.5.8 |
|   consul_agent                                             | running |     |                  |           |
|   route_emitter                                            | running |     |                  |           |
|   metron_agent                                             | running |     |                  |           |
+------------------------------------------------------------+---------+-----+------------------+-----------+

logs from CC:

==> Starting Consul agent...
==> Starting Consul agent RPC...
==> Consul agent running!
         Node name: 'api-z1-0'
        Datacenter: 'dc1'
            Server: false (bootstrap: false)
       Client Addr: 127.0.0.1 (HTTP: 8500, HTTPS: -1, DNS: 53, RPC: 8400)
      Cluster Addr: 10.10.3.5 (LAN: 8301, WAN: 8302)
    Gossip encrypt: false, RPC-TLS: false, TLS-Incoming: false
             Atlas: <disabled>

==> Log data will now stream in as it occurs:

    2016/04/08 05:17:33 [INFO] serf: Ignoring previous leave in snapshot
    2016/04/08 05:17:33 [INFO] serf: EventMemberJoin: api-z1-0 10.10.3.5
    2016/04/08 05:17:33 [INFO] serf: Attempting re-join to previously known node: cc-bridge-z1-0: 10.10.5.7:8301
    2016/04/08 05:17:33 [ERR] agent: failed to sync remote state: No known Consul servers
    2016/04/08 05:17:33 [INFO] agent: Joining cluster...
    2016/04/08 05:17:33 [INFO] agent: (LAN) joining: [10.10.3.105]
    2016/04/08 05:17:33 [INFO] serf: EventMemberJoin: route-emitter-z1-0 10.10.5.8
    2016/04/08 05:17:33 [INFO] serf: EventMemberJoin: blobstore-z1-0 10.10.3.4
    2016/04/08 05:17:33 [INFO] serf: EventMemberJoin: brain-z1-0 10.10.5.5
    2016/04/08 05:17:33 [INFO] serf: EventMemberJoin: access-z1-0 10.10.5.9
    2016/04/08 05:17:33 [INFO] serf: EventMemberJoin: consul-z1-0 10.10.3.105
    2016/04/08 05:17:33 [INFO] serf: EventMemberJoin: hm9000-z1-0 10.10.3.6
    2016/04/08 05:17:33 [INFO] serf: EventMemberJoin: runner-z1-0 10.10.3.10
    2016/04/08 05:17:33 [INFO] serf: EventMemberJoin: router-z1-0 10.10.3.102
    2016/04/08 05:17:33 [INFO] serf: EventMemberJoin: database-z1-0 10.10.5.4
    2016/04/08 05:17:33 [INFO] serf: EventMemberJoin: cc-bridge-z1-0 10.10.5.7
    2016/04/08 05:17:33 [INFO] serf: EventMemberJoin: cell-z1-0 10.10.5.6
    2016/04/08 05:17:33 [INFO] serf: Re-joined to previously known node: cc-bridge-z1-0: 10.10.5.7:8301
    2016/04/08 05:17:33 [INFO] consul: adding server consul-z1-0 (Addr: 10.10.3.105:8300) (DC: dc1)
    2016/04/08 05:17:33 [INFO] agent: (LAN) joined: 1 Err: <nil>
    2016/04/08 05:17:33 [INFO] agent: Join completed. Synced with 1 initial agents
    2016/04/08 05:17:33 [INFO] agent: Synced service 'cloud-controller-ng'
{"timestamp":"1460092654.212332964","source":"confab","message":"confab.agent-client.verify-joined.members.request","log_level":1,"data":{"wan":false}}
{"timestamp":"1460092654.214618683","source":"confab","message":"confab.agent-client.verify-joined.members.response","log_level":1,"data":{"members":["10.10.5.5","10.10.5.9","10.10.3.10","10.10.5.7","10.10.5.6","10.10.3.5","10.10.5.8","10.10.3.4","10.10.3.105","10.10.3.6","10.10.3.102","10.10.5.4"],"wan":false}}
{"timestamp":"1460092654.214711666","source":"confab","message":"confab.agent-client.verify-joined.members.joined","log_level":1,"data":{}}
{"timestamp":"1460092654.214767694","source":"confab","message":"confab.controller.boot-agent.success","log_level":1,"data":{}}
{"timestamp":"1460092654.214818478","source":"confab","message":"confab.agent-runner.run.write-pidfile","log_level":1,"data":{"path":"/var/vcap/sys/run/consul_agent/consul_agent.pid","pid":4994}}
    2016/04/08 05:17:34 [INFO] agent: Synced check 'service:cloud-controller-ng'
    2016/04/08 05:17:37 [WARN] agent: Check 'service:cloud-controller-ng' is now critical
    2016/04/08 05:17:37 [INFO] agent: Synced check 'service:cloud-controller-ng'
    2016/04/08 05:17:40 [WARN] agent: Check 'service:cloud-controller-ng' is now critical
    2016/04/08 05:17:43 [WARN] agent: Check 'service:cloud-controller-ng' is now critical
    2016/04/08 05:17:46 [WARN] agent: Check 'service:cloud-controller-ng' is now critical
    2016/04/08 05:17:49 [INFO] agent: Synced check 'service:cloud-controller-ng'
    2016/04/08 05:18:32 [INFO] serf: EventMemberLeave: runner-z1-0 10.10.3.10
    2016/04/08 05:18:39 [INFO] serf: EventMemberJoin: runner-z1-0 10.10.3.10
    2016/04/08 05:19:46 [INFO] serf: EventMemberLeave: database-z1-0 10.10.5.4
    2016/04/08 05:20:03 [INFO] serf: EventMemberLeave: brain-z1-0 10.10.5.5
    2016/04/08 05:20:11 [INFO] serf: EventMemberJoin: brain-z1-0 10.10.5.5
    2016/04/08 05:20:14 [INFO] serf: EventMemberJoin: database-z1-0 10.10.5.4
    2016/04/08 05:20:22 [INFO] serf: EventMemberLeave: cc-bridge-z1-0 10.10.5.7
    2016/04/08 05:20:22 [INFO] serf: EventMemberLeave: access-z1-0 10.10.5.9
    2016/04/08 05:20:23 [INFO] serf: EventMemberLeave: route-emitter-z1-0 10.10.5.8
    2016/04/08 05:20:28 [INFO] serf: EventMemberJoin: route-emitter-z1-0 10.10.5.8
    2016/04/08 05:20:28 [INFO] serf: EventMemberLeave: cell-z1-0 10.10.5.6
    2016/04/08 05:20:29 [INFO] serf: EventMemberJoin: access-z1-0 10.10.5.9
    2016/04/08 05:20:34 [INFO] serf: EventMemberJoin: cc-bridge-z1-0 10.10.5.7
    2016/04/08 05:20:41 [INFO] serf: EventMemberJoin: cell-z1-0 10.10.5.6
    2016/04/08 05:36:11 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:nsync: Service 'nsync' check', dropping from service 'nsync'
    2016/04/08 05:36:11 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:nsync: Service 'nsync' check', dropping from service 'nsync'
    2016/04/08 05:36:11 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:nsync: Service 'nsync' check', dropping from service 'nsync'
    2016/04/08 05:36:11 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:nsync: Service 'nsync' check', dropping from service 'nsync'
    2016/04/08 05:36:11 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:nsync: Service 'nsync' check', dropping from service 'nsync'
    2016/04/08 05:36:11 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:nsync: Service 'nsync' check', dropping from service 'nsync'
    2016/04/08 05:36:49 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:stager: Service 'stager' check', dropping from service 'stager'
    2016/04/08 05:36:49 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:stager: Service 'stager' check', dropping from service 'stager'
    2016/04/08 05:36:53 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:nsync: Service 'nsync' check', dropping from service 'nsync'
    2016/04/08 05:36:53 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:nsync: Service 'nsync' check', dropping from service 'nsync'
    2016/04/08 05:36:54 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:nsync: Service 'nsync' check', dropping from service 'nsync'
    2016/04/08 05:36:54 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:nsync: Service 'nsync' check', dropping from service 'nsync'
    2016/04/08 05:36:54 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:nsync: Service 'nsync' check', dropping from service 'nsync'
    2016/04/08 05:36:54 [WARN] dns: node 'cc-bridge-z1-0' failing health check 'service:nsync: Service 'nsync' check', dropping from service 'nsync'

logs from CC-Bridge (content is repeated many times):

    2016/04/08 05:38:29 [WARN] agent: Check 'service:nsync' is now critical
    2016/04/08 05:38:29 [INFO] agent: Synced check 'service:nsync'
    2016/04/08 05:38:30 [WARN] agent: Check 'service:stager' is now critical
    2016/04/08 05:38:30 [INFO] agent: Synced check 'service:stager'
    2016/04/08 05:38:31 [INFO] agent: Synced check 'service:nsync'
    2016/04/08 05:38:31 [WARN] agent: Check 'service:cc-uploader' is now critical
    2016/04/08 05:38:31 [INFO] agent: Synced check 'service:cc-uploader'
    2016/04/08 05:38:32 [INFO] agent: Synced check 'service:stager'
    2016/04/08 05:38:32 [INFO] agent: Synced check 'service:cc-uploader'
    2016/04/08 05:38:32 [WARN] agent: Check 'service:tps' is now critical
    2016/04/08 05:38:32 [INFO] agent: Synced check 'service:tps'
    2016/04/08 05:38:32 [INFO] agent: Synced check 'service:tps'

[cwlbraa]

Hi @pako-grape,

It looks like bosh thinks all of your bridge jobs are operating, but consul doesn't agree. Is it possible that your bridge processes are flapping? If you could bosh ssh into that bridge VM, and watch -n0.5 monit summary for a bit, I'd be curious to see if all the processes are always up.

Additionally, do the TPS or nsync jobs have obvious error log lines?

[cwlbraa]

Also, diego-release v0.1490.0 is not a release as of yet. Our last release (yesterday) was v0.1464.0.

[emalm]

I suspect that's supposed to be 0.1460.0, based on https://github.com/cloudfoundry/cf-release/releases/tag/v233#recommended-diego-release-version.

[pako-grape]

In fact diego release is v0.1460.0. Sorry for this typo.
After over 3 minutes with 'watch -n0.5 monit summary' it seems that all jobs are running non stop.
Logs from TPS listener:

{"timestamp":"1460178373.272938728","source":"tps-listener","message":"tps-listener.exited-with-failure","log_level":2,"data":{"error":"Exit trace for group:\nregistration-runner exited with error: Put http://127.0.0.1:8500/v1/agent/service/deregister/: dial tcp 127.0.0.1:8500: getsockopt: connection refused\napi exited with nil\ndebug-server exited with nil\n"}}
{"timestamp":"1460178385.528144360","source":"tps-listener","message":"tps-listener.registration-runner.starting","log_level":1,"data":{"registration":{"Name":"tps","Port":1518,"Check":{"TTL":"3s"},"Checks":null},"service":"tps","session":"1"}}
{"timestamp":"1460178385.528466463","source":"tps-listener","message":"tps-listener.registration-runner.attempting-registering-service","log_level":1,"data":{"service":"tps","session":"1"}}
{"timestamp":"1460178385.539237261","source":"tps-listener","message":"tps-listener.registration-runner.succeeded-registering-service","log_level":1,"data":{"service":"tps","session":"1"}}
{"timestamp":"1460178385.547142506","source":"tps-listener","message":"tps-listener.registration-runner.poll-until-signaled.started","log_level":1,"data":{"service":"tps","session":"1.1","update-interval":"1.5s"}}
{"timestamp":"1460178385.547278881","source":"tps-listener","message":"tps-listener.started","log_level":1,"data":{}}
{"timestamp":"1460179059.668472052","source":"tps-listener","message":"tps-listener.registration-runner.poll-until-signaled.deregistering-service","log_level":1,"data":{"service":"tps","session":"1.1","update-interval":"1.5s"}}
{"timestamp":"1460179059.668750763","source":"tps-listener","message":"tps-listener.registration-runner.poll-until-signaled.finished","log_level":1,"data":{"service":"tps","session":"1.1","update-interval":"1.5s"}}
{"timestamp":"1460179059.668825150","source":"tps-listener","message":"tps-listener.registration-runner.finished","log_level":1,"data":{"service":"tps","session":"1"}}
{"timestamp":"1460179059.668975353","source":"tps-listener","message":"tps-listener.exited-with-failure","log_level":2,"data":{"error":"Exit trace for group:\nregistration-runner exited with error: Put http://127.0.0.1:8500/v1/agent/service/deregister/: dial tcp 127.0.0.1:8500: connection refused\napi exited with nil\ndebug-server exited with nil\n"}}
{"timestamp":"1460179072.479903460","source":"tps-listener","message":"tps-listener.registration-runner.starting","log_level":1,"data":{"registration":{"Name":"tps","Port":1518,"Check":{"TTL":"3s"},"Checks":null},"service":"tps","session":"1"}}
{"timestamp":"1460179072.480226755","source":"tps-listener","message":"tps-listener.registration-runner.attempting-registering-service","log_level":1,"data":{"service":"tps","session":"1"}}
{"timestamp":"1460179072.487333298","source":"tps-listener","message":"tps-listener.registration-runner.succeeded-registering-service","log_level":1,"data":{"service":"tps","session":"1"}}
{"timestamp":"1460179072.500604868","source":"tps-listener","message":"tps-listener.registration-runner.poll-until-signaled.started","log_level":1,"data":{"service":"tps","session":"1.1","update-interval":"1.5s"}}
{"timestamp":"1460179072.500660181","source":"tps-listener","message":"tps-listener.started","log_level":1,"data":{}}

Logs from TPS watcher:

{"timestamp":"1460178386.370812654","source":"tps-watcher","message":"tps-watcher.watcher.starting","log_level":1,"data":{"session":"2"}}
{"timestamp":"1460178386.371064425","source":"tps-watcher","message":"tps-watcher.watcher.started","log_level":1,"data":{"session":"2"}}
{"timestamp":"1460178386.371150255","source":"tps-watcher","message":"tps-watcher.watcher.subscribing-to-events","log_level":1,"data":{"session":"2"}}
{"timestamp":"1460178386.371956587","source":"tps-watcher","message":"tps-watcher.started","log_level":1,"data":{}}
{"timestamp":"1460178386.405641079","source":"tps-watcher","message":"tps-watcher.watcher.subscribed-to-events","log_level":1,"data":{"session":"2"}}
{"timestamp":"1460179005.702743053","source":"tps-watcher","message":"tps-watcher.watcher.failed-getting-next-event","log_level":2,"data":{"error":"EOF","session":"2"}}
{"timestamp":"1460179006.703215837","source":"tps-watcher","message":"tps-watcher.watcher.failed-getting-next-event","log_level":2,"data":{"error":"EOF","session":"2"}}
{"timestamp":"1460179007.703614712","source":"tps-watcher","message":"tps-watcher.watcher.failed-getting-next-event","log_level":2,"data":{"error":"EOF","session":"2"}}
{"timestamp":"1460179008.703970909","source":"tps-watcher","message":"tps-watcher.watcher.subscribing-to-events","log_level":1,"data":{"session":"2"}}
{"timestamp":"1460179020.357481718","source":"tps-watcher","message":"tps-watcher.watcher.subscribed-to-events","log_level":1,"data":{"session":"2"}}
{"timestamp":"1460179057.240381718","source":"tps-watcher","message":"tps-watcher.lock.lost-lock","log_level":1,"data":{"err":"Lost lock 'v1/locks/tps_watcher_lock'","key":"v1/locks/tps_watcher_lock","session":"1","value":"7e21aa50-f1aa-4ce9-61b9-e99e0a22d04c"}}
{"timestamp":"1460179057.240549326","source":"tps-watcher","message":"tps-watcher.lock.done","log_level":1,"data":{"key":"v1/locks/tps_watcher_lock","session":"1","value":"7e21aa50-f1aa-4ce9-61b9-e99e0a22d04c"}}
{"timestamp":"1460179057.240639210","source":"tps-watcher","message":"tps-watcher.watcher.stopping","log_level":1,"data":{"session":"2"}}
{"timestamp":"1460179057.240725040","source":"tps-watcher","message":"tps-watcher.watcher.finished","log_level":1,"data":{"session":"2"}}
{"timestamp":"1460179057.240951061","source":"tps-watcher","message":"tps-watcher.exited-with-failure","log_level":2,"data":{"error":"Exit trace for group:\nlock-maintainer exited with error: lock lost\nwatcher exited with nil\ndebug-server exited with nil\n"}}
{"timestamp":"1460179073.473150969","source":"tps-watcher","message":"tps-watcher.lock.starting","log_level":1,"data":{"key":"v1/locks/tps_watcher_lock","session":"1","value":"0e60f21a-2d16-48fd-678b-0dd53a9d00e4"}}
{"timestamp":"1460179073.473260880","source":"tps-watcher","message":"tps-watcher.lock.acquiring-lock","log_level":1,"data":{"key":"v1/locks/tps_watcher_lock","session":"1","value":"0e60f21a-2d16-48fd-678b-0dd53a9d00e4"}}
{"timestamp":"1460179073.496469975","source":"tps-watcher","message":"tps-watcher.lock.acquire-lock-succeeded","log_level":1,"data":{"key":"v1/locks/tps_watcher_lock","session":"1","value":"0e60f21a-2d16-48fd-678b-0dd53a9d00e4"}}
{"timestamp":"1460179073.496716738","source":"tps-watcher","message":"tps-watcher.lock.started","log_level":1,"data":{"key":"v1/locks/tps_watcher_lock","session":"1","value":"0e60f21a-2d16-48fd-678b-0dd53a9d00e4"}}

[jfmyers9]

Hi @pako-grape,

Is there any way you could give us the contents of the monit log file in /var/vcap/monit/monit.log? This should give us a better idea of the lifecycle of processes on the cc_bridge VM.

Also from the above logs, we see that both the TPS listener and the TPS watcher exited. Was this a recurring failure? Or did this only happen once during the deploy? Also we notice that there were no logs after the started log line, was the CF installation under almost no load during the above investigation?

Thanks,

@jfmyers9 && @andrew-edgar, CF Diego Team

[cwlbraa]

Hi @pako-grape, we were looking at https://github.com/cloudfoundry/cf-release/issues/926 over the weekend and your issue seems vaguely similar.

Did you generate your manifest with the scripts/generate-deployment-manifest script provided with v0.1460.0? Some older versions of diego-release manifest generation use manifest-based configuration for consul registration and that can cause service registration to fail.

You can also check to see if something like the following block exists in your manifest. If so, removing it may get you past the problem:

properties:
  consul:
    agent:
      services:
        bbs: {}
        etcd: {}
        auctioneer: {}
        cc_uploader: {}
        nsync: {}
        stager: {}
        tps: {}
        file_server: {}
        ssh_proxy: {}
      datacenter: null
      log_level: null
      servers:
        lan:
        - 10.0.16.4

should look more like:

properties:
  consul:
    agent:
      datacenter: 
      domain: cf.internal
      log_level: 
      servers:
        lan:
        - 10.10.2.37
        - 10.10.2.38
        - 10.10.3.37

If this doesn't address your problem, please paste the content of your manifest here (with credentials REDACTED), and we can have a closer look.

@cwlbraa && @nimakaviani, also CF Diego Team

[pako-grape]

Thank you very much!
@cwlbraa - that's it. I'am almost 100% sure.
I will check this out next week but issue can be closed.
I still cannot believe that this was such a breeze...
Thanks a lot for your help and time.

[emalm]

Thanks, @pako-grape! Glad to hear that's probably the issue. If it turns out to be something else, please let us know, and we'll be happy to assist again.

Best,
Eric