From http://logs.openstack.org/periodic/periodic-tempest-devstack-vm-check-hourly/404/logs/screen-n-api.txt
2012-11-29 19:09:36 DEBUG nova.utils [req-08a4f894-d80e-4718-8699-e194bb0f5639 demo demo] Running cmd (subprocess): openssl enc -d -aes-128-cbc -in /tmp/tmpZ8v3HM/image.encrypted -K 0d8dd9155e185e1b7acb2ac0bc1c3339 -iv 77ef7e43a0abc52b9970eae9bf036058 -out /tmp/tmpZ8v3HM/image.tar.gz execute /opt/stack/nova/nova/utils.py:185
2012-11-29 19:09:36 DEBUG nova.utils [req-08a4f894-d80e-4718-8699-e194bb0f5639 demo demo] Result was 0 execute /opt/stack/nova/nova/utils.py:209
2012-11-29 19:09:36 DEBUG nova.api.ec2 [req-c6f1a01b-43cb-482c-85e0-0fb0722a58ab demo demo] action: DeregisterImage __call__ /opt/stack/nova/nova/api/ec2/__init__.py:339
2012-11-29 19:09:36 DEBUG nova.api.ec2 [req-c6f1a01b-43cb-482c-85e0-0fb0722a58ab demo demo] arg: ImageId val: ami-00000001 __call__ /opt/stack/nova/nova/api/ec2/__init__.py:341
2012-11-29 19:09:36 AUDIT nova.api.ec2.cloud [req-c6f1a01b-43cb-482c-85e0-0fb0722a58ab demo demo] De-registering image ami-00000001
2012-11-29 19:09:37 DEBUG nova.api.ec2.apirequest [req-c6f1a01b-43cb-482c-85e0-0fb0722a58ab demo demo] <?xml version="1.0" ?><DeregisterImageResponse xmlns="http://ec2.amazonaws.com/doc/2009-11-30/"><requestId>req-c6f1a01b-43cb-482c-85e0-0fb0722a58ab</requestId><return>true</return></DeregisterImageResponse> _render_response /opt/stack/nova/nova/api/ec2/apirequest.py:103
2012-11-29 19:09:37 INFO nova.api.ec2 [req-c6f1a01b-43cb-482c-85e0-0fb0722a58ab demo demo] 0.527777s 127.0.0.1 POST /services/Cloud/ CloudController:DeregisterImage 200 [Boto/2.1.1 (linux2)] application/x-www-form-urlencoded text/xml
2012-11-29 19:09:37 INFO nova.ec2.wsgi.server [req-c6f1a01b-43cb-482c-85e0-0fb0722a58ab demo demo] 127.0.0.1 "POST /services/Cloud/ HTTP/1.1" status: 200 len: 307 time: 0.5290320
No handlers could be found for logger "glanceclient.common.http"
2012-11-29 19:09:37 ERROR nova.image.s3 [req-08a4f894-d80e-4718-8699-e194bb0f5639 demo demo] Failed to upload testbucket/bundle.img.manifest.xml to /tmp/tmpZ8v3HM
2012-11-29 19:09:37 29483 TRACE nova.image.s3 Traceback (most recent call last):
2012-11-29 19:09:37 29483 TRACE nova.image.s3 File "/opt/stack/nova/nova/image/s3.py", line 347, in delayed_create
2012-11-29 19:09:37 29483 TRACE nova.image.s3 _update_image_data(context, image_uuid, image_file)
2012-11-29 19:09:37 29483 TRACE nova.image.s3 File "/opt/stack/nova/nova/image/s3.py", line 291, in _update_image_data
2012-11-29 19:09:37 29483 TRACE nova.image.s3 purge_props=False)
2012-11-29 19:09:37 29483 TRACE nova.image.s3 File "/opt/stack/nova/nova/image/glance.py", line 257, in update
2012-11-29 19:09:37 29483 TRACE nova.image.s3 _reraise_translated_image_exception(image_id)
2012-11-29 19:09:37 29483 TRACE nova.image.s3 File "/opt/stack/nova/nova/image/glance.py", line 255, in update
2012-11-29 19:09:37 29483 TRACE nova.image.s3 image_id, **image_meta)
2012-11-29 19:09:37 29483 TRACE nova.image.s3 File "/opt/stack/nova/nova/image/glance.py", line 142, in call
2012-11-29 19:09:37 29483 TRACE nova.image.s3 return getattr(client.images, method)(*args, **kwargs)
2012-11-29 19:09:37 29483 TRACE nova.image.s3 File "/opt/stack/python-glanceclient/glanceclient/v1/images.py", line 253, in update
2012-11-29 19:09:37 29483 TRACE nova.image.s3 'PUT', url, headers=hdrs, body=image_data)
2012-11-29 19:09:37 29483 TRACE nova.image.s3 File "/opt/stack/python-glanceclient/glanceclient/common/http.py", line 219, in raw_request
2012-11-29 19:09:37 29483 TRACE nova.image.s3 return self._http_request(url, method, **kwargs)
2012-11-29 19:09:37 29483 TRACE nova.image.s3 File "/opt/stack/python-glanceclient/glanceclient/common/http.py", line 180, in _http_request
2012-11-29 19:09:37 29483 TRACE nova.image.s3 raise exc.from_response(resp)
2012-11-29 19:09:37 29483 TRACE nova.image.s3 ImageNotFound: Image d3b7f3f0-035d-4953-8e91-98869acf1c04 could not be found.
2012-11-29 19:09:37 29483 TRACE nova.image.s3
Traceback (most recent call last):
File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/poll.py", line 97, in wait
readers.get(fileno, noop).cb(fileno)
File "/opt/stack/nova/nova/image/s3.py", line 351, in delayed_create
_update_image_state(context, image_uuid, 'failed_upload')
File "/opt/stack/nova/nova/image/s3.py", line 286, in _update_image_state
purge_props=False)
File "/opt/stack/nova/nova/image/glance.py", line 257, in update
_reraise_translated_image_exception(image_id)
File "/opt/stack/nova/nova/image/glance.py", line 255, in update
image_id, **image_meta)
File "/opt/stack/nova/nova/image/glance.py", line 142, in call
return getattr(client.images, method)(*args, **kwargs)
File "/opt/stack/python-glanceclient/glanceclient/v1/images.py", line 253, in update
'PUT', url, headers=hdrs, body=image_data)
File "/opt/stack/python-glanceclient/glanceclient/common/http.py", line 219, in raw_request
return self._http_request(url, method, **kwargs)
File "/opt/stack/python-glanceclient/glanceclient/common/http.py", line 180, in _http_request
raise exc.from_response(resp)
ImageNotFound: Image d3b7f3f0-035d-4953-8e91-98869acf1c04 could not be found.
Removing descriptor: 11
In the glance api log i see registry. client [cf9eec5d- e4c3-4f1a- 8c48-42e28c4a2b c5 115a9bf9618847b 696db6bf7dedaaf 8b 3b352b57729d497 eaac7668e99413b 17] Registry request DELETE /images/ d3b7f3f0- 035d-4953- 8e91-98869acf1c 04 HTTP 200 request id req-1a68836d- c489-485d- 9346-f0897d72ab 8c do_request /opt/stack/ glance/ glance/ registry/ client. py:95 registry. client: Registry request DELETE /images/ d3b7f3f0- 035d-4953- 8e91-98869acf1c 04 HTTP 200 request id req-1a68836d- c489-485d- 9346-f0897d72ab 8c registry. client [fc593de0- bc25-4133- bf1e-dba50a3571 06 115a9bf9618847b 696db6bf7dedaaf 8b 3b352b57729d497 eaac7668e99413b 17] Registry client request GET /images/ d3b7f3f0- 035d-4953- 8e91-98869acf1c 04 raised NotFound registry. client: Registry client request GET /images/ d3b7f3f0- 035d-4953- 8e91-98869acf1c 04 raised NotFound
2012-11-29 19:09:37 DEBUG glance.
DEBUG:glance.
2012-11-29 19:09:37 INFO glance.
INFO:glance.
which corresponds to nova api logs's
2012-11-29 19:09:37 29483 TRACE nova.image.s3 ImageNotFound: Image d3b7f3f0- 035d-4953- 8e91-98869acf1c 04 could not be found.
So we are calling a DELETE and then trying to access d3b7f3f0- 035d-4953- 8e91-98869acf1c 04. So this is a valid case and we are doing the right thing except for the extra logs :)