cf deploy fails with Error 400007: `access_z1/0' is not running after update [migrated from cf-release]

[Amit-PivotalLabs]

Original issue: cloudfoundry/cf-release#846
Original poster: @vinvaidya

---

vagrant@agent-id-bosh-0:~/cf-release$ sudo chmod 777 /vagrant
vagrant@agent-id-bosh-0:~/cf-release$ bosh -n deploy
Acting as user 'admin' on deployment 'cf-warden-diego' on 'Bosh Lite Director'
Getting deployment properties from director...

Deploying
---------

Director task 47
  Started unknown
  Started unknown > Binding deployment. Done (00:00:00)

  Started preparing deployment
  Started preparing deployment > Binding releases. Done (00:00:00)
  Started preparing deployment > Binding existing deployment. Done (00:00:00)
  Started preparing deployment > Binding resource pools. Done (00:00:00)
  Started preparing deployment > Binding stemcells. Done (00:00:01)
  Started preparing deployment > Binding templates. Done (00:00:00)
  Started preparing deployment > Binding properties. Done (00:00:00)
  Started preparing deployment > Binding unallocated VMs. Done (00:00:00)
  Started preparing deployment > Binding instance networks. Done (00:00:00)

  Started preparing package compilation > Finding packages to compile. Done (00:00:00)

  Started compiling packages
  Started compiling packages > windows_app_lifecycle/fda65a66cef79dbaaa2bb810f0f03e14c4b88927
  Started compiling packages > docker/00a534d3a876a90b1c9654b25ce572c102092efc
  Started compiling packages > rootfs_cflinuxfs2/965e96aee38224d80afa4db415156e02ab541fcf
  Started compiling packages > busybox/1593c41beb57c12d7f2b82dff61b47d4d119913d
  Started compiling packages > shadow/ffd1741bd9e0a176e67c61ef70cd0ed76b0ec285
  Started compiling packages > iptables/7226d311e90f49b05287e79f339581a1de9ea82e
     Done compiling packages > windows_app_lifecycle/fda65a66cef79dbaaa2bb810f0f03e14c4b88927 (00:00:07)
  Started compiling packages > golang_1.4/714698bc352d2a1dbe321376f0676037568147bb
     Done compiling packages > docker/00a534d3a876a90b1c9654b25ce572c102092efc (00:00:13)
  Started compiling packages > golang_1.4/714698bc352d2a1dbe321376f0676037568147bb
     Done compiling packages > busybox/1593c41beb57c12d7f2b82dff61b47d4d119913d (00:00:32)
  Started compiling packages > pid_utils/81f185e4c02f2e4cb7b73a8f243d1918c6408e50. Done (00:00:01)
  Started compiling packages > golang1.4/714698bc352d2a1dbe321376f0676037568147bb
     Done compiling packages > golang_1.4/714698bc352d2a1dbe321376f0676037568147bb (00:00:37)
  Started compiling packages > etcd-common/a5492fb0ad41a80d2fa083172c0430073213a296. Done (00:00:05)
  Started compiling packages > garden-linux/231112e883bbe493c9b17921c0aba425406d6447
     Done compiling packages > rootfs_cflinuxfs2/965e96aee38224d80afa4db415156e02ab541fcf (00:01:09)
     Done compiling packages > golang_1.4/714698bc352d2a1dbe321376f0676037568147bb (00:01:00)
  Started compiling packages > file_server/c0000e8043712bcd3074b75b38439b62de59c76d
  Started compiling packages > ssh_proxy/bc248efd7c7533e450a3de56a1e0a5ffc7f3db0c
     Done compiling packages > iptables/7226d311e90f49b05287e79f339581a1de9ea82e (00:01:19)
  Started compiling packages > route_emitter/7147e67c458c00a324ba2650464ffbc37406edb1
     Done compiling packages > golang1.4/714698bc352d2a1dbe321376f0676037568147bb (00:00:51)
  Started compiling packages > healthcheck/bdfc36c8979b4c376050172b8bd7e2cffb4eaec1
     Done compiling packages > file_server/c0000e8043712bcd3074b75b38439b62de59c76d (00:00:19)
  Started compiling packages > diego-sshd/f635da735cabd3ccc072ea32925d491aa7b919c3
     Done compiling packages > ssh_proxy/bc248efd7c7533e450a3de56a1e0a5ffc7f3db0c (00:00:24)
  Started compiling packages > cc_uploader/3ea295ac75955f78484fa6225b3cea121896f95a
     Done compiling packages > route_emitter/7147e67c458c00a324ba2650464ffbc37406edb1 (00:00:24)
  Started compiling packages > tps/cb4f43ff24cc210b670b90f6bfd8f784121e3426
     Done compiling packages > healthcheck/bdfc36c8979b4c376050172b8bd7e2cffb4eaec1 (00:00:25)
  Started compiling packages > nsync/4ded2365610a9ab7f5aefdd6b8d001e2ed782a46
     Done compiling packages > garden-linux/231112e883bbe493c9b17921c0aba425406d6447 (00:01:10)
  Started compiling packages > stager/ed82bcd09e5c393934ad7f8956894562a0e95699
     Done compiling packages > cc_uploader/3ea295ac75955f78484fa6225b3cea121896f95a (00:00:22)
  Started compiling packages > rep/a9d2ad959635703dd331891b6304efd83f4c0132
     Done compiling packages > diego-sshd/f635da735cabd3ccc072ea32925d491aa7b919c3 (00:00:40)
  Started compiling packages > converger/20f9a80160cdff28d0f4d27af082891832486a4e
     Done compiling packages > tps/cb4f43ff24cc210b670b90f6bfd8f784121e3426 (00:00:34)
  Started compiling packages > auctioneer/e8b031796da3dec9f60c1f1b423460b159e93148
     Done compiling packages > nsync/4ded2365610a9ab7f5aefdd6b8d001e2ed782a46 (00:00:29)
  Started compiling packages > bbs/0fb75455c194e7382204d942e5a1f9521b41dac7
     Done compiling packages > shadow/ffd1741bd9e0a176e67c61ef70cd0ed76b0ec285 (00:02:24)
  Started compiling packages > etcd/b38616a5b7e6cff0f1db95facb6b2e729fba0c30
     Done compiling packages > stager/ed82bcd09e5c393934ad7f8956894562a0e95699 (00:00:26)
  Started compiling packages > docker_app_lifecycle/0a921e4aae3176c4e745b0062c141f0184ffe833
     Done compiling packages > rep/a9d2ad959635703dd331891b6304efd83f4c0132 (00:00:31)
  Started compiling packages > buildpack_app_lifecycle/fbd0123a2273c360bbc68190333814678839c051
     Done compiling packages > converger/20f9a80160cdff28d0f4d27af082891832486a4e (00:00:24)
     Done compiling packages > auctioneer/e8b031796da3dec9f60c1f1b423460b159e93148 (00:00:27)
     Done compiling packages > bbs/0fb75455c194e7382204d942e5a1f9521b41dac7 (00:00:32)
     Done compiling packages > buildpack_app_lifecycle/fbd0123a2273c360bbc68190333814678839c051 (00:00:32)
     Done compiling packages > docker_app_lifecycle/0a921e4aae3176c4e745b0062c141f0184ffe833 (00:00:40)
     Done compiling packages > etcd/b38616a5b7e6cff0f1db95facb6b2e729fba0c30 (00:00:47)
     Done compiling packages (00:03:11)

  Started preparing dns > Binding DNS. Done (00:00:00)

  Started creating bound missing vms
  Started creating bound missing vms > access_z1/0
  Started creating bound missing vms > brain_z1/0
  Started creating bound missing vms > cc_bridge_z1/0
  Started creating bound missing vms > cell_z1/0
  Started creating bound missing vms > database_z1/0
  Started creating bound missing vms > route_emitter_z1/0
     Done creating bound missing vms > database_z1/0 (00:00:03)
     Done creating bound missing vms > route_emitter_z1/0 (00:00:03)
     Done creating bound missing vms > cc_bridge_z1/0 (00:00:03)
     Done creating bound missing vms > brain_z1/0 (00:00:04)
     Done creating bound missing vms > cell_z1/0 (00:00:05)
     Done creating bound missing vms > access_z1/0 (00:00:05)
     Done creating bound missing vms (00:00:05)

  Started binding instance vms
  Started binding instance vms > brain_z1/0
  Started binding instance vms > database_z1/0
  Started binding instance vms > cell_z1/0
  Started binding instance vms > cc_bridge_z1/0
  Started binding instance vms > route_emitter_z1/0
  Started binding instance vms > access_z1/0
     Done binding instance vms > brain_z1/0 (00:00:00)
     Done binding instance vms > access_z1/0 (00:00:01)
     Done binding instance vms > cc_bridge_z1/0 (00:00:01)
     Done binding instance vms > database_z1/0 (00:00:01)
     Done binding instance vms > route_emitter_z1/0 (00:00:01)
     Done binding instance vms > cell_z1/0 (00:00:01)
     Done binding instance vms (00:00:01)

  Started preparing configuration > Binding configuration. Done (00:00:04)

  Started updating job database_z1 > database_z1/0 (canary)
. Done (00:01:34)
  Started updating job brain_z1 > brain_z1/0 (canary). Done (00:00:13)
  Started updating job cell_z1 > cell_z1/0 (canary)
  Started updating job cc_bridge_z1 > cc_bridge_z1/0 (canary)
  Started updating job route_emitter_z1 > route_emitter_z1/0 (canary)
  Started updating job access_z1 > access_z1/0 (canary)
     Done updating job route_emitter_z1 > route_emitter_z1/0 (canary) (00:00:13)
     Done updating job cc_bridge_z1 > cc_bridge_z1/0 (canary) (00:00:20)
     Done updating job cell_z1 > cell_z1/0 (canary) (00:00:40)
   Failed updating job access_z1 > access_z1/0 (canary): `access_z1/0' is not running after update (00:02:13)

Error 400007: `access_z1/0' is not running after update

Task 47 error

For a more detailed error report, run: bosh task 47 --debug

bosh vms for cf-warden-diego shows:

Deployment `cf-warden-diego'

Director task 88

Task 88 done

+--------------------+---------+------------------+---------------+
| Job/index          | State   | Resource Pool    | IPs           |
+--------------------+---------+------------------+---------------+
| access_z1/0        | failing | access_z1        | 10.244.16.6   |
| brain_z1/0         | running | brain_z1         | 10.244.16.134 |
| cc_bridge_z1/0     | running | cc_bridge_z1     | 10.244.16.142 |
| cell_z1/0          | running | cell_z1          | 10.244.16.138 |
| database_z1/0      | running | database_z1      | 10.244.16.130 |
| route_emitter_z1/0 | running | route_emitter_z1 | 10.244.16.146 |
+--------------------+---------+------------------+---------------+

VMs total: 6



vagrant@agent-id-bosh-0:~$ bosh cck cf-warden-diego
Performing cloud check...

Director task 90
  Started scanning 6 vms
  Started scanning 6 vms > Checking VM states. Done (00:00:00)
  Started scanning 6 vms > 6 OK, 0 unresponsive, 0 missing, 0 unbound, 0 out of sync. Done (00:00:00)
     Done scanning 6 vms (00:00:00)

  Started scanning 1 persistent disks
  Started scanning 1 persistent disks > Looking for inactive disks. Done (00:00:02)
  Started scanning 1 persistent disks > 1 OK, 0 missing, 0 inactive, 0 mount-info mismatch. Done (00:00:00)
     Done scanning 1 persistent disks (00:00:02)

Task 90 done

Started     2015-11-09 07:29:57 UTC
Finished    2015-11-09 07:29:59 UTC
Duration    00:00:02

Scan is complete, checking if any problems found...
No problems found

[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/107734476.

[emalm]

Thanks for the report, @vinvaidya, and the transfer to diego-release, @Amit-PivotalLabs.

@vinvaidya, we've seen this same issue infrequently in some of our Diego environments, especially on BOSH-Lite, and we'd be interesting in reproducing and then fixing it. Does the problem resolve if you try re-deploying Diego? Also, would you be able to provide some logs from the failure? The debug logs from the original deploy task would be useful (run bosh task 47 --debug), as well as the logs in /var/vcap/sys/log/ and in /var/vcap/monit/monit.log from that access_z1 0 VM. Since those logs are quite large, it would be best for you to provide them in a gist.

Thanks,
Eric, CF Runtime Diego PM

[emalm]

P.S. @vinvaidya Could you also please let us know what versions of CF and Diego you're deploying, and on which version of the BOSH-Lite vagrant box?

Thanks again,
Eric

[vinvaidya]

Uploaded files:
https://gist.github.com/vinvaidya

I am using cf v222 and diego v0.1437.0 and BOSH 1.3074.0

[vinvaidya]

Redeploying does not help, fails at the same location. The /var/vcap/sys/log/ has other directories and logs but i did not see anything that seemed like an error except the ssh_proxy which is uploaded.

[cwlbraa]

your error logs show that ssh-proxy is not receiving uaa_token_url (the /oauth/token endpoint of your uaa) from your manifest. In our bosh-lite manifest generation, this property is generally flown in from the cf-release manifest.

[vinvaidya]

Sure, I could also see that error. Could you suggest how to fix it? What specifically needs to change in the cf-release manifest to get it to work. I had used the following command to generate the manifest as suggested in readme:

./scripts/generate-bosh-lite-dev-manifest
~/workspace/diego-release/stubs-for-cf-release/enable_diego_windows_in_cc.yml

[cwlbraa]

We tried to reproduce your problem by following the diego readme for v222/v0.1437.0, but we couldn't. If you want to hand edit your deployment, the usual full url for that field in a generated bosh-lite diego manifest looks like this:

properties:
  ssh_proxy:
    uaa_token_url: https://uaa.bosh-lite.com/oauth/token

however, when we generate diego manifests, this should come from the cf manifest:

properties:
  uaa:
     url: $(what does your cf manifest say here? usually it's https://uaa.bosh-lite.com/)

[rbromero]

I am seeing similar problems after following the README.md located here: https://github.com/cloudfoundry-incubator/diego-release

As I am reviewing what releases I am working with it looks like the instructions led me to some dev releases rather than stable releases. Here is what I have deployed while I am experiencing the problems:

+--------------+-----------------+-------------+
| Name | Versions | Commit Hash |
+--------------+-----------------+-------------+
| cf | 223 | f8f63fd8+ |
| | 223+dev.1* | 9934cb7d |
| diego | 0.1440.0+dev.1 | 89810af |
| | 0.1440.0+dev.2* | 89810af |
| etcd | 18* | 52f3a004+ |
| garden-linux | 0.327.0* | c127a931 |
+--------------+-----------------+-------------+

I am now going to try to re-deploy using stable versions of the cf-release and the diego-release

[rbromero]

Also, here is the version of BOSH that I am running: BOSH 1.3126.0

In addition, I did verify that the uaa_token_url: https://uaa.bosh-lite.com/oauth/token configuration exists in the diego.yml manifest when I encountered the problem.

[cwlbraa]

@vinvaidya @rbromero We recommend using bosh upload stemcell https://bosh.io/d/stemcells/bosh-warden-boshlite-ubuntu-trusty-go_agent?v=2776 as there was a regression on later bosh-lite stemcells, and 3126 is possibly being pulled.

NOTE: make sure all other stemcells are deleted as the manifests will refer to the latest version.

@rbromero Our bosh-lite setup steps go through the process of generating a dev version for the cf and diego releases, so the dev releases you see there are expected. If you want to use specific versions you must manually override your deployment manifests. If using the 2776 stemcell doesn't solve your issues, could you verify that your logs look like the logs at https://gist.github.com/vinvaidya , and if they don't, bundle them up and make us a new issue? Thanks.

[rbromero]

I have tested this with the 2776 stemcell and I am seeing the same problem. My logs looks the same as those in the gist posted by @vinvaidya.

Thanks,
Ricardo

[cwlbraa]

@vinvaidya @rbromero looking through vindaidya's manifest, we noticed that properties.ssh_proxy.uaa_secret was empty. this field is used alongside uaa_token_url to generate the flag that diego is complaining about in your logs. like uaa_token_url, this field is flown in from your cf manifest, specifically from properties.uaa.clients.ssh-proxy.secret – can you check that this value is present in your cf manifest?