Director Down After Reboot

[Steve Wall]

I used bosh-bootstrap to install MicroBOSH in AWS. After rebooting the "firstbosh" server, it looks like the Director did not start. Should the Director start at boot? I poked around init.d and nothing jumped out to me. I wasn't able to find any System Admin level documentation on trouble shooting the environment. i.e. what processes should be running, where things live, etc. There was some good documentation on how to use BOSH, but I didn't notice anything discussing how things work under the cover.

[Dr Nic Williams]

Can you paste in the output of when it is booting up MicroBOSH and the choice of base stemcell it made?

Perhaps the bosh-bootstrap is using an old URL for getting stemcells and using a new BOSH CLI and perhaps something isn't working btw them.

Just trying to guess what regression might have caused this issue.

Nic

On Fri, Sep 12, 2014 at 7:27 AM, Steve Wall <stevew...@gmail.com> wrote:

I used bosh-bootstrap to install MicroBOSH in AWS. After rebooting the "firstbosh" server, it looks like the Director did not start. Should the Director start at boot? I poked around init.d and nothing jumped out to me. I wasn't able to find any System Admin level documentation on trouble shooting the environment. i.e. what processes should be running, where things live, etc. There was some good documentation on how to use BOSH, but I didn't notice anything discussing how things work under the cover.

To unsubscribe from this group and stop receiving emails from it, send an email to bosh-dev+u...@cloudfoundry.org.

[Steve Wall]

Here's the bosh_micro_deploy.log. Is that what you are referring to?

# Logfile created on 2014-09-10 21:55:25 +0000 by logger.rb/31641

I, [2014-09-10T21:55:25.033823 #30208] [0x1072ff0]  INFO -- : No existing deployments found (will save to /home/ubuntu/.microbosh/deployments/bosh-deployments.yml)

I, [2014-09-10T21:55:25.034927 #30208] [0x1072ff0]  INFO -- : using configured ip=xxx.209.19

I, [2014-09-10T21:55:26.015673 #30216] [0xeadff8]  INFO -- : No existing deployments found (will save to /home/ubuntu/.microbosh/deployments/bosh-deployments.yml)

I, [2014-09-10T21:55:33.575638 #30216] [0xeadff8]  INFO -- : bosh-registry is ready on port 25888

I, [2014-09-10T21:55:43.210581 #30216] [0xeadff8]  INFO -- : Loading yaml from /tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/stemcell.MF

I, [2014-09-10T21:55:49.407494 #30216] [create_disk(4096, i-f680cba8)]  INFO -- : [AWS EC2 200 0.14857 0 retries] describe_instances(:instance_ids=>["i-f680cba8"])

I, [2014-09-10T21:55:49.549657 #30216] [create_disk(4096, i-f680cba8)]  INFO -- : [AWS EC2 200 0.141223 0 retries] create_volume(:availability_zone=>"us-west-1a",:size=>4,:volume_type=>"standard")

I, [2014-09-10T21:55:49.549792 #30216] [create_disk(4096, i-f680cba8)]  INFO -- : Creating volume 'vol-2db2932d'

I, [2014-09-10T21:55:49.650021 #30216] [create_disk(4096, i-f680cba8)]  INFO -- : [AWS EC2 200 0.099554 0 retries] describe_volumes(:volume_ids=>["vol-2db2932d"])

D, [2014-09-10T21:55:49.650173 #30216] [create_disk(4096, i-f680cba8)] DEBUG -- : Waiting for vol-2db2932d to be available, retrying in 2 seconds (1/54)

I, [2014-09-10T21:55:51.740145 #30216] [create_disk(4096, i-f680cba8)]  INFO -- : [AWS EC2 200 0.089146 0 retries] describe_volumes(:volume_ids=>["vol-2db2932d"])

I, [2014-09-10T21:55:51.740327 #30216] [create_disk(4096, i-f680cba8)]  INFO -- : vol-2db2932d is now available, took 2.190485567s

I, [2014-09-10T21:55:51.941510 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.2007 0 retries] describe_instances(:instance_ids=>["i-f680cba8"])

I, [2014-09-10T21:55:52.474585 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.531986 0 retries] attach_volume(:device=>"/dev/sdf",:instance_id=>"i-f680cba8",:volume_id=>"vol-2db2932d")

I, [2014-09-10T21:55:52.474685 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : Attaching 'vol-2db2932d' to 'i-f680cba8' as '/dev/sdf'

I, [2014-09-10T21:55:52.697066 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.221934 0 retries] describe_volumes(:volume_ids=>["vol-2db2932d"])

D, [2014-09-10T21:55:52.697263 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for volume vol-2db2932d to be attached to instance i-f680cba8 as device /dev/sdf to be attached, retrying in 2 seconds (1/54)

I, [2014-09-10T21:55:54.811682 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.113609 0 retries] describe_volumes(:volume_ids=>["vol-2db2932d"])

D, [2014-09-10T21:55:54.811852 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for volume vol-2db2932d to be attached to instance i-f680cba8 as device /dev/sdf to be attached, retrying in 4 seconds (2/54)

I, [2014-09-10T21:55:59.002982 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.190318 0 retries] describe_volumes(:volume_ids=>["vol-2db2932d"])

I, [2014-09-10T21:55:59.003143 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : volume vol-2db2932d to be attached to instance i-f680cba8 as device /dev/sdf is now attached, took 6.528402762s

I, [2014-09-10T21:55:59.003177 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : Attached 'vol-2db2932d' to 'i-f680cba8' as '/dev/sdf'

I, [2014-09-10T21:55:59.003268 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : Creating stemcell with: 'vol-2db2932d' and '{"name"=>"bosh-aws-xen-ubuntu-lucid", "version"=>"2579", "infrastructure"=>"aws", "architecture"=>"x86_64", "root_device_name"=>"/dev/sda1", "kernel_id"=>nil, "disk"=>4096}'

I, [2014-09-10T21:55:59.004142 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : falling back to using included copy stemcell

D, [2014-09-10T21:57:33.718960 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : stemcell copy output:

0+32260 records in

0+32260 records out

2147483648 bytes (2.1 GB) copied, 94.6648 s, 22.7 MB/s

I, [2014-09-10T21:57:33.888152 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.168363 0 retries] create_snapshot(:volume_id=>"vol-2db2932d")

I, [2014-09-10T21:57:33.983282 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.094378 0 retries] describe_snapshots(:snapshot_ids=>["snap-a6498667"])

D, [2014-09-10T21:57:33.983468 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for snap-a6498667 to be completed, retrying in 2 seconds (1/18)

I, [2014-09-10T21:57:36.051173 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.067012 0 retries] describe_snapshots(:snapshot_ids=>["snap-a6498667"])

D, [2014-09-10T21:57:36.051370 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for snap-a6498667 to be completed, retrying in 4 seconds (2/18)

I, [2014-09-10T21:57:40.112140 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.05999 0 retries] describe_snapshots(:snapshot_ids=>["snap-a6498667"])

D, [2014-09-10T21:57:40.112303 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for snap-a6498667 to be completed, retrying in 8 seconds (3/18)

I, [2014-09-10T21:57:48.181401 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.068178 0 retries] describe_snapshots(:snapshot_ids=>["snap-a6498667"])

D, [2014-09-10T21:57:48.181610 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for snap-a6498667 to be completed, retrying in 16 seconds (4/18)

I, [2014-09-10T21:58:04.255941 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.073217 0 retries] describe_snapshots(:snapshot_ids=>["snap-a6498667"])

D, [2014-09-10T21:58:04.256159 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for snap-a6498667 to be completed, retrying in 32 seconds (5/18)

I, [2014-09-10T21:58:36.332593 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.075304 0 retries] describe_snapshots(:snapshot_ids=>["snap-a6498667"])

D, [2014-09-10T21:58:36.332807 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for snap-a6498667 to be completed, retrying in 32 seconds (6/18)

I, [2014-09-10T21:59:08.446311 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.11241 0 retries] describe_snapshots(:snapshot_ids=>["snap-a6498667"])

D, [2014-09-10T21:59:08.446539 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for snap-a6498667 to be completed, retrying in 32 seconds (7/18)

I, [2014-09-10T21:59:40.519488 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.071887 0 retries] describe_snapshots(:snapshot_ids=>["snap-a6498667"])

D, [2014-09-10T21:59:40.519705 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for snap-a6498667 to be completed, retrying in 32 seconds (8/18)

I, [2014-09-10T22:00:12.618501 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.097737 0 retries] describe_snapshots(:snapshot_ids=>["snap-a6498667"])

I, [2014-09-10T22:00:12.618714 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : snap-a6498667 is now completed, took 158.730445907s

I, [2014-09-10T22:00:12.778694 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.159605 0 retries] describe_images(:filters=>[{:name=>"architecture",:values=>["x86_64"]},{:name=>"image-type",:values=>["kernel"]},{:name=>"owner-alias",:values=>["amazon"]}])

I, [2014-09-10T22:00:12.778892 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : auto-selected AKI: aki-81396bc4

I, [2014-09-10T22:00:13.020676 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.241165 0 retries] register_image(:architecture=>"x86_64",:block_device_mappings=>[{:device_name=>"/dev/sda",:ebs=>{:snapshot_id=>"snap-a6498667"}},{:device_name=>"/dev/sdb",:virtual_name=>"ephemeral0"}],:description=>"bosh-aws-xen-ubuntu-lucid 2579",:kernel_id=>"aki-81396bc4",:name=>"BOSH-aab5f3ae-c2d2-44fb-9a37-429dbfed9210",:root_device_name=>"/dev/sda1")

I, [2014-09-10T22:00:13.188928 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.167451 0 retries] describe_images(:image_ids=>["ami-4bb3bd0e"])

I, [2014-09-10T22:00:13.189243 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : ami-4bb3bd0e is now available, took 0.168423866s

I, [2014-09-10T22:00:13.438687 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.248971 0 retries] create_tags(:resources=>["ami-4bb3bd0e"],:tags=>[{:key=>"Name",:value=>"bosh-aws-xen-ubuntu-lucid 2579"}])

I, [2014-09-10T22:00:13.715798 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.276465 0 retries] describe_instances(:instance_ids=>["i-f680cba8"])

I, [2014-09-10T22:00:14.137437 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.420565 0 retries] detach_volume(:device=>"/dev/sdf",:force=>true,:instance_id=>"i-f680cba8",:volume_id=>"vol-2db2932d")

I, [2014-09-10T22:00:14.137504 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : Detaching `vol-2db2932d' from `i-f680cba8'

I, [2014-09-10T22:00:14.416266 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.278165 0 retries] describe_volumes(:volume_ids=>["vol-2db2932d"])

D, [2014-09-10T22:00:14.416481 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for volume vol-2db2932d to be detached to instance i-f680cba8 as device /dev/sdf to be detached, retrying in 2 seconds (1/54)

I, [2014-09-10T22:00:16.585239 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.16787 0 retries] describe_volumes(:volume_ids=>["vol-2db2932d"])

D, [2014-09-10T22:00:16.585445 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for volume vol-2db2932d to be detached to instance i-f680cba8 as device /dev/sdf to be detached, retrying in 4 seconds (2/54)

I, [2014-09-10T22:00:20.670915 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.084647 0 retries] describe_volumes(:volume_ids=>["vol-2db2932d"])

D, [2014-09-10T22:00:20.671097 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)] DEBUG -- : Waiting for volume vol-2db2932d to be detached to instance i-f680cba8 as device /dev/sdf to be detached, retrying in 8 seconds (3/54)

I, [2014-09-10T22:00:28.791891 #30216] [create_stemcell(/tmp/d20140910-30216-99vti1/sc-20140910-30216-iu19is/image...)]  INFO -- : [AWS EC2 200 0.119952 0 retries] describe_volumes(:volume_ids=>["vol-2db2932d"])

I, [2014-09-10T22:00:28.792203 #30216] [delete_disk(vol-2db2932d)]  INFO -- : Deleting volume `vol-2db2932d'

I, [2014-09-10T22:00:29.039946 #30216] [delete_disk(vol-2db2932d)]  INFO -- : [AWS EC2 200 0.247114 0 retries] delete_volume(:volume_id=>"vol-2db2932d")

I, [2014-09-10T22:00:29.173130 #30216] [delete_disk(vol-2db2932d)]  INFO -- : [AWS EC2 200 0.132697 0 retries] describe_volumes(:volume_ids=>["vol-2db2932d"])

D, [2014-09-10T22:00:29.173286 #30216] [delete_disk(vol-2db2932d)] DEBUG -- : Waiting for vol-2db2932d to be deleted, retrying in 2 seconds (1/54)

I, [2014-09-10T22:00:31.244672 #30216] [delete_disk(vol-2db2932d)]  INFO -- : [AWS EC2 400 0.069931 0 retries] describe_volumes(:volume_ids=>["vol-2db2932d"]) AWS::EC2::Errors::InvalidVolume::NotFound The volume 'vol-2db2932d' does not exist.

I, [2014-09-10T22:00:31.244841 #30216] [delete_disk(vol-2db2932d)]  INFO -- : Volume `vol-2db2932d' has been deleted

I, [2014-09-10T22:00:31.433119 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : [AWS EC2 200 0.159043 0 retries] describe_images(:filters=>[{:name=>"image-id",:values=>["ami-4bb3bd0e"]}])

I, [2014-09-10T22:00:31.433351 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : Creating new instance with: {:count=>1, :image_id=>"ami-4bb3bd0e", :instance_type=>"m1.medium", :user_data=>"{\"registry\":{\"endpoint\":\"http://admin:admin@localhost:25888\"},\"dns\":{\"nameserver\":null}}", :key_name=>"firstbosh", :security_groups=>["ssh", "dns_server", "bosh"]}

I, [2014-09-10T22:00:31.433481 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : Launching on demand instance...

W, [2014-09-10T22:00:31.433526 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  WARN -- : IP address was in use:

I, [2014-09-10T22:00:32.385237 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : [AWS EC2 200 0.9509 0 retries] run_instances(:client_token=>"e0baec0a-6380-4aba-9e1a-a688fa48ddca",:image_id=>"ami-4bb3bd0e",:instance_type=>"m1.medium",:key_name=>"firstbosh",:max_count=>1,:min_count=>1,:security_groups=>["ssh","dns_server","bosh"],:user_data=>"eyJyZWdpc3RyeSI6eyJlbmRwb2ludCI6Imh0dHA6Ly9hZG1pbjphZG1pbkBs\nb2NhbGhvc3Q6MjU4ODgifSwiZG5zIjp7Im5hbWVzZXJ2ZXIiOm51bGx9fQ==")

I, [2014-09-10T22:00:32.385375 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : Waiting for instance to be ready...

I, [2014-09-10T22:00:32.632236 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : [AWS EC2 200 0.246019 0 retries] describe_instances(:instance_ids=>["i-df90db81"])

D, [2014-09-10T22:00:32.632753 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)] DEBUG -- : Waiting for i-df90db81 to be running, retrying in 2 seconds (1/54)

I, [2014-09-10T22:00:34.728075 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : [AWS EC2 200 0.094481 0 retries] describe_instances(:instance_ids=>["i-df90db81"])

D, [2014-09-10T22:00:34.728550 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)] DEBUG -- : Waiting for i-df90db81 to be running, retrying in 4 seconds (2/54)

I, [2014-09-10T22:00:38.850417 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : [AWS EC2 200 0.121034 0 retries] describe_instances(:instance_ids=>["i-df90db81"])

D, [2014-09-10T22:00:38.850843 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)] DEBUG -- : Waiting for i-df90db81 to be running, retrying in 8 seconds (3/54)

I, [2014-09-10T22:00:47.108901 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : [AWS EC2 200 0.257137 0 retries] describe_instances(:instance_ids=>["i-df90db81"])

D, [2014-09-10T22:00:47.109436 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)] DEBUG -- : Waiting for i-df90db81 to be running, retrying in 16 seconds (4/54)

I, [2014-09-10T22:01:03.475522 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : [AWS EC2 200 0.365037 0 retries] describe_instances(:instance_ids=>["i-df90db81"])

I, [2014-09-10T22:01:03.476057 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : i-df90db81 is now running, took 31.090556852s

I, [2014-09-10T22:01:03.476113 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : Creating new instance 'i-df90db81'

I, [2014-09-10T22:01:03.476453 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : Associating instance `i-df90db81' with elastic IP `xxx.209.19'

I, [2014-09-10T22:01:03.572927 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : [AWS EC2 200 0.095822 0 retries] describe_addresses(:public_ips=>["xxx.209.19"])

I, [2014-09-10T22:01:03.935782 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : [AWS EC2 200 0.362276 0 retries] associate_address(:allocation_id=>"eipalloc-fa293498",:instance_id=>"i-df90db81")

I, [2014-09-10T22:01:04.021178 #30216] [create_vm(bm-42aaef33-83a5-47f3-a033-b843564cb5e4, ...)]  INFO -- : [AWS EC2 200 0.084961 0 retries] describe_images(:image_ids=>["ami-4bb3bd0e"])

I, [2014-09-10T22:01:04.318025 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.232698 0 retries] create_tags(:resources=>["i-df90db81"],:tags=>[{:key=>"Name",:value=>"firstbosh"}])

I, [2014-09-10T22:01:04.421507 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.101068 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:01:04.500946 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.078962 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:01:04.501050 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:01:19.559887 #30216] [0xeadff8] DEBUG -- : tcp socket xxx.209.19:22 is readable

I, [2014-09-10T22:02:19.560265 #30216] [0xeadff8]  INFO -- : Starting SSH session for port forwarding to vc...@xxx.209.19...

D, [2014-09-10T22:02:19.733560 #30216] [0xeadff8] DEBUG -- : ssh vc...@xxx.209.19: ESTABLISHED

I, [2014-09-10T22:02:19.733785 #30216] [0xeadff8]  INFO -- : SSH forwarding for port 25888 started: OK

D, [2014-09-10T22:02:19.733912 #30216] [0xeadff8] DEBUG -- : Waiting for agent to be ready: nil

I, [2014-09-10T22:02:19.831964 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.096989 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:19.924253 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.09151 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:19.924429 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:02:20.926421 #30216] [0xeadff8] DEBUG -- : Waiting for agent to be ready: #<Bosh::Agent::Error: Request details:

uri: https://vcap:b00t...@xxx.209.19:6868/agent

payload: {"method":"ping","arguments":[],"reply_to":"bm-42aaef33-83a5-47f3-a033-b843564cb5e4"}

user: vcap

password: b00tstrap

Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:6868)>

I, [2014-09-10T22:02:20.998963 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.071381 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:21.086303 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.086714 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:21.086445 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:02:22.089014 #30216] [0xeadff8] DEBUG -- : Waiting for agent to be ready: #<Bosh::Agent::Error: Request details:

uri: https://vcap:b00t...@xxx.209.19:6868/agent

payload: {"method":"ping","arguments":[],"reply_to":"bm-42aaef33-83a5-47f3-a033-b843564cb5e4"}

user: vcap

password: b00tstrap

Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:6868)>

I, [2014-09-10T22:02:22.175409 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.08533 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:22.256447 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.080415 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:22.256603 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:02:23.258984 #30216] [0xeadff8] DEBUG -- : Waiting for agent to be ready: #<Bosh::Agent::Error: Request details:

uri: https://vcap:b00t...@xxx.209.19:6868/agent

payload: {"method":"ping","arguments":[],"reply_to":"bm-42aaef33-83a5-47f3-a033-b843564cb5e4"}

user: vcap

password: b00tstrap

Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:6868)>

I, [2014-09-10T22:02:23.341195 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.081099 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:23.416862 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.075029 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:23.417055 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:02:24.419532 #30216] [0xeadff8] DEBUG -- : Waiting for agent to be ready: #<Bosh::Agent::Error: Request details:

uri: https://vcap:b00t...@xxx.209.19:6868/agent

payload: {"method":"ping","arguments":[],"reply_to":"bm-42aaef33-83a5-47f3-a033-b843564cb5e4"}

user: vcap

password: b00tstrap

Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:6868)>

I, [2014-09-10T22:02:24.496010 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.075387 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:24.566322 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.069798 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:24.567769 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:02:25.570179 #30216] [0xeadff8] DEBUG -- : Waiting for agent to be ready: #<Bosh::Agent::Error: Request details:

uri: https://vcap:b00t...@xxx.209.19:6868/agent

payload: {"method":"ping","arguments":[],"reply_to":"bm-42aaef33-83a5-47f3-a033-b843564cb5e4"}

user: vcap

password: b00tstrap

Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:6868)>

I, [2014-09-10T22:02:25.647769 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.076601 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:25.723038 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.07477 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:25.723143 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:02:26.725143 #30216] [0xeadff8] DEBUG -- : Waiting for agent to be ready: #<Bosh::Agent::Error: Request details:

uri: https://vcap:b00t...@xxx.209.19:6868/agent

payload: {"method":"ping","arguments":[],"reply_to":"bm-42aaef33-83a5-47f3-a033-b843564cb5e4"}

user: vcap

password: b00tstrap

Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:6868)>

I, [2014-09-10T22:02:26.797974 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.072158 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:26.870084 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.07162 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:26.870224 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:02:27.872278 #30216] [0xeadff8] DEBUG -- : Waiting for agent to be ready: #<Bosh::Agent::Error: Request details:

uri: https://vcap:b00t...@xxx.209.19:6868/agent

payload: {"method":"ping","arguments":[],"reply_to":"bm-42aaef33-83a5-47f3-a033-b843564cb5e4"}

user: vcap

password: b00tstrap

Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:6868)>

I, [2014-09-10T22:02:27.950217 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.076874 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:28.027910 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.077198 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:28.028022 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:02:29.030364 #30216] [0xeadff8] DEBUG -- : Waiting for agent to be ready: #<Bosh::Agent::Error: Request details:

uri: https://vcap:b00t...@xxx.209.19:6868/agent

payload: {"method":"ping","arguments":[],"reply_to":"bm-42aaef33-83a5-47f3-a033-b843564cb5e4"}

user: vcap

password: b00tstrap

Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:6868)>

I, [2014-09-10T22:02:29.113086 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.082004 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:29.187244 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.07365 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:29.187366 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:02:30.189136 #30216] [0xeadff8] DEBUG -- : Waiting for agent to be ready: #<Bosh::Agent::Error: Request details:

uri: https://vcap:b00t...@xxx.209.19:6868/agent

payload: {"method":"ping","arguments":[],"reply_to":"bm-42aaef33-83a5-47f3-a033-b843564cb5e4"}

user: vcap

password: b00tstrap

Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:6868)>

I, [2014-09-10T22:02:30.265583 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.074815 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:30.342985 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.076942 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:30.343093 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:02:31.344890 #30216] [0xeadff8] DEBUG -- : Waiting for agent to be ready: #<Bosh::Agent::Error: Request details:

uri: https://vcap:b00t...@xxx.209.19:6868/agent

payload: {"method":"ping","arguments":[],"reply_to":"bm-42aaef33-83a5-47f3-a033-b843564cb5e4"}

user: vcap

password: b00tstrap

Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:6868)>

I, [2014-09-10T22:02:31.462946 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.117052 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:31.544647 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.081199 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:31.544759 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:02:32.546923 #30216] [0xeadff8] DEBUG -- : Waiting for agent to be ready: #<Bosh::Agent::Error: Request details:

uri: https://vcap:b00t...@xxx.209.19:6868/agent

payload: {"method":"ping","arguments":[],"reply_to":"bm-42aaef33-83a5-47f3-a033-b843564cb5e4"}

user: vcap

password: b00tstrap

Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:6868)>

I, [2014-09-10T22:02:32.622643 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.074904 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:32.693712 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.070551 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:32.693834 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

I, [2014-09-10T22:02:32.915278 #30216] [create_disk(16384, i-df90db81)]  INFO -- : [AWS EC2 200 0.172843 0 retries] describe_instances(:instance_ids=>["i-df90db81"])

I, [2014-09-10T22:02:33.045667 #30216] [create_disk(16384, i-df90db81)]  INFO -- : [AWS EC2 200 0.129612 0 retries] create_volume(:availability_zone=>"us-west-1a",:size=>16,:volume_type=>"standard")

I, [2014-09-10T22:02:33.045797 #30216] [create_disk(16384, i-df90db81)]  INFO -- : Creating volume 'vol-72b59472'

I, [2014-09-10T22:02:33.167917 #30216] [create_disk(16384, i-df90db81)]  INFO -- : [AWS EC2 200 0.121688 0 retries] describe_volumes(:volume_ids=>["vol-72b59472"])

D, [2014-09-10T22:02:33.168047 #30216] [create_disk(16384, i-df90db81)] DEBUG -- : Waiting for vol-72b59472 to be available, retrying in 2 seconds (1/54)

I, [2014-09-10T22:02:35.320981 #30216] [create_disk(16384, i-df90db81)]  INFO -- : [AWS EC2 200 0.099232 0 retries] describe_volumes(:volume_ids=>["vol-72b59472"])

I, [2014-09-10T22:02:35.322181 #30216] [create_disk(16384, i-df90db81)]  INFO -- : vol-72b59472 is now available, took 2.276333799s

I, [2014-09-10T22:02:35.422744 #30216] [attach_disk(i-df90db81, vol-72b59472)]  INFO -- : [AWS EC2 200 0.097999 0 retries] describe_instances(:instance_ids=>["i-df90db81"])

I, [2014-09-10T22:02:35.811046 #30216] [attach_disk(i-df90db81, vol-72b59472)]  INFO -- : [AWS EC2 200 0.38743 0 retries] attach_volume(:device=>"/dev/sdf",:instance_id=>"i-df90db81",:volume_id=>"vol-72b59472")

I, [2014-09-10T22:02:35.811118 #30216] [attach_disk(i-df90db81, vol-72b59472)]  INFO -- : Attaching 'vol-72b59472' to 'i-df90db81' as '/dev/sdf'

I, [2014-09-10T22:02:36.028473 #30216] [attach_disk(i-df90db81, vol-72b59472)]  INFO -- : [AWS EC2 200 0.216954 0 retries] describe_volumes(:volume_ids=>["vol-72b59472"])

D, [2014-09-10T22:02:36.028619 #30216] [attach_disk(i-df90db81, vol-72b59472)] DEBUG -- : Waiting for volume vol-72b59472 to be attached to instance i-df90db81 as device /dev/sdf to be attached, retrying in 2 seconds (1/54)

I, [2014-09-10T22:02:38.121720 #30216] [attach_disk(i-df90db81, vol-72b59472)]  INFO -- : [AWS EC2 200 0.092482 0 retries] describe_volumes(:volume_ids=>["vol-72b59472"])

D, [2014-09-10T22:02:38.121840 #30216] [attach_disk(i-df90db81, vol-72b59472)] DEBUG -- : Waiting for volume vol-72b59472 to be attached to instance i-df90db81 as device /dev/sdf to be attached, retrying in 4 seconds (2/54)

I, [2014-09-10T22:02:42.336450 #30216] [attach_disk(i-df90db81, vol-72b59472)]  INFO -- : [AWS EC2 200 0.213761 0 retries] describe_volumes(:volume_ids=>["vol-72b59472"])

I, [2014-09-10T22:02:42.336649 #30216] [attach_disk(i-df90db81, vol-72b59472)]  INFO -- : volume vol-72b59472 to be attached to instance i-df90db81 as device /dev/sdf is now attached, took 6.525477543s

I, [2014-09-10T22:02:42.336686 #30216] [attach_disk(i-df90db81, vol-72b59472)]  INFO -- : Attached 'vol-72b59472' to 'i-df90db81' as '/dev/sdf'

I, [2014-09-10T22:02:42.348876 #30216] [attach_disk(i-df90db81, vol-72b59472)]  INFO -- : Attached `vol-72b59472' to `i-df90db81'

I, [2014-09-10T22:02:42.439998 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.090065 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}]

I, [2014-09-10T22:02:42.518047 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.077558 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:42.518161 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

I, [2014-09-10T22:02:51.798469 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.091365 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:51.879714 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.080608 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:51.879830 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

I, [2014-09-10T22:02:53.018024 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.092747 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:53.107537 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.089011 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:53.107648 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

I, [2014-09-10T22:02:53.181049 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.072969 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:53.255187 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.073677 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:53.255304 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:02:53.289079 #30216] [0xeadff8] DEBUG -- : skipping rendering since the agent appears to be ruby

I, [2014-09-10T22:02:53.365199 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.075334 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:53.473824 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.108121 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:02:53.473938 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

I, [2014-09-10T22:03:21.314499 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.092694 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:03:21.396144 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.080962 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:03:21.396258 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

I, [2014-09-10T22:03:21.553645 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.07646 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:03:21.643250 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.089118 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:03:21.643359 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

D, [2014-09-10T22:03:21.643440 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: nil

D, [2014-09-10T22:03:22.645160 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:23.647212 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:24.649399 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:25.651458 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:26.653597 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:27.655169 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:28.657332 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:29.659290 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:30.660916 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:31.662614 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:32.665876 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:33.668064 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:34.669909 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:35.671703 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:36.673291 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:37.675217 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:38.677396 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:39.679769 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:40.682019 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:41.683979 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:42.686168 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:43.689142 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:44.691193 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Errno::ECONNREFUSED: Connection refused - connect(2) (https://xxx.209.19:25555)>

D, [2014-09-10T22:03:45.735413 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has n 

ot started yet.>

D, [2014-09-10T22:03:46.759620 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:03:47.788890 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:03:48.826424 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:03:49.854053 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:03:50.888919 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:03:51.928787 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:03:52.956601 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:03:53.981222 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:03:55.003987 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:03:56.031048 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:03:57.054839 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:03:58.089914 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:03:59.110546 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

D, [2014-09-10T22:04:00.129937 #30216] [0xeadff8] DEBUG -- : Waiting for director to be ready: #<Bosh::Deployer::DirectorGatewayError: Nginx has started but the application it is proxying to has not started yet.>

I, [2014-09-10T22:04:00.401546 #30216] [0xeadff8]  INFO -- : Director is ready: {"name"=>"firstbosh", "uuid"=>"1b143d70-10e0-4b6e-9590-6c084809d977", "version"=>"1.2579.0 (release:4fef83a2 bosh:4fef83a2)", "user"=>nil, "cpi"=>"aws", "features"=>{"dns"=>{"status"=>true, "extras"=>{"domain_name"=>"microbosh"}}, "compiled_package_cache"=>{"status"=>false, "extras"=>{"provider"=>nil}}, "snapshots"=>{"status"=>false}}}

I, [2014-09-10T22:04:05.511023 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.127698 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:04:05.578044 #30216] [0xeadff8]  INFO -- : [AWS EC2 200 0.066233 0 retries] describe_addresses(:filters=>[{:name=>"instance-id",:values=>["i-df90db81"]}])

I, [2014-09-10T22:04:05.578229 #30216] [0xeadff8]  INFO -- : discovered bosh ip=xxx.209.19

[Steve Wall]

Would you be able to tell me a bit more regarding the MicroBOSH boot up process? How does it boot? What log file does it create? Maybe a pointer to the script that starts it up would be helpful. I'll continue to dig into this via the github repo for bosh and if I'm able to get more detail I'll post as well. 

On Friday, September 12, 2014 8:32:07 AM UTC-6, Dr Nic Williams wrote:

[Dmitriy Kalinin]

Each vm has run it installed. Runit is configured to start bosh-agent. You can find that configuration in /etc/sv/... Once bosh-agent is started it stars logging to /var/vcap/bosh/log/current. Somewhere in the log it should say 'Starting agent' whenever agent starts/restarts.

Each vm also have assigned processes (specified by deployment manifest) that are started by monit. You should be able to see them if you run 'sudo us' and then 'minot summary'

I'll add more docs about this.

-dmitriy

[Steve Wall]

Do you know the vcap password? I tried b00tstrap without success.

I'm started looking around the /etc/sv directory structure and a lot of things are owned by root:root. Is that expected?

[Dr Nic Williams]

To ssh in use the ssh key

ssh vcap@IP -i ~/.microbosh/ssh/firstbosh

[Dr Nic Williams]

Root password is c1oudc0w

On Fri, Sep 12, 2014 at 9:37 AM, Dmitriy Kalinin <dkal...@pivotal.io> wrote:

[Steve Wall]

I was able to ssh into the instance, but then executing sudo prompted for a password.

[Steve Wall]

That worked!

[Steve Wall]

Just to make sure I'm understanding things correctly, I'd like to level set a bit. I used bosh-bootstrap to install MicroBOSH on AWS. MicroBOSH is a BOSH installation on one VM. Does that sound correct?

On that VM, I'm seeing monit running and the log file under /etc/sv/agent/log. The Director does not appear to be running. When I hit the https://firstbosh_ip_address:25555/info it times out. How would I check to see if Director is running? Something else that would be interesting to know is how Director is started? 

[Dmitriy Kalinin]

Correct.

`monit summary` should tell you if director is running.

If this is AWS, make sure that /var/vcap/jobs/director contains some files. In some cases AWS throws away ephemeral disk (which is where /var/vcap/jobs) which would result in director not starting up since the code is no longer there. In that case you want to redeploy your microbosh via `bosh micro deploy <stemcell> --update` to bring it back.

[Steve Wall]

It appears you are correct with ephemeral disk being the issue.

root@bm-42aaef33-83a5-47f3-a033-b843564cb5e4:/var/vcap/jobs# file director

director: broken symbolic link to `/var/vcap/data/jobs/director/cc1da8b6e4aefd733c9bf4a9c49d7890cc1318d0/42dfec8e088c1511a66b47f0886808f3d08a20a5'

root@bm-42aaef33-83a5-47f3-a033-b843564cb5e4:/var/vcap/jobs#

But I'm still struggling to get this going. Running the bosh update command didn't seem to correct the issue. Being a newb, I'm sure there is something I'm missing. Here's the results when I attempt the bosh update. The "Unknown Director" looks strange. I was expecting it to point to the firstbosh server that is the current target. What am I missing?

ubuntu@ip-172-31-10-11:~/.microbosh/deployments$ bosh target

Current target is https://172.31.8.30:25555 (firstbosh)

ubuntu@ip-172-31-10-11:~/.microbosh/deployments$ bosh micro deploy  firstbosh/bosh-stemcell-latest-aws-xen-ubuntu.tgz --update

Updating `firstbosh/micro_bosh.yml' to `Unknown Director' (type 'yes' to continue): yes

Verifying stemcell...

File exists and readable                                     OK

Verifying tarball...

Read tarball                                                 OK

Manifest exists                                              OK

Stemcell image file                                          OK

Stemcell properties                                          OK

Stemcell info

-------------

Name:    bosh-aws-xen-ubuntu-lucid

Version: 2579

Will skip deploy due to no changes

Deployed `firstbosh/micro_bosh.yml' to `Unknown Director', took 00:00:05 to complete

[Dmitriy Kalinin]

Ahh right. micro deployer thinks it does not have to do anything because stemcell/properties did not change. 

You just need to change your microbosh manifest to trigger the change. (Add a dummy property to the end - trigger_deploy: true).

We do not currently have a way to force a micro deployment but that's something we have on our list to implement.

[fabi...@gmail.com]

Before I start, thanks for your help.

I'm facing the same problem here, but I'm not using Amazon, I'm using VMWare ESXi instead.

Here at my job we are evaluating the Pivotal Cloud Foundry, I'm trying the latest stable version (so far) 1.3.5 (Elastic Runtime), I was able to install the Ops Manager, Elastic Runtime and then, I shut down my lab environment, when I get back in the other day, I turned on all the environment and tried to install the RabbitMQ, but the nginx didn't start at the Ops Manager VM and all I've got was the error message "[WARNING] cannot access director, trying 4 more times..."

Since this is one old thread, is there any patch to this issue already?

Best Regards

Fabio G. Martins

[Dmitriy Kalinin]

For OpsManager related questions, please use https://support.pivotal.io to file a support ticket.