Bug 888241

Summary: cinder creating a bootable volume from image-id fails with 500 error from glance-api
Product: Red Hat OpenStack Reporter: Eoghan Glynn <eglynn>
Component: openstack-packstackAssignee: Derek Higgins <derekh>
Status: CLOSED ERRATA QA Contact: Nir Magnezi <nmagnezi>
Severity: high Docs Contact:
Priority: high    
Version: 2.1CC: aortega, derekh, mmagr, ykaul
Target Milestone: snapshot2Keywords: Reopened, Triaged
Target Release: 2.1   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: openstack-packstack-2012.2.2-0.8.dev346.el6ost Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-02-14 18:23:37 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Eoghan Glynn 2012-12-18 11:20:17 UTC
Description of problem:

When creating a bootable volume in the "new way" via cinder, the image retrieval call out to glance fails with a 500 ServerError.

It looks like the glanceclient is using the v2 API.


Version-Release number of selected component (if applicable):

$ rpm -qa | grep -e 'cinder\|glance'
openstack-glance-2012.2.1-1.el6ost.noarch
python-glanceclient-0.5.1-1.el6.noarch
python-glance-2012.2.1-1.el6ost.noarch
python-cinderclient-0.2.26-1.el6.noarch
python-cinder-2012.2.1-1.el6ost.noarch
openstack-cinder-2012.2.1-1.el6ost.noarch


How reproducible:

100%


Steps to Reproduce:

1. wget -c https://launchpad.net/cirros/trunk/0.3.0/+download/cirros-0.3.0-x86_64-disk.img -O //var/tmp/cirros-0.3.0-x86_64-disk.img

2. IMAGE_ID=$(glance image-create --name cirros --disk-format qcow2 --container-format bare --is-public 1 < /var/tmp/cirros-0.3.0-x86_64-disk.img | grep 'id' | awk '{print $4}')

3. cinder create --image-id $IMAGE_ID 1
  
Actual results:

Bootable volume is created but goes into the error state when the image download is attemtped by cinder.


Expected results:

Bootable volume is created and becomes available shortly thereafter.


Additional info:

 cinder.log:
 ===========
2012-12-18 05:44:00 INFO cinder.volume.manager [req-10b7589e-1b31-49b1-ad0d-26bd044c16fa a24ce67b1a434dc396ee9a4600e00969 4665470fba654e0bb7f4c272d99ad161] volume volume-e504272c-0daa-491d-b66a-66deadaab5f7: creating
2012-12-18 05:44:00 13792 ERROR cinder.openstack.common.rpc.amqp [-] Exception during message handling
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp Traceback (most recent call last):
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/cinder/openstack/common/rpc/amqp.py", line 276, in _process_data
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp     rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/cinder/openstack/common/rpc/dispatcher.py", line 145, in dispatch
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp     return getattr(proxyobj, method)(ctxt, **kwargs)
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 163, in create_volume
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp     volume_ref['id'], {'status': 'error'})
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp   File "/usr/lib64/python2.6/contextlib.py", line 23, in __exit__
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp     self.gen.next()
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 146, in create_volume
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp     image_location = image_service.get_location(context, image_id)
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/cinder/image/glance.py", line 194, in get_location
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp     _reraise_translated_image_exception(image_id)
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/cinder/image/glance.py", line 192, in get_location
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp     image_meta = client.call(context, 2, 'get', image_id)
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/cinder/image/glance.py", line 122, in call
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp     return getattr(client.images, method)(*args, **kwargs)
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/glanceclient/v2/images.py", line 54, in get
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp     resp, body = self.http_client.json_request('GET', url)
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 175, in json_request
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp     resp, body_iter = self._http_request(url, method, **kwargs)
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/glanceclient/common/http.py", line 159, in _http_request
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp     raise exc.from_response(resp)
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp HTTPInternalServerError: HTTPInternalServerError (HTTP 500)
2012-12-18 05:44:00 13792 TRACE cinder.openstack.common.rpc.amqp

 glance-api.log
 ==============
2012-12-18 05:44:00 DEBUG glance.registry.client [3a66ffed-aa79-450a-b235-572bc6a21d89 a24ce67b1a434dc396ee9a4600e00969 4665470fba654e0bb7f4c272d99ad161] Registry request GET /images/45e3f8d7-a389-4a87-89b8-58977e0c5e89 HTTP 200 request id req-dee44a97-9e83-47f0-a5c4-bb9a12f5e676 do_request /usr/lib/python2.6/site-packages/glance/registry/client.py:94
2012-12-18 05:44:00 20434 DEBUG glance.api.middleware.version_negotiation [-] Determining version of request: HEAD /v1/images/45e3f8d7-a389-4a87-89b8-58977e0c5e89 Accept:  process_request /usr/lib/python2.6/site-packages/glance/api/middleware/version_negotiation.py:45
2012-12-18 05:44:00 20434 DEBUG glance.api.middleware.version_negotiation [-] Using url versioning process_request /usr/lib/python2.6/site-packages/glance/api/middleware/version_negotiation.py:58
2012-12-18 05:44:00 20434 DEBUG glance.api.middleware.version_negotiation [-] Matched version: v1 process_request /usr/lib/python2.6/site-packages/glance/api/middleware/version_negotiation.py:70
2012-12-18 05:44:00 20434 DEBUG glance.api.middleware.version_negotiation [-] new uri /v1/images/45e3f8d7-a389-4a87-89b8-58977e0c5e89 process_request /usr/lib/python2.6/site-packages/glance/api/middleware/version_negotiation.py:71
2012-12-18 05:44:00 DEBUG glance.api.policy [fb86f3e9-9403-4dce-a6aa-72ab0b7da9f2 a24ce67b1a434dc396ee9a4600e00969 4665470fba654e0bb7f4c272d99ad161] Loading policy from /etc/glance/policy.json _read_policy_file /usr/lib/python2.6/site-packages/glance/api/policy.py:86
2012-12-18 05:44:00 DEBUG glance.api.policy [fb86f3e9-9403-4dce-a6aa-72ab0b7da9f2 a24ce67b1a434dc396ee9a4600e00969 4665470fba654e0bb7f4c272d99ad161] Loaded policy rules: {u'default': [], u'manage_image_cache': [[u'role:admin']]} load_rules /usr/lib/python2.6/site-packages/glance/api/policy.py:63
2012-12-18 05:44:00 DEBUG glance.common.client [fb86f3e9-9403-4dce-a6aa-72ab0b7da9f2 a24ce67b1a434dc396ee9a4600e00969 4665470fba654e0bb7f4c272d99ad161] Constructed URL: http://0.0.0.0:9191/images/45e3f8d7-a389-4a87-89b8-58977e0c5e89 _construct_url /usr/lib/python2.6/site-packages/glance/common/client.py:464
2012-12-18 05:44:00 DEBUG glance.registry.client [fb86f3e9-9403-4dce-a6aa-72ab0b7da9f2 a24ce67b1a434dc396ee9a4600e00969 4665470fba654e0bb7f4c272d99ad161] Registry request GET /images/45e3f8d7-a389-4a87-89b8-58977e0c5e89 HTTP 200 request id req-5032e3ee-23ec-4bbb-abcd-16705a42e0a6 do_request /usr/lib/python2.6/site-packages/glance/registry/client.py:94
2012-12-18 05:44:00 20434 DEBUG glance.api.middleware.version_negotiation [-] Determining version of request: GET /v2/schemas/image Accept:  process_request /usr/lib/python2.6/site-packages/glance/api/middleware/version_negotiation.py:45
2012-12-18 05:44:00 20434 DEBUG glance.api.middleware.version_negotiation [-] Using url versioning process_request /usr/lib/python2.6/site-packages/glance/api/middleware/version_negotiation.py:58
2012-12-18 05:44:00 20434 DEBUG glance.api.middleware.version_negotiation [-] Matched version: v2 process_request /usr/lib/python2.6/site-packages/glance/api/middleware/version_negotiation.py:70
2012-12-18 05:44:00 20434 DEBUG glance.api.middleware.version_negotiation [-] new uri /v2/schemas/image process_request /usr/lib/python2.6/site-packages/glance/api/middleware/version_negotiation.py:71
2012-12-18 05:44:00 20434 DEBUG glance.api.middleware.version_negotiation [-] Determining version of request: GET /v2/images/45e3f8d7-a389-4a87-89b8-58977e0c5e89 Accept:  process_request /usr/lib/python2.6/site-packages/glance/api/middleware/version_negotiation.py:45
2012-12-18 05:44:00 20434 DEBUG glance.api.middleware.version_negotiation [-] Using url versioning process_request /usr/lib/python2.6/site-packages/glance/api/middleware/version_negotiation.py:58
2012-12-18 05:44:00 20434 DEBUG glance.api.middleware.version_negotiation [-] Matched version: v2 process_request /usr/lib/python2.6/site-packages/glance/api/middleware/version_negotiation.py:70
2012-12-18 05:44:00 20434 DEBUG glance.api.middleware.version_negotiation [-] new uri /v2/images/45e3f8d7-a389-4a87-89b8-58977e0c5e89 process_request /usr/lib/python2.6/site-packages/glance/api/middleware/version_negotiation.py:71
2012-12-18 05:44:00 DEBUG glance.api.policy [8775618b-9059-41e8-a763-23569751284f a24ce67b1a434dc396ee9a4600e00969 4665470fba654e0bb7f4c272d99ad161] Loading policy from /etc/glance/policy.json _read_policy_file /usr/lib/python2.6/site-packages/glance/api/policy.py:86
2012-12-18 05:44:00 DEBUG glance.api.policy [8775618b-9059-41e8-a763-23569751284f a24ce67b1a434dc396ee9a4600e00969 4665470fba654e0bb7f4c272d99ad161] Loaded policy rules: {u'default': [], u'manage_image_cache': [[u'role:admin']]} load_rules /usr/lib/python2.6/site-packages/glance/api/policy.py:63
2012-12-18 05:44:00 20434 INFO sqlalchemy.engine.base.Engine [-] SELECT images.created_at AS images_created_at, images.updated_at AS images_updated_at, images.deleted_at AS images_deleted_at, images.deleted AS images_deleted, images.id AS images_id, images.name AS images_name, images.disk_format AS images_disk_format, images.container_format AS images_container_format, images.size AS images_size, images.status AS images_status, images.is_public AS images_is_public, images.location AS images_location, images.checksum AS images_checksum, images.min_disk AS images_min_disk, images.min_ram AS images_min_ram, images.owner AS images_owner, images.protected AS images_protected, image_properties_1.created_at AS image_properties_1_created_at, image_properties_1.updated_at AS image_properties_1_updated_at, image_properties_1.deleted_at AS image_properties_1_deleted_at, image_properties_1.deleted AS image_properties_1_deleted, image_properties_1.id AS image_properties_1_id, image_properties_1.image_id AS image_properties_1_image_id, image_properties_1.name AS image_properties_1_name, image_properties_1.value AS image_properties_1_value 
FROM images LEFT OUTER JOIN image_properties AS image_properties_1 ON images.id = image_properties_1.image_id 
WHERE images.id = ?
2012-12-18 05:44:00 20434 INFO sqlalchemy.engine.base.Engine [-] (u'45e3f8d7-a389-4a87-89b8-58977e0c5e89',)
2012-12-18 05:44:00 20434 INFO sqlalchemy.engine.base.Engine [-] ROLLBACK

Comment 2 Eoghan Glynn 2012-12-18 13:51:12 UTC
The problem occurs because the sql_connection config option is only set to a mysql URL for the glance-registry.conf, whereas the glance-api.conf remains at the default sqlite URL.

When cinder tries to use the glance v2 API (which is enabled by default), the glance-api service attempts to retrieve the image metadata directly from the DB (as opposed to delegating to the glance-registry service).

Since the sqlite DB has never been initialized, the images table is not found, and sqlalchemy bombs out with an operational exception which is mapped by glance to 500 ServerError response.

Comment 3 Eoghan Glynn 2012-12-18 15:22:45 UTC
This is only a problem in packstack-driven installs, as the glance.pp template does not override the sql_connection config for glance-api.conf.

Comment 4 Eoghan Glynn 2012-12-18 15:32:04 UTC
The issue does not occur when the openstack-glance-api is yum install'd directly (as opposed to being packstack'd), as the spec file sets the config appropriately:

 https://github.com/fedora-openstack/openstack-glance/blob/master/openstack-glance.spec#L115

Comment 5 Eoghan Glynn 2012-12-18 15:33:30 UTC
Pull requests for packstack fix:

  https://github.com/fedora-openstack/packstack/pull/25

and also related puppetlabs-glance fix:

 https://github.com/puppetlabs/puppetlabs-glance/pull/65

Comment 7 Eoghan Glynn 2012-12-18 20:35:37 UTC
The related puppetlabs-glance pull request was also accepted upstream:

  https://github.com/puppetlabs/puppetlabs-glance/commit/b08af59f

Comment 8 Eoghan Glynn 2012-12-20 16:19:31 UTC
Reassigning to derekh for driving brew builds etc.

Comment 9 Yaniv Kaul 2012-12-25 07:22:39 UTC
QE: note that the issue is with packstack and the puppet module installing Cinder, not with Cinder itself.

Comment 12 Nir Magnezi 2013-01-24 10:43:28 UTC
Verified With: openstack-packstack-2012.2.2-0.5.dev318.el6ost.noarch

Followed the steps in Comment #0 - 'Steps to Reproduce' and successfully created a volume.
Nevertheless, While installing OpenStack with packstack - I've reopened bug #885793 - Therefore I had to configure cinder.conf manually.

Comment 13 Derek Higgins 2013-01-28 14:36:28 UTC
The fix attached above needs an addition if the glance and cinder services are running on separate hosts

Fix submitted upstream
https://review.openstack.org/20600

Comment 14 Nir Magnezi 2013-01-28 14:55:08 UTC
Reopening.
I've found that this issue was indeed solved for some topologies, but in case: cinder, glance and keystone are on separated nodes, creating a bootable volume fails:

# wget -c https://launchpad.net/cirros/trunk/0.3.0/+download/cirros-0.3.0-x86_64-disk.img -O //var/tmp/cirros-0.3.0-x86_64-disk.img
# IMAGE_ID=$(glance image-create --name cirros --disk-format qcow2 --container-format bare --is-public 1 < /var/tmp/cirros-0.3.0-x86_64-disk.img | grep 'id' | awk '{print $4}')
# cinder create --image-id $IMAGE_ID 1

ERROR: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-e54f2996-5ce5-4f00-9799-8c02cf7e40a1)

The solution: add glance_host=<glance_host_ip> to cinder.conf

Comment 16 errata-xmlrpc 2013-01-29 11:10:01 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHEA-2013-0204.html

Comment 19 Nir Magnezi 2013-01-31 12:19:57 UTC
Verified With: openstack-packstack-2012.2.2-0.8.dev346.el6ost.noarch

Followed the steps I was trying to execute on Comment #14
1. 'glance_host' was added to cinder.conf
2. I was able to create the volume.

Comment 21 errata-xmlrpc 2013-02-14 18:23:37 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHBA-2013-0260.html