Skip to content

Instantly share code, notes, and snippets.

@devcamcar

devcamcar/gist:ef42d68a5ee29cd99184

Created May 16, 2014 00:28
Show Gist options
  • Save devcamcar/ef42d68a5ee29cd99184 to your computer and use it in GitHub Desktop.
Save devcamcar/ef42d68a5ee29cd99184 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
gistfile1.txt
Director task 18
# Logfile created on 2014-05-16 00:20:48 +0000 by logger.rb/31641
I, [2014-05-16T00:20:48.405066 #2657] INFO -- : Director Version : 1.2427.0
I, [2014-05-16T00:20:48.405182 #2657] INFO -- : Enqueuing task: 18
I, [2014-05-16T00:20:51.286318 #9215] [0x109c080] INFO -- : Starting task: 18
I, [2014-05-16T00:20:51.286531 #9215] [task:18] INFO -- : Creating job
I, [2014-05-16T00:20:51.286688 #9215] [task:18] INFO -- : Reading deployment manifest
D, [2014-05-16T00:20:51.287092 #9215] [task:18] DEBUG -- : Manifest:
---
name: cf
director_uuid: <director_id>
releases:
- name: cf
version: 171
compilation:
workers: 3
network: default
reuse_compilation_vms: true
cloud_properties:
instance_type: m1.small
update:
canaries: 0
canary_watch_time: 30000-600000
update_watch_time: 30000-600000
max_in_flight: 32
serial: false
networks:
- name: default
type: dynamic
cloud_properties:
security_groups:
- default
- bosh
- cf-private
- name: external
type: dynamic
cloud_properties:
security_groups:
- default
- bosh
- cf-public
- name: floating
type: vip
cloud_properties: {}
resource_pools:
- name: common
network: default
size: 14
stemcell:
name: bosh-openstack-kvm-ubuntu
version: 2427
cloud_properties:
instance_type: m1.small
- name: large
network: default
size: 3
stemcell:
name: bosh-openstack-kvm-ubuntu
version: 2427
cloud_properties:
instance_type: m1.medium
jobs:
- name: nats
templates:
- name: nats
- name: nats_stream_forwarder
instances: 1
resource_pool: common
networks:
- name: default
default:
- dns
- gateway
- name: syslog_aggregator
templates:
- name: syslog_aggregator
instances: 1
resource_pool: common
persistent_disk: 65536
networks:
- name: default
default:
- dns
- gateway
- name: nfs_server
templates:
- name: debian_nfs_server
instances: 1
resource_pool: common
persistent_disk: 65535
networks:
- name: default
default:
- dns
- gateway
- name: postgres
templates:
- name: postgres
instances: 1
resource_pool: common
persistent_disk: 65536
networks:
- name: default
default:
- dns
- gateway
properties:
db: databases
- name: uaa
templates:
- name: uaa
instances: 1
resource_pool: common
networks:
- name: default
default:
- dns
- gateway
- name: loggregator
templates:
- name: loggregator
instances: 1
resource_pool: common
networks:
- name: default
default:
- dns
- gateway
- name: trafficcontroller
templates:
- name: loggregator_trafficcontroller
instances: 1
resource_pool: common
networks:
- name: default
default:
- dns
- gateway
- name: cloud_controller
templates:
- name: cloud_controller_ng
instances: 1
resource_pool: common
networks:
- name: default
default:
- dns
- gateway
properties:
ccdb: ccdb
- name: cloud_controller_worker
templates:
- name: cloud_controller_worker
instances: 1
resource_pool: common
networks:
- name: default
default:
- dns
- gateway
properties:
ccdb: ccdb
- name: clock_global
templates:
- name: cloud_controller_clock
instances: 1
resource_pool: common
networks:
- name: default
default:
- dns
- gateway
properties:
ccdb: ccdb
- name: etcd
templates:
- name: etcd
instances: 1
resource_pool: common
persistent_disk: 10024
networks:
- name: default
default:
- dns
- gateway
- name: health_manager
templates:
- name: hm9000
instances: 1
resource_pool: common
networks:
- name: default
default:
- dns
- gateway
- name: dea
templates:
- name: dea_logging_agent
- name: dea_next
instances: 3
resource_pool: large
networks:
- name: default
default:
- dns
- gateway
- name: router
templates:
- name: gorouter
instances: 1
resource_pool: common
networks:
- name: default
default:
- dns
- gateway
- name: haproxy
templates:
- name: haproxy
instances: 1
resource_pool: common
networks:
- name: external
default:
- dns
- gateway
- name: floating
static_ips:
- <static_ip>
properties:
domain: <static_ip>.xip.io
system_domain: <static_ip>.xip.io
system_domain_organization: admin
app_domains:
- <static_ip>.xip.io
haproxy: {}
networks:
apps: default
nats:
user: nats
password: <password>
address: 0.nats.default.cf.microbosh
port: 4222
machines:
- 0.nats.default.cf.microbosh
syslog_aggregator:
address: 0.syslog-aggregator.default.cf.microbosh
port: 54321
nfs_server:
address: 0.nfs-server.default.cf.microbosh
network: ! '*.cf.microbosh'
idmapd_domain: localdomain
debian_nfs_server:
no_root_squash: true
loggregator_endpoint:
shared_secret: <password>
host: 0.trafficcontroller.default.cf.microbosh
loggregator:
servers:
zone:
- 0.loggregator.default.cf.microbosh
traffic_controller:
zone: zone
logger_endpoint:
use_ssl: false
port: 80
ssl:
skip_cert_verify: true
router:
endpoint_timeout: 60
status:
port: 8080
user: gorouter
password: <password>
servers:
z1:
- 0.router.default.cf.microbosh
z2: []
etcd:
machines:
- 0.etcd.default.cf.microbosh
dea: &25458860
disk_mb: 102400
disk_overcommit_factor: 2
memory_mb: 15000
memory_overcommit_factor: 3
directory_server_protocol: http
mtu: 1460
deny_networks:
- 169.254.0.0/16
dea_next: *25458860
disk_quota_enabled: false
dea_logging_agent:
status:
user: admin
password: <password>
databases:
db_scheme: postgres
address: 0.postgres.default.cf.microbosh
port: 5524
roles:
- tag: admin
name: ccadmin
password: <password>
- tag: admin
name: uaaadmin
password: <password>
databases:
- tag: cc
name: ccdb
citext: true
- tag: uaa
name: uaadb
citext: true
ccdb: &25991480
db_scheme: postgres
address: 0.postgres.default.cf.microbosh
port: 5524
roles:
- tag: admin
name: ccadmin
password: <password>
databases:
- tag: cc
name: ccdb
citext: true
ccdb_ng: *25991480
uaadb:
db_scheme: postgresql
address: 0.postgres.default.cf.microbosh
port: 5524
roles:
- tag: admin
name: uaaadmin
password: <password>
databases:
- tag: uaa
name: uaadb
citext: true
cc: &25907320
srv_api_uri: http://api.<static_ip>.xip.io
jobs:
local:
number_of_workers: 2
generic:
number_of_workers: 2
global:
timeout_in_seconds: 14400
app_bits_packer:
timeout_in_seconds:
app_events_cleanup:
timeout_in_seconds:
app_usage_events_cleanup:
timeout_in_seconds:
blobstore_delete:
timeout_in_seconds:
blobstore_upload:
timeout_in_seconds:
droplet_deletion:
timeout_in_seconds:
droplet_upload:
timeout_in_seconds:
model_deletion:
timeout_in_seconds:
bulk_api_password: <password>
staging_upload_user: upload
staging_upload_password: <password>
quota_definitions:
default:
memory_limit: 10240
total_services: 100
non_basic_services_allowed: true
total_routes: 1000
trial_db_allowed: true
resource_pool:
resource_directory_key: cloudfoundry-resources
fog_connection:
provider: Local
local_root: /var/vcap/nfs/shared
packages:
app_package_directory_key: cloudfoundry-packages
fog_connection:
provider: Local
local_root: /var/vcap/nfs/shared
droplets:
droplet_directory_key: cloudfoundry-droplets
fog_connection:
provider: Local
local_root: /var/vcap/nfs/shared
buildpacks:
buildpack_directory_key: cloudfoundry-buildpacks
fog_connection:
provider: Local
local_root: /var/vcap/nfs/shared
install_buildpacks:
- name: java_buildpack
package: buildpack_java
- name: ruby_buildpack
package: buildpack_ruby
- name: nodejs_buildpack
package: buildpack_nodejs
- name: go_buildpack
package: buildpack_go
db_encryption_key: <password>
hm9000_noop: false
diego: false
newrelic:
license_key:
environment_name: cf
ccng: *25907320
login:
enabled: false
uaa:
url: http://uaa.<static_ip>.xip.io
no_ssl: true
cc:
client_secret: <password>
admin:
client_secret: <password>
batch:
username: batch
password: <password>
clients:
cf:
override: true
authorized-grant-types: password,implicit,refresh_token
authorities: uaa.none
scope: cloud_controller.read,cloud_controller.write,openid,password.write,cloud_controller.admin,scim.read,scim.write
access-token-validity: 7200
refresh-token-validity: 1209600
admin:
secret: <password>
authorized-grant-types: client_credentials
authorities: clients.read,clients.write,clients.secret,password.write,scim.read,uaa.admin
scim:
users:
- admin|<password>|scim.write,scim.read,openid,cloud_controller.admin,uaa.admin,password.write
- services|<password>|scim.write,scim.read,openid,cloud_controller.admin
jwt:
signing_key: ! '-----BEGIN RSA PRIVATE KEY-----
MIICXAIBAAKBgQDHFr+KICms+tuT1OXJwhCUmR2dKVy7psa8xzElSyzqx7oJyfJ1
JZyOzToj9T5SfTIq396agbHJWVfYphNahvZ/7uMXqHxf+ZH9BL1gk9Y6kCnbM5R6
0gfwjyW1/dQPjOzn9N394zd2FJoFHwdq9Qs0wBugspULZVNRxq7veq/fzwIDAQAB
AoGBAJ8dRTQFhIllbHx4GLbpTQsWXJ6w4hZvskJKCLM/o8R4n+0W45pQ1xEiYKdA
Z/DRcnjltylRImBD8XuLL8iYOQSZXNMb1h3g5/UGbUXLmCgQLOUUlnYt34QOQm+0
KvUqfMSFBbKMsYBAoQmNdTHBaz3dZa8ON9hh/f5TT8u0OWNRAkEA5opzsIXv+52J
duc1VGyX3SwlxiE2dStW8wZqGiuLH142n6MKnkLU4ctNLiclw6BZePXFZYIK+AkE
xQ+k16je5QJBAN0TIKMPWIbbHVr5rkdUqOyezlFFWYOwnMmw/BKa1d3zp54VP/P8
+5aQ2d4sMoKEOfdWH7UqMe3FszfYFvSu5KMCQFMYeFaaEEP7Jn8rGzfQ5HQd44ek
lQJqmq6CE2BXbY/i34FuvPcKU70HEEygY6Y9d8J3o6zQ0K9SYNu+pcXt4lkCQA3h
jJQQe5uEGJTExqed7jllQ0khFJzLMx0K6tj0NeeIzAaGCQz13oo2sCdeGRHO4aDh
HH6Qlq/6UOV5wP8+GAcCQFgRCcB+hrje8hfEEefHcFpyKH+5g1Eu1k0mLrxK2zd+
4SlotYRHgPCEubokb2S1zfZDWIXW3HmggnGgM949TlY=
-----END RSA PRIVATE KEY-----
'
verification_key: ! '-----BEGIN PUBLIC KEY-----
MIGfMA0GCSqGSIb3DQEBAQUAA4GNADCBiQKBgQDHFr+KICms+tuT1OXJwhCUmR2d
KVy7psa8xzElSyzqx7oJyfJ1JZyOzToj9T5SfTIq396agbHJWVfYphNahvZ/7uMX
qHxf+ZH9BL1gk9Y6kCnbM5R60gfwjyW1/dQPjOzn9N394zd2FJoFHwdq9Qs0wBug
spULZVNRxq7veq/fzwIDAQAB
-----END PUBLIC KEY-----
'
I, [2014-05-16T00:20:51.287320 #9215] [task:18] INFO -- : Creating deployment plan
I, [2014-05-16T00:20:51.288115 #9215] [task:18] INFO -- : Deployment plan options: {}
I, [2014-05-16T00:20:51.332322 #9215] [task:18] INFO -- : Created deployment plan
D, [2014-05-16T00:20:53.958451 #9215] [task:18] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:53.959775 #9215] [task:18] DEBUG -- : (0.000975s) SELECT * FROM "tasks" WHERE "id" = 18
D, [2014-05-16T00:20:53.960597 #9215] [task:18] DEBUG -- : Released connection: 19562740
I, [2014-05-16T00:20:53.960982 #9215] [task:18] INFO -- : Performing task: 18
D, [2014-05-16T00:20:53.962282 #9215] [task:18] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:53.962763 #9215] [task:18] DEBUG -- : (0.000173s) BEGIN
D, [2014-05-16T00:20:53.965617 #9215] [task:18] DEBUG -- : (0.000630s) UPDATE "tasks" SET "state" = 'processing', "timestamp" = '2014-05-16 00:20:53.961636+0000', "description" = 'create deployment', "result" = NULL, "output" = '/var/vcap/store/director/tasks/18', "user_id" = NULL, "checkpoint_time" = '2014-05-16 00:20:53.961765+0000', "type" = 'update_deployment' WHERE ("id" = 18)
D, [2014-05-16T00:20:53.967423 #9215] [task:18] DEBUG -- : (0.001458s) COMMIT
D, [2014-05-16T00:20:53.967707 #9215] [task:18] DEBUG -- : Released connection: 19562740
I, [2014-05-16T00:20:53.967882 #9215] [task:18] INFO -- : Acquiring deployment lock on cf
D, [2014-05-16T00:20:53.968220 #9215] [task:18] DEBUG -- : Acquiring lock: lock:deployment:cf
D, [2014-05-16T00:20:53.968540 #9215] [task:18] DEBUG -- : Redis >> SETNX lock:deployment:cf 1400199664.9683535:21d2c2e4-cd9c-4aae-977b-99fc64b3cd12
D, [2014-05-16T00:20:53.969221 #9215] [task:18] DEBUG -- : Redis >> 0.52ms
D, [2014-05-16T00:20:53.969350 #9215] [task:18] DEBUG -- : Acquired lock: lock:deployment:cf
I, [2014-05-16T00:20:53.969568 #9215] [task:18] INFO -- : Preparing deployment
I, [2014-05-16T00:20:53.969948 #9215] [task:18] INFO -- : Preparing deployment
I, [2014-05-16T00:20:53.970448 #9215] [task:18] INFO -- : Binding deployment
D, [2014-05-16T00:20:53.970680 #9215] [task:18] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:53.971360 #9215] [0x2014dc8] DEBUG -- : Renewing lock: lock:deployment:cf
D, [2014-05-16T00:20:53.971664 #9215] [0x2014dc8] DEBUG -- : Redis >> WATCH lock:deployment:cf
D, [2014-05-16T00:20:53.971989 #9215] [task:18] DEBUG -- : (0.001078s) BEGIN
D, [2014-05-16T00:20:53.973767 #9215] [0x2014dc8] DEBUG -- : Redis >> AUTH redis
D, [2014-05-16T00:20:53.974179 #9215] [task:18] DEBUG -- : (0.001146s) SELECT * FROM "deployments" WHERE ("name" = 'cf') LIMIT 1
D, [2014-05-16T00:20:53.974763 #9215] [0x2014dc8] DEBUG -- : Redis >> 0.75ms
D, [2014-05-16T00:20:53.975057 #9215] [task:18] DEBUG -- : (0.000422s) COMMIT
D, [2014-05-16T00:20:53.975296 #9215] [task:18] DEBUG -- : Released connection: 19562740
I, [2014-05-16T00:20:53.975857 #9215] [task:18] INFO -- : Binding releases
I, [2014-05-16T00:20:53.976079 #9215] [task:18] INFO -- : Acquiring release lock: cf
D, [2014-05-16T00:20:53.976288 #9215] [task:18] DEBUG -- : Acquiring lock: lock:release:cf
D, [2014-05-16T00:20:53.976512 #9215] [task:18] DEBUG -- : Redis >> SETNX lock:release:cf 1400199664.976422:3fde05d5-0bac-46b4-a3f3-65171cccb786
D, [2014-05-16T00:20:53.976924 #9215] [0x2014dc8] DEBUG -- : Redis >> 5.09ms
D, [2014-05-16T00:20:53.977117 #9215] [0x2014dc8] DEBUG -- : Redis >> GET lock:deployment:cf
D, [2014-05-16T00:20:53.977427 #9215] [task:18] DEBUG -- : Redis >> 0.76ms
D, [2014-05-16T00:20:53.977571 #9215] [task:18] DEBUG -- : Acquired lock: lock:release:cf
D, [2014-05-16T00:20:53.978496 #9215] [task:18] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:53.978691 #9215] [task:18] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:53.978917 #9215] [task:18] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:53.979299 #9215] [0x2014dc8] DEBUG -- : Redis >> 2.00ms
D, [2014-05-16T00:20:53.979804 #9215] [0x2014dc8] DEBUG -- : Redis >> MULTI
D, [2014-05-16T00:20:53.979970 #9215] [0x2014dc8] DEBUG -- : Redis >> SET lock:deployment:cf 1400199664.97946:21d2c2e4-cd9c-4aae-977b-99fc64b3cd12
D, [2014-05-16T00:20:53.980110 #9215] [0x2014dc8] DEBUG -- : Redis >> EXEC
D, [2014-05-16T00:20:53.980405 #9215] [task:18] DEBUG -- : (0.001287s) SELECT * FROM "releases" WHERE ("name" = 'cf') LIMIT 1
D, [2014-05-16T00:20:53.980661 #9215] [task:18] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:53.982168 #9215] [task:18] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:53.982449 #9215] [task:18] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:53.982816 #9215] [task:18] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:53.983588 #9215] [0x2014dc8] DEBUG -- : Redis >> 3.27ms
D, [2014-05-16T00:20:53.984137 #9215] [0x1e9225c] DEBUG -- : Renewing lock: lock:release:cf
D, [2014-05-16T00:20:53.984326 #9215] [0x1e9225c] DEBUG -- : Redis >> WATCH lock:release:cf
D, [2014-05-16T00:20:53.984713 #9215] [task:18] DEBUG -- : (0.001679s) SELECT * FROM "release_versions" WHERE (("release_versions"."release_id" = 1) AND ("version" = '171')) LIMIT 1
D, [2014-05-16T00:20:53.985040 #9215] [task:18] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:53.985199 #9215] [task:18] DEBUG -- : Found release `cf/171'
D, [2014-05-16T00:20:53.987216 #9215] [task:18] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:53.988038 #9215] [0x1e9225c] DEBUG -- : Redis >> AUTH redis
D, [2014-05-16T00:20:53.988243 #9215] [task:18] DEBUG -- : (0.000777s) SELECT "release_versions".* FROM "release_versions" INNER JOIN "deployments_release_versions" ON (("deployments_release_versions"."release_version_id" = "release_versions"."id") AND ("deployments_release_versions"."deployment_id" = 2))
D, [2014-05-16T00:20:53.988784 #9215] [task:18] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:53.989235 #9215] [task:18] DEBUG -- : Deleting lock: lock:release:cf
D, [2014-05-16T00:20:53.989428 #9215] [task:18] DEBUG -- : Redis >> WATCH lock:release:cf
D, [2014-05-16T00:20:53.989839 #9215] [0x1e9225c] DEBUG -- : Redis >> 1.31ms
D, [2014-05-16T00:20:53.990052 #9215] [0x1e9225c] DEBUG -- : Redis >> 5.48ms
D, [2014-05-16T00:20:53.990238 #9215] [0x1e9225c] DEBUG -- : Lock renewal thread exiting
D, [2014-05-16T00:20:53.990430 #9215] [0x1e9225c] DEBUG -- : Redis >> QUIT
D, [2014-05-16T00:20:53.990775 #9215] [task:18] DEBUG -- : Redis >> 1.18ms
D, [2014-05-16T00:20:53.991002 #9215] [task:18] DEBUG -- : Redis >> GET lock:release:cf
D, [2014-05-16T00:20:53.991405 #9215] [0x1e9225c] DEBUG -- : Redis >> 0.82ms
D, [2014-05-16T00:20:53.991873 #9215] [task:18] DEBUG -- : Redis >> 0.70ms
D, [2014-05-16T00:20:53.992251 #9215] [task:18] DEBUG -- : Redis >> MULTI
D, [2014-05-16T00:20:53.992389 #9215] [task:18] DEBUG -- : Redis >> DEL lock:release:cf
D, [2014-05-16T00:20:53.992497 #9215] [task:18] DEBUG -- : Redis >> EXEC
D, [2014-05-16T00:20:53.993137 #9215] [task:18] DEBUG -- : Redis >> 0.52ms
D, [2014-05-16T00:20:53.993299 #9215] [task:18] DEBUG -- : Deleted lock: lock:release:cf
I, [2014-05-16T00:20:53.993688 #9215] [task:18] INFO -- : Binding existing deployment
D, [2014-05-16T00:20:53.994836 #9215] [task:18] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:53.995733 #9215] [task:18] DEBUG -- : (0.000674s) SELECT * FROM "vms" WHERE ("vms"."deployment_id" = 2)
D, [2014-05-16T00:20:53.996429 #9215] [task:18] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:53.997010 #9215] [task:18] DEBUG -- : Creating new thread
D, [2014-05-16T00:20:53.997222 #9215] [task:18] DEBUG -- : Creating new thread
D, [2014-05-16T00:20:53.997629 #9215] [task:18] DEBUG -- : Creating new thread
D, [2014-05-16T00:20:54.039065 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.039273 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.039359 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.039494 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.039936 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.040126 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.040259 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.040402 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.040530 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.040656 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.040781 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.040910 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.041032 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.041158 #9215] [task:18] DEBUG -- : All threads are currently busy, queuing action
D, [2014-05-16T00:20:54.041353 #9215] [task:18] DEBUG -- : Waiting for tasks to complete
D, [2014-05-16T00:20:54.041600 #9215] [0x1d9b31c] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.041871 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Requesting current VM state for: 0c02b694-e905-43d9-a359-6d626625730b
D, [2014-05-16T00:20:54.042733 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.042915 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.043126 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.045683 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : (0.002281s) SELECT * FROM "vms" WHERE ("agent_id" = '0c02b694-e905-43d9-a359-6d626625730b') LIMIT 1
D, [2014-05-16T00:20:54.046007 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.048123 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : SENT: agent.0c02b694-e905-43d9-a359-6d626625730b {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.a8c15554-a4a3-4ce4-ac27-f9018e9a2f40"}
D, [2014-05-16T00:20:54.050511 #9215] [0x1d9afd4] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.050743 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Requesting current VM state for: 1ddd6a31-9549-4099-97f8-26fc591dd29f
D, [2014-05-16T00:20:54.050877 #9215] [0x1d9b6c8] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.051872 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Requesting current VM state for: c0b26d2f-b027-46b0-bd9a-d9f46858d371
D, [2014-05-16T00:20:54.051643 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.058156 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : (0.000327s) SET standard_conforming_strings = ON
D, [2014-05-16T00:20:54.058760 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : (0.000200s) SET client_min_messages = 'WARNING'
D, [2014-05-16T00:20:54.059137 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : (0.000196s) SET DateStyle = 'ISO'
D, [2014-05-16T00:20:54.059313 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.059443 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.059722 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.061382 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.a8c15554-a4a3-4ce4-ac27-f9018e9a2f40 {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.syslog-aggregator.default.cf.microbosh","ip":"10.0.0.99","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"0c02b694-e905-43d9-a359-6d626625730b","vm":{"name":"vm-f47e3666-9556-4998-86b4-9c5da3131196"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:03","offset":"-0.006060"},"job":{"name":"haproxy","templates":[{"name":"haproxy","version":"13","sha1":"76fa7e157b553a77d27dc5056ac1447d79e56846","blobstore_id":"1d38b7ee-83d1-4014-9dbe-22f9c11b33f8"}],"template":"haproxy","version":"13","sha1":"76fa7e157b553a77d27dc5056ac1447d79e56846","blobstore_id":"1d38b7ee-83d1-4014-9dbe-22f9c11b33f8"},"index":0}}
D, [2014-05-16T00:20:54.062060 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : (0.002151s) SELECT * FROM "vms" WHERE ("agent_id" = 'c0b26d2f-b027-46b0-bd9a-d9f46858d371') LIMIT 1
D, [2014-05-16T00:20:54.070905 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.071243 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.071543 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : SENT: agent.c0b26d2f-b027-46b0-bd9a-d9f46858d371 {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.2933975a-f3f3-4fbe-bf8c-fbda237a3dce"}
D, [2014-05-16T00:20:54.072125 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.072501 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : (0.000250s) SELECT * FROM "vms" WHERE ("agent_id" = '1ddd6a31-9549-4099-97f8-26fc591dd29f') LIMIT 1
D, [2014-05-16T00:20:54.072751 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.073016 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : SENT: agent.1ddd6a31-9549-4099-97f8-26fc591dd29f {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.f110caca-0271-44b5-a397-8c1c565ce9c6"}
D, [2014-05-16T00:20:54.070784 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.syslog-aggregator.default.cf.microbosh",
"ip"=>"10.0.0.99",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"0c02b694-e905-43d9-a359-6d626625730b",
"vm"=>{"name"=>"vm-f47e3666-9556-4998-86b4-9c5da3131196"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:03", "offset"=>"-0.006060"},
"job"=>
{"name"=>"haproxy",
"templates"=>
[{"name"=>"haproxy",
"version"=>"13",
"sha1"=>"76fa7e157b553a77d27dc5056ac1447d79e56846",
"blobstore_id"=>"1d38b7ee-83d1-4014-9dbe-22f9c11b33f8"}],
"template"=>"haproxy",
"version"=>"13",
"sha1"=>"76fa7e157b553a77d27dc5056ac1447d79e56846",
"blobstore_id"=>"1d38b7ee-83d1-4014-9dbe-22f9c11b33f8"},
"index"=>0}
D, [2014-05-16T00:20:54.074226 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.074928 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : (0.000559s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 13) LIMIT 1
D, [2014-05-16T00:20:54.075114 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.075379 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.076153 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.076707 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : (0.000406s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 17)
D, [2014-05-16T00:20:54.076842 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.076963 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.077231 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.077330 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.077412 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.077489 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.077564 #9215] [bind_existing_deployment(0c02b694-e905-43d9-a359-6d626625730b)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.077633 #9215] [0x1d9b31c] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.077715 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Requesting current VM state for: a601bba3-f52c-4e02-b358-c2d245abbd65
D, [2014-05-16T00:20:54.078057 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.078157 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.078327 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.078695 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : (0.000253s) SELECT * FROM "vms" WHERE ("agent_id" = 'a601bba3-f52c-4e02-b358-c2d245abbd65') LIMIT 1
D, [2014-05-16T00:20:54.078868 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.079127 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : SENT: agent.a601bba3-f52c-4e02-b358-c2d245abbd65 {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.f800fade-ef14-494a-a6ca-bbd2004bee90"}
D, [2014-05-16T00:20:54.079990 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.2933975a-f3f3-4fbe-bf8c-fbda237a3dce {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.nats.default.cf.microbosh","ip":"10.0.0.89","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"c0b26d2f-b027-46b0-bd9a-d9f46858d371","vm":{"name":"vm-3da996d0-629c-4bb2-a384-8aaa955c103e"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:06","offset":"-0.002172"},"job":{"name":"clock_global","templates":[{"name":"cloud_controller_clock","version":"6","sha1":"fb2fa12c4a9181772e2566d094310219ed124e48","blobstore_id":"e77b2f92-4b32-4c60-a12d-5cdb227488db"}],"template":"cloud_controller_clock","version":"6","sha1":"fb2fa12c4a9181772e2566d094310219ed124e48","blobstore_id":"e77b2f92-4b32-4c60-a12d-5cdb227488db"},"index":0}}
D, [2014-05-16T00:20:54.080538 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.f110caca-0271-44b5-a397-8c1c565ce9c6 {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.syslog-aggregator.default.cf.microbosh","ip":"10.0.0.87","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"1ddd6a31-9549-4099-97f8-26fc591dd29f","vm":{"name":"vm-4d02a494-c7a5-4da8-b998-cea70d2ad2be"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:06","offset":"-0.002755"},"job":{"name":"router","templates":[{"name":"gorouter","version":"21","sha1":"67e38485998b05555614bdcdb86dedbaba2827c2","blobstore_id":"c460956e-cdaf-4f43-a96c-147f4986e7f1"}],"template":"gorouter","version":"21","sha1":"67e38485998b05555614bdcdb86dedbaba2827c2","blobstore_id":"c460956e-cdaf-4f43-a96c-147f4986e7f1"},"index":0}}
D, [2014-05-16T00:20:54.086216 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.nats.default.cf.microbosh",
"ip"=>"10.0.0.89",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"c0b26d2f-b027-46b0-bd9a-d9f46858d371",
"vm"=>{"name"=>"vm-3da996d0-629c-4bb2-a384-8aaa955c103e"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:06", "offset"=>"-0.002172"},
"job"=>
{"name"=>"clock_global",
"templates"=>
[{"name"=>"cloud_controller_clock",
"version"=>"6",
"sha1"=>"fb2fa12c4a9181772e2566d094310219ed124e48",
"blobstore_id"=>"e77b2f92-4b32-4c60-a12d-5cdb227488db"}],
"template"=>"cloud_controller_clock",
"version"=>"6",
"sha1"=>"fb2fa12c4a9181772e2566d094310219ed124e48",
"blobstore_id"=>"e77b2f92-4b32-4c60-a12d-5cdb227488db"},
"index"=>0}
D, [2014-05-16T00:20:54.086743 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.093092 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.syslog-aggregator.default.cf.microbosh",
"ip"=>"10.0.0.87",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"1ddd6a31-9549-4099-97f8-26fc591dd29f",
"vm"=>{"name"=>"vm-4d02a494-c7a5-4da8-b998-cea70d2ad2be"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:06", "offset"=>"-0.002755"},
"job"=>
{"name"=>"router",
"templates"=>
[{"name"=>"gorouter",
"version"=>"21",
"sha1"=>"67e38485998b05555614bdcdb86dedbaba2827c2",
"blobstore_id"=>"c460956e-cdaf-4f43-a96c-147f4986e7f1"}],
"template"=>"gorouter",
"version"=>"21",
"sha1"=>"67e38485998b05555614bdcdb86dedbaba2827c2",
"blobstore_id"=>"c460956e-cdaf-4f43-a96c-147f4986e7f1"},
"index"=>0}
D, [2014-05-16T00:20:54.093959 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.094384 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.f800fade-ef14-494a-a6ca-bbd2004bee90 {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.trafficcontroller.default.cf.microbosh","ip":"10.0.0.95","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"a601bba3-f52c-4e02-b358-c2d245abbd65","vm":{"name":"vm-34bdf6c8-483e-4fa5-bdd8-35b68d6f341e"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:06","offset":"-0.007692"},"job":{"name":"trafficcontroller","templates":[{"name":"loggregator_trafficcontroller","version":"14","sha1":"75efc58c0ca39344f1b9679d259e808333b89dea","blobstore_id":"3a8f316f-f30b-48e0-a787-3491349a8c7f"}],"template":"loggregator_trafficcontroller","version":"14","sha1":"75efc58c0ca39344f1b9679d259e808333b89dea","blobstore_id":"3a8f316f-f30b-48e0-a787-3491349a8c7f"},"index":0}}
D, [2014-05-16T00:20:54.096300 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : (0.009376s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 6) LIMIT 1
D, [2014-05-16T00:20:54.096601 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.096825 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.097764 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.098328 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : (0.000340s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 10)
D, [2014-05-16T00:20:54.098545 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.098771 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.099190 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.099352 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.099484 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.099719 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.099854 #9215] [bind_existing_deployment(c0b26d2f-b027-46b0-bd9a-d9f46858d371)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.099989 #9215] [0x1d9b6c8] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.100145 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Requesting current VM state for: 4b7865b2-3762-460e-8af0-c47f99f71901
D, [2014-05-16T00:20:54.100737 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.100924 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.101145 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.101469 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : (0.007231s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 5) LIMIT 1
D, [2014-05-16T00:20:54.101805 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.102086 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.103326 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.103993 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : (0.002630s) SELECT * FROM "vms" WHERE ("agent_id" = '4b7865b2-3762-460e-8af0-c47f99f71901') LIMIT 1
D, [2014-05-16T00:20:54.104353 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.104805 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : SENT: agent.4b7865b2-3762-460e-8af0-c47f99f71901 {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.058dbab3-1806-451f-9482-713b78fbe445"}
D, [2014-05-16T00:20:54.114016 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.trafficcontroller.default.cf.microbosh",
"ip"=>"10.0.0.95",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"a601bba3-f52c-4e02-b358-c2d245abbd65",
"vm"=>{"name"=>"vm-34bdf6c8-483e-4fa5-bdd8-35b68d6f341e"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:06", "offset"=>"-0.007692"},
"job"=>
{"name"=>"trafficcontroller",
"templates"=>
[{"name"=>"loggregator_trafficcontroller",
"version"=>"14",
"sha1"=>"75efc58c0ca39344f1b9679d259e808333b89dea",
"blobstore_id"=>"3a8f316f-f30b-48e0-a787-3491349a8c7f"}],
"template"=>"loggregator_trafficcontroller",
"version"=>"14",
"sha1"=>"75efc58c0ca39344f1b9679d259e808333b89dea",
"blobstore_id"=>"3a8f316f-f30b-48e0-a787-3491349a8c7f"},
"index"=>0}
D, [2014-05-16T00:20:54.114288 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : (0.010648s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 16)
D, [2014-05-16T00:20:54.115034 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.115146 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.115323 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.115401 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.115461 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.115526 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.115618 #9215] [bind_existing_deployment(1ddd6a31-9549-4099-97f8-26fc591dd29f)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.115684 #9215] [0x1d9afd4] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.115778 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Requesting current VM state for: ef4f6bd5-b870-46fd-abfb-a59ab448db68
D, [2014-05-16T00:20:54.116151 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.116334 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.058dbab3-1806-451f-9482-713b78fbe445 {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.cloud-controller.default.cf.microbosh","ip":"10.0.0.98","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"4b7865b2-3762-460e-8af0-c47f99f71901","vm":{"name":"vm-7bbbae85-e9ff-4c21-a81a-92a924cbf35a"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:06","offset":"-0.006743"},"job":{"name":"loggregator","templates":[{"name":"loggregator","version":"22","sha1":"072eab81e04b2f8e561be45e1d796be0999a721b","blobstore_id":"6698ce75-b156-46c2-9ccc-57ed9cff1e71"}],"template":"loggregator","version":"22","sha1":"072eab81e04b2f8e561be45e1d796be0999a721b","blobstore_id":"6698ce75-b156-46c2-9ccc-57ed9cff1e71"},"index":0}}
D, [2014-05-16T00:20:54.121588 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.cloud-controller.default.cf.microbosh",
"ip"=>"10.0.0.98",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"4b7865b2-3762-460e-8af0-c47f99f71901",
"vm"=>{"name"=>"vm-7bbbae85-e9ff-4c21-a81a-92a924cbf35a"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:06", "offset"=>"-0.006743"},
"job"=>
{"name"=>"loggregator",
"templates"=>
[{"name"=>"loggregator",
"version"=>"22",
"sha1"=>"072eab81e04b2f8e561be45e1d796be0999a721b",
"blobstore_id"=>"6698ce75-b156-46c2-9ccc-57ed9cff1e71"}],
"template"=>"loggregator",
"version"=>"22",
"sha1"=>"072eab81e04b2f8e561be45e1d796be0999a721b",
"blobstore_id"=>"6698ce75-b156-46c2-9ccc-57ed9cff1e71"},
"index"=>0}
D, [2014-05-16T00:20:54.116460 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.122226 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.122603 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : (0.000246s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 11) LIMIT 1
D, [2014-05-16T00:20:54.122777 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.122925 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.123489 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.123844 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : (0.000196s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 6)
D, [2014-05-16T00:20:54.123972 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.124077 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.124270 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.124349 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.124411 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.124476 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.124535 #9215] [bind_existing_deployment(4b7865b2-3762-460e-8af0-c47f99f71901)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.124598 #9215] [0x1d9b6c8] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.124672 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Requesting current VM state for: 8e338b8f-07e5-4639-957d-8f0f2980ddee
D, [2014-05-16T00:20:54.125000 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.125095 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.125231 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.125590 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : (0.000249s) SELECT * FROM "vms" WHERE ("agent_id" = '8e338b8f-07e5-4639-957d-8f0f2980ddee') LIMIT 1
D, [2014-05-16T00:20:54.125767 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.126015 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : SENT: agent.8e338b8f-07e5-4639-957d-8f0f2980ddee {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.d1abdca0-3f85-4991-9c90-0c1f39fdffbe"}
D, [2014-05-16T00:20:54.126398 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.126748 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : (0.000231s) SELECT * FROM "vms" WHERE ("agent_id" = 'ef4f6bd5-b870-46fd-abfb-a59ab448db68') LIMIT 1
D, [2014-05-16T00:20:54.126937 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.127185 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : SENT: agent.ef4f6bd5-b870-46fd-abfb-a59ab448db68 {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.1d01f970-355b-4775-9ee0-acf0ae47a114"}
D, [2014-05-16T00:20:54.114863 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.127789 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : (0.000257s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 9) LIMIT 1
D, [2014-05-16T00:20:54.127964 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.128094 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.128679 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.128999 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : (0.000189s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 7)
D, [2014-05-16T00:20:54.129124 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.129227 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.129402 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.129480 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.129539 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.129625 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.129685 #9215] [bind_existing_deployment(a601bba3-f52c-4e02-b358-c2d245abbd65)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.129747 #9215] [0x1d9b31c] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.129822 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Requesting current VM state for: bfb93886-8b79-418a-be3f-6ebb24a17e3e
D, [2014-05-16T00:20:54.130151 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.130263 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.130382 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.130736 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : (0.000244s) SELECT * FROM "vms" WHERE ("agent_id" = 'bfb93886-8b79-418a-be3f-6ebb24a17e3e') LIMIT 1
D, [2014-05-16T00:20:54.130932 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.131177 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : SENT: agent.bfb93886-8b79-418a-be3f-6ebb24a17e3e {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.60109f17-e3da-41a0-9618-8f901067ed55"}
D, [2014-05-16T00:20:54.138009 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.60109f17-e3da-41a0-9618-8f901067ed55 {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.uaa.default.cf.microbosh","ip":"10.0.0.93","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"bfb93886-8b79-418a-be3f-6ebb24a17e3e","vm":{"name":"vm-d20fabc0-e3e0-4830-93e8-5dc51e1b54dc"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:06","offset":"-0.012793"},"job":{"name":"etcd","templates":[{"name":"etcd","version":"6","sha1":"8d90e829eefb34f340450b91cc1c4fa4d871426c","blobstore_id":"64067334-f41b-458b-9b58-0244205950b5"}],"template":"etcd","version":"6","sha1":"8d90e829eefb34f340450b91cc1c4fa4d871426c","blobstore_id":"64067334-f41b-458b-9b58-0244205950b5"},"index":0}}
D, [2014-05-16T00:20:54.146173 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.uaa.default.cf.microbosh",
"ip"=>"10.0.0.93",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"bfb93886-8b79-418a-be3f-6ebb24a17e3e",
"vm"=>{"name"=>"vm-d20fabc0-e3e0-4830-93e8-5dc51e1b54dc"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:06", "offset"=>"-0.012793"},
"job"=>
{"name"=>"etcd",
"templates"=>
[{"name"=>"etcd",
"version"=>"6",
"sha1"=>"8d90e829eefb34f340450b91cc1c4fa4d871426c",
"blobstore_id"=>"64067334-f41b-458b-9b58-0244205950b5"}],
"template"=>"etcd",
"version"=>"6",
"sha1"=>"8d90e829eefb34f340450b91cc1c4fa4d871426c",
"blobstore_id"=>"64067334-f41b-458b-9b58-0244205950b5"},
"index"=>0}
D, [2014-05-16T00:20:54.147118 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.147458 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.1d01f970-355b-4775-9ee0-acf0ae47a114 {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.nats.default.cf.microbosh","ip":"10.0.0.102","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"ef4f6bd5-b870-46fd-abfb-a59ab448db68","vm":{"name":"vm-ee04550d-db96-404d-952a-27dccc32eefb"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:03","offset":"-0.022121"},"job":{"name":"nfs_server","templates":[{"name":"debian_nfs_server","version":"11","sha1":"947ae501d722e2724333cd03b67acf7a143347a5","blobstore_id":"b6e5c5c7-8e98-4b5b-ab04-804521b6e96f"}],"template":"debian_nfs_server","version":"11","sha1":"947ae501d722e2724333cd03b67acf7a143347a5","blobstore_id":"b6e5c5c7-8e98-4b5b-ab04-804521b6e96f"},"index":0}}
D, [2014-05-16T00:20:54.148043 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : (0.000650s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 7) LIMIT 1
D, [2014-05-16T00:20:54.148352 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.148575 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.149529 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.149861 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.d1abdca0-3f85-4991-9c90-0c1f39fdffbe {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.loggregator.default.cf.microbosh","ip":"10.0.0.104","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"8e338b8f-07e5-4639-957d-8f0f2980ddee","vm":{"name":"vm-aff79b88-2d3b-4ef6-a6cc-0c085fa85bc0"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:07","offset":"-0.013410"},"job":{"name":"nats","templates":[{"name":"nats","version":"24","sha1":"7c56b42f9b27168f66de5663b8c22d193409d252","blobstore_id":"2280b895-72a5-4475-b5da-11b689da0170"},{"name":"nats_stream_forwarder","version":"9","sha1":"25fc386974bf2fc29e9682b3a381c36911517585","blobstore_id":"f924f5c6-4bdd-4339-b630-37823fb47b7a"}],"template":"nats","version":"24","sha1":"7c56b42f9b27168f66de5663b8c22d193409d252","blobstore_id":"2280b895-72a5-4475-b5da-11b689da0170"},"index":0}}
D, [2014-05-16T00:20:54.159214 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.nats.default.cf.microbosh",
"ip"=>"10.0.0.102",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"ef4f6bd5-b870-46fd-abfb-a59ab448db68",
"vm"=>{"name"=>"vm-ee04550d-db96-404d-952a-27dccc32eefb"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:03", "offset"=>"-0.022121"},
"job"=>
{"name"=>"nfs_server",
"templates"=>
[{"name"=>"debian_nfs_server",
"version"=>"11",
"sha1"=>"947ae501d722e2724333cd03b67acf7a143347a5",
"blobstore_id"=>"b6e5c5c7-8e98-4b5b-ab04-804521b6e96f"}],
"template"=>"debian_nfs_server",
"version"=>"11",
"sha1"=>"947ae501d722e2724333cd03b67acf7a143347a5",
"blobstore_id"=>"b6e5c5c7-8e98-4b5b-ab04-804521b6e96f"},
"index"=>0}
D, [2014-05-16T00:20:54.160218 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.160605 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : (0.010793s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 11)
D, [2014-05-16T00:20:54.160865 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.161084 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.161415 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.161699 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : (0.001225s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 14) LIMIT 1
D, [2014-05-16T00:20:54.171095 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.loggregator.default.cf.microbosh",
"ip"=>"10.0.0.104",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"8e338b8f-07e5-4639-957d-8f0f2980ddee",
"vm"=>{"name"=>"vm-aff79b88-2d3b-4ef6-a6cc-0c085fa85bc0"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:07", "offset"=>"-0.013410"},
"job"=>
{"name"=>"nats",
"templates"=>
[{"name"=>"nats",
"version"=>"24",
"sha1"=>"7c56b42f9b27168f66de5663b8c22d193409d252",
"blobstore_id"=>"2280b895-72a5-4475-b5da-11b689da0170"},
{"name"=>"nats_stream_forwarder",
"version"=>"9",
"sha1"=>"25fc386974bf2fc29e9682b3a381c36911517585",
"blobstore_id"=>"f924f5c6-4bdd-4339-b630-37823fb47b7a"}],
"template"=>"nats",
"version"=>"24",
"sha1"=>"7c56b42f9b27168f66de5663b8c22d193409d252",
"blobstore_id"=>"2280b895-72a5-4475-b5da-11b689da0170"},
"index"=>0}
D, [2014-05-16T00:20:54.171287 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.171784 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.172825 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.173282 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.173486 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.173667 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.175483 #9215] [bind_existing_deployment(bfb93886-8b79-418a-be3f-6ebb24a17e3e)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.175656 #9215] [0x1d9b31c] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.175795 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Requesting current VM state for: fc4785e9-7684-469f-8cda-8be736acf152
D, [2014-05-16T00:20:54.175080 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.182515 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : (0.007063s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 17) LIMIT 1
D, [2014-05-16T00:20:54.183085 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : (0.001027s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 3)
D, [2014-05-16T00:20:54.183436 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : (0.001802s) SET standard_conforming_strings = ON
D, [2014-05-16T00:20:54.183881 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : (0.000205s) SET client_min_messages = 'WARNING'
D, [2014-05-16T00:20:54.184287 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : (0.000236s) SET DateStyle = 'ISO'
D, [2014-05-16T00:20:54.184455 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.184715 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.185186 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.186337 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.186633 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.186976 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.187132 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.187304 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.187447 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.187630 #9215] [bind_existing_deployment(ef4f6bd5-b870-46fd-abfb-a59ab448db68)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.187774 #9215] [0x1d9afd4] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.187932 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Requesting current VM state for: ec16d720-5685-457a-8a6e-86148fb2d27d
D, [2014-05-16T00:20:54.188675 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.189056 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.189296 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.189433 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.189621 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.190348 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : (0.000553s) SELECT * FROM "vms" WHERE ("agent_id" = 'ec16d720-5685-457a-8a6e-86148fb2d27d') LIMIT 1
D, [2014-05-16T00:20:54.190661 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.191146 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : SENT: agent.ec16d720-5685-457a-8a6e-86148fb2d27d {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.bc454597-3170-4089-9743-ff0d2d860d10"}
D, [2014-05-16T00:20:54.191691 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : (0.002418s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 1)
D, [2014-05-16T00:20:54.192769 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.192979 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.193287 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.193422 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.193551 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.193664 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.193781 #9215] [bind_existing_deployment(8e338b8f-07e5-4639-957d-8f0f2980ddee)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.193889 #9215] [0x1d9b6c8] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.194017 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Requesting current VM state for: 6a6591bf-8958-47d1-b82c-e025a07ea1b3
D, [2014-05-16T00:20:54.194602 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.194766 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.194963 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.196183 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : (0.001039s) SELECT * FROM "vms" WHERE ("agent_id" = '6a6591bf-8958-47d1-b82c-e025a07ea1b3') LIMIT 1
D, [2014-05-16T00:20:54.196488 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.196903 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : SENT: agent.6a6591bf-8958-47d1-b82c-e025a07ea1b3 {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.04543a9a-d3d0-4452-b555-84d0b8dfaedb"}
D, [2014-05-16T00:20:54.197488 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.198088 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : (0.000405s) SELECT * FROM "vms" WHERE ("agent_id" = 'fc4785e9-7684-469f-8cda-8be736acf152') LIMIT 1
D, [2014-05-16T00:20:54.198424 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.198847 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : SENT: agent.fc4785e9-7684-469f-8cda-8be736acf152 {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.e3323635-e977-4794-833e-dff62c6cba58"}
D, [2014-05-16T00:20:54.203707 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.bc454597-3170-4089-9743-ff0d2d860d10 {"value":{"deployment":"cf","resource_pool":{"name":"large","cloud_properties":{"instance_type":"m1.medium"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"1.dea.default.cf.microbosh","ip":"10.0.0.109","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"ec16d720-5685-457a-8a6e-86148fb2d27d","vm":{"name":"vm-c76eaa75-b2c1-4879-96de-387f1343cb74"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:06","offset":"-0.008486"},"job":{"name":"dea","templates":[{"name":"dea_logging_agent","version":"15","sha1":"c1232a051982df2779fa0ef1527406840224c0ca","blobstore_id":"969ece16-90c4-44f3-ae2e-6b7a49859744"},{"name":"dea_next","version":"38","sha1":"add6292c060b193fb626a1496ce54d2dc4d52d6e","blobstore_id":"c2881bad-d98d-4718-a32d-98cd1cf4628a"}],"template":"dea_logging_agent","version":"15","sha1":"c1232a051982df2779fa0ef1527406840224c0ca","blobstore_id":"969ece16-90c4-44f3-ae2e-6b7a49859744"},"index":1}}
D, [2014-05-16T00:20:54.212815 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"large",
"cloud_properties"=>{"instance_type"=>"m1.medium"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"1.dea.default.cf.microbosh",
"ip"=>"10.0.0.109",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"ec16d720-5685-457a-8a6e-86148fb2d27d",
"vm"=>{"name"=>"vm-c76eaa75-b2c1-4879-96de-387f1343cb74"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:06", "offset"=>"-0.008486"},
"job"=>
{"name"=>"dea",
"templates"=>
[{"name"=>"dea_logging_agent",
"version"=>"15",
"sha1"=>"c1232a051982df2779fa0ef1527406840224c0ca",
"blobstore_id"=>"969ece16-90c4-44f3-ae2e-6b7a49859744"},
{"name"=>"dea_next",
"version"=>"38",
"sha1"=>"add6292c060b193fb626a1496ce54d2dc4d52d6e",
"blobstore_id"=>"c2881bad-d98d-4718-a32d-98cd1cf4628a"}],
"template"=>"dea_logging_agent",
"version"=>"15",
"sha1"=>"c1232a051982df2779fa0ef1527406840224c0ca",
"blobstore_id"=>"969ece16-90c4-44f3-ae2e-6b7a49859744"},
"index"=>1}
D, [2014-05-16T00:20:54.213397 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.213646 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.e3323635-e977-4794-833e-dff62c6cba58 {"value":{"deployment":"cf","resource_pool":{"name":"large","cloud_properties":{"instance_type":"m1.medium"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.dea.default.cf.microbosh","ip":"10.0.0.111","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"fc4785e9-7684-469f-8cda-8be736acf152","vm":{"name":"vm-44fec9aa-db69-4e7b-8e53-c5f9aef98735"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:06","offset":"-0.009113"},"job":{"name":"dea","templates":[{"name":"dea_logging_agent","version":"15","sha1":"c1232a051982df2779fa0ef1527406840224c0ca","blobstore_id":"969ece16-90c4-44f3-ae2e-6b7a49859744"},{"name":"dea_next","version":"38","sha1":"add6292c060b193fb626a1496ce54d2dc4d52d6e","blobstore_id":"c2881bad-d98d-4718-a32d-98cd1cf4628a"}],"template":"dea_logging_agent","version":"15","sha1":"c1232a051982df2779fa0ef1527406840224c0ca","blobstore_id":"969ece16-90c4-44f3-ae2e-6b7a49859744"},"index":0}}
D, [2014-05-16T00:20:54.222950 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"large",
"cloud_properties"=>{"instance_type"=>"m1.medium"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.dea.default.cf.microbosh",
"ip"=>"10.0.0.111",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"fc4785e9-7684-469f-8cda-8be736acf152",
"vm"=>{"name"=>"vm-44fec9aa-db69-4e7b-8e53-c5f9aef98735"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:06", "offset"=>"-0.009113"},
"job"=>
{"name"=>"dea",
"templates"=>
[{"name"=>"dea_logging_agent",
"version"=>"15",
"sha1"=>"c1232a051982df2779fa0ef1527406840224c0ca",
"blobstore_id"=>"969ece16-90c4-44f3-ae2e-6b7a49859744"},
{"name"=>"dea_next",
"version"=>"38",
"sha1"=>"add6292c060b193fb626a1496ce54d2dc4d52d6e",
"blobstore_id"=>"c2881bad-d98d-4718-a32d-98cd1cf4628a"}],
"template"=>"dea_logging_agent",
"version"=>"15",
"sha1"=>"c1232a051982df2779fa0ef1527406840224c0ca",
"blobstore_id"=>"969ece16-90c4-44f3-ae2e-6b7a49859744"},
"index"=>0}
D, [2014-05-16T00:20:54.223233 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.04543a9a-d3d0-4452-b555-84d0b8dfaedb {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.uaa.default.cf.microbosh","ip":"10.0.0.105","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"6a6591bf-8958-47d1-b82c-e025a07ea1b3","vm":{"name":"vm-3009834e-0b0b-4f31-a99b-896c007967da"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:07","offset":"-0.014835"},"job":{"name":"syslog_aggregator","templates":[{"name":"syslog_aggregator","version":"25","sha1":"fac5f27923a8025df87c3fccb42bb21b4bcad524","blobstore_id":"08577070-1f4d-4108-8fe9-01cfa8d52276"}],"template":"syslog_aggregator","version":"25","sha1":"fac5f27923a8025df87c3fccb42bb21b4bcad524","blobstore_id":"08577070-1f4d-4108-8fe9-01cfa8d52276"},"index":0}}
D, [2014-05-16T00:20:54.224143 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.224900 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : (0.011334s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 20) LIMIT 1
D, [2014-05-16T00:20:54.225157 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.225321 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.225922 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.234429 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.uaa.default.cf.microbosh",
"ip"=>"10.0.0.105",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"6a6591bf-8958-47d1-b82c-e025a07ea1b3",
"vm"=>{"name"=>"vm-3009834e-0b0b-4f31-a99b-896c007967da"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:07", "offset"=>"-0.014835"},
"job"=>
{"name"=>"syslog_aggregator",
"templates"=>
[{"name"=>"syslog_aggregator",
"version"=>"25",
"sha1"=>"fac5f27923a8025df87c3fccb42bb21b4bcad524",
"blobstore_id"=>"08577070-1f4d-4108-8fe9-01cfa8d52276"}],
"template"=>"syslog_aggregator",
"version"=>"25",
"sha1"=>"fac5f27923a8025df87c3fccb42bb21b4bcad524",
"blobstore_id"=>"08577070-1f4d-4108-8fe9-01cfa8d52276"},
"index"=>0}
D, [2014-05-16T00:20:54.234961 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.235193 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : (0.009104s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 14)
D, [2014-05-16T00:20:54.235353 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.235614 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.235973 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.236161 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : (0.001054s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 16) LIMIT 1
D, [2014-05-16T00:20:54.236795 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.236511 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.236953 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.238086 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.237246 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.238314 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.236333 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : (0.011528s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 19) LIMIT 1
D, [2014-05-16T00:20:54.238417 #9215] [bind_existing_deployment(ec16d720-5685-457a-8a6e-86148fb2d27d)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.238641 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : (0.000401s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 2)
D, [2014-05-16T00:20:54.238859 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.239124 #9215] [0x1d9afd4] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.239721 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.240173 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.239938 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Requesting current VM state for: 5f3b1df5-b2b9-4ef3-90c4-59bc36319c81
D, [2014-05-16T00:20:54.240371 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.241386 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.241135 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.241516 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.241952 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.241769 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.242032 #9215] [bind_existing_deployment(6a6591bf-8958-47d1-b82c-e025a07ea1b3)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.242567 #9215] [0x1d9b6c8] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.242380 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.242664 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Requesting current VM state for: 8d347fda-852a-4f15-98ea-cc3d68e077c2
D, [2014-05-16T00:20:54.243232 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.243402 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.243536 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.243788 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : (0.000895s) SELECT * FROM "vms" WHERE ("agent_id" = '5f3b1df5-b2b9-4ef3-90c4-59bc36319c81') LIMIT 1
D, [2014-05-16T00:20:54.239637 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.243998 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.244202 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : (0.000479s) SELECT * FROM "vms" WHERE ("agent_id" = '8d347fda-852a-4f15-98ea-cc3d68e077c2') LIMIT 1
D, [2014-05-16T00:20:54.245360 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : SENT: agent.5f3b1df5-b2b9-4ef3-90c4-59bc36319c81 {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.3e5eb0fa-79a8-400c-bcb2-a02f6c7eb692"}
D, [2014-05-16T00:20:54.245956 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.246346 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : SENT: agent.8d347fda-852a-4f15-98ea-cc3d68e077c2 {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.48cf337e-2bc8-4387-af72-985ea616d745"}
D, [2014-05-16T00:20:54.246589 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.247595 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : (0.000814s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 13)
D, [2014-05-16T00:20:54.247835 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.248003 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.248242 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.248345 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.248424 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.248511 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.248591 #9215] [bind_existing_deployment(fc4785e9-7684-469f-8cda-8be736acf152)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.248675 #9215] [0x1d9b31c] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.248776 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Requesting current VM state for: 794f87dc-935c-4f98-85ef-16b466ddc744
D, [2014-05-16T00:20:54.249211 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.249360 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.249517 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.249983 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : (0.000324s) SELECT * FROM "vms" WHERE ("agent_id" = '794f87dc-935c-4f98-85ef-16b466ddc744') LIMIT 1
D, [2014-05-16T00:20:54.250204 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.250555 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : SENT: agent.794f87dc-935c-4f98-85ef-16b466ddc744 {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.54625641-84d5-4bf8-9a37-161d4ffb587b"}
D, [2014-05-16T00:20:54.258017 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.48cf337e-2bc8-4387-af72-985ea616d745 {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.nfs-server.default.cf.microbosh","ip":"10.0.0.101","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"8d347fda-852a-4f15-98ea-cc3d68e077c2","vm":{"name":"vm-f9af81a4-25a5-4036-90db-cac40a410757"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:06","offset":"-0.002477"},"job":{"name":"uaa","templates":[{"name":"uaa","version":"47","sha1":"315f66a2d99218e638460b24e409ffa05b5d64e9","blobstore_id":"aee8860a-656b-4fc1-ac47-5fe2a9786aa7"}],"template":"uaa","version":"47","sha1":"315f66a2d99218e638460b24e409ffa05b5d64e9","blobstore_id":"aee8860a-656b-4fc1-ac47-5fe2a9786aa7"},"index":0}}
D, [2014-05-16T00:20:54.266080 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.nfs-server.default.cf.microbosh",
"ip"=>"10.0.0.101",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"8d347fda-852a-4f15-98ea-cc3d68e077c2",
"vm"=>{"name"=>"vm-f9af81a4-25a5-4036-90db-cac40a410757"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:06", "offset"=>"-0.002477"},
"job"=>
{"name"=>"uaa",
"templates"=>
[{"name"=>"uaa",
"version"=>"47",
"sha1"=>"315f66a2d99218e638460b24e409ffa05b5d64e9",
"blobstore_id"=>"aee8860a-656b-4fc1-ac47-5fe2a9786aa7"}],
"template"=>"uaa",
"version"=>"47",
"sha1"=>"315f66a2d99218e638460b24e409ffa05b5d64e9",
"blobstore_id"=>"aee8860a-656b-4fc1-ac47-5fe2a9786aa7"},
"index"=>0}
D, [2014-05-16T00:20:54.266343 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.54625641-84d5-4bf8-9a37-161d4ffb587b {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.loggregator.default.cf.microbosh","ip":"10.0.0.94","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"794f87dc-935c-4f98-85ef-16b466ddc744","vm":{"name":"vm-b08bc75e-c3de-4ec2-bd1f-8ffb284aa096"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:06","offset":"-0.007508"},"job":{"name":"cloud_controller","templates":[{"name":"cloud_controller_ng","version":"40","sha1":"39ed87e6a53592ee572fdeb2e54ffaa53727e74d","blobstore_id":"3a7b184f-9397-4142-8e94-59a52561b15e"}],"template":"cloud_controller_ng","version":"40","sha1":"39ed87e6a53592ee572fdeb2e54ffaa53727e74d","blobstore_id":"3a7b184f-9397-4142-8e94-59a52561b15e"},"index":0}}
D, [2014-05-16T00:20:54.267897 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.3e5eb0fa-79a8-400c-bcb2-a02f6c7eb692 {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.postgres.default.cf.microbosh","ip":"10.0.0.103","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"5f3b1df5-b2b9-4ef3-90c4-59bc36319c81","vm":{"name":"vm-2a4bc937-ec70-42fa-b593-b3ed1b729d17"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:03","offset":"-0.006774"},"job":{"name":"postgres","templates":[{"name":"postgres","version":"5","sha1":"0228430151570ea1e6cbb0c26c79b5ceaa83ef4d","blobstore_id":"78b57dd4-6b68-4ec9-84d1-d801fa158ecf"}],"template":"postgres","version":"5","sha1":"0228430151570ea1e6cbb0c26c79b5ceaa83ef4d","blobstore_id":"78b57dd4-6b68-4ec9-84d1-d801fa158ecf"},"index":0}}
D, [2014-05-16T00:20:54.267269 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.282439 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.postgres.default.cf.microbosh",
"ip"=>"10.0.0.103",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"5f3b1df5-b2b9-4ef3-90c4-59bc36319c81",
"vm"=>{"name"=>"vm-2a4bc937-ec70-42fa-b593-b3ed1b729d17"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:03", "offset"=>"-0.006774"},
"job"=>
{"name"=>"postgres",
"templates"=>
[{"name"=>"postgres",
"version"=>"5",
"sha1"=>"0228430151570ea1e6cbb0c26c79b5ceaa83ef4d",
"blobstore_id"=>"78b57dd4-6b68-4ec9-84d1-d801fa158ecf"}],
"template"=>"postgres",
"version"=>"5",
"sha1"=>"0228430151570ea1e6cbb0c26c79b5ceaa83ef4d",
"blobstore_id"=>"78b57dd4-6b68-4ec9-84d1-d801fa158ecf"},
"index"=>0}
D, [2014-05-16T00:20:54.274060 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.loggregator.default.cf.microbosh",
"ip"=>"10.0.0.94",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"794f87dc-935c-4f98-85ef-16b466ddc744",
"vm"=>{"name"=>"vm-b08bc75e-c3de-4ec2-bd1f-8ffb284aa096"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:06", "offset"=>"-0.007508"},
"job"=>
{"name"=>"cloud_controller",
"templates"=>
[{"name"=>"cloud_controller_ng",
"version"=>"40",
"sha1"=>"39ed87e6a53592ee572fdeb2e54ffaa53727e74d",
"blobstore_id"=>"3a7b184f-9397-4142-8e94-59a52561b15e"}],
"template"=>"cloud_controller_ng",
"version"=>"40",
"sha1"=>"39ed87e6a53592ee572fdeb2e54ffaa53727e74d",
"blobstore_id"=>"3a7b184f-9397-4142-8e94-59a52561b15e"},
"index"=>0}
D, [2014-05-16T00:20:54.283173 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.283876 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.284161 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : (0.001538s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 12) LIMIT 1
D, [2014-05-16T00:20:54.284567 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.284740 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.285418 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.285632 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : (0.001296s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 15) LIMIT 1
D, [2014-05-16T00:20:54.285843 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.285947 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : (0.000375s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 5)
D, [2014-05-16T00:20:54.286069 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : (0.001617s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 10) LIMIT 1
D, [2014-05-16T00:20:54.286569 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.287068 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.287293 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.287389 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.287468 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.287572 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.287657 #9215] [bind_existing_deployment(8d347fda-852a-4f15-98ea-cc3d68e077c2)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.287733 #9215] [0x1d9b6c8] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.287827 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Requesting current VM state for: 9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5
D, [2014-05-16T00:20:54.286329 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.288953 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.289320 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.290489 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.290661 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.290877 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.291018 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.291634 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : (0.000692s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 8)
D, [2014-05-16T00:20:54.291821 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : (0.000680s) SELECT * FROM "vms" WHERE ("agent_id" = '9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5') LIMIT 1
D, [2014-05-16T00:20:54.292177 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.292501 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.292829 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.292903 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.293736 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : SENT: agent.9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5 {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.4a87a30d-495a-491f-aa79-bf8d5fed4411"}
D, [2014-05-16T00:20:54.293182 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.294298 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.294372 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.294461 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.294524 #9215] [bind_existing_deployment(794f87dc-935c-4f98-85ef-16b466ddc744)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.294587 #9215] [0x1d9b31c] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.294665 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Requesting current VM state for: 6f17dc6a-8de4-4bac-ac16-fac86ed20b7a
D, [2014-05-16T00:20:54.295008 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.295107 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.295224 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.295591 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : (0.002864s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 4)
D, [2014-05-16T00:20:54.295722 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.295845 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.296025 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.296103 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.296162 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.296228 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.296288 #9215] [bind_existing_deployment(5f3b1df5-b2b9-4ef3-90c4-59bc36319c81)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.296350 #9215] [0x1d9afd4] DEBUG -- : Found an action that needs to be processed
D, [2014-05-16T00:20:54.296427 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Requesting current VM state for: 3050f941-b646-4826-9cc7-aa0f0e987d72
D, [2014-05-16T00:20:54.296757 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.296869 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.296985 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.297150 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : (0.001820s) SELECT * FROM "vms" WHERE ("agent_id" = '6f17dc6a-8de4-4bac-ac16-fac86ed20b7a') LIMIT 1
D, [2014-05-16T00:20:54.297323 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.297570 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : SENT: agent.6f17dc6a-8de4-4bac-ac16-fac86ed20b7a {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.8465e31a-9146-4f61-b0be-17202820dae3"}
D, [2014-05-16T00:20:54.297933 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : (0.000845s) SELECT * FROM "vms" WHERE ("agent_id" = '3050f941-b646-4826-9cc7-aa0f0e987d72') LIMIT 1
D, [2014-05-16T00:20:54.298113 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.298426 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : SENT: agent.3050f941-b646-4826-9cc7-aa0f0e987d72 {"method":"get_state","arguments":[],"reply_to":"director.152efc42-4f78-45e6-9225-adff344c874c.24c7d44d-932a-46fa-8aef-5124adc4ee8d"}
D, [2014-05-16T00:20:54.305445 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.4a87a30d-495a-491f-aa79-bf8d5fed4411 {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.postgres.default.cf.microbosh","ip":"10.0.0.91","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5","vm":{"name":"vm-969cca6f-dd14-43a5-857f-da019e90c028"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:03","offset":"-0.007312"},"job":{"name":"cloud_controller_worker","templates":[{"name":"cloud_controller_worker","version":"6","sha1":"fafea4fbe58a9194dfcd2e12a49fc7f29497a27b","blobstore_id":"972f66a3-b8d3-46fc-a31d-e7417a2d67de"}],"template":"cloud_controller_worker","version":"6","sha1":"fafea4fbe58a9194dfcd2e12a49fc7f29497a27b","blobstore_id":"972f66a3-b8d3-46fc-a31d-e7417a2d67de"},"index":0}}
D, [2014-05-16T00:20:54.312705 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.postgres.default.cf.microbosh",
"ip"=>"10.0.0.91",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5",
"vm"=>{"name"=>"vm-969cca6f-dd14-43a5-857f-da019e90c028"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:03", "offset"=>"-0.007312"},
"job"=>
{"name"=>"cloud_controller_worker",
"templates"=>
[{"name"=>"cloud_controller_worker",
"version"=>"6",
"sha1"=>"fafea4fbe58a9194dfcd2e12a49fc7f29497a27b",
"blobstore_id"=>"972f66a3-b8d3-46fc-a31d-e7417a2d67de"}],
"template"=>"cloud_controller_worker",
"version"=>"6",
"sha1"=>"fafea4fbe58a9194dfcd2e12a49fc7f29497a27b",
"blobstore_id"=>"972f66a3-b8d3-46fc-a31d-e7417a2d67de"},
"index"=>0}
D, [2014-05-16T00:20:54.313717 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.314109 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.8465e31a-9146-4f61-b0be-17202820dae3 {"value":{"deployment":"cf","resource_pool":{"name":"common","cloud_properties":{"instance_type":"m1.small"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"0.nfs-server.default.cf.microbosh","ip":"10.0.0.90","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"6f17dc6a-8de4-4bac-ac16-fac86ed20b7a","vm":{"name":"vm-55ea7c66-de66-4968-964a-1194fb9962b9"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:06","offset":"-0.009475"},"job":{"name":"health_manager","templates":[{"name":"hm9000","version":"16","sha1":"c5aaf3c5a7aaab9d43853b1e1b2abb60f32a4a34","blobstore_id":"ed8edb90-9e49-4cb2-8759-c73c2500c5d9"}],"template":"hm9000","version":"16","sha1":"c5aaf3c5a7aaab9d43853b1e1b2abb60f32a4a34","blobstore_id":"ed8edb90-9e49-4cb2-8759-c73c2500c5d9"},"index":0}}
D, [2014-05-16T00:20:54.314616 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : (0.000628s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 8) LIMIT 1
D, [2014-05-16T00:20:54.315485 #9215] [0x19e95e8] DEBUG -- : RECEIVED: director.152efc42-4f78-45e6-9225-adff344c874c.24c7d44d-932a-46fa-8aef-5124adc4ee8d {"value":{"deployment":"cf","resource_pool":{"name":"large","cloud_properties":{"instance_type":"m1.medium"},"stemcell":{"name":"bosh-openstack-kvm-ubuntu","version":"2427"}},"networks":{"default":{"type":"dynamic","cloud_properties":{"security_groups":["default","bosh","cf-private"]},"dns":["10.0.0.85"],"default":["dns","gateway"],"dns_record_name":"2.dea.default.cf.microbosh","ip":"10.0.0.108","netmask":"255.255.0.0","gateway":"10.0.0.1"}},"agent_id":"3050f941-b646-4826-9cc7-aa0f0e987d72","vm":{"name":"vm-18b5d6bf-b651-4c1d-86cd-8fda2ee9227a"},"job_state":"running","bosh_protocol":"1","ntp":{"timestamp":"16 May 00:15:06","offset":"-0.007708"},"job":{"name":"dea","templates":[{"name":"dea_logging_agent","version":"15","sha1":"c1232a051982df2779fa0ef1527406840224c0ca","blobstore_id":"969ece16-90c4-44f3-ae2e-6b7a49859744"},{"name":"dea_next","version":"38","sha1":"add6292c060b193fb626a1496ce54d2dc4d52d6e","blobstore_id":"c2881bad-d98d-4718-a32d-98cd1cf4628a"}],"template":"dea_logging_agent","version":"15","sha1":"c1232a051982df2779fa0ef1527406840224c0ca","blobstore_id":"969ece16-90c4-44f3-ae2e-6b7a49859744"},"index":2}}
D, [2014-05-16T00:20:54.315912 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.322323 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.323002 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Acquired connection: 19562740
D, [2014-05-16T00:20:54.321880 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"common",
"cloud_properties"=>{"instance_type"=>"m1.small"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"0.nfs-server.default.cf.microbosh",
"ip"=>"10.0.0.90",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"6f17dc6a-8de4-4bac-ac16-fac86ed20b7a",
"vm"=>{"name"=>"vm-55ea7c66-de66-4968-964a-1194fb9962b9"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:06", "offset"=>"-0.009475"},
"job"=>
{"name"=>"health_manager",
"templates"=>
[{"name"=>"hm9000",
"version"=>"16",
"sha1"=>"c5aaf3c5a7aaab9d43853b1e1b2abb60f32a4a34",
"blobstore_id"=>"ed8edb90-9e49-4cb2-8759-c73c2500c5d9"}],
"template"=>"hm9000",
"version"=>"16",
"sha1"=>"c5aaf3c5a7aaab9d43853b1e1b2abb60f32a4a34",
"blobstore_id"=>"ed8edb90-9e49-4cb2-8759-c73c2500c5d9"},
"index"=>0}
D, [2014-05-16T00:20:54.331146 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Received VM state: {"deployment"=>"cf",
"resource_pool"=>
{"name"=>"large",
"cloud_properties"=>{"instance_type"=>"m1.medium"},
"stemcell"=>{"name"=>"bosh-openstack-kvm-ubuntu", "version"=>"2427"}},
"networks"=>
{"default"=>
{"type"=>"dynamic",
"cloud_properties"=>
{"security_groups"=>["default", "bosh", "cf-private"]},
"dns"=>["10.0.0.85"],
"default"=>["dns", "gateway"],
"dns_record_name"=>"2.dea.default.cf.microbosh",
"ip"=>"10.0.0.108",
"netmask"=>"255.255.0.0",
"gateway"=>"10.0.0.1"}},
"agent_id"=>"3050f941-b646-4826-9cc7-aa0f0e987d72",
"vm"=>{"name"=>"vm-18b5d6bf-b651-4c1d-86cd-8fda2ee9227a"},
"job_state"=>"running",
"bosh_protocol"=>"1",
"ntp"=>{"timestamp"=>"16 May 00:15:06", "offset"=>"-0.007708"},
"job"=>
{"name"=>"dea",
"templates"=>
[{"name"=>"dea_logging_agent",
"version"=>"15",
"sha1"=>"c1232a051982df2779fa0ef1527406840224c0ca",
"blobstore_id"=>"969ece16-90c4-44f3-ae2e-6b7a49859744"},
{"name"=>"dea_next",
"version"=>"38",
"sha1"=>"add6292c060b193fb626a1496ce54d2dc4d52d6e",
"blobstore_id"=>"c2881bad-d98d-4718-a32d-98cd1cf4628a"}],
"template"=>"dea_logging_agent",
"version"=>"15",
"sha1"=>"c1232a051982df2779fa0ef1527406840224c0ca",
"blobstore_id"=>"969ece16-90c4-44f3-ae2e-6b7a49859744"},
"index"=>2}
D, [2014-05-16T00:20:54.331883 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.332089 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : (0.008930s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 9)
D, [2014-05-16T00:20:54.332998 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Released connection: 19562740
D, [2014-05-16T00:20:54.333116 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.333351 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.333446 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.333574 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.333689 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.333767 #9215] [bind_existing_deployment(9a8fb858-4d8f-4cf6-88d7-7cf0db1a14c5)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.333844 #9215] [0x1d9b6c8] DEBUG -- : Thread is no longer needed, cleaning up
D, [2014-05-16T00:20:54.332644 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.334030 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : (0.001150s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 4) LIMIT 1
D, [2014-05-16T00:20:54.334364 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.334536 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.335476 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Acquired connection: 41747440
D, [2014-05-16T00:20:54.335800 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : (0.001583s) SELECT * FROM "instances" WHERE ("instances"."vm_id" = 18) LIMIT 1
D, [2014-05-16T00:20:54.336004 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.336160 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Verified VM state
D, [2014-05-16T00:20:54.336772 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.336972 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : (0.001239s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 12)
D, [2014-05-16T00:20:54.337116 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Released connection: 41747440
D, [2014-05-16T00:20:54.337329 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.337655 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.337804 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.337929 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.338082 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.338236 #9215] [bind_existing_deployment(6f17dc6a-8de4-4bac-ac16-fac86ed20b7a)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.338365 #9215] [0x1d9b31c] DEBUG -- : Thread is no longer needed, cleaning up
D, [2014-05-16T00:20:54.340503 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : (0.003587s) SELECT * FROM "persistent_disks" WHERE ("persistent_disks"."instance_id" = 15)
D, [2014-05-16T00:20:54.340631 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.340723 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Processing network reservations
D, [2014-05-16T00:20:54.340872 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Binding instance VM
D, [2014-05-16T00:20:54.340946 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Found job and instance spec
D, [2014-05-16T00:20:54.341004 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Copying network reservations
D, [2014-05-16T00:20:54.341084 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Copying resource pool reservation
D, [2014-05-16T00:20:54.341144 #9215] [bind_existing_deployment(3050f941-b646-4826-9cc7-aa0f0e987d72)] DEBUG -- : Finished binding VM
D, [2014-05-16T00:20:54.341204 #9215] [0x1d9afd4] DEBUG -- : Thread is no longer needed, cleaning up
D, [2014-05-16T00:20:54.341333 #9215] [task:18] DEBUG -- : Shutting down pool
I, [2014-05-16T00:20:54.341837 #9215] [task:18] INFO -- : Binding resource pools
I, [2014-05-16T00:20:54.342265 #9215] [task:18] INFO -- : Binding stemcells
D, [2014-05-16T00:20:54.343032 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.343278 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.343469 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.343616 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.343810 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.344793 #9215] [task:18] DEBUG -- : (0.000813s) SELECT * FROM "stemcells" WHERE (("name" = 'bosh-openstack-kvm-ubuntu') AND ("version" = '2427')) LIMIT 1
D, [2014-05-16T00:20:54.345039 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.346587 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.348178 #9215] [task:18] DEBUG -- : (0.001378s) SELECT "deployments".* FROM "deployments" INNER JOIN "deployments_stemcells" ON (("deployments_stemcells"."deployment_id" = "deployments"."id") AND ("deployments_stemcells"."stemcell_id" = 1))
D, [2014-05-16T00:20:54.348428 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.349100 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.349254 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.349454 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.349560 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.349749 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.350354 #9215] [task:18] DEBUG -- : (0.000437s) SELECT * FROM "stemcells" WHERE (("name" = 'bosh-openstack-kvm-ubuntu') AND ("version" = '2427')) LIMIT 1
D, [2014-05-16T00:20:54.350590 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.351807 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.352534 #9215] [task:18] DEBUG -- : (0.000522s) SELECT "deployments".* FROM "deployments" INNER JOIN "deployments_stemcells" ON (("deployments_stemcells"."deployment_id" = "deployments"."id") AND ("deployments_stemcells"."stemcell_id" = 1))
D, [2014-05-16T00:20:54.352769 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.353207 #9215] [task:18] INFO -- : Binding templates
D, [2014-05-16T00:20:54.353368 #9215] [task:18] DEBUG -- : Binding template `nats'
D, [2014-05-16T00:20:54.354632 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.356406 #9215] [task:18] DEBUG -- : (0.001636s) SELECT "templates".* FROM "templates" INNER JOIN "release_versions_templates" ON (("release_versions_templates"."template_id" = "templates"."id") AND ("release_versions_templates"."release_version_id" = 1))
D, [2014-05-16T00:20:54.357057 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.358133 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.359307 #9215] [task:18] DEBUG -- : (0.001010s) SELECT "packages".* FROM "packages" INNER JOIN "packages_release_versions" ON (("packages_release_versions"."package_id" = "packages"."id") AND ("packages_release_versions"."release_version_id" = 1))
D, [2014-05-16T00:20:54.360158 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.360795 #9215] [task:18] DEBUG -- : Bound template `nats'
D, [2014-05-16T00:20:54.360868 #9215] [task:18] DEBUG -- : Binding template `nats_stream_forwarder'
D, [2014-05-16T00:20:54.360962 #9215] [task:18] DEBUG -- : Bound template `nats_stream_forwarder'
D, [2014-05-16T00:20:54.361027 #9215] [task:18] DEBUG -- : Binding template `syslog_aggregator'
D, [2014-05-16T00:20:54.361102 #9215] [task:18] DEBUG -- : Bound template `syslog_aggregator'
D, [2014-05-16T00:20:54.361163 #9215] [task:18] DEBUG -- : Binding template `debian_nfs_server'
D, [2014-05-16T00:20:54.361259 #9215] [task:18] DEBUG -- : Bound template `debian_nfs_server'
D, [2014-05-16T00:20:54.361319 #9215] [task:18] DEBUG -- : Binding template `postgres'
D, [2014-05-16T00:20:54.361393 #9215] [task:18] DEBUG -- : Bound template `postgres'
D, [2014-05-16T00:20:54.361454 #9215] [task:18] DEBUG -- : Binding template `uaa'
D, [2014-05-16T00:20:54.361534 #9215] [task:18] DEBUG -- : Bound template `uaa'
D, [2014-05-16T00:20:54.361594 #9215] [task:18] DEBUG -- : Binding template `loggregator'
D, [2014-05-16T00:20:54.361670 #9215] [task:18] DEBUG -- : Bound template `loggregator'
D, [2014-05-16T00:20:54.361730 #9215] [task:18] DEBUG -- : Binding template `loggregator_trafficcontroller'
D, [2014-05-16T00:20:54.361808 #9215] [task:18] DEBUG -- : Bound template `loggregator_trafficcontroller'
D, [2014-05-16T00:20:54.361871 #9215] [task:18] DEBUG -- : Binding template `cloud_controller_ng'
D, [2014-05-16T00:20:54.361990 #9215] [task:18] DEBUG -- : Bound template `cloud_controller_ng'
D, [2014-05-16T00:20:54.362053 #9215] [task:18] DEBUG -- : Binding template `cloud_controller_worker'
D, [2014-05-16T00:20:54.362156 #9215] [task:18] DEBUG -- : Bound template `cloud_controller_worker'
D, [2014-05-16T00:20:54.362230 #9215] [task:18] DEBUG -- : Binding template `cloud_controller_clock'
D, [2014-05-16T00:20:54.362338 #9215] [task:18] DEBUG -- : Bound template `cloud_controller_clock'
D, [2014-05-16T00:20:54.362399 #9215] [task:18] DEBUG -- : Binding template `etcd'
D, [2014-05-16T00:20:54.362471 #9215] [task:18] DEBUG -- : Bound template `etcd'
D, [2014-05-16T00:20:54.362531 #9215] [task:18] DEBUG -- : Binding template `hm9000'
D, [2014-05-16T00:20:54.362615 #9215] [task:18] DEBUG -- : Bound template `hm9000'
D, [2014-05-16T00:20:54.362677 #9215] [task:18] DEBUG -- : Binding template `dea_logging_agent'
D, [2014-05-16T00:20:54.362767 #9215] [task:18] DEBUG -- : Bound template `dea_logging_agent'
D, [2014-05-16T00:20:54.362827 #9215] [task:18] DEBUG -- : Binding template `dea_next'
D, [2014-05-16T00:20:54.362912 #9215] [task:18] DEBUG -- : Bound template `dea_next'
D, [2014-05-16T00:20:54.362971 #9215] [task:18] DEBUG -- : Binding template `gorouter'
D, [2014-05-16T00:20:54.363047 #9215] [task:18] DEBUG -- : Bound template `gorouter'
D, [2014-05-16T00:20:54.363106 #9215] [task:18] DEBUG -- : Binding template `haproxy'
D, [2014-05-16T00:20:54.363178 #9215] [task:18] DEBUG -- : Bound template `haproxy'
I, [2014-05-16T00:20:54.364423 #9215] [task:18] INFO -- : Binding properties
I, [2014-05-16T00:20:54.385112 #9215] [task:18] INFO -- : Binding unallocated VMs
I, [2014-05-16T00:20:54.385610 #9215] [task:18] INFO -- : Binding instance networks
I, [2014-05-16T00:20:54.385894 #9215] [task:18] INFO -- : Compiling and binding packages
I, [2014-05-16T00:20:54.386036 #9215] [task:18] INFO -- : Generating a list of compile tasks
I, [2014-05-16T00:20:54.386272 #9215] [task:18] INFO -- : Job templates `cf/nats', `cf/nats_stream_forwarder' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.386390 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.387100 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.387201 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.387321 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.388011 #9215] [task:18] DEBUG -- : (0.000580s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 2) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.388204 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.388297 #9215] [task:18] INFO -- : Found compiled version of package `common/6' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.388968 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.389345 #9215] [task:18] DEBUG -- : (0.000244s) SELECT * FROM "packages" WHERE ("packages"."id" = 2) LIMIT 1
D, [2014-05-16T00:20:54.389522 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.389764 #9215] [task:18] INFO -- : Processing package `common/6' dependencies
I, [2014-05-16T00:20:54.389921 #9215] [task:18] INFO -- : Checking whether package `gnatsd/5' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.390555 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.390655 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.390774 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.391160 #9215] [task:18] DEBUG -- : (0.000276s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 5) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["golang","6"]]')) LIMIT 1
D, [2014-05-16T00:20:54.391343 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.391433 #9215] [task:18] INFO -- : Found compiled version of package `gnatsd/5' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.391916 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.392288 #9215] [task:18] DEBUG -- : (0.000239s) SELECT * FROM "packages" WHERE ("packages"."id" = 5) LIMIT 1
D, [2014-05-16T00:20:54.392457 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.392585 #9215] [task:18] INFO -- : Processing package `gnatsd/5' dependencies
I, [2014-05-16T00:20:54.392711 #9215] [task:18] INFO -- : Package `gnatsd/5' depends on package `golang/6'
I, [2014-05-16T00:20:54.392807 #9215] [task:18] INFO -- : Checking whether package `golang/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.393369 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.393466 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.393581 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.393963 #9215] [task:18] DEBUG -- : (0.000272s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 31) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.394143 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.394248 #9215] [task:18] INFO -- : Found compiled version of package `golang/6' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.394702 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.395070 #9215] [task:18] DEBUG -- : (0.000239s) SELECT * FROM "packages" WHERE ("packages"."id" = 31) LIMIT 1
D, [2014-05-16T00:20:54.395241 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.395367 #9215] [task:18] INFO -- : Processing package `golang/6' dependencies
I, [2014-05-16T00:20:54.395519 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.396149 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.396247 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.396367 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.397013 #9215] [task:18] DEBUG -- : (0.000537s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 21) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["ruby","13"]]')) LIMIT 1
D, [2014-05-16T00:20:54.397180 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.397289 #9215] [task:18] INFO -- : Found compiled version of package `syslog_aggregator/9' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.397742 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.398107 #9215] [task:18] DEBUG -- : (0.000236s) SELECT * FROM "packages" WHERE ("packages"."id" = 21) LIMIT 1
D, [2014-05-16T00:20:54.398292 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.398422 #9215] [task:18] INFO -- : Processing package `syslog_aggregator/9' dependencies
I, [2014-05-16T00:20:54.398546 #9215] [task:18] INFO -- : Package `syslog_aggregator/9' depends on package `ruby/13'
I, [2014-05-16T00:20:54.398625 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.399191 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.399288 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.399408 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.399823 #9215] [task:18] DEBUG -- : (0.000307s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 24) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.399990 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.400097 #9215] [task:18] INFO -- : Found compiled version of package `ruby/13' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.400615 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.400982 #9215] [task:18] DEBUG -- : (0.000236s) SELECT * FROM "packages" WHERE ("packages"."id" = 24) LIMIT 1
D, [2014-05-16T00:20:54.401151 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.401276 #9215] [task:18] INFO -- : Processing package `ruby/13' dependencies
I, [2014-05-16T00:20:54.401412 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.401525 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.401626 #9215] [task:18] INFO -- : Checking whether package `nats/11' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.402199 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.402334 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.402453 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.402835 #9215] [task:18] DEBUG -- : (0.000273s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 4) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["ruby","13"]]')) LIMIT 1
D, [2014-05-16T00:20:54.403018 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.403110 #9215] [task:18] INFO -- : Found compiled version of package `nats/11' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.403593 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.403961 #9215] [task:18] DEBUG -- : (0.000233s) SELECT * FROM "packages" WHERE ("packages"."id" = 4) LIMIT 1
D, [2014-05-16T00:20:54.404134 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.404264 #9215] [task:18] INFO -- : Processing package `nats/11' dependencies
I, [2014-05-16T00:20:54.404388 #9215] [task:18] INFO -- : Package `nats/11' depends on package `ruby/13'
I, [2014-05-16T00:20:54.404483 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.404578 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.404669 #9215] [task:18] INFO -- : Job templates `cf/syslog_aggregator' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.404741 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.404846 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.404952 #9215] [task:18] INFO -- : Job templates `cf/debian_nfs_server' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.405026 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.405125 #9215] [task:18] INFO -- : Checking whether package `debian_nfs_server/4' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.405686 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.405783 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.405901 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.406290 #9215] [task:18] DEBUG -- : (0.000282s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 10) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.406455 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.406546 #9215] [task:18] INFO -- : Found compiled version of package `debian_nfs_server/4' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.407017 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.407382 #9215] [task:18] DEBUG -- : (0.000236s) SELECT * FROM "packages" WHERE ("packages"."id" = 10) LIMIT 1
D, [2014-05-16T00:20:54.407577 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.407712 #9215] [task:18] INFO -- : Processing package `debian_nfs_server/4' dependencies
I, [2014-05-16T00:20:54.407849 #9215] [task:18] INFO -- : Job templates `cf/postgres' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.407940 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.408054 #9215] [task:18] INFO -- : Checking whether package `postgres/5' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.408623 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.408719 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.408840 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.409219 #9215] [task:18] DEBUG -- : (0.000271s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 17) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.409384 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.409490 #9215] [task:18] INFO -- : Found compiled version of package `postgres/5' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.411663 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.412043 #9215] [task:18] DEBUG -- : (0.000240s) SELECT * FROM "packages" WHERE ("packages"."id" = 17) LIMIT 1
D, [2014-05-16T00:20:54.412218 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.412399 #9215] [task:18] INFO -- : Processing package `postgres/5' dependencies
I, [2014-05-16T00:20:54.412573 #9215] [task:18] INFO -- : Job templates `cf/uaa' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.412657 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.412782 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.412885 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.412984 #9215] [task:18] INFO -- : Checking whether package `uaa/49' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.413564 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.413662 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.413781 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.414173 #9215] [task:18] DEBUG -- : (0.000272s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 9) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["ruby","13"]]')) LIMIT 1
D, [2014-05-16T00:20:54.414375 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.414468 #9215] [task:18] INFO -- : Found compiled version of package `uaa/49' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.414921 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.415285 #9215] [task:18] DEBUG -- : (0.000234s) SELECT * FROM "packages" WHERE ("packages"."id" = 9) LIMIT 1
D, [2014-05-16T00:20:54.415459 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.415630 #9215] [task:18] INFO -- : Processing package `uaa/49' dependencies
I, [2014-05-16T00:20:54.415757 #9215] [task:18] INFO -- : Package `uaa/49' depends on package `ruby/13'
I, [2014-05-16T00:20:54.415836 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.415941 #9215] [task:18] INFO -- : Job templates `cf/loggregator' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.416017 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.416121 #9215] [task:18] INFO -- : Checking whether package `loggregator/23' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.416722 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.416823 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.416940 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.417321 #9215] [task:18] DEBUG -- : (0.000272s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 11) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["golang","6"]]')) LIMIT 1
D, [2014-05-16T00:20:54.417487 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.417578 #9215] [task:18] INFO -- : Found compiled version of package `loggregator/23' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.418030 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.418423 #9215] [task:18] DEBUG -- : (0.000247s) SELECT * FROM "packages" WHERE ("packages"."id" = 11) LIMIT 1
D, [2014-05-16T00:20:54.418594 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.418722 #9215] [task:18] INFO -- : Processing package `loggregator/23' dependencies
I, [2014-05-16T00:20:54.418844 #9215] [task:18] INFO -- : Package `loggregator/23' depends on package `golang/6'
I, [2014-05-16T00:20:54.418922 #9215] [task:18] INFO -- : Checking whether package `golang/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.419041 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.419153 #9215] [task:18] INFO -- : Job templates `cf/loggregator_trafficcontroller' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.419227 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.419343 #9215] [task:18] INFO -- : Checking whether package `loggregator_trafficcontroller/14' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.419950 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.420051 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.420166 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.420543 #9215] [task:18] DEBUG -- : (0.000269s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 36) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["golang","6"]]')) LIMIT 1
D, [2014-05-16T00:20:54.420726 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.420817 #9215] [task:18] INFO -- : Found compiled version of package `loggregator_trafficcontroller/14' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.421372 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.421739 #9215] [task:18] DEBUG -- : (0.000238s) SELECT * FROM "packages" WHERE ("packages"."id" = 36) LIMIT 1
D, [2014-05-16T00:20:54.421909 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.422038 #9215] [task:18] INFO -- : Processing package `loggregator_trafficcontroller/14' dependencies
I, [2014-05-16T00:20:54.422165 #9215] [task:18] INFO -- : Package `loggregator_trafficcontroller/14' depends on package `golang/6'
I, [2014-05-16T00:20:54.422276 #9215] [task:18] INFO -- : Checking whether package `golang/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.422396 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.422509 #9215] [task:18] INFO -- : Job templates `cf/cloud_controller_ng' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.422583 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.422693 #9215] [task:18] INFO -- : Checking whether package `cloud_controller_ng/49' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.423346 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.423444 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.423590 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.423980 #9215] [task:18] DEBUG -- : (0.000277s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 1) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["libpq","6"],["mysqlclient","4"],["ruby","13"],["sqlite","4"]]')) LIMIT 1
D, [2014-05-16T00:20:54.424148 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.424238 #9215] [task:18] INFO -- : Found compiled version of package `cloud_controller_ng/49' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.424694 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.425070 #9215] [task:18] DEBUG -- : (0.000232s) SELECT * FROM "packages" WHERE ("packages"."id" = 1) LIMIT 1
D, [2014-05-16T00:20:54.425241 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.425367 #9215] [task:18] INFO -- : Processing package `cloud_controller_ng/49' dependencies
I, [2014-05-16T00:20:54.425505 #9215] [task:18] INFO -- : Package `cloud_controller_ng/49' depends on package `libpq/6'
I, [2014-05-16T00:20:54.425586 #9215] [task:18] INFO -- : Checking whether package `libpq/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.426156 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.426291 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.426413 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.426790 #9215] [task:18] DEBUG -- : (0.000269s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 23) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.426956 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.427046 #9215] [task:18] INFO -- : Found compiled version of package `libpq/6' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.427495 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.427905 #9215] [task:18] DEBUG -- : (0.000234s) SELECT * FROM "packages" WHERE ("packages"."id" = 23) LIMIT 1
D, [2014-05-16T00:20:54.428075 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.428202 #9215] [task:18] INFO -- : Processing package `libpq/6' dependencies
I, [2014-05-16T00:20:54.428327 #9215] [task:18] INFO -- : Package `cloud_controller_ng/49' depends on package `mysqlclient/4'
I, [2014-05-16T00:20:54.428406 #9215] [task:18] INFO -- : Checking whether package `mysqlclient/4' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.428966 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.429064 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.429180 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.429558 #9215] [task:18] DEBUG -- : (0.000269s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 33) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.429725 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.429816 #9215] [task:18] INFO -- : Found compiled version of package `mysqlclient/4' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.430279 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.430654 #9215] [task:18] DEBUG -- : (0.000234s) SELECT * FROM "packages" WHERE ("packages"."id" = 33) LIMIT 1
D, [2014-05-16T00:20:54.430823 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.430959 #9215] [task:18] INFO -- : Processing package `mysqlclient/4' dependencies
I, [2014-05-16T00:20:54.431084 #9215] [task:18] INFO -- : Package `cloud_controller_ng/49' depends on package `sqlite/4'
I, [2014-05-16T00:20:54.431164 #9215] [task:18] INFO -- : Checking whether package `sqlite/4' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.431751 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.431852 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.431970 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.432344 #9215] [task:18] DEBUG -- : (0.000266s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 35) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.432510 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.432601 #9215] [task:18] INFO -- : Found compiled version of package `sqlite/4' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.433052 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.433471 #9215] [task:18] DEBUG -- : (0.000277s) SELECT * FROM "packages" WHERE ("packages"."id" = 35) LIMIT 1
D, [2014-05-16T00:20:54.433645 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.433771 #9215] [task:18] INFO -- : Processing package `sqlite/4' dependencies
I, [2014-05-16T00:20:54.433897 #9215] [task:18] INFO -- : Package `cloud_controller_ng/49' depends on package `ruby/13'
I, [2014-05-16T00:20:54.433976 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.434093 #9215] [task:18] INFO -- : Checking whether package `nginx/12' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.434674 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.434771 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.434886 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.435257 #9215] [task:18] DEBUG -- : (0.000263s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 39) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.435423 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.435515 #9215] [task:18] INFO -- : Found compiled version of package `nginx/12' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.436004 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.436375 #9215] [task:18] DEBUG -- : (0.000240s) SELECT * FROM "packages" WHERE ("packages"."id" = 39) LIMIT 1
D, [2014-05-16T00:20:54.436547 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.436673 #9215] [task:18] INFO -- : Processing package `nginx/12' dependencies
I, [2014-05-16T00:20:54.436801 #9215] [task:18] INFO -- : Checking whether package `nginx_newrelic_plugin/1' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.437392 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.437489 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.437607 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.437982 #9215] [task:18] DEBUG -- : (0.000267s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 20) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["ruby","13"]]')) LIMIT 1
D, [2014-05-16T00:20:54.438150 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.438272 #9215] [task:18] INFO -- : Found compiled version of package `nginx_newrelic_plugin/1' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.438733 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.439112 #9215] [task:18] DEBUG -- : (0.000234s) SELECT * FROM "packages" WHERE ("packages"."id" = 20) LIMIT 1
D, [2014-05-16T00:20:54.439291 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.439421 #9215] [task:18] INFO -- : Processing package `nginx_newrelic_plugin/1' dependencies
I, [2014-05-16T00:20:54.439545 #9215] [task:18] INFO -- : Package `nginx_newrelic_plugin/1' depends on package `ruby/13'
I, [2014-05-16T00:20:54.439655 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.439753 #9215] [task:18] INFO -- : Checking whether package `libpq/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.439834 #9215] [task:18] INFO -- : Checking whether package `mysqlclient/4' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.439911 #9215] [task:18] INFO -- : Checking whether package `sqlite/4' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.439987 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.440078 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.440181 #9215] [task:18] INFO -- : Checking whether package `buildpack_java/3' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.440731 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.440827 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.440944 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.441320 #9215] [task:18] DEBUG -- : (0.000267s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 32) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.441504 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.441593 #9215] [task:18] INFO -- : Found compiled version of package `buildpack_java/3' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.442045 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.442422 #9215] [task:18] DEBUG -- : (0.000249s) SELECT * FROM "packages" WHERE ("packages"."id" = 32) LIMIT 1
D, [2014-05-16T00:20:54.442592 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.442722 #9215] [task:18] INFO -- : Processing package `buildpack_java/3' dependencies
I, [2014-05-16T00:20:54.442868 #9215] [task:18] INFO -- : Checking whether package `buildpack_java_offline/1' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.443419 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.443517 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.443665 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.444040 #9215] [task:18] DEBUG -- : (0.000267s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 15) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.444220 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.444312 #9215] [task:18] INFO -- : Found compiled version of package `buildpack_java_offline/1' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.444763 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.445121 #9215] [task:18] DEBUG -- : (0.000232s) SELECT * FROM "packages" WHERE ("packages"."id" = 15) LIMIT 1
D, [2014-05-16T00:20:54.445289 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.445416 #9215] [task:18] INFO -- : Processing package `buildpack_java_offline/1' dependencies
I, [2014-05-16T00:20:54.445544 #9215] [task:18] INFO -- : Checking whether package `buildpack_ruby/1' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.446119 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.446231 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.446353 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.446727 #9215] [task:18] DEBUG -- : (0.000267s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 30) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.446891 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.446997 #9215] [task:18] INFO -- : Found compiled version of package `buildpack_ruby/1' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.447449 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.447835 #9215] [task:18] DEBUG -- : (0.000258s) SELECT * FROM "packages" WHERE ("packages"."id" = 30) LIMIT 1
D, [2014-05-16T00:20:54.448008 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.448135 #9215] [task:18] INFO -- : Processing package `buildpack_ruby/1' dependencies
I, [2014-05-16T00:20:54.448264 #9215] [task:18] INFO -- : Checking whether package `buildpack_nodejs/1' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.448837 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.448934 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.449051 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.449424 #9215] [task:18] DEBUG -- : (0.000264s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 13) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.449589 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.449678 #9215] [task:18] INFO -- : Found compiled version of package `buildpack_nodejs/1' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.450148 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.450546 #9215] [task:18] DEBUG -- : (0.000237s) SELECT * FROM "packages" WHERE ("packages"."id" = 13) LIMIT 1
D, [2014-05-16T00:20:54.450715 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.450845 #9215] [task:18] INFO -- : Processing package `buildpack_nodejs/1' dependencies
I, [2014-05-16T00:20:54.450973 #9215] [task:18] INFO -- : Checking whether package `buildpack_go/2' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.451537 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.451671 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.451795 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.452181 #9215] [task:18] DEBUG -- : (0.000270s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 27) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.452347 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.452439 #9215] [task:18] INFO -- : Found compiled version of package `buildpack_go/2' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.452921 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.453284 #9215] [task:18] DEBUG -- : (0.000234s) SELECT * FROM "packages" WHERE ("packages"."id" = 27) LIMIT 1
D, [2014-05-16T00:20:54.453454 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.453582 #9215] [task:18] INFO -- : Processing package `buildpack_go/2' dependencies
I, [2014-05-16T00:20:54.453719 #9215] [task:18] INFO -- : Job templates `cf/cloud_controller_worker' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.453801 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.453926 #9215] [task:18] INFO -- : Checking whether package `cloud_controller_ng/49' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.454030 #9215] [task:18] INFO -- : Checking whether package `nginx/12' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.454147 #9215] [task:18] INFO -- : Checking whether package `nginx_newrelic_plugin/1' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.454261 #9215] [task:18] INFO -- : Checking whether package `libpq/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.454362 #9215] [task:18] INFO -- : Checking whether package `mysqlclient/4' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.454460 #9215] [task:18] INFO -- : Checking whether package `sqlite/4' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.454557 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.454657 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.454754 #9215] [task:18] INFO -- : Checking whether package `buildpack_java/3' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.454852 #9215] [task:18] INFO -- : Checking whether package `buildpack_java_offline/1' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.454949 #9215] [task:18] INFO -- : Checking whether package `buildpack_ruby/1' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.455069 #9215] [task:18] INFO -- : Checking whether package `buildpack_nodejs/1' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.455166 #9215] [task:18] INFO -- : Checking whether package `buildpack_go/2' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.455269 #9215] [task:18] INFO -- : Job templates `cf/cloud_controller_clock' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.455341 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.455439 #9215] [task:18] INFO -- : Checking whether package `cloud_controller_ng/49' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.455535 #9215] [task:18] INFO -- : Checking whether package `nginx/12' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.455663 #9215] [task:18] INFO -- : Checking whether package `nginx_newrelic_plugin/1' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.455763 #9215] [task:18] INFO -- : Checking whether package `libpq/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.455876 #9215] [task:18] INFO -- : Checking whether package `mysqlclient/4' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.455978 #9215] [task:18] INFO -- : Checking whether package `sqlite/4' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.456076 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.456174 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.456272 #9215] [task:18] INFO -- : Checking whether package `buildpack_java/3' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.456381 #9215] [task:18] INFO -- : Checking whether package `buildpack_java_offline/1' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.456480 #9215] [task:18] INFO -- : Checking whether package `buildpack_ruby/1' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.456578 #9215] [task:18] INFO -- : Checking whether package `buildpack_nodejs/1' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.456674 #9215] [task:18] INFO -- : Checking whether package `buildpack_go/2' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.456796 #9215] [task:18] INFO -- : Job templates `cf/etcd' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.456868 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.456966 #9215] [task:18] INFO -- : Checking whether package `etcd/4' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.457567 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.457666 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.457788 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.458198 #9215] [task:18] DEBUG -- : (0.000278s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 37) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["git","2"],["golang","6"]]')) LIMIT 1
D, [2014-05-16T00:20:54.458389 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.458480 #9215] [task:18] INFO -- : Found compiled version of package `etcd/4' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.458933 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.459303 #9215] [task:18] DEBUG -- : (0.000240s) SELECT * FROM "packages" WHERE ("packages"."id" = 37) LIMIT 1
D, [2014-05-16T00:20:54.459475 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.459651 #9215] [task:18] INFO -- : Processing package `etcd/4' dependencies
I, [2014-05-16T00:20:54.459784 #9215] [task:18] INFO -- : Package `etcd/4' depends on package `golang/6'
I, [2014-05-16T00:20:54.459864 #9215] [task:18] INFO -- : Checking whether package `golang/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.459976 #9215] [task:18] INFO -- : Package `etcd/4' depends on package `git/2'
I, [2014-05-16T00:20:54.460047 #9215] [task:18] INFO -- : Checking whether package `git/2' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.460594 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.460714 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.460882 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.461267 #9215] [task:18] DEBUG -- : (0.000271s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 12) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.461437 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.461527 #9215] [task:18] INFO -- : Found compiled version of package `git/2' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.462081 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.462476 #9215] [task:18] DEBUG -- : (0.000263s) SELECT * FROM "packages" WHERE ("packages"."id" = 12) LIMIT 1
D, [2014-05-16T00:20:54.462673 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.462801 #9215] [task:18] INFO -- : Processing package `git/2' dependencies
I, [2014-05-16T00:20:54.462946 #9215] [task:18] INFO -- : Job templates `cf/hm9000' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.463026 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.463149 #9215] [task:18] INFO -- : Checking whether package `hm9000/15' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.463806 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.463908 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.464026 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.464407 #9215] [task:18] DEBUG -- : (0.000273s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 26) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["git","2"],["golang","6"]]')) LIMIT 1
D, [2014-05-16T00:20:54.464574 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.464663 #9215] [task:18] INFO -- : Found compiled version of package `hm9000/15' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.465115 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.465498 #9215] [task:18] DEBUG -- : (0.000236s) SELECT * FROM "packages" WHERE ("packages"."id" = 26) LIMIT 1
D, [2014-05-16T00:20:54.465667 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.465793 #9215] [task:18] INFO -- : Processing package `hm9000/15' dependencies
I, [2014-05-16T00:20:54.465920 #9215] [task:18] INFO -- : Package `hm9000/15' depends on package `golang/6'
I, [2014-05-16T00:20:54.465999 #9215] [task:18] INFO -- : Checking whether package `golang/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.466110 #9215] [task:18] INFO -- : Package `hm9000/15' depends on package `git/2'
I, [2014-05-16T00:20:54.466181 #9215] [task:18] INFO -- : Checking whether package `git/2' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.466301 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.466438 #9215] [task:18] INFO -- : Job templates `cf/dea_logging_agent', `cf/dea_next' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.466513 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.466613 #9215] [task:18] INFO -- : Checking whether package `dea_logging_agent/23' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.467178 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.467274 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.467390 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.467824 #9215] [task:18] DEBUG -- : (0.000303s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 18) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["golang","6"]]')) LIMIT 1
D, [2014-05-16T00:20:54.467990 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.468080 #9215] [task:18] INFO -- : Found compiled version of package `dea_logging_agent/23' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.468526 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.468886 #9215] [task:18] DEBUG -- : (0.000234s) SELECT * FROM "packages" WHERE ("packages"."id" = 18) LIMIT 1
D, [2014-05-16T00:20:54.469055 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.469202 #9215] [task:18] INFO -- : Processing package `dea_logging_agent/23' dependencies
I, [2014-05-16T00:20:54.469325 #9215] [task:18] INFO -- : Package `dea_logging_agent/23' depends on package `golang/6'
I, [2014-05-16T00:20:54.469402 #9215] [task:18] INFO -- : Checking whether package `golang/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.469531 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.469636 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.469719 #9215] [task:18] INFO -- : Checking whether package `dea_next/48' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.470344 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.470443 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.470559 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.470948 #9215] [task:18] DEBUG -- : (0.000266s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 7) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["golang","6"],["ruby","13"]]')) LIMIT 1
D, [2014-05-16T00:20:54.471114 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.471205 #9215] [task:18] INFO -- : Found compiled version of package `dea_next/48' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.471707 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.472079 #9215] [task:18] DEBUG -- : (0.000240s) SELECT * FROM "packages" WHERE ("packages"."id" = 7) LIMIT 1
D, [2014-05-16T00:20:54.472246 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.472372 #9215] [task:18] INFO -- : Processing package `dea_next/48' dependencies
I, [2014-05-16T00:20:54.472507 #9215] [task:18] INFO -- : Package `dea_next/48' depends on package `ruby/13'
I, [2014-05-16T00:20:54.472586 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.472695 #9215] [task:18] INFO -- : Package `dea_next/48' depends on package `golang/6'
I, [2014-05-16T00:20:54.472765 #9215] [task:18] INFO -- : Checking whether package `golang/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.472866 #9215] [task:18] INFO -- : Checking whether package `warden/43' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.473473 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.473570 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.473701 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.474085 #9215] [task:18] DEBUG -- : (0.000275s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 28) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["ruby","13"]]')) LIMIT 1
D, [2014-05-16T00:20:54.474282 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.474395 #9215] [task:18] INFO -- : Found compiled version of package `warden/43' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.474847 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.475215 #9215] [task:18] DEBUG -- : (0.000240s) SELECT * FROM "packages" WHERE ("packages"."id" = 28) LIMIT 1
D, [2014-05-16T00:20:54.475382 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.475511 #9215] [task:18] INFO -- : Processing package `warden/43' dependencies
I, [2014-05-16T00:20:54.475670 #9215] [task:18] INFO -- : Package `warden/43' depends on package `ruby/13'
I, [2014-05-16T00:20:54.475751 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.475867 #9215] [task:18] INFO -- : Checking whether package `rootfs_lucid64/3' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.476429 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.476527 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.476651 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.477033 #9215] [task:18] DEBUG -- : (0.000273s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 34) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.477218 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.477309 #9215] [task:18] INFO -- : Found compiled version of package `rootfs_lucid64/3' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.477765 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.478135 #9215] [task:18] DEBUG -- : (0.000242s) SELECT * FROM "packages" WHERE ("packages"."id" = 34) LIMIT 1
D, [2014-05-16T00:20:54.478317 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.478445 #9215] [task:18] INFO -- : Processing package `rootfs_lucid64/3' dependencies
I, [2014-05-16T00:20:54.478579 #9215] [task:18] INFO -- : Checking whether package `ruby/13' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.478699 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.478781 #9215] [task:18] INFO -- : Checking whether package `buildpack_cache/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.479334 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.479430 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.479544 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.479953 #9215] [task:18] DEBUG -- : (0.000272s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 14) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.480141 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.480231 #9215] [task:18] INFO -- : Found compiled version of package `buildpack_cache/9' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.480684 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.481050 #9215] [task:18] DEBUG -- : (0.000232s) SELECT * FROM "packages" WHERE ("packages"."id" = 14) LIMIT 1
D, [2014-05-16T00:20:54.481218 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.481345 #9215] [task:18] INFO -- : Processing package `buildpack_cache/9' dependencies
I, [2014-05-16T00:20:54.481502 #9215] [task:18] INFO -- : Job templates `cf/gorouter' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.481588 #9215] [task:18] INFO -- : Checking whether package `common/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.481700 #9215] [task:18] INFO -- : Checking whether package `golang/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.481801 #9215] [task:18] INFO -- : Checking whether package `gorouter/28' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.482400 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.482497 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.482631 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.483026 #9215] [task:18] DEBUG -- : (0.000267s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 38) AND ("stemcell_id" = 1) AND ("dependency_key" = '[["golang","6"]]')) LIMIT 1
D, [2014-05-16T00:20:54.483189 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.483279 #9215] [task:18] INFO -- : Found compiled version of package `gorouter/28' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.483764 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.484137 #9215] [task:18] DEBUG -- : (0.000242s) SELECT * FROM "packages" WHERE ("packages"."id" = 38) LIMIT 1
D, [2014-05-16T00:20:54.484335 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.484462 #9215] [task:18] INFO -- : Processing package `gorouter/28' dependencies
I, [2014-05-16T00:20:54.484591 #9215] [task:18] INFO -- : Package `gorouter/28' depends on package `golang/6'
I, [2014-05-16T00:20:54.484670 #9215] [task:18] INFO -- : Checking whether package `golang/6' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.484766 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.484881 #9215] [task:18] INFO -- : Job templates `cf/haproxy' need to run on stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.484954 #9215] [task:18] INFO -- : Checking whether package `haproxy/2' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.485532 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.485628 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.485758 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.486140 #9215] [task:18] DEBUG -- : (0.000274s) SELECT * FROM "compiled_packages" WHERE (("package_id" = 22) AND ("stemcell_id" = 1) AND ("dependency_key" = '[]')) LIMIT 1
D, [2014-05-16T00:20:54.486334 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.486427 #9215] [task:18] INFO -- : Found compiled version of package `haproxy/2' for stemcell `bosh-openstack-kvm-ubuntu/2427'
D, [2014-05-16T00:20:54.486907 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.487274 #9215] [task:18] DEBUG -- : (0.000240s) SELECT * FROM "packages" WHERE ("packages"."id" = 22) LIMIT 1
D, [2014-05-16T00:20:54.487442 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.487594 #9215] [task:18] INFO -- : Processing package `haproxy/2' dependencies
I, [2014-05-16T00:20:54.487742 #9215] [task:18] INFO -- : Checking whether package `syslog_aggregator/9' needs to be compiled for stemcell `bosh-openstack-kvm-ubuntu/2427'
I, [2014-05-16T00:20:54.488008 #9215] [task:18] INFO -- : All packages are already compiled
I, [2014-05-16T00:20:54.488081 #9215] [task:18] INFO -- : Finished preparing deployment
I, [2014-05-16T00:20:54.488136 #9215] [task:18] INFO -- : Updating deployment
I, [2014-05-16T00:20:54.488375 #9215] [task:18] INFO -- : Binding DNS
D, [2014-05-16T00:20:54.501460 #9215] [task:18] DEBUG -- : (0.000276s) SET standard_conforming_strings = ON
D, [2014-05-16T00:20:54.501883 #9215] [task:18] DEBUG -- : (0.000187s) SET client_min_messages = 'WARNING'
D, [2014-05-16T00:20:54.502238 #9215] [task:18] DEBUG -- : (0.000161s) SET DateStyle = 'ISO'
D, [2014-05-16T00:20:54.502384 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.502526 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.504818 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.504956 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.505149 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.505257 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.505489 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.512566 #9215] [task:18] DEBUG -- : (0.006895s) SELECT "pg_attribute"."attname" AS "name", CAST("pg_attribute"."atttypid" AS integer) AS "oid", format_type("pg_type"."oid", "pg_attribute"."atttypmod") AS "db_type", pg_get_expr("pg_attrdef"."adbin", "pg_class"."oid") AS "default", NOT "pg_attribute"."attnotnull" AS "allow_null", COALESCE(("pg_attribute"."attnum" = ANY("pg_index"."indkey")), false) AS "primary_key", "pg_namespace"."nspname" FROM "pg_class" INNER JOIN "pg_attribute" ON ("pg_attribute"."attrelid" = "pg_class"."oid") INNER JOIN "pg_type" ON ("pg_type"."oid" = "pg_attribute"."atttypid") INNER JOIN "pg_namespace" ON ("pg_namespace"."oid" = "pg_class"."relnamespace") LEFT OUTER JOIN "pg_attrdef" ON (("pg_attrdef"."adrelid" = "pg_class"."oid") AND ("pg_attrdef"."adnum" = "pg_attribute"."attnum")) LEFT OUTER JOIN "pg_index" ON (("pg_index"."indrelid" = "pg_class"."oid") AND ("pg_index"."indisprimary" IS TRUE)) WHERE (("pg_attribute"."attisdropped" IS FALSE) AND ("pg_attribute"."attnum" > 0) AND ("pg_class"."relname" = 'domains') AND ("pg_namespace"."nspname" !~* 'pg_*|information_schema')) ORDER BY "pg_attribute"."attnum"
D, [2014-05-16T00:20:54.513350 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.523721 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.523833 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.523964 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.524034 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.524332 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.526595 #9215] [task:18] DEBUG -- : (0.002144s) SELECT "pg_attribute"."attname" AS "name", CAST("pg_attribute"."atttypid" AS integer) AS "oid", format_type("pg_type"."oid", "pg_attribute"."atttypmod") AS "db_type", pg_get_expr("pg_attrdef"."adbin", "pg_class"."oid") AS "default", NOT "pg_attribute"."attnotnull" AS "allow_null", COALESCE(("pg_attribute"."attnum" = ANY("pg_index"."indkey")), false) AS "primary_key", "pg_namespace"."nspname" FROM "pg_class" INNER JOIN "pg_attribute" ON ("pg_attribute"."attrelid" = "pg_class"."oid") INNER JOIN "pg_type" ON ("pg_type"."oid" = "pg_attribute"."atttypid") INNER JOIN "pg_namespace" ON ("pg_namespace"."oid" = "pg_class"."relnamespace") LEFT OUTER JOIN "pg_attrdef" ON (("pg_attrdef"."adrelid" = "pg_class"."oid") AND ("pg_attrdef"."adnum" = "pg_attribute"."attnum")) LEFT OUTER JOIN "pg_index" ON (("pg_index"."indrelid" = "pg_class"."oid") AND ("pg_index"."indisprimary" IS TRUE)) WHERE (("pg_attribute"."attisdropped" IS FALSE) AND ("pg_attribute"."attnum" > 0) AND ("pg_class"."relname" = 'records') AND ("pg_namespace"."nspname" !~* 'pg_*|information_schema')) ORDER BY "pg_attribute"."attnum"
D, [2014-05-16T00:20:54.527040 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.529595 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.529703 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.529821 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.529891 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.530003 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.531227 #9215] [task:18] DEBUG -- : (0.001110s) SELECT * FROM "domains" WHERE (("name" = 'microbosh') AND ("type" = 'NATIVE')) LIMIT 1
D, [2014-05-16T00:20:54.531405 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.531883 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.531991 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.532108 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.532174 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.532286 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.532995 #9215] [task:18] DEBUG -- : (0.000603s) SELECT * FROM "records" WHERE (("domain_id" = 1) AND ("name" = 'microbosh') AND ("type" = 'SOA')) LIMIT 1
D, [2014-05-16T00:20:54.533173 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.533429 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.533655 #9215] [task:18] DEBUG -- : (0.000097s) BEGIN
D, [2014-05-16T00:20:54.581281 #9215] [task:18] DEBUG -- : (0.000768s) UPDATE "records" SET "name" = 'microbosh', "type" = 'SOA', "content" = 'localhost hostmaster@localhost 0 10800 604800 30', "ttl" = 300, "prio" = NULL, "change_date" = NULL, "domain_id" = 1 WHERE ("id" = 1)
D, [2014-05-16T00:20:54.583375 #9215] [task:18] DEBUG -- : (0.001753s) COMMIT
D, [2014-05-16T00:20:54.583649 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.584757 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.584930 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.585163 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.585308 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.585527 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.585643 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.585839 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.586840 #9215] [task:18] DEBUG -- : (0.000818s) SELECT * FROM "records" WHERE (("domain_id" = 1) AND ("name" = 'microbosh') AND ("type" = 'NS') AND ("ttl" = 14400) AND ("content" = 'ns.microbosh')) LIMIT 1
D, [2014-05-16T00:20:54.587216 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.588053 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.588275 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.588475 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.588590 #9215] [task:18] DEBUG -- : Released connection: 44021080
D, [2014-05-16T00:20:54.588879 #9215] [task:18] DEBUG -- : Acquired connection: 44021080
D, [2014-05-16T00:20:54.589743 #9215] [task:18] DEBUG -- : (0.000619s) SELECT * FROM "records" WHERE (("domain_id" = 1) AND ("name" = 'ns.microbosh') AND ("type" = 'A') AND ("ttl" = 14400) AND ("content" IS NULL)) LIMIT 1
D, [2014-05-16T00:20:54.590036 #9215] [task:18] DEBUG -- : Released connection: 44021080
I, [2014-05-16T00:20:54.590476 #9215] [task:18] INFO -- : Updating resource pools
I, [2014-05-16T00:20:54.590864 #9215] [task:18] INFO -- : Deleting 0 extra VMs
I, [2014-05-16T00:20:54.590985 #9215] [task:18] INFO -- : Deleting 0 extra VMs
D, [2014-05-16T00:20:54.591092 #9215] [task:18] DEBUG -- : Waiting for tasks to complete
I, [2014-05-16T00:20:54.591271 #9215] [task:18] INFO -- : Deleting 0 outdated idle VMs
I, [2014-05-16T00:20:54.591358 #9215] [task:18] INFO -- : Deleting 0 outdated idle VMs
D, [2014-05-16T00:20:54.591453 #9215] [task:18] DEBUG -- : Waiting for tasks to complete
I, [2014-05-16T00:20:54.591659 #9215] [task:18] INFO -- : Creating 0 missing VMs
I, [2014-05-16T00:20:54.591731 #9215] [task:18] INFO -- : Creating 0 missing VMs
D, [2014-05-16T00:20:54.591842 #9215] [task:18] DEBUG -- : Waiting for tasks to complete
D, [2014-05-16T00:20:54.591943 #9215] [task:18] DEBUG -- : Shutting down pool
D, [2014-05-16T00:20:54.592190 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.593962 #9215] [task:18] DEBUG -- : (0.001595s) SELECT * FROM "tasks" WHERE "id" = 18
D, [2014-05-16T00:20:54.594648 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:54.594732 #9215] [task:18] INFO -- : Binding instance VMs
I, [2014-05-16T00:20:54.595161 #9215] [task:18] INFO -- : Binding configuration
D, [2014-05-16T00:20:54.596643 #9215] [task:18] DEBUG -- : Downloading template `nats' (2280b895-72a5-4475-b5da-11b689da0170)...
D, [2014-05-16T00:20:54.600394 #9215] [task:18] DEBUG -- : Template `nats' downloaded to /var/vcap/data/tmp/director/template-6798a5eb-e862-4d9b-8078-a3c3a43cf9a6 (took 0.003645888s)
D, [2014-05-16T00:20:54.620540 #9215] [task:18] DEBUG -- : Downloading template `nats_stream_forwarder' (f924f5c6-4bdd-4339-b630-37823fb47b7a)...
D, [2014-05-16T00:20:54.623090 #9215] [task:18] DEBUG -- : Template `nats_stream_forwarder' downloaded to /var/vcap/data/tmp/director/template-da992de5-8e03-4a30-8a2a-f7e697a925c2 (took 0.002385512s)
D, [2014-05-16T00:20:54.656295 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.657505 #9215] [task:18] DEBUG -- : (0.000981s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 1) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:54.657965 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.658909 #9215] [task:18] DEBUG -- : Downloading template `syslog_aggregator' (08577070-1f4d-4108-8fe9-01cfa8d52276)...
D, [2014-05-16T00:20:54.661432 #9215] [task:18] DEBUG -- : Template `syslog_aggregator' downloaded to /var/vcap/data/tmp/director/template-db3df228-0600-4f11-aca5-d6841e579569 (took 0.002406409s)
D, [2014-05-16T00:20:54.685134 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.685793 #9215] [task:18] DEBUG -- : (0.000426s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 2) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:54.686200 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.687025 #9215] [task:18] DEBUG -- : Downloading template `debian_nfs_server' (b6e5c5c7-8e98-4b5b-ab04-804521b6e96f)...
D, [2014-05-16T00:20:54.689696 #9215] [task:18] DEBUG -- : Template `debian_nfs_server' downloaded to /var/vcap/data/tmp/director/template-51c6a9ad-2840-43e1-b47c-6520b2b4f27f (took 0.002542995s)
D, [2014-05-16T00:20:54.709045 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.709773 #9215] [task:18] DEBUG -- : (0.000425s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 3) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:54.710387 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.711497 #9215] [task:18] DEBUG -- : Downloading template `postgres' (78b57dd4-6b68-4ec9-84d1-d801fa158ecf)...
D, [2014-05-16T00:20:54.714743 #9215] [task:18] DEBUG -- : Template `postgres' downloaded to /var/vcap/data/tmp/director/template-4f599614-a78b-43c3-b497-a0d32d3d9a39 (took 0.003043127s)
D, [2014-05-16T00:20:54.757240 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.757775 #9215] [task:18] DEBUG -- : (0.000327s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 4) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:54.758223 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.759308 #9215] [task:18] DEBUG -- : Downloading template `uaa' (aee8860a-656b-4fc1-ac47-5fe2a9786aa7)...
D, [2014-05-16T00:20:54.761735 #9215] [task:18] DEBUG -- : Template `uaa' downloaded to /var/vcap/data/tmp/director/template-c004d2c4-21f7-47fb-8b25-14d28be1648d (took 0.002318214s)
D, [2014-05-16T00:20:54.798415 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.799059 #9215] [task:18] DEBUG -- : (0.000390s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 5) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:54.799467 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.800515 #9215] [task:18] DEBUG -- : Downloading template `loggregator' (6698ce75-b156-46c2-9ccc-57ed9cff1e71)...
D, [2014-05-16T00:20:54.802647 #9215] [task:18] DEBUG -- : Template `loggregator' downloaded to /var/vcap/data/tmp/director/template-00eaa3d2-2d3a-422c-ae2a-cffcd765132c (took 0.002029264s)
D, [2014-05-16T00:20:54.828401 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.828916 #9215] [task:18] DEBUG -- : (0.000306s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 6) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:54.829318 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.830249 #9215] [task:18] DEBUG -- : Downloading template `loggregator_trafficcontroller' (3a8f316f-f30b-48e0-a787-3491349a8c7f)...
D, [2014-05-16T00:20:54.832673 #9215] [task:18] DEBUG -- : Template `loggregator_trafficcontroller' downloaded to /var/vcap/data/tmp/director/template-c88d95aa-3916-4f54-9f2c-3e0456f3b81b (took 0.002313097s)
D, [2014-05-16T00:20:54.856042 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.856548 #9215] [task:18] DEBUG -- : (0.000295s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 7) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:54.856941 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:54.861196 #9215] [task:18] DEBUG -- : Downloading template `cloud_controller_ng' (3a7b184f-9397-4142-8e94-59a52561b15e)...
D, [2014-05-16T00:20:54.863621 #9215] [task:18] DEBUG -- : Template `cloud_controller_ng' downloaded to /var/vcap/data/tmp/director/template-c0097a62-f121-4134-a7ca-dc22995dba38 (took 0.002315623s)
D, [2014-05-16T00:20:54.996987 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:54.998189 #9215] [task:18] DEBUG -- : (0.000857s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 8) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:54.999009 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:55.004791 #9215] [task:18] DEBUG -- : Downloading template `cloud_controller_worker' (972f66a3-b8d3-46fc-a31d-e7417a2d67de)...
D, [2014-05-16T00:20:55.007923 #9215] [task:18] DEBUG -- : Template `cloud_controller_worker' downloaded to /var/vcap/data/tmp/director/template-b3df6649-eccd-4df9-8a52-e5570a57e55d (took 0.003023921s)
D, [2014-05-16T00:20:55.075287 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:55.076062 #9215] [task:18] DEBUG -- : (0.000526s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 9) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:55.076541 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:55.080807 #9215] [task:18] DEBUG -- : Downloading template `cloud_controller_clock' (e77b2f92-4b32-4c60-a12d-5cdb227488db)...
D, [2014-05-16T00:20:55.083169 #9215] [task:18] DEBUG -- : Template `cloud_controller_clock' downloaded to /var/vcap/data/tmp/director/template-31d432fc-8d0d-479a-86b4-187820bd145e (took 0.002256622s)
D, [2014-05-16T00:20:55.141020 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:55.141841 #9215] [task:18] DEBUG -- : (0.000581s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 10) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:55.142406 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:55.144006 #9215] [task:18] DEBUG -- : Downloading template `etcd' (64067334-f41b-458b-9b58-0244205950b5)...
D, [2014-05-16T00:20:55.147303 #9215] [task:18] DEBUG -- : Template `etcd' downloaded to /var/vcap/data/tmp/director/template-c7af8a29-c876-4783-9979-d448b0bd5e9b (took 0.003131389s)
D, [2014-05-16T00:20:55.161076 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:55.161601 #9215] [task:18] DEBUG -- : (0.000308s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 11) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:55.162002 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:55.163001 #9215] [task:18] DEBUG -- : Downloading template `hm9000' (ed8edb90-9e49-4cb2-8759-c73c2500c5d9)...
D, [2014-05-16T00:20:55.164981 #9215] [task:18] DEBUG -- : Template `hm9000' downloaded to /var/vcap/data/tmp/director/template-4abac04e-df30-4ff1-b335-3879b9cb1ffd (took 0.001878394s)
D, [2014-05-16T00:20:55.186441 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:55.187080 #9215] [task:18] DEBUG -- : (0.000394s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 12) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:55.187486 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:55.190031 #9215] [task:18] DEBUG -- : Downloading template `dea_logging_agent' (969ece16-90c4-44f3-ae2e-6b7a49859744)...
D, [2014-05-16T00:20:55.192024 #9215] [task:18] DEBUG -- : Template `dea_logging_agent' downloaded to /var/vcap/data/tmp/director/template-3f6e7844-bbd9-434b-9f5d-81c0a356b781 (took 0.001883687s)
D, [2014-05-16T00:20:55.207747 #9215] [task:18] DEBUG -- : Downloading template `dea_next' (c2881bad-d98d-4718-a32d-98cd1cf4628a)...
D, [2014-05-16T00:20:55.209877 #9215] [task:18] DEBUG -- : Template `dea_next' downloaded to /var/vcap/data/tmp/director/template-224a0f03-4a2c-4bca-9e51-299480c21341 (took 0.001932121s)
D, [2014-05-16T00:20:55.244783 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:55.245358 #9215] [task:18] DEBUG -- : (0.000343s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 13) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:55.245778 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:55.263537 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:55.264002 #9215] [task:18] DEBUG -- : (0.000277s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 14) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:55.264338 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:55.281264 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:55.281764 #9215] [task:18] DEBUG -- : (0.000272s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 15) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:55.282085 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:55.283092 #9215] [task:18] DEBUG -- : Downloading template `gorouter' (c460956e-cdaf-4f43-a96c-147f4986e7f1)...
D, [2014-05-16T00:20:55.286585 #9215] [task:18] DEBUG -- : Template `gorouter' downloaded to /var/vcap/data/tmp/director/template-e7fae3ad-dd0c-4f18-81b7-95fdb8e534f9 (took 0.00336558s)
D, [2014-05-16T00:20:55.379898 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:55.381275 #9215] [task:18] DEBUG -- : (0.001006s) SELECT * FROM "rendered_templates_archives" WHERE ("rendered_templates_archives"."instance_id" = 16) ORDER BY "created_at" DESC LIMIT 1
D, [2014-05-16T00:20:55.382007 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:55.383641 #9215] [task:18] DEBUG -- : Downloading template `haproxy' (1d38b7ee-83d1-4014-9dbe-22f9c11b33f8)...
D, [2014-05-16T00:20:55.387740 #9215] [task:18] DEBUG -- : Template `haproxy' downloaded to /var/vcap/data/tmp/director/template-b1eca526-1b56-470d-bd7d-86b85d0c7c09 (took 0.003919062s)
D, [2014-05-16T00:20:55.415007 #9215] [task:18] DEBUG -- : #<NoMethodError: undefined method `ip' for nil:NilClass>
D, [2014-05-16T00:20:55.415255 #9215] [task:18] DEBUG -- : Error filling in template `syslog_forwarder.conf.erb' for `haproxy/0' (line 17: undefined method `ip' for nil:NilClass)
haproxy/syslog_forwarder.conf.erb:17:in `block in get_binding'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/properties/template_evaluation_context.rb:97:in `if_p'
haproxy/syslog_forwarder.conf.erb:1:in `get_binding'
/var/vcap/packages/ruby/lib/ruby/1.9.1/erb.rb:838:in `eval'
/var/vcap/packages/ruby/lib/ruby/1.9.1/erb.rb:838:in `result'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/source_erb.rb:17:in `render'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/job_template_renderer.rb:26:in `block in render'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/job_template_renderer.rb:25:in `map'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/job_template_renderer.rb:25:in `render'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/job_instance_renderer.rb:14:in `block in render'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/job_instance_renderer.rb:12:in `map'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/job_instance_renderer.rb:12:in `render'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/job_renderer.rb:15:in `block in render_job_instances'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/job_renderer.rb:14:in `each'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/job_renderer.rb:14:in `render_job_instances'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/deployment_plan/assembler.rb:315:in `block in bind_configuration'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/deployment_plan/assembler.rb:314:in `each'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/deployment_plan/assembler.rb:314:in `bind_configuration'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/deployment_plan/updater.rb:29:in `block in update'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/jobs/base_job.rb:48:in `block in track_and_log'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/event_log.rb:83:in `call'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/event_log.rb:83:in `advance_and_track'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/event_log.rb:36:in `track'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/jobs/base_job.rb:46:in `track_and_log'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/deployment_plan/updater.rb:28:in `update'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/jobs/update_deployment.rb:52:in `update'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/jobs/update_deployment.rb:78:in `block in perform'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/lock_helper.rb:21:in `block in with_deployment_lock'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/lock.rb:58:in `lock'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/lock_helper.rb:21:in `with_deployment_lock'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/jobs/update_deployment.rb:71:in `perform'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/job_runner.rb:98:in `perform_job'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/job_runner.rb:29:in `block in run'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_formatter.rb:46:in `with_thread_name'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/job_runner.rb:29:in `run'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/jobs/base_job.rb:10:in `perform'
/var/vcap/packages/director/gem_home/gems/resque-1.23.1/lib/resque/job.rb:125:in `perform'
/var/vcap/packages/director/gem_home/gems/resque-1.23.1/lib/resque/worker.rb:186:in `perform'
/var/vcap/packages/director/gem_home/gems/resque-1.23.1/lib/resque/worker.rb:149:in `block in work'
/var/vcap/packages/director/gem_home/gems/resque-1.23.1/lib/resque/worker.rb:128:in `loop'
/var/vcap/packages/director/gem_home/gems/resque-1.23.1/lib/resque/worker.rb:128:in `work'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/bin/bosh-director-worker:76:in `<top (required)>'
/var/vcap/packages/director/bin/bosh-director-worker:23:in `load'
/var/vcap/packages/director/bin/bosh-director-worker:23:in `<main>'
D, [2014-05-16T00:20:55.417338 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:55.418048 #9215] [task:18] DEBUG -- : (0.000530s) SELECT "stemcells".* FROM "stemcells" INNER JOIN "deployments_stemcells" ON (("deployments_stemcells"."stemcell_id" = "stemcells"."id") AND ("deployments_stemcells"."deployment_id" = 2))
D, [2014-05-16T00:20:55.418320 #9215] [task:18] DEBUG -- : Released connection: 27685160
D, [2014-05-16T00:20:55.418593 #9215] [task:18] DEBUG -- : Deleting lock: lock:deployment:cf
D, [2014-05-16T00:20:55.418699 #9215] [0x2014dc8] DEBUG -- : Lock renewal thread exiting
D, [2014-05-16T00:20:55.419036 #9215] [0x2014dc8] DEBUG -- : Redis >> QUIT
D, [2014-05-16T00:20:55.419401 #9215] [0x2014dc8] DEBUG -- : Redis >> 0.27ms
D, [2014-05-16T00:20:55.418908 #9215] [task:18] DEBUG -- : Redis >> WATCH lock:deployment:cf
D, [2014-05-16T00:20:55.419796 #9215] [task:18] DEBUG -- : Redis >> 0.14ms
D, [2014-05-16T00:20:55.419900 #9215] [task:18] DEBUG -- : Redis >> GET lock:deployment:cf
D, [2014-05-16T00:20:55.420134 #9215] [task:18] DEBUG -- : Redis >> 0.14ms
D, [2014-05-16T00:20:55.420303 #9215] [task:18] DEBUG -- : Redis >> MULTI
D, [2014-05-16T00:20:55.420388 #9215] [task:18] DEBUG -- : Redis >> DEL lock:deployment:cf
D, [2014-05-16T00:20:55.420458 #9215] [task:18] DEBUG -- : Redis >> EXEC
D, [2014-05-16T00:20:55.420853 #9215] [task:18] DEBUG -- : Redis >> 0.31ms
D, [2014-05-16T00:20:55.420974 #9215] [task:18] DEBUG -- : Deleted lock: lock:deployment:cf
E, [2014-05-16T00:20:55.421396 #9215] [task:18] ERROR -- : Error filling in template `syslog_forwarder.conf.erb' for `haproxy/0' (line 17: undefined method `ip' for nil:NilClass)
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/source_erb.rb:32:in `rescue in render'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/source_erb.rb:17:in `render'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/job_template_renderer.rb:26:in `block in render'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/job_template_renderer.rb:25:in `map'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/job_template_renderer.rb:25:in `render'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/job_instance_renderer.rb:14:in `block in render'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/job_instance_renderer.rb:12:in `map'
/var/vcap/packages/director/gem_home/gems/bosh-director-core-1.2427.0/lib/bosh/director/core/templates/job_instance_renderer.rb:12:in `render'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/job_renderer.rb:15:in `block in render_job_instances'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/job_renderer.rb:14:in `each'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/job_renderer.rb:14:in `render_job_instances'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/deployment_plan/assembler.rb:315:in `block in bind_configuration'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/deployment_plan/assembler.rb:314:in `each'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/deployment_plan/assembler.rb:314:in `bind_configuration'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/deployment_plan/updater.rb:29:in `block in update'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/jobs/base_job.rb:48:in `block in track_and_log'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/event_log.rb:83:in `call'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/event_log.rb:83:in `advance_and_track'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/event_log.rb:36:in `track'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/jobs/base_job.rb:46:in `track_and_log'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/deployment_plan/updater.rb:28:in `update'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/jobs/update_deployment.rb:52:in `update'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/jobs/update_deployment.rb:78:in `block in perform'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/lock_helper.rb:21:in `block in with_deployment_lock'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/lock.rb:58:in `lock'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/lock_helper.rb:21:in `with_deployment_lock'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/jobs/update_deployment.rb:71:in `perform'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/job_runner.rb:98:in `perform_job'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/job_runner.rb:29:in `block in run'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_formatter.rb:46:in `with_thread_name'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/job_runner.rb:29:in `run'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/jobs/base_job.rb:10:in `perform'
/var/vcap/packages/director/gem_home/gems/resque-1.23.1/lib/resque/job.rb:125:in `perform'
/var/vcap/packages/director/gem_home/gems/resque-1.23.1/lib/resque/worker.rb:186:in `perform'
/var/vcap/packages/director/gem_home/gems/resque-1.23.1/lib/resque/worker.rb:149:in `block in work'
/var/vcap/packages/director/gem_home/gems/resque-1.23.1/lib/resque/worker.rb:128:in `loop'
/var/vcap/packages/director/gem_home/gems/resque-1.23.1/lib/resque/worker.rb:128:in `work'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/bin/bosh-director-worker:76:in `<top (required)>'
/var/vcap/packages/director/bin/bosh-director-worker:23:in `load'
/var/vcap/packages/director/bin/bosh-director-worker:23:in `<main>'
D, [2014-05-16T00:20:55.421947 #9215] [task:18] DEBUG -- : Acquired connection: 27685160
D, [2014-05-16T00:20:55.422346 #9215] [task:18] DEBUG -- : (0.000105s) BEGIN
D, [2014-05-16T00:20:55.424088 #9215] [task:18] DEBUG -- : (0.000644s) UPDATE "tasks" SET "state" = 'error', "timestamp" = '2014-05-16 00:20:55.421647+0000', "description" = 'create deployment', "result" = 'Error filling in template `syslog_forwarder.conf.erb'' for `haproxy/0'' (line 17: undefined method `ip'' for nil:NilClass)', "output" = '/var/vcap/store/director/tasks/18', "user_id" = NULL, "checkpoint_time" = '2014-05-16 00:20:53.961765+0000', "type" = 'update_deployment' WHERE ("id" = 18)
D, [2014-05-16T00:20:55.426223 #9215] [task:18] DEBUG -- : (0.001727s) COMMIT
D, [2014-05-16T00:20:55.426537 #9215] [task:18] DEBUG -- : Released connection: 27685160
I, [2014-05-16T00:20:55.426847 #9215] [0x109c080] INFO -- : Task took 4.140243203 seconds to process.
Task 18 error
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment