bosh upload stemcell failed: Execution expired

stemcell.log

root@ip-10-10-10-62:~/bosh-workspace/stemcells# bosh task 9 --debug

Director task 9
# Logfile created on 2014-11-12 10:31:16 +0000 by logger.rb/44203
I, [2014-11-12T10:31:16.074227 #2818]  INFO -- : Director Version : 1.2765.0
I, [2014-11-12T10:31:16.074292 #2818]  INFO -- : Enqueuing task: 9
I, [2014-11-12T10:31:17.167180 #8538] [0x3fb19c881318]  INFO -- : Looking for task with task id 9
D, [2014-11-12T10:31:17.188066 #8538] [0x3fb19c881318] DEBUG -- : (0.020135s) SELECT * FROM "tasks" WHERE "id" = 9
I, [2014-11-12T10:31:17.192974 #8538] [0x3fb19c881318]  INFO -- : Starting task: 9
I, [2014-11-12T10:31:17.193137 #8538] [task:9]  INFO -- : Creating job
D, [2014-11-12T10:31:23.791680 #8538] [task:9] DEBUG -- : (0.000558s) SELECT * FROM "tasks" WHERE "id" = 9
I, [2014-11-12T10:31:23.792382 #8538] [task:9]  INFO -- : Performing task: 9
D, [2014-11-12T10:31:23.793123 #8538] [task:9] DEBUG -- : (0.000119s) BEGIN
D, [2014-11-12T10:31:23.795473 #8538] [task:9] DEBUG -- : (0.000781s) UPDATE "tasks" SET "state" = 'processing', "timestamp" = '2014-11-12 10:31:23.792524+0000', "description" = 'create stemcell', "result" = NULL, "output" = '/var/vcap/store/director/tasks/9', "user_id" = NULL, "checkpoint_time" = '2014-11-12 10:31:23.792617+0000', "type" = 'update_stemcell' WHERE ("id" = 9)
D, [2014-11-12T10:31:23.797195 #8538] [task:9] DEBUG -- : (0.001505s) COMMIT
I, [2014-11-12T10:31:23.797340 #8538] [task:9]  INFO -- : Processing update stemcell
I, [2014-11-12T10:31:23.798007 #8538] [task:9]  INFO -- : Extracting stemcell archive
I, [2014-11-12T10:31:29.664576 #8538] [task:9]  INFO -- : Verifying stemcell manifest
I, [2014-11-12T10:31:29.666267 #8538] [task:9]  INFO -- : Found stemcell image `bosh-aws-xen-ubuntu-trusty-go_agent/2652', cloud properties are {"name"=>"bosh-aws-xen-ubuntu-trusty-go_agent", "version"=>"2652", "infrastructure"=>"aws", "architecture"=>"x86_64", "root_device_name"=>"/dev/sda1"}
I, [2014-11-12T10:31:29.666372 #8538] [task:9]  INFO -- : Verifying stemcell image
I, [2014-11-12T10:31:29.666765 #8538] [task:9]  INFO -- : Checking if this stemcell already exists
D, [2014-11-12T10:31:29.668832 #8538] [task:9] DEBUG -- : (0.000846s) SELECT * FROM "stemcells" WHERE (("name" = 'bosh-aws-xen-ubuntu-trusty-go_agent') AND ("version" = '2652')) LIMIT 1
I, [2014-11-12T10:31:29.669486 #8538] [task:9]  INFO -- : Uploading stemcell bosh-aws-xen-ubuntu-trusty-go_agent/2652 to the cloud
D, [2014-11-12T10:31:53.798238 #8538] [task:9-checkpoint] DEBUG -- : (0.000208s) BEGIN
D, [2014-11-12T10:31:53.799707 #8538] [task:9-checkpoint] DEBUG -- : (0.000405s) UPDATE "tasks" SET "checkpoint_time" = '2014-11-12 10:31:53.796100+0000' WHERE ("id" = 9)
D, [2014-11-12T10:31:53.801656 #8538] [task:9-checkpoint] DEBUG -- : (0.001625s) COMMIT
I, [2014-11-12T10:32:15.630123 #8538] [create_disk(2048, i-11a7081b)]  INFO -- : [AWS EC2 200 45.920017 2 retries] describe_instances(:instance_ids=>["i-11a7081b"]) Net::OpenTimeout execution expired

E, [2014-11-12T10:32:15.630432 #8538] [create_stemcell(/var/vcap/data/tmp/director/stemcell20141112-8538-1a9duop/image...)] ERROR -- : execution expired (Net::OpenTimeout)
/var/vcap/packages/ruby/lib/ruby/2.1.0/net/http.rb:879:in `initialize'
/var/vcap/packages/ruby/lib/ruby/2.1.0/net/http.rb:879:in `open'
/var/vcap/packages/ruby/lib/ruby/2.1.0/net/http.rb:879:in `block in connect'
/var/vcap/packages/ruby/lib/ruby/2.1.0/timeout.rb:91:in `block in timeout'
/var/vcap/packages/ruby/lib/ruby/2.1.0/timeout.rb:101:in `call'
/var/vcap/packages/ruby/lib/ruby/2.1.0/timeout.rb:101:in `timeout'
/var/vcap/packages/ruby/lib/ruby/2.1.0/net/http.rb:878:in `connect'
/var/vcap/packages/ruby/lib/ruby/2.1.0/net/http.rb:863:in `do_start'
/var/vcap/packages/ruby/lib/ruby/2.1.0/net/http.rb:858:in `start'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/http/connection_pool.rb:321:in `start_session'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/http/connection_pool.rb:125:in `session_for'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/http/net_http_handler.rb:55:in `handle'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:253:in `block in make_sync_request'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:289:in `retry_server_errors'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:249:in `make_sync_request'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:511:in `block (2 levels) in client_request'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:391:in `log_client_request'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:477:in `block in client_request'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:373:in `return_or_raise'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:476:in `client_request'
(eval):3:in `describe_instances'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/ec2/resource.rb:72:in `describe_call'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/ec2/instance.rb:787:in `get_resource'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/resource.rb:235:in `block (2 levels) in define_attribute_getter'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/cacheable.rb:63:in `retrieve_attribute'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/ec2/resource.rb:66:in `retrieve_attribute'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/resource.rb:235:in `block in define_attribute_getter'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/ec2/instance.rb:527:in `availability_zone'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_aws_cpi-1.2765.0/lib/cloud/aws/availability_zone_selector.rb:19:in `select_availability_zone'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_aws_cpi-1.2765.0/lib/cloud/aws/cloud.rb:179:in `block in create_disk'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_common-1.2765.0/lib/common/thread_formatter.rb:46:in `with_thread_name'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_aws_cpi-1.2765.0/lib/cloud/aws/cloud.rb:166:in `create_disk'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_aws_cpi-1.2765.0/lib/cloud/aws/cloud.rb:422:in `block in create_stemcell'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_common-1.2765.0/lib/common/thread_formatter.rb:46:in `with_thread_name'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_aws_cpi-1.2765.0/lib/cloud/aws/cloud.rb:410:in `create_stemcell'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/jobs/update_stemcell.rb:84:in `block in perform'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/jobs/base_job.rb:48:in `block in track_and_log'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/event_log.rb:83:in `call'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/event_log.rb:83:in `advance_and_track'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/event_log.rb:36:in `track'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/jobs/base_job.rb:46:in `track_and_log'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/jobs/update_stemcell.rb:83:in `perform'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/job_runner.rb:104:in `perform_job'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/job_runner.rb:31:in `block in run'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_common-1.2765.0/lib/common/thread_formatter.rb:46:in `with_thread_name'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/job_runner.rb:31:in `run'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/jobs/base_job.rb:10:in `perform'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/job.rb:227:in `perform'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/worker.rb:250:in `perform'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/worker.rb:189:in `block in work'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/worker.rb:166:in `loop'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/worker.rb:166:in `work'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/bin/bosh-director-worker:78:in `<top (required)>'
/var/vcap/packages/director/bin/bosh-director-worker:16:in `load'
/var/vcap/packages/director/bin/bosh-director-worker:16:in `<main>'
E, [2014-11-12T10:32:15.768207 #8538] [task:9] ERROR -- : execution expired
/var/vcap/packages/ruby/lib/ruby/2.1.0/net/http.rb:879:in `initialize'
/var/vcap/packages/ruby/lib/ruby/2.1.0/net/http.rb:879:in `open'
/var/vcap/packages/ruby/lib/ruby/2.1.0/net/http.rb:879:in `block in connect'
/var/vcap/packages/ruby/lib/ruby/2.1.0/timeout.rb:91:in `block in timeout'
/var/vcap/packages/ruby/lib/ruby/2.1.0/timeout.rb:101:in `call'
/var/vcap/packages/ruby/lib/ruby/2.1.0/timeout.rb:101:in `timeout'
/var/vcap/packages/ruby/lib/ruby/2.1.0/net/http.rb:878:in `connect'
/var/vcap/packages/ruby/lib/ruby/2.1.0/net/http.rb:863:in `do_start'
/var/vcap/packages/ruby/lib/ruby/2.1.0/net/http.rb:858:in `start'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/http/connection_pool.rb:321:in `start_session'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/http/connection_pool.rb:125:in `session_for'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/http/net_http_handler.rb:55:in `handle'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:253:in `block in make_sync_request'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:289:in `retry_server_errors'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:249:in `make_sync_request'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:511:in `block (2 levels) in client_request'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:391:in `log_client_request'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:477:in `block in client_request'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:373:in `return_or_raise'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/client.rb:476:in `client_request'
(eval):3:in `describe_instances'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/ec2/resource.rb:72:in `describe_call'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/ec2/instance.rb:787:in `get_resource'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/resource.rb:235:in `block (2 levels) in define_attribute_getter'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/cacheable.rb:63:in `retrieve_attribute'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/ec2/resource.rb:66:in `retrieve_attribute'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/core/resource.rb:235:in `block in define_attribute_getter'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/aws-sdk-1.44.0/lib/aws/ec2/instance.rb:527:in `availability_zone'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_aws_cpi-1.2765.0/lib/cloud/aws/availability_zone_selector.rb:19:in `select_availability_zone'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_aws_cpi-1.2765.0/lib/cloud/aws/cloud.rb:179:in `block in create_disk'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_common-1.2765.0/lib/common/thread_formatter.rb:46:in `with_thread_name'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_aws_cpi-1.2765.0/lib/cloud/aws/cloud.rb:166:in `create_disk'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_aws_cpi-1.2765.0/lib/cloud/aws/cloud.rb:422:in `block in create_stemcell'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_common-1.2765.0/lib/common/thread_formatter.rb:46:in `with_thread_name'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_aws_cpi-1.2765.0/lib/cloud/aws/cloud.rb:410:in `create_stemcell'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/jobs/update_stemcell.rb:84:in `block in perform'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/jobs/base_job.rb:48:in `block in track_and_log'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/event_log.rb:83:in `call'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/event_log.rb:83:in `advance_and_track'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/event_log.rb:36:in `track'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/jobs/base_job.rb:46:in `track_and_log'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/jobs/update_stemcell.rb:83:in `perform'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/job_runner.rb:104:in `perform_job'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/job_runner.rb:31:in `block in run'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh_common-1.2765.0/lib/common/thread_formatter.rb:46:in `with_thread_name'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/job_runner.rb:31:in `run'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/lib/bosh/director/jobs/base_job.rb:10:in `perform'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/job.rb:227:in `perform'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/worker.rb:250:in `perform'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/worker.rb:189:in `block in work'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/worker.rb:166:in `loop'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/resque-1.25.2/lib/resque/worker.rb:166:in `work'
/var/vcap/packages/director/gem_home/ruby/2.1.0/gems/bosh-director-1.2765.0/bin/bosh-director-worker:78:in `<top (required)>'
/var/vcap/packages/director/bin/bosh-director-worker:16:in `load'
/var/vcap/packages/director/bin/bosh-director-worker:16:in `<main>'
D, [2014-11-12T10:32:15.769024 #8538] [task:9] DEBUG -- : (0.000205s) BEGIN
D, [2014-11-12T10:32:15.770584 #8538] [task:9] DEBUG -- : (0.000582s) UPDATE "tasks" SET "state" = 'error', "timestamp" = '2014-11-12 10:32:15.768471+0000', "description" = 'create stemcell', "result" = 'execution expired', "output" = '/var/vcap/store/director/tasks/9', "user_id" = NULL, "checkpoint_time" = '2014-11-12 10:31:53.796100+0000', "type" = 'update_stemcell' WHERE ("id" = 9)
D, [2014-11-12T10:32:15.788334 #8538] [task:9] DEBUG -- : (0.017615s) COMMIT
I, [2014-11-12T10:32:15.788541 #8538] [0x3fb19c881318]  INFO -- : Task took 58.595392535 seconds to process.

Task 9 error