gistfile1.txt

root@ip-10-46-175-98:/var/vcap/store# cat microboshes/deployments/jambaymicrobosh/bosh_micro_deploy.log 
# Logfile created on 2013-01-27 22:46:25 +0000 by logger.rb/31641
I, [2013-01-27T22:46:25.383228 #11803] [0xe716ac]  INFO -- : No existing deployments found (will save to /var/vcap/store/microboshes/deployments/bosh-deployments.yml)
I, [2013-01-27T22:46:27.444117 #11805] [0x67f69c]  INFO -- : No existing deployments found (will save to /var/vcap/store/microboshes/deployments/bosh-deployments.yml)
I, [2013-01-27T22:46:45.797031 #11805] [0x67f69c]  INFO -- : aws_registry is ready on port 25888
I, [2013-01-27T22:47:00.320559 #11805] [0x67f69c]  INFO -- : Loading yaml from /var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/stemcell.MF
I, [2013-01-27T22:47:07.039140 #11805] [create_disk(4096, i-9421f7e4)]  INFO -- : [AWS EC2 200 0.200857 0 retries] describe_instances(:instance_ids=>["i-9421f7e4"])  

I, [2013-01-27T22:47:07.382192 #11805] [create_disk(4096, i-9421f7e4)]  INFO -- : [AWS EC2 200 0.341628 0 retries] create_volume(:availability_zone=>"us-east-1d",:size=>4)  

I, [2013-01-27T22:47:07.382474 #11805] [create_disk(4096, i-9421f7e4)]  INFO -- : Creating volume `vol-76647108'
D, [2013-01-27T22:47:07.382595 #11805] [create_disk(4096, i-9421f7e4)] DEBUG -- : Waiting for vol-76647108 to be available (3.0923e-05s)
I, [2013-01-27T22:47:07.454302 #11805] [create_disk(4096, i-9421f7e4)]  INFO -- : [AWS EC2 200 0.071063 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

I, [2013-01-27T22:47:07.454569 #11805] [create_disk(4096, i-9421f7e4)]  INFO -- : vol-76647108 is now available, took 0.072025216s
I, [2013-01-27T22:47:07.515102 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.059894 0 retries] describe_instances(:instance_ids=>["i-9421f7e4"])  

I, [2013-01-27T22:47:07.638632 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.122348 0 retries] attach_volume(:device=>"/dev/sdf",:instance_id=>"i-9421f7e4",:volume_id=>"vol-76647108")  

I, [2013-01-27T22:47:07.638799 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : Attaching `vol-76647108' to `i-9421f7e4'
D, [2013-01-27T22:47:07.638883 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x000000037723a8> to be attached (1.7915e-05s)
I, [2013-01-27T22:47:07.759769 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.120371 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:47:08.767048 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x000000037723a8> to be attached (1.128143625s)
I, [2013-01-27T22:47:08.895151 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.127161 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:47:09.896988 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x000000037723a8> to be attached (2.258112282s)
I, [2013-01-27T22:47:09.952042 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.054194 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:47:10.957074 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x000000037723a8> to be attached (3.318183975s)
I, [2013-01-27T22:47:11.014301 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.056365 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:47:12.017058 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x000000037723a8> to be attached (4.378161387s)
I, [2013-01-27T22:47:12.084650 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.066696 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:47:13.087055 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x000000037723a8> to be attached (5.448157325s)
I, [2013-01-27T22:47:13.197682 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.10974 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:47:14.207063 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x000000037723a8> to be attached (6.568166147s)
I, [2013-01-27T22:47:14.264643 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.056679 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:47:15.267042 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x000000037723a8> to be attached (7.62813944s)
I, [2013-01-27T22:47:15.414204 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.146192 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

I, [2013-01-27T22:47:15.414459 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : #<AWS::EC2::Attachment:0x000000037723a8> is now attached, took 7.775596457s
I, [2013-01-27T22:47:15.414517 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : Attached `vol-76647108' to `i-9421f7e4', device name is `/dev/sdf'
I, [2013-01-27T22:47:15.414588 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : Copying stemcell disk image to '/dev/sdf'
I, [2013-01-27T22:47:15.414726 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : falling back to using dd to copy stemcell
D, [2013-01-27T22:54:46.428319 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : stemcell copy output:
4194304+0 records in
4194304+0 records out
2147483648 bytes (2.1 GB) copied, 450.659 s, 4.8 MB/s

I, [2013-01-27T22:54:46.881774 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.452363 0 retries] create_snapshot(:volume_id=>"vol-76647108")  

D, [2013-01-27T22:54:46.881973 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (1.3703e-05s)
I, [2013-01-27T22:54:46.960107 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.077455 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:54:47.967045 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (1.085047248s)
I, [2013-01-27T22:54:48.056908 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.088905 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:54:49.067051 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (2.1850523s)
I, [2013-01-27T22:54:49.132002 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.063961 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:54:50.137081 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (3.255086702s)
I, [2013-01-27T22:54:50.197698 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.05964 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:54:51.207078 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (4.325079774s)
I, [2013-01-27T22:54:51.279249 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.071187 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:54:52.287057 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (5.405061267s)
I, [2013-01-27T22:54:52.346279 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.058237 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:54:53.347074 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (6.4650832s)
I, [2013-01-27T22:54:53.409839 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.06181 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:54:54.417069 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (7.535072202s)
I, [2013-01-27T22:54:54.478775 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.060746 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:54:55.487052 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (8.605052982s)
I, [2013-01-27T22:54:55.551575 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.063555 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:54:56.557224 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (9.675259414s)
I, [2013-01-27T22:54:56.616231 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.058092 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:54:57.617014 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (10.73502951s)
I, [2013-01-27T22:54:57.676565 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.058639 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:54:58.677063 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (11.795069944s)
I, [2013-01-27T22:54:58.747546 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.06942 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:54:59.757029 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (12.87503916s)
I, [2013-01-27T22:54:59.818708 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.060714 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:00.827066 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (13.945073174s)
I, [2013-01-27T22:55:00.885723 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.057671 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:01.887088 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (15.005079307s)
I, [2013-01-27T22:55:02.069284 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.181201 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:03.077064 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (16.195072215s)
I, [2013-01-27T22:55:03.175979 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.097862 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:04.177081 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (17.29508776s)
I, [2013-01-27T22:55:04.241042 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.062934 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:05.247064 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (18.365071239s)
I, [2013-01-27T22:55:05.307477 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.059411 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:06.317065 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (19.435073205s)
I, [2013-01-27T22:55:06.593242 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.275118 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:07.597083 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (20.71508612s)
I, [2013-01-27T22:55:07.662358 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.06408 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:08.667208 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (21.785242192s)
I, [2013-01-27T22:55:08.727741 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.059628 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:09.736997 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (22.855024826s)
I, [2013-01-27T22:55:09.799049 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.061163 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:10.807073 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (23.925080628s)
I, [2013-01-27T22:55:10.871900 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.063906 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:11.877030 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (24.995039791s)
I, [2013-01-27T22:55:11.936284 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.058348 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:12.937017 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (26.05502721s)
I, [2013-01-27T22:55:12.995353 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.057421 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:14.007043 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (27.125047215s)
I, [2013-01-27T22:55:14.066258 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.058228 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:15.067082 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (28.185088858s)
I, [2013-01-27T22:55:15.127251 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.059251 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:16.137044 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (29.255052065s)
I, [2013-01-27T22:55:16.195869 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.05788 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:17.197096 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (30.315097833s)
I, [2013-01-27T22:55:17.264612 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.066588 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:18.267050 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (31.38505128s)
I, [2013-01-27T22:55:18.334224 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.06626 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:19.337057 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (32.455057282s)
I, [2013-01-27T22:55:19.399680 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.057788 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:20.407080 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (33.525085185s)
I, [2013-01-27T22:55:20.465766 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.05776 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:21.467060 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (34.585060775s)
I, [2013-01-27T22:55:21.528468 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.060481 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:22.537040 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (35.655044866s)
I, [2013-01-27T22:55:22.592049 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.054077 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:23.597060 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (36.715061736s)
I, [2013-01-27T22:55:23.661272 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.063288 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:24.667045 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (37.785047426s)
I, [2013-01-27T22:55:24.732393 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.064435 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:25.737044 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (38.855046186s)
I, [2013-01-27T22:55:25.802099 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.064124 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:26.807069 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (39.925072717s)
I, [2013-01-27T22:55:26.866780 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.058807 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:27.876995 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (40.995021471s)
I, [2013-01-27T22:55:27.934499 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.056638 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:28.936996 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (42.055020933s)
I, [2013-01-27T22:55:28.995829 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.057941 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:29.997014 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (43.115029066s)
I, [2013-01-27T22:55:30.058523 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.060556 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:31.067050 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (44.185050916s)
I, [2013-01-27T22:55:31.125943 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.057972 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:32.127037 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (45.245042117s)
I, [2013-01-27T22:55:32.188441 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.060493 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:33.197062 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (46.315052151s)
I, [2013-01-27T22:55:33.280196 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.082201 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:34.287045 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (47.405047203s)
I, [2013-01-27T22:55:34.349529 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.061551 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:35.357046 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (48.475047219s)
I, [2013-01-27T22:55:35.419339 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.061254 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:36.427057 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (49.545062835s)
I, [2013-01-27T22:55:36.489293 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.061333 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:37.497044 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (50.61504802s)
I, [2013-01-27T22:55:37.563307 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.065341 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:38.567062 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (51.68506862s)
I, [2013-01-27T22:55:38.622398 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.054398 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:39.627052 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (52.745051761s)
I, [2013-01-27T22:55:39.685774 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.057803 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:40.687047 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (53.805047796s)
I, [2013-01-27T22:55:40.756490 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.068484 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:41.757045 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (54.875047136s)
I, [2013-01-27T22:55:41.818080 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.060119 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:42.827041 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (55.945040575s)
I, [2013-01-27T22:55:42.904514 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.076536 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:43.907069 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (57.025077194s)
I, [2013-01-27T22:55:44.108510 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.200428 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:45.120771 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (58.238794158s)
I, [2013-01-27T22:55:45.176313 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.0544 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:46.180792 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (59.298804488s)
I, [2013-01-27T22:55:46.238637 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.056841 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:47.240823 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (60.35882779s)
I, [2013-01-27T22:55:47.301416 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.05963 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:48.310821 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (61.428827769s)
I, [2013-01-27T22:55:48.373225 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.061464 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:49.380777 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (62.498784195s)
I, [2013-01-27T22:55:49.462283 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.080622 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:50.470778 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (63.588785388s)
I, [2013-01-27T22:55:50.526905 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.05521 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:51.530798 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (64.648800766s)
I, [2013-01-27T22:55:51.600989 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.069259 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:52.610790 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (65.728799124s)
I, [2013-01-27T22:55:52.669048 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.057342 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:53.670796 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (66.788798432s)
I, [2013-01-27T22:55:53.732391 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.060689 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:54.740794 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (67.858797234s)
I, [2013-01-27T22:55:54.807893 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.066181 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:55.810807 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (68.928808041s)
I, [2013-01-27T22:55:55.867007 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.055285 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:56.870800 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (69.988802377s)
I, [2013-01-27T22:55:56.926647 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.054846 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:57.930795 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (71.048798499s)
I, [2013-01-27T22:55:57.987127 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.055409 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:55:58.990801 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (72.108803934s)
I, [2013-01-27T22:55:59.052004 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.060248 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:00.060794 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (73.178798437s)
I, [2013-01-27T22:56:00.120216 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.058509 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:01.120863 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (74.238869973s)
I, [2013-01-27T22:56:01.179547 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.057753 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:02.180833 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (75.298840964s)
I, [2013-01-27T22:56:02.248328 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.066484 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:03.250996 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (76.369029071s)
I, [2013-01-27T22:56:03.435272 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.183387 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:04.440834 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (77.558839742s)
I, [2013-01-27T22:56:04.502246 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.060471 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:05.510831 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (78.628835376s)
I, [2013-01-27T22:56:05.575323 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.063552 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:06.580855 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (79.698861505s)
I, [2013-01-27T22:56:06.660310 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.078513 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:07.660806 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (80.778807197s)
I, [2013-01-27T22:56:07.720299 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.058578 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:08.720809 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (81.838819169s)
I, [2013-01-27T22:56:08.798916 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.077189 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:09.800798 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (82.918799664s)
I, [2013-01-27T22:56:09.856484 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.054761 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:10.860860 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (83.978866131s)
I, [2013-01-27T22:56:10.920025 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.058235 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:11.920825 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (85.038833179s)
I, [2013-01-27T22:56:11.984064 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.062314 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:12.990797 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (86.108800921s)
I, [2013-01-27T22:56:13.054531 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.062737 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:14.060804 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (87.178805519s)
I, [2013-01-27T22:56:14.175604 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.11386 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:15.180793 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (88.298796457s)
I, [2013-01-27T22:56:15.244242 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.062547 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:16.250834 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (89.368836592s)
I, [2013-01-27T22:56:16.308658 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.05688 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:17.310810 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (90.428810704s)
I, [2013-01-27T22:56:17.374295 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.062551 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:18.380820 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (91.498826781s)
I, [2013-01-27T22:56:18.451024 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.069191 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:19.460794 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (92.578799906s)
I, [2013-01-27T22:56:19.524037 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.062277 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:20.530811 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (93.648813368s)
I, [2013-01-27T22:56:20.652845 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.121036 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:21.660800 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (94.778804829s)
I, [2013-01-27T22:56:21.733914 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.071952 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:22.740821 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (95.858826136s)
I, [2013-01-27T22:56:22.805273 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.063461 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:23.810852 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (96.928859983s)
I, [2013-01-27T22:56:23.871298 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.059421 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:24.880791 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (97.998793544s)
I, [2013-01-27T22:56:24.942500 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.060783 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:25.950795 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (99.068795725s)
I, [2013-01-27T22:56:26.013697 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.061971 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:27.020791 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (100.138791074s)
I, [2013-01-27T22:56:27.085498 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.063785 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:28.090807 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (101.208805142s)
I, [2013-01-27T22:56:28.156855 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.065137 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:29.160797 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (102.278795779s)
I, [2013-01-27T22:56:29.229664 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.062214 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

D, [2013-01-27T22:56:30.230794 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for snap-2a38ed6b to be completed (103.348794251s)
I, [2013-01-27T22:56:30.300724 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.068992 0 retries] describe_snapshots(:snapshot_ids=>["snap-2a38ed6b"])  

I, [2013-01-27T22:56:30.301030 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : snap-2a38ed6b is now completed, took 103.419073621s
I, [2013-01-27T22:56:39.748353 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 9.446687 0 retries] describe_images(:filters=>[{:name=>"architecture",:values=>["x86_64"]},{:name=>"image-type",:values=>["kernel"]},{:name=>"owner-alias",:values=>["amazon"]}])  

I, [2013-01-27T22:56:39.748789 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : auto-selected AKI: aki-8e5ea7e7
I, [2013-01-27T22:56:40.024981 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.275535 0 retries] register_image(:architecture=>"x86_64",:block_device_mappings=>[{:device_name=>"/dev/sda",:ebs=>{:snapshot_id=>"snap-2a38ed6b"}},{:device_name=>"/dev/sdb",:virtual_name=>"ephemeral0"}],:description=>"micro-bosh-stemcell 0.8.1",:kernel_id=>"aki-8e5ea7e7",:name=>"BOSH-d5ddb129-b51b-4cd0-a4da-6c2436e1dbad",:root_device_name=>"/dev/sda1")  

D, [2013-01-27T22:56:40.025206 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for ami-e9039680 to be available (1.3362e-05s)
I, [2013-01-27T22:56:40.116603 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.090814 0 retries] describe_images(:image_ids=>["ami-e9039680"])  

I, [2013-01-27T22:56:40.117076 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : ami-e9039680 is now available, took 0.091887673s
I, [2013-01-27T22:56:40.295345 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.177734 0 retries] create_tags(:resources=>["ami-e9039680"],:tags=>[{:key=>"Name",:value=>"micro-bosh-stemcell 0.8.1"}])  

I, [2013-01-27T22:56:40.424957 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.128914 0 retries] describe_instances(:instance_ids=>["i-9421f7e4"])  

I, [2013-01-27T22:56:40.569429 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.143178 0 retries] detach_volume(:device=>"/dev/sdf",:instance_id=>"i-9421f7e4",:volume_id=>"vol-76647108")  

I, [2013-01-27T22:56:40.569537 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : Detaching `vol-76647108' from `i-9421f7e4'
D, [2013-01-27T22:56:40.569619 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (2.2766e-05s)
I, [2013-01-27T22:56:40.722173 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.152033 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:41.730796 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (1.161162552s)
I, [2013-01-27T22:56:41.857661 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.125977 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:42.860794 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (2.291162117s)
I, [2013-01-27T22:56:42.923615 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.06197 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:43.930787 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (3.361155524s)
I, [2013-01-27T22:56:44.002386 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.07075 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:45.010816 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (4.441187635s)
I, [2013-01-27T22:56:45.069790 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.058006 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:46.074534 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (5.504906283s)
I, [2013-01-27T22:56:46.129972 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.054569 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:47.134543 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (6.564913737s)
I, [2013-01-27T22:56:47.199206 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.06378 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:48.204539 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (7.634904898s)
I, [2013-01-27T22:56:48.266911 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.061492 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:49.274543 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (8.704915678s)
I, [2013-01-27T22:56:49.336928 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.061504 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:50.344565 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (9.774935606s)
I, [2013-01-27T22:56:50.410901 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.065354 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:51.414566 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (10.844936406s)
I, [2013-01-27T22:56:51.531727 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.116275 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:52.534542 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (11.964908738s)
I, [2013-01-27T22:56:52.697558 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.162149 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:53.704538 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)] DEBUG -- : Waiting for #<AWS::EC2::Attachment:0x0000000458f9b8> to be detached (13.13491093s)
I, [2013-01-27T22:56:53.888671 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : [AWS EC2 200 0.18327 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

I, [2013-01-27T22:56:53.889145 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : attachment is no longer found, assuming it to be detached
I, [2013-01-27T22:56:53.889253 #11805] [create_stemcell(/var/vcap/store/tmp/d20130127-11805-1uyokh9/sc-20130127-11805-i6t98y/image...)]  INFO -- : #<AWS::EC2::Attachment:0x0000000458f9b8> is now detached, took 13.319653951s
I, [2013-01-27T22:56:54.003847 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.11378 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

I, [2013-01-27T22:56:54.148501 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.143914 0 retries] delete_volume(:volume_id=>"vol-76647108")  

I, [2013-01-27T22:56:54.148628 #11805] [delete_disk(vol-76647108)]  INFO -- : Deleting volume `vol-76647108'
D, [2013-01-27T22:56:54.148716 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (2.257e-05s)
I, [2013-01-27T22:56:54.341811 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.192473 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:55.344578 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (1.195848129s)
I, [2013-01-27T22:56:55.402861 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.057128 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:56.404575 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (2.255842918s)
I, [2013-01-27T22:56:56.456795 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.051245 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:57.464587 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (3.315861846s)
I, [2013-01-27T22:56:57.523208 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.057669 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:58.524568 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (4.375843679s)
I, [2013-01-27T22:56:58.586102 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.060589 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:56:59.594543 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (5.445813268s)
I, [2013-01-27T22:56:59.647935 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.052477 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:00.654538 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (6.505813842s)
I, [2013-01-27T22:57:00.710671 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055183 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:01.714600 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (7.565877892s)
I, [2013-01-27T22:57:01.782205 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.066647 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:02.784571 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (8.635844799s)
I, [2013-01-27T22:57:02.841162 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055635 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:03.844726 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (9.696027731s)
I, [2013-01-27T22:57:03.894027 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.048389 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:04.894575 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (10.745845438s)
I, [2013-01-27T22:57:04.949296 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053776 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:05.954622 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (11.805896308s)
I, [2013-01-27T22:57:06.015593 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.060022 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:07.024534 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (12.875814487s)
I, [2013-01-27T22:57:07.079676 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.054161 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:08.084547 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (13.935821014s)
I, [2013-01-27T22:57:08.138873 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053408 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:09.144545 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (14.995821737s)
I, [2013-01-27T22:57:09.199080 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053615 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:10.204580 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (16.055857918s)
I, [2013-01-27T22:57:10.265582 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.060095 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:11.274572 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (17.125845165s)
I, [2013-01-27T22:57:11.334442 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.05895 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:12.344548 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (18.195817336s)
I, [2013-01-27T22:57:12.398672 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.05313 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:13.404562 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (19.255839246s)
I, [2013-01-27T22:57:13.476310 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.070829 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:14.484546 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (20.335815784s)
I, [2013-01-27T22:57:14.537425 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.051952 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:15.544651 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (21.395926408s)
I, [2013-01-27T22:57:15.609812 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.064238 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:16.614548 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (22.465819462s)
I, [2013-01-27T22:57:16.717704 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.102201 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:17.724557 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (23.575827307s)
I, [2013-01-27T22:57:17.785876 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.060406 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:18.794547 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (24.645815301s)
I, [2013-01-27T22:57:18.847135 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.051633 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:19.854559 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (25.705826938s)
I, [2013-01-27T22:57:19.909300 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053809 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:20.914566 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (26.765841212s)
I, [2013-01-27T22:57:20.967761 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.05225 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:21.974547 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (27.825817927s)
I, [2013-01-27T22:57:22.037345 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.061897 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:23.044623 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (28.895921888s)
I, [2013-01-27T22:57:23.098142 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.052571 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:24.104510 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (29.955797922s)
I, [2013-01-27T22:57:24.166222 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.06084 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:25.174543 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (31.025819183s)
I, [2013-01-27T22:57:25.231315 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055879 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:26.233292 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (32.084566031s)
I, [2013-01-27T22:57:26.288159 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053948 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:27.294577 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (33.145849321s)
I, [2013-01-27T22:57:27.351992 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.056468 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:28.354537 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (34.205810563s)
I, [2013-01-27T22:57:28.408410 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.0529 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:29.414564 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (35.26584371s)
I, [2013-01-27T22:57:29.609444 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.193854 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:30.614568 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (36.465838216s)
I, [2013-01-27T22:57:30.671191 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055463 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:31.674551 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (37.525821417s)
I, [2013-01-27T22:57:31.732683 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.057151 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:32.734533 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (38.585810243s)
I, [2013-01-27T22:57:32.791770 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.056307 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:33.794557 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (39.645833134s)
I, [2013-01-27T22:57:33.870785 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.075284 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:34.874541 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (40.725812701s)
I, [2013-01-27T22:57:34.934420 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.058969 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:35.944569 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (41.795843902s)
I, [2013-01-27T22:57:35.998612 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053104 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:37.004543 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (42.855813217s)
I, [2013-01-27T22:57:37.056335 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.050879 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:38.064544 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (43.915815597s)
I, [2013-01-27T22:57:38.122847 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.057378 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:39.124560 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (44.975830534s)
I, [2013-01-27T22:57:39.185762 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.060184 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:40.194540 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (46.045817016s)
I, [2013-01-27T22:57:40.257769 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.062317 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:41.264536 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (47.115818489s)
I, [2013-01-27T22:57:41.319317 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053865 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:42.324546 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (48.175816746s)
I, [2013-01-27T22:57:42.383520 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.058051 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:43.384511 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (49.235795121s)
I, [2013-01-27T22:57:43.441384 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055984 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:44.444540 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (50.295818212s)
I, [2013-01-27T22:57:44.508902 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.063383 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:45.518267 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (51.369545538s)
I, [2013-01-27T22:57:45.575960 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.056801 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:46.578334 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (52.429611019s)
I, [2013-01-27T22:57:46.634283 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055046 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:47.638293 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (53.489575221s)
I, [2013-01-27T22:57:47.693469 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.054247 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:48.698291 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (54.549565367s)
I, [2013-01-27T22:57:48.753833 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.054644 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:49.758291 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (55.609567474s)
I, [2013-01-27T22:57:49.811599 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.0523 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:50.818323 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (56.66959698s)
I, [2013-01-27T22:57:50.875777 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.056528 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:51.878330 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (57.729605944s)
I, [2013-01-27T22:57:51.979673 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.10043 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:52.988292 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (58.83956243s)
I, [2013-01-27T22:57:53.045194 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055992 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:54.048306 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (59.899576174s)
I, [2013-01-27T22:57:54.104269 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.05505 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:55.108298 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (60.959567594s)
I, [2013-01-27T22:57:55.160379 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.051077 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:56.168304 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (62.019579402s)
I, [2013-01-27T22:57:56.222262 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.05304 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:57.228328 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (63.079600653s)
I, [2013-01-27T22:57:57.322223 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.092974 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:58.328294 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (64.179566486s)
I, [2013-01-27T22:57:58.388573 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.059367 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:57:59.398438 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (65.249708994s)
I, [2013-01-27T22:57:59.453181 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053813 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:00.458373 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (66.309672527s)
I, [2013-01-27T22:58:00.513582 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.050752 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:01.518289 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (67.369564227s)
I, [2013-01-27T22:58:01.577589 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.058376 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:02.578326 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (68.429600494s)
I, [2013-01-27T22:58:02.634006 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.054759 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:03.638316 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (69.489589923s)
I, [2013-01-27T22:58:03.697652 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.058415 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:04.698321 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (70.549595385s)
I, [2013-01-27T22:58:04.752664 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053427 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:05.758353 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (71.609628835s)
I, [2013-01-27T22:58:05.819332 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.059994 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:06.828336 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (72.679609345s)
I, [2013-01-27T22:58:06.940850 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.111315 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:07.948325 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (73.799596495s)
I, [2013-01-27T22:58:08.007967 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.05847 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:09.018321 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (74.869595568s)
I, [2013-01-27T22:58:09.078685 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.059398 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:10.088311 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (75.939578454s)
I, [2013-01-27T22:58:10.142277 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053008 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:11.148309 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (76.999579694s)
I, [2013-01-27T22:58:11.208420 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.059105 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:12.218305 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (78.069576483s)
I, [2013-01-27T22:58:12.272799 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053583 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:13.278292 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (79.129563753s)
I, [2013-01-27T22:58:13.330630 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.051412 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:14.338332 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (80.18960755s)
I, [2013-01-27T22:58:14.389147 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.04988 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:15.398302 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (81.249578383s)
I, [2013-01-27T22:58:15.459779 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.060553 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:16.468291 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (82.31956043s)
I, [2013-01-27T22:58:16.520185 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.050968 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:17.528313 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (83.379582681s)
I, [2013-01-27T22:58:17.587380 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.058132 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:18.588392 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (84.439691625s)
I, [2013-01-27T22:58:18.648884 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.059611 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:19.658253 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (85.50954544s)
I, [2013-01-27T22:58:19.712695 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053548 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:20.718295 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (86.569570312s)
I, [2013-01-27T22:58:20.778166 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.05889 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:21.788299 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (87.63957941s)
I, [2013-01-27T22:58:21.850903 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.061712 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:22.858291 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (88.709562614s)
I, [2013-01-27T22:58:22.911652 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.052454 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:23.918297 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (89.769566804s)
I, [2013-01-27T22:58:23.973738 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.054498 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:24.978316 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (90.829592261s)
I, [2013-01-27T22:58:25.037903 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.058662 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:26.048295 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (91.899565832s)
I, [2013-01-27T22:58:26.106729 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.057503 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:27.108293 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (92.959563441s)
I, [2013-01-27T22:58:27.180606 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.071296 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:28.188290 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (94.039557994s)
I, [2013-01-27T22:58:28.249990 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.060775 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:29.258318 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (95.109587998s)
I, [2013-01-27T22:58:29.339780 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.080502 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:30.348298 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (96.199566902s)
I, [2013-01-27T22:58:30.405727 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.056527 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:31.408294 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (97.259562087s)
I, [2013-01-27T22:58:31.466025 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.056814 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:32.468292 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (98.319561242s)
I, [2013-01-27T22:58:32.521002 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.051803 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:33.528294 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (99.37956995s)
I, [2013-01-27T22:58:33.602070 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.072876 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:34.608331 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (100.45960026s)
I, [2013-01-27T22:58:34.680828 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.071568 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:35.688318 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (101.539590503s)
I, [2013-01-27T22:58:35.745402 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.056153 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:36.748300 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (102.599566321s)
I, [2013-01-27T22:58:36.806669 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.057439 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:37.808265 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (103.659551056s)
I, [2013-01-27T22:58:37.863092 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053882 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:38.868297 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (104.719586479s)
I, [2013-01-27T22:58:38.929375 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.060191 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:39.938322 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (105.789594052s)
I, [2013-01-27T22:58:40.000298 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.061047 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:41.008325 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (106.859598296s)
I, [2013-01-27T22:58:41.068124 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.05884 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:42.078296 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (107.929565236s)
I, [2013-01-27T22:58:42.134892 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055678 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:43.138301 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (108.989570933s)
I, [2013-01-27T22:58:43.220909 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.081638 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:44.228294 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (110.079562319s)
I, [2013-01-27T22:58:44.425335 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.196044 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:45.432070 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (111.283342777s)
I, [2013-01-27T22:58:45.487999 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.054791 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:46.492047 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (112.343315648s)
I, [2013-01-27T22:58:46.551125 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.058109 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:47.552044 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (113.403311942s)
I, [2013-01-27T22:58:47.609661 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.05669 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:48.612048 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (114.463318264s)
I, [2013-01-27T22:58:48.667945 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.054952 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:49.672072 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (115.523347801s)
I, [2013-01-27T22:58:49.730456 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.057442 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:50.732076 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (116.583351986s)
I, [2013-01-27T22:58:50.806694 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.073682 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:51.812059 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (117.663327526s)
I, [2013-01-27T22:58:51.872030 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.05905 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:52.882047 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (118.733316104s)
I, [2013-01-27T22:58:52.937659 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.054681 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:53.942110 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (119.793407774s)
I, [2013-01-27T22:58:53.999093 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.056016 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:55.002021 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (120.853307235s)
I, [2013-01-27T22:58:55.057932 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055026 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:56.062037 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (121.913318165s)
I, [2013-01-27T22:58:56.120124 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.057202 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:57.122070 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (122.973343455s)
I, [2013-01-27T22:58:57.183319 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.060297 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:58.192030 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (124.04330678s)
I, [2013-01-27T22:58:58.247803 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.054879 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:58:59.252050 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (125.103317649s)
I, [2013-01-27T22:58:59.314307 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055666 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:00.322068 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (126.17333699s)
I, [2013-01-27T22:59:00.370865 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.047875 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:01.372064 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (127.223339663s)
I, [2013-01-27T22:59:01.426115 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053122 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:02.432035 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (128.283310334s)
I, [2013-01-27T22:59:02.486477 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053506 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:03.492080 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (129.343353213s)
I, [2013-01-27T22:59:03.560691 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.067678 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:04.562070 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (130.413342934s)
I, [2013-01-27T22:59:04.621556 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.058539 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:05.622051 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (131.473326659s)
I, [2013-01-27T22:59:05.682503 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.059521 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:06.692051 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (132.543324791s)
I, [2013-01-27T22:59:06.754790 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.061816 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:07.762056 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (133.613326076s)
I, [2013-01-27T22:59:07.816624 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053655 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:08.822044 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (134.673314244s)
I, [2013-01-27T22:59:08.881660 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.058701 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:09.892054 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (135.743327411s)
I, [2013-01-27T22:59:09.946030 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.052959 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:10.952075 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (136.803347429s)
I, [2013-01-27T22:59:11.006991 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053971 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:12.012080 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (137.86335455s)
I, [2013-01-27T22:59:12.075817 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.06281 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:13.082082 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (138.933354382s)
I, [2013-01-27T22:59:13.138639 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055621 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:14.142196 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (139.993461584s)
I, [2013-01-27T22:59:14.199954 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.056839 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:15.202068 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (141.053340689s)
I, [2013-01-27T22:59:15.256096 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053004 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:16.262075 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (142.11334899s)
I, [2013-01-27T22:59:16.318102 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055093 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:17.322177 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (143.17345197s)
I, [2013-01-27T22:59:17.376705 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.053598 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:18.382040 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (144.233323063s)
I, [2013-01-27T22:59:18.443366 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.060438 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:19.452083 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (145.30335542s)
I, [2013-01-27T22:59:19.511847 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.058824 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:20.582096 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (146.433369569s)
I, [2013-01-27T22:59:20.637716 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.054689 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:21.642070 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (147.493343056s)
I, [2013-01-27T22:59:21.825242 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.18216 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:22.832086 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (148.683359858s)
I, [2013-01-27T22:59:22.889887 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.056667 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:23.892060 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (149.743328152s)
I, [2013-01-27T22:59:23.949009 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055985 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:24.952044 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (150.803313726s)
I, [2013-01-27T22:59:25.011779 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.058795 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:26.022057 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (151.87332697s)
I, [2013-01-27T22:59:26.078253 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055204 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:27.082062 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (152.93333669s)
I, [2013-01-27T22:59:27.138155 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055165 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:28.142046 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (153.99331577s)
I, [2013-01-27T22:59:28.201278 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.058308 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:29.202057 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (155.053327852s)
I, [2013-01-27T22:59:29.258368 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 200 0.055399 0 retries] describe_volumes(:volume_ids=>["vol-76647108"])  

D, [2013-01-27T22:59:30.262058 #11805] [delete_disk(vol-76647108)] DEBUG -- : Waiting for vol-76647108 to be deleted (156.113325554s)
I, [2013-01-27T22:59:30.307971 #11805] [delete_disk(vol-76647108)]  INFO -- : [AWS EC2 400 0.044209 0 retries] describe_volumes(:volume_ids=>["vol-76647108"]) AWS::EC2::Errors::InvalidVolume::NotFound The volume 'vol-76647108' does not exist.

I, [2013-01-27T22:59:30.308257 #11805] [delete_disk(vol-76647108)]  INFO -- : Volume `vol-76647108' has been deleted
D, [2013-01-27T22:59:30.509302 #11805] [create_vm(bm-852fd4ca-6bfa-41ad-8fe4-ad50a65c8360, ...)] DEBUG -- : using security groups: jambaymicrobosh
I, [2013-01-27T22:59:30.594633 #11805] [create_vm(bm-852fd4ca-6bfa-41ad-8fe4-ad50a65c8360, ...)]  INFO -- : [AWS EC2 200 0.084622 0 retries] describe_images(:image_ids=>["ami-e9039680"])  

I, [2013-01-27T22:59:30.594894 #11805] [create_vm(bm-852fd4ca-6bfa-41ad-8fe4-ad50a65c8360, ...)]  INFO -- : Creating new instance...
I, [2013-01-27T22:59:31.093402 #11805] [create_vm(bm-852fd4ca-6bfa-41ad-8fe4-ad50a65c8360, ...)]  INFO -- : [AWS EC2 400 0.294115 0 retries] run_instances(:client_token=>"354ac14c-68d5-11e2-9a14-123139331f94",:image_id=>"ami-e9039680",:instance_type=>"m1.medium",:key_name=>"jambaymicrobosh",:max_count=>1,:min_count=>1,:placement=>{:availability_zone=>"us-east-1b"},:security_groups=>["jambaymicrobosh"],:user_data=>"eyJyZWdpc3RyeSI6eyJlbmRwb2ludCI6Imh0dHA6Ly9hZG1pbjphZG1pbkBs\nb2NhbGhvc3Q6MjU4ODgifX0=") AWS::EC2::Errors::Unsupported The requested Availability Zone is currently constrained and we are no longer accepting new customer requests for t1/m1/c1/m2 instance types. Please retry your request by not specifying an Availability Zone or choosing us-east-1a, us-east-1d, us-east-1c.

I, [2013-01-27T22:59:31.158030 #11805] [delete_stemcell(ami-e9039680)]  INFO -- : [AWS EC2 200 0.062969 0 retries] describe_images(:image_ids=>["ami-e9039680"])  

D, [2013-01-27T22:59:31.158631 #11805] [delete_stemcell(ami-e9039680)] DEBUG -- : queuing snapshot snap-2a38ed6b for deletion
I, [2013-01-27T22:59:31.306743 #11805] [delete_stemcell(ami-e9039680)]  INFO -- : [AWS EC2 200 0.147579 0 retries] deregister_image(:image_id=>"ami-e9039680")  

I, [2013-01-27T22:59:31.306858 #11805] [delete_stemcell(ami-e9039680)]  INFO -- : cleaning up snapshot snap-2a38ed6b
I, [2013-01-27T22:59:31.375589 #11805] [delete_stemcell(ami-e9039680)]  INFO -- : [AWS EC2 400 0.067319 0 retries] delete_snapshot(:snapshot_id=>"snap-2a38ed6b") AWS::EC2::Errors::InvalidSnapshot::InUse The snapshot snap-2a38ed6b is currently in use by ami-e9039680