redis-log

D, [2015-03-19T06:01:53.847340 #8589] [task:296] DEBUG -- : Acquired connection: 44478040
D, [2015-03-19T06:01:53.847695 #8589] [task:296] DEBUG -- : (0.000233s) SELECT * FROM "tasks" WHERE "id" = 296
D, [2015-03-19T06:01:53.848068 #8589] [task:296] DEBUG -- : Released connection: 44478040
D, [2015-03-19T06:01:53.948256 #8589] [task:296] DEBUG -- : Acquired connection: 44478040
D, [2015-03-19T06:01:53.948610 #8589] [task:296] DEBUG -- : (0.000248s) SELECT * FROM "tasks" WHERE "id" = 296
D, [2015-03-19T06:01:53.948964 #8589] [task:296] DEBUG -- : Released connection: 44478040
D, [2015-03-19T06:01:54.049156 #8589] [task:296] DEBUG -- : Acquired connection: 44478040
D, [2015-03-19T06:01:54.049490 #8589] [task:296] DEBUG -- : (0.000230s) SELECT * FROM "tasks" WHERE "id" = 296
D, [2015-03-19T06:01:54.049838 #8589] [task:296] DEBUG -- : Released connection: 44478040
E, [2015-03-19T06:01:54.061176 #8589] [compile_package(memcached/cb508a2dc25a3aeafacddbd43574f300a50101da, bosh-openstack-kvm-ubuntu/2427)] ERROR -- : error creating vm: execution expired
D, [2015-03-19T06:01:54.061351 #8589] [compile_package(memcached/cb508a2dc25a3aeafacddbd43574f300a50101da, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Deleting lock: lock:compile:57:1
D, [2015-03-19T06:01:54.061525 #8589] [compile_package(memcached/cb508a2dc25a3aeafacddbd43574f300a50101da, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> WATCH lock:compile:57:1
D, [2015-03-19T06:01:54.061953 #8589] [0x28ad3cc] DEBUG -- : Lock renewal thread exiting
D, [2015-03-19T06:01:54.062099 #8589] [0x28ad3cc] DEBUG -- : Redis >> QUIT 
D, [2015-03-19T06:01:54.062498 #8589] [compile_package(memcached/cb508a2dc25a3aeafacddbd43574f300a50101da, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> 0.90ms
D, [2015-03-19T06:01:54.062593 #8589] [compile_package(memcached/cb508a2dc25a3aeafacddbd43574f300a50101da, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> GET lock:compile:57:1
D, [2015-03-19T06:01:54.062776 #8589] [compile_package(memcached/cb508a2dc25a3aeafacddbd43574f300a50101da, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> 0.11ms
D, [2015-03-19T06:01:54.062932 #8589] [compile_package(memcached/cb508a2dc25a3aeafacddbd43574f300a50101da, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> MULTI 
D, [2015-03-19T06:01:54.063013 #8589] [compile_package(memcached/cb508a2dc25a3aeafacddbd43574f300a50101da, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> DEL lock:compile:57:1
D, [2015-03-19T06:01:54.063082 #8589] [compile_package(memcached/cb508a2dc25a3aeafacddbd43574f300a50101da, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> EXEC 
D, [2015-03-19T06:01:54.063470 #8589] [compile_package(memcached/cb508a2dc25a3aeafacddbd43574f300a50101da, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> 0.29ms
D, [2015-03-19T06:01:54.063564 #8589] [compile_package(memcached/cb508a2dc25a3aeafacddbd43574f300a50101da, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Deleted lock: lock:compile:57:1
D, [2015-03-19T06:01:54.064113 #8589] [0x2645698] DEBUG -- : Worker thread raised exception: execution expired - /var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:850:in `gets'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:850:in `block in parse_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:847:in `parse_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:830:in `read_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:652:in `get_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:1114:in `do_get_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:1063:in `do_get_block'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:869:in `block in do_request'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:956:in `protect_keep_alive_disconnected'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:868:in `do_request'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:756:in `request'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:671:in `put'
/var/vcap/packages/director/gem_home/gems/bosh-registry-1.2427.0/lib/bosh/registry/client.rb:63:in `update_settings'
/var/vcap/packages/director/gem_home/gems/bosh_openstack_cpi-1.2427.0/lib/cloud/openstack/cloud.rb:261:in `block in create_vm'
/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_openstack_cpi-1.2427.0/lib/cloud/openstack/cloud.rb:183:in `create_vm'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/vm_creator.rb:41:in `create'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/vm_creator.rb:9:in `create'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:153:in `prepare_vm'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:80:in `block in compile_package'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/lock_helper.rb:89:in `block in with_compile_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:88:in `with_compile_lock'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:73:in `compile_package'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:300:in `block (2 levels) in process_task'
/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/package_compiler.rb:298:in `block in process_task'
/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/package_compiler.rb:294:in `process_task'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:254:in `block (4 levels) in compile_packages'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:79:in `call'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:79:in `block (2 levels) in create_thread'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:63:in `loop'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:63:in `block in create_thread'
D, [2015-03-19T06:01:54.064229 #8589] [0x2645698] DEBUG -- : Thread is no longer needed, cleaning up
D, [2015-03-19T06:01:54.064541 #8589] [0x28ad3cc] DEBUG -- : Redis >> 2.36ms
D, [2015-03-19T06:01:54.150062 #8589] [task:296] DEBUG -- : Acquired connection: 44478040
D, [2015-03-19T06:01:54.150424 #8589] [task:296] DEBUG -- : (0.000248s) SELECT * FROM "tasks" WHERE "id" = 296
D, [2015-03-19T06:01:54.150786 #8589] [task:296] DEBUG -- : Released connection: 44478040
D, [2015-03-19T06:01:54.150907 #8589] [task:296] DEBUG -- : Acquired connection: 44478040
D, [2015-03-19T06:01:54.151215 #8589] [task:296] DEBUG -- : (0.000212s) SELECT * FROM "tasks" WHERE "id" = 296
D, [2015-03-19T06:01:54.151593 #8589] [task:296] DEBUG -- : Released connection: 44478040
D, [2015-03-19T06:01:54.151683 #8589] [task:296] DEBUG -- : Waiting for tasks to complete
D, [2015-03-19T06:01:54.151807 #8589] [task:296] DEBUG -- : Shutting down pool
E, [2015-03-19T06:01:54.377681 #8589] [compile_package(rootfs_lucid64/9b3f611b46e076b94b37645c98f9100e7bcef5dd, bosh-openstack-kvm-ubuntu/2427)] ERROR -- : error creating vm: execution expired
D, [2015-03-19T06:01:54.377841 #8589] [compile_package(rootfs_lucid64/9b3f611b46e076b94b37645c98f9100e7bcef5dd, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Deleting lock: lock:compile:87:1
D, [2015-03-19T06:01:54.378218 #8589] [compile_package(rootfs_lucid64/9b3f611b46e076b94b37645c98f9100e7bcef5dd, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> WATCH lock:compile:87:1
D, [2015-03-19T06:01:54.377975 #8589] [0x2915dc8] DEBUG -- : Lock renewal thread exiting
D, [2015-03-19T06:01:54.378616 #8589] [0x2915dc8] DEBUG -- : Redis >> QUIT 
D, [2015-03-19T06:01:54.379024 #8589] [0x2915dc8] DEBUG -- : Redis >> 0.27ms
D, [2015-03-19T06:01:54.379242 #8589] [compile_package(rootfs_lucid64/9b3f611b46e076b94b37645c98f9100e7bcef5dd, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> 0.93ms
D, [2015-03-19T06:01:54.379335 #8589] [compile_package(rootfs_lucid64/9b3f611b46e076b94b37645c98f9100e7bcef5dd, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> GET lock:compile:87:1
D, [2015-03-19T06:01:54.379573 #8589] [compile_package(rootfs_lucid64/9b3f611b46e076b94b37645c98f9100e7bcef5dd, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> 0.12ms
D, [2015-03-19T06:01:54.379696 #8589] [compile_package(rootfs_lucid64/9b3f611b46e076b94b37645c98f9100e7bcef5dd, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> MULTI 
D, [2015-03-19T06:01:54.379770 #8589] [compile_package(rootfs_lucid64/9b3f611b46e076b94b37645c98f9100e7bcef5dd, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> DEL lock:compile:87:1
D, [2015-03-19T06:01:54.379845 #8589] [compile_package(rootfs_lucid64/9b3f611b46e076b94b37645c98f9100e7bcef5dd, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> EXEC 
D, [2015-03-19T06:01:54.380168 #8589] [compile_package(rootfs_lucid64/9b3f611b46e076b94b37645c98f9100e7bcef5dd, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> 0.26ms
D, [2015-03-19T06:01:54.380263 #8589] [compile_package(rootfs_lucid64/9b3f611b46e076b94b37645c98f9100e7bcef5dd, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Deleted lock: lock:compile:87:1
D, [2015-03-19T06:01:54.380602 #8589] [0x2643fb4] DEBUG -- : Worker thread raised exception: execution expired - /var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:850:in `gets'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:850:in `block in parse_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:847:in `parse_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:830:in `read_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:652:in `get_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:1114:in `do_get_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:1063:in `do_get_block'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:869:in `block in do_request'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:956:in `protect_keep_alive_disconnected'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:868:in `do_request'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:756:in `request'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:671:in `put'
/var/vcap/packages/director/gem_home/gems/bosh-registry-1.2427.0/lib/bosh/registry/client.rb:63:in `update_settings'
/var/vcap/packages/director/gem_home/gems/bosh_openstack_cpi-1.2427.0/lib/cloud/openstack/cloud.rb:261:in `block in create_vm'
/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_openstack_cpi-1.2427.0/lib/cloud/openstack/cloud.rb:183:in `create_vm'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/vm_creator.rb:41:in `create'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/vm_creator.rb:9:in `create'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:153:in `prepare_vm'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:80:in `block in compile_package'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/lock_helper.rb:89:in `block in with_compile_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:88:in `with_compile_lock'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:73:in `compile_package'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:300:in `block (2 levels) in process_task'
/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/package_compiler.rb:298:in `block in process_task'
/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/package_compiler.rb:294:in `process_task'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:254:in `block (4 levels) in compile_packages'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:79:in `call'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:79:in `block (2 levels) in create_thread'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:63:in `loop'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:63:in `block in create_thread'
D, [2015-03-19T06:01:54.380706 #8589] [0x2643fb4] DEBUG -- : Thread is no longer needed, cleaning up
D, [2015-03-19T06:01:57.919809 #8589] [0x1589638] DEBUG -- : Renewing lock: lock:deployment:cf-redis-memcached
D, [2015-03-19T06:01:57.920439 #8589] [0x1589638] DEBUG -- : Redis >> WATCH lock:deployment:cf-redis-memcached
D, [2015-03-19T06:01:57.921157 #8589] [0x1589638] DEBUG -- : Redis >> 0.59ms
D, [2015-03-19T06:01:57.921261 #8589] [0x1589638] DEBUG -- : Redis >> GET lock:deployment:cf-redis-memcached
D, [2015-03-19T06:01:57.921602 #8589] [0x1589638] DEBUG -- : Redis >> 0.26ms
D, [2015-03-19T06:01:57.921824 #8589] [0x1589638] DEBUG -- : Redis >> MULTI 
D, [2015-03-19T06:01:57.921932 #8589] [0x1589638] DEBUG -- : Redis >> SET lock:deployment:cf-redis-memcached 1426744928.9216862:73c71d4c-a823-4536-b14b-164740b317f3
D, [2015-03-19T06:01:57.922029 #8589] [0x1589638] DEBUG -- : Redis >> EXEC 
D, [2015-03-19T06:01:57.922480 #8589] [0x1589638] DEBUG -- : Redis >> 0.37ms
D, [2015-03-19T06:01:57.954749 #8589] [task:296-checkpoint] DEBUG -- : Acquired connection: 44478040
D, [2015-03-19T06:01:57.955416 #8589] [task:296-checkpoint] DEBUG -- : (0.000362s) BEGIN
D, [2015-03-19T06:01:57.957997 #8589] [task:296-checkpoint] DEBUG -- : (0.000758s) UPDATE "tasks" SET "checkpoint_time" = '2015-03-19 06:01:57.953574+0000' WHERE ("id" = 296)
D, [2015-03-19T06:01:57.970745 #8589] [task:296-checkpoint] DEBUG -- : (0.012477s) COMMIT
D, [2015-03-19T06:01:57.970903 #8589] [task:296-checkpoint] DEBUG -- : Released connection: 44478040
D, [2015-03-19T06:01:58.033453 #8589] [0x174da78] DEBUG -- : Renewing lock: lock:compile:56:1
D, [2015-03-19T06:01:58.033618 #8589] [0x174da78] DEBUG -- : Redis >> WATCH lock:compile:56:1
D, [2015-03-19T06:01:58.034065 #8589] [0x174da78] DEBUG -- : Redis >> 0.34ms
D, [2015-03-19T06:01:58.034172 #8589] [0x174da78] DEBUG -- : Redis >> GET lock:compile:56:1
D, [2015-03-19T06:01:58.034450 #8589] [0x174da78] DEBUG -- : Redis >> 0.20ms
D, [2015-03-19T06:01:58.034626 #8589] [0x174da78] DEBUG -- : Redis >> MULTI 
D, [2015-03-19T06:01:58.034700 #8589] [0x174da78] DEBUG -- : Redis >> SET lock:compile:56:1 1426744929.0345402:a26728d1-5cc7-48b4-b9d7-6a8ad03f4006
D, [2015-03-19T06:01:58.034762 #8589] [0x174da78] DEBUG -- : Redis >> EXEC 
D, [2015-03-19T06:01:58.035125 #8589] [0x174da78] DEBUG -- : Redis >> 0.27ms
D, [2015-03-19T06:02:02.922851 #8589] [0x1589638] DEBUG -- : Renewing lock: lock:deployment:cf-redis-memcached
D, [2015-03-19T06:02:02.923235 #8589] [0x1589638] DEBUG -- : Redis >> WATCH lock:deployment:cf-redis-memcached
D, [2015-03-19T06:02:02.924279 #8589] [0x1589638] DEBUG -- : Redis >> 0.89ms
D, [2015-03-19T06:02:02.925222 #8589] [0x1589638] DEBUG -- : Redis >> GET lock:deployment:cf-redis-memcached
D, [2015-03-19T06:02:02.925840 #8589] [0x1589638] DEBUG -- : Redis >> 0.45ms
D, [2015-03-19T06:02:02.926195 #8589] [0x1589638] DEBUG -- : Redis >> MULTI 
D, [2015-03-19T06:02:02.926354 #8589] [0x1589638] DEBUG -- : Redis >> SET lock:deployment:cf-redis-memcached 1426744933.9260337:73c71d4c-a823-4536-b14b-164740b317f3
D, [2015-03-19T06:02:02.926484 #8589] [0x1589638] DEBUG -- : Redis >> EXEC 
D, [2015-03-19T06:02:02.927202 #8589] [0x1589638] DEBUG -- : Redis >> 0.56ms
D, [2015-03-19T06:02:03.035362 #8589] [0x174da78] DEBUG -- : Renewing lock: lock:compile:56:1
D, [2015-03-19T06:02:03.035544 #8589] [0x174da78] DEBUG -- : Redis >> WATCH lock:compile:56:1
D, [2015-03-19T06:02:03.036077 #8589] [0x174da78] DEBUG -- : Redis >> 0.42ms
D, [2015-03-19T06:02:03.036295 #8589] [0x174da78] DEBUG -- : Redis >> GET lock:compile:56:1
D, [2015-03-19T06:02:03.036880 #8589] [0x174da78] DEBUG -- : Redis >> 0.42ms
D, [2015-03-19T06:02:03.037127 #8589] [0x174da78] DEBUG -- : Redis >> MULTI 
D, [2015-03-19T06:02:03.037285 #8589] [0x174da78] DEBUG -- : Redis >> SET lock:compile:56:1 1426744934.0370214:a26728d1-5cc7-48b4-b9d7-6a8ad03f4006
D, [2015-03-19T06:02:03.037401 #8589] [0x174da78] DEBUG -- : Redis >> EXEC 
D, [2015-03-19T06:02:03.038281 #8589] [0x174da78] DEBUG -- : Redis >> 0.68ms
E, [2015-03-19T06:02:05.319152 #8589] [compile_package(libyaml/568edb735b91c85c62d7ebd6cd287c98d0edb6ce, bosh-openstack-kvm-ubuntu/2427)] ERROR -- : error creating vm: execution expired
D, [2015-03-19T06:02:05.319776 #8589] [compile_package(libyaml/568edb735b91c85c62d7ebd6cd287c98d0edb6ce, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Deleting lock: lock:compile:56:1
D, [2015-03-19T06:02:05.320122 #8589] [compile_package(libyaml/568edb735b91c85c62d7ebd6cd287c98d0edb6ce, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> WATCH lock:compile:56:1
D, [2015-03-19T06:02:05.320681 #8589] [compile_package(libyaml/568edb735b91c85c62d7ebd6cd287c98d0edb6ce, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> 0.43ms
D, [2015-03-19T06:02:05.320794 #8589] [compile_package(libyaml/568edb735b91c85c62d7ebd6cd287c98d0edb6ce, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> GET lock:compile:56:1
D, [2015-03-19T06:02:05.321014 #8589] [compile_package(libyaml/568edb735b91c85c62d7ebd6cd287c98d0edb6ce, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> 0.13ms
D, [2015-03-19T06:02:05.321235 #8589] [compile_package(libyaml/568edb735b91c85c62d7ebd6cd287c98d0edb6ce, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> MULTI 
D, [2015-03-19T06:02:05.321318 #8589] [compile_package(libyaml/568edb735b91c85c62d7ebd6cd287c98d0edb6ce, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> DEL lock:compile:56:1
D, [2015-03-19T06:02:05.321398 #8589] [compile_package(libyaml/568edb735b91c85c62d7ebd6cd287c98d0edb6ce, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> EXEC 
D, [2015-03-19T06:02:05.321824 #8589] [compile_package(libyaml/568edb735b91c85c62d7ebd6cd287c98d0edb6ce, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Redis >> 0.35ms
D, [2015-03-19T06:02:05.321962 #8589] [compile_package(libyaml/568edb735b91c85c62d7ebd6cd287c98d0edb6ce, bosh-openstack-kvm-ubuntu/2427)] DEBUG -- : Deleted lock: lock:compile:56:1
D, [2015-03-19T06:02:05.322530 #8589] [0x29ac14c] DEBUG -- : Worker thread raised exception: execution expired - /var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:850:in `gets'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:850:in `block in parse_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:847:in `parse_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:830:in `read_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:652:in `get_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:1114:in `do_get_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:1063:in `do_get_block'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:869:in `block in do_request'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:956:in `protect_keep_alive_disconnected'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:868:in `do_request'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:756:in `request'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:671:in `put'
/var/vcap/packages/director/gem_home/gems/bosh-registry-1.2427.0/lib/bosh/registry/client.rb:63:in `update_settings'
/var/vcap/packages/director/gem_home/gems/bosh_openstack_cpi-1.2427.0/lib/cloud/openstack/cloud.rb:261:in `block in create_vm'
/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_openstack_cpi-1.2427.0/lib/cloud/openstack/cloud.rb:183:in `create_vm'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/vm_creator.rb:41:in `create'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/vm_creator.rb:9:in `create'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:153:in `prepare_vm'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:80:in `block in compile_package'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/lock_helper.rb:89:in `block in with_compile_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:88:in `with_compile_lock'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:73:in `compile_package'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:300:in `block (2 levels) in process_task'
/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/package_compiler.rb:298:in `block in process_task'
/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/package_compiler.rb:294:in `process_task'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:254:in `block (4 levels) in compile_packages'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:79:in `call'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:79:in `block (2 levels) in create_thread'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:63:in `loop'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:63:in `block in create_thread'
D, [2015-03-19T06:02:05.322669 #8589] [0x29ac14c] DEBUG -- : Thread is no longer needed, cleaning up
D, [2015-03-19T06:02:05.323048 #8589] [0x174da78] DEBUG -- : Lock renewal thread exiting
D, [2015-03-19T06:02:05.323185 #8589] [0x174da78] DEBUG -- : Redis >> QUIT 
D, [2015-03-19T06:02:05.323503 #8589] [0x174da78] DEBUG -- : Redis >> 0.23ms
D, [2015-03-19T06:02:05.324015 #8589] [task:296] DEBUG -- : Waiting for tasks to complete
D, [2015-03-19T06:02:05.324103 #8589] [task:296] DEBUG -- : Shutting down pool
D, [2015-03-19T06:02:05.324231 #8589] [task:296] DEBUG -- : Deleting lock: lock:deployment:cf-redis-memcached
D, [2015-03-19T06:02:05.324308 #8589] [0x1589638] DEBUG -- : Lock renewal thread exiting
D, [2015-03-19T06:02:05.324554 #8589] [0x1589638] DEBUG -- : Redis >> QUIT 
D, [2015-03-19T06:02:05.324803 #8589] [0x1589638] DEBUG -- : Redis >> 0.17ms
D, [2015-03-19T06:02:05.324433 #8589] [task:296] DEBUG -- : Redis >> WATCH lock:deployment:cf-redis-memcached
D, [2015-03-19T06:02:05.325178 #8589] [task:296] DEBUG -- : Redis >> 0.16ms
D, [2015-03-19T06:02:05.325257 #8589] [task:296] DEBUG -- : Redis >> GET lock:deployment:cf-redis-memcached
D, [2015-03-19T06:02:05.325446 #8589] [task:296] DEBUG -- : Redis >> 0.11ms
D, [2015-03-19T06:02:05.325554 #8589] [task:296] DEBUG -- : Redis >> MULTI 
D, [2015-03-19T06:02:05.325621 #8589] [task:296] DEBUG -- : Redis >> DEL lock:deployment:cf-redis-memcached
D, [2015-03-19T06:02:05.325686 #8589] [task:296] DEBUG -- : Redis >> EXEC 
D, [2015-03-19T06:02:05.326097 #8589] [task:296] DEBUG -- : Redis >> 0.34ms
D, [2015-03-19T06:02:05.326203 #8589] [task:296] DEBUG -- : Deleted lock: lock:deployment:cf-redis-memcached
E, [2015-03-19T06:02:05.327539 #8589] [task:296] ERROR -- : execution expired
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:850:in `gets'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:850:in `block in parse_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:847:in `parse_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:830:in `read_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient/session.rb:652:in `get_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:1114:in `do_get_header'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:1063:in `do_get_block'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:869:in `block in do_request'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:956:in `protect_keep_alive_disconnected'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:868:in `do_request'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:756:in `request'
/var/vcap/packages/director/gem_home/gems/httpclient-2.2.4/lib/httpclient.rb:671:in `put'
/var/vcap/packages/director/gem_home/gems/bosh-registry-1.2427.0/lib/bosh/registry/client.rb:63:in `update_settings'
/var/vcap/packages/director/gem_home/gems/bosh_openstack_cpi-1.2427.0/lib/cloud/openstack/cloud.rb:261:in `block in create_vm'
/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_openstack_cpi-1.2427.0/lib/cloud/openstack/cloud.rb:183:in `create_vm'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/vm_creator.rb:41:in `create'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/vm_creator.rb:9:in `create'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:153:in `prepare_vm'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:80:in `block in compile_package'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/lock_helper.rb:89:in `block in with_compile_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:88:in `with_compile_lock'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:73:in `compile_package'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:300:in `block (2 levels) in process_task'
/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/package_compiler.rb:298:in `block in process_task'
/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/package_compiler.rb:294:in `process_task'
/var/vcap/packages/director/gem_home/gems/bosh-director-1.2427.0/lib/bosh/director/package_compiler.rb:254:in `block (4 levels) in compile_packages'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:79:in `call'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:79:in `block (2 levels) in create_thread'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:63:in `loop'
/var/vcap/packages/director/gem_home/gems/bosh_common-1.2427.0/lib/common/thread_pool.rb:63:in `block in create_thread'
D, [2015-03-19T06:02:05.328676 #8589] [task:296] DEBUG -- : Acquired connection: 44478040
D, [2015-03-19T06:02:05.329535 #8589] [task:296] DEBUG -- : (0.000630s) BEGIN
D, [2015-03-19T06:02:05.333237 #8589] [task:296] DEBUG -- : (0.001734s) UPDATE "tasks" SET "state" = 'error', "timestamp" = '2015-03-19 06:02:05.328051+0000', "description" = 'create deployment', "result" = 'execution expired', "output" = '/var/vcap/store/director/tasks/296', "user_id" = 2, "checkpoint_time" = '2015-03-19 06:01:57.953574+0000', "type" = 'update_deployment' WHERE ("id" = 296)
D, [2015-03-19T06:02:05.360282 #8589] [task:296] DEBUG -- : (0.026792s) COMMIT
D, [2015-03-19T06:02:05.360485 #8589] [task:296] DEBUG -- : Released connection: 44478040
I, [2015-03-19T06:02:05.360740 #8589] [0x137f07c]  INFO -- : Task took 2 minutes 9.61423383799999 seconds to process.

Task 296 error

hello,I get the same problem when deploy cf with mcrobosh on openstack, have you solved it yet? Thanks!