expired image location url cause glance client errors

[Mark Nye]

We have a multi-node Openstack cluster running Folsom 2012.2.3 on Ubuntu 12.04. A few days ago we added a new compute node, and found that we were unable to launch new instances from a pre-existing Ubuntu Server 12.04 LTS image stored in glance. Each spawning attempt would deposit a glance client exception (shown below) in the compute node's nova-compute.log.

After quite a lot of investigation, I found that the original --location URL (used during "glance image-create") of the Ubuntu Server image had gone out of date. This was evidently causing a BadStoreUri exception on the glance server during instance spawning, resulting in a 500 error being returned to our new compute node's glance client. I was able to resolve the problem by re-importing an Ubuntu Server 12.04 LTS image from a working mirror.

Improved error logging would have saved us hours of troubleshooting.

2013-06-27 21:19:24 ERROR nova.compute.manager [req-f8d7c23a-e8ad-4059-bea4-4fc588a6afe0 9d8968d3f17f4697aaf923c14651ce7b e5fb3c6db0db4e9c86d0301005e2e5bb] [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] Instance failed to spawn
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] Traceback (most recent call last):
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 756, in _spawn
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] block_device_info)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 117, in wrapped
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] temp_level, payload)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] self.gen.next()
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 92, in wrapped
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] return f(*args, **kw)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 1099, in spawn
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] admin_pass=admin_password)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 1365, in _create_image
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] project_id=instance['project_id'])
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", line 131, in cache
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] *args, **kwargs)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", line 178, in create_image
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] prepare_template(target=base, *args, **kwargs)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/utils.py", line 795, in inner
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] retval = f(*args, **kwargs)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", line 122, in call_if_not_exists
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] fetch_func(target=target, *args, **kwargs)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/utils.py", line 440, in fetch_image
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] images.fetch_to_raw(context, image_id, target, user_id, project_id)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/virt/images.py", line 87, in fetch_to_raw
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] fetch(context, image_href, path_tmp, user_id, project_id)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/virt/images.py", line 82, in fetch
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] image_service.download(context, image_id, image_file)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/image/glance.py", line 222, in download
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] _reraise_translated_image_exception(image_id)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/image/glance.py", line 220, in download
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] image_chunks = self._client.call(context, 1, 'data', image_id)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/nova/image/glance.py", line 138, in call
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] return getattr(client.images, method)(*args, **kwargs)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/glanceclient/v1/images.py", line 108, in data
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] resp, body = self.api.raw_request('GET', '/v1/images/%s' % image_id)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/glanceclient/common/http.py", line 191, in raw_request
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] return self._http_request(url, method, **kwargs)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] File "/usr/lib/python2.7/dist-packages/glanceclient/common/http.py", line 158, in _http_request
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] raise exc.from_response(resp)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d] HTTPInternalServerError: HTTPInternalServerError (HTTP 500)
2013-06-27 21:19:24 5290 TRACE nova.compute.manager [instance: 1cdd84ad-ba1b-4e5c-8711-8e2c91b48c3d]

[Zhi Yan Liu (lzy-dev)]

Hello Mark Nye, so do you think this issue is a bug/defect of the OpenStack/Glance? I consider this is an invalid report.

[Mark Nye (launuhpad)]

The sequence of events was as follows:

1) Brought up a fresh Folsom cluster
2) Imported the Ubuntu Server 12.04 LTS image from an Ubuntu mirror
3) Imported image works on all compute nodes
4) Original URI to image becomes invalid
5) Added new compute node to cluster
6) Imported image works with pre-existing compute nodes, but fails to spawn on new compute node
7) Neither the compute node nova logs or the controller glance logs give a clear indication of the cause of the failure

To me, this seems like undesirable behavior.

[Robert Collins (lifeless)]

The import should have copied the image into glance; did your new compute have a new glance instance or something?

[Mark Nye (launuhpad)]

No, glance is running only on the controller node, and nova.conf is identical on all of the compute nodes, except of course for the local IP address changes. "nova-manage service list" showed services enabled and happy on all compute nodes. Still, the image with the outdated URI would not spawn on the new hardware.

[Bert JW Regeer (bertjwregeer)]

I just had the same issue happen to me.

Traceback:

2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] Traceback (most recent call last):
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 1103, in _spawn
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] block_device_info)
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 1521, in spawn
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] admin_pass=admin_password)
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 1807, in _create_image
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] project_id=instance['project_id'])
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", line 158, in cache
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] *args, **kwargs)
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", line 258, in create_image
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] prepare_template(target=base, *args, **kwargs)
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] File "/usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py", line 228, in inner
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] retval = f(*args, **kwargs)
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", line 146, in call_if_not_exists
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] fetch_func(target=target, *args, **kwargs)
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/utils.py", line 593, in fetch_image
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] images.fetch_to_raw(context, image_id, target, user_id, project_id)
2013-07-23 21:12:45.499 1319 TRACE nova.compute.manager [instance: 4cf71433-9a45-4b20-aeff-be5116c60aa8] File "/usr/lib/python2.7/dist-packages/nova/virt/images.py", line 207, in fetch_to_raw
2013-07-23 21:12:45.499 1319 TRACE nov...

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/128202
Committed: https://git.openstack.org/cgit/openstack/glance/commit/?id=633bec8fd45897735e1fcb9844903fe597903b21
Submitter: Jenkins
Branch: master

commit 633bec8fd45897735e1fcb9844903fe597903b21
Author: ankitagrawal <email address hidden>
Date: Fri Oct 10 05:31:46 2014 -0700

    Improve error log for expired image location url

    If image is not present at the specified location while creating instance
    from image, then HTTPInternalServerError 500 response along with stack trace
    is logged on nova compute which does not help user to understand the exact
    cause of failure.

    Return HTTPNotFound error to the nova compute in case of image url got
    expired or image is not present at the given location to give clear
    indication of the cause of failure to user.

    Closes-Bug: #1198566
    Change-Id: I9acd9112aeae8d3b3c0c3921f306e716e5808c2e

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/juno
Review: https://review.openstack.org/130119

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/130119
Committed: https://git.openstack.org/cgit/openstack/glance/commit/?id=3cdd0aaa67400fcf6f04323c4697ebed1966c65f
Submitter: Jenkins
Branch: stable/juno

commit 3cdd0aaa67400fcf6f04323c4697ebed1966c65f
Author: ankitagrawal <email address hidden>
Date: Fri Oct 10 05:31:46 2014 -0700

    Improve error log for expired image location url

    If image is not present at the specified location while creating instance
    from image, then HTTPInternalServerError 500 response along with stack trace
    is logged on nova compute which does not help user to understand the exact
    cause of failure.

    Return HTTPNotFound error to the nova compute in case of image url got
    expired or image is not present at the given location to give clear
    indication of the cause of failure to user.

    Closes-Bug: #1198566
    Change-Id: I9acd9112aeae8d3b3c0c3921f306e716e5808c2e
    (cherry picked from commit 633bec8fd45897735e1fcb9844903fe597903b21)