ImageNotFound ERROR in n-api log after good tempest run

[David Kranz]

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

[Davanum Srinivas (DIMS) (dims-v)]

In the glance api log i see
2012-11-29 19:09:37 DEBUG glance.registry.client [cf9eec5d-e4c3-4f1a-8c48-42e28c4a2bc5 115a9bf9618847b696db6bf7dedaaf8b 3b352b57729d497eaac7668e99413b17] Registry request DELETE /images/d3b7f3f0-035d-4953-8e91-98869acf1c04 HTTP 200 request id req-1a68836d-c489-485d-9346-f0897d72ab8c do_request /opt/stack/glance/glance/registry/client.py:95
DEBUG:glance.registry.client:Registry request DELETE /images/d3b7f3f0-035d-4953-8e91-98869acf1c04 HTTP 200 request id req-1a68836d-c489-485d-9346-f0897d72ab8c
2012-11-29 19:09:37 INFO glance.registry.client [fc593de0-bc25-4133-bf1e-dba50a357106 115a9bf9618847b696db6bf7dedaaf8b 3b352b57729d497eaac7668e99413b17] Registry client request GET /images/d3b7f3f0-035d-4953-8e91-98869acf1c04 raised NotFound
INFO:glance.registry.client:Registry client request GET /images/d3b7f3f0-035d-4953-8e91-98869acf1c04 raised NotFound

which corresponds to nova api logs's

2012-11-29 19:09:37 29483 TRACE nova.image.s3 ImageNotFound: Image d3b7f3f0-035d-4953-8e91-98869acf1c04 could not be found.

So we are calling a DELETE and then trying to access d3b7f3f0-035d-4953-8e91-98869acf1c04. So this is a valid case and we are doing the right thing except for the extra logs :)

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/30088

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/30088
Committed: http://github.com/openstack/nova/commit/47daf90e11d75e04442ab50ac3b3ece2ae79423f
Submitter: Jenkins
Branch: master

commit 47daf90e11d75e04442ab50ac3b3ece2ae79423f
Author: Chris Yeoh <email address hidden>
Date: Wed May 22 20:36:37 2013 +0930

    _s3_create handles image being deleted

    Change so _s3_create handles the image it is creating
    being deleted while it is creating it without logging a stacktrace
    and instead just logging a simple message explaining what happened.

    Fixes bug 1084703

    Change-Id: I9d984dd1cf4f393010493cacd048d20ad5225db8