can't boot a volume from a volume that has been created from a snapshot

[Yogev Rabl]

Description of problem:
A volume that has been created from a snapshot of a volume failed to boot an instance with the following error:

2014-03-12 18:03:39.790 9573 ERROR nova.compute.manager [req-f67dabd7-f013-483a-a386-d5a511b86be7 1654b1a85ba647df87fc9258962949fb 87761b8cc7d34be29063ad24073b2172] [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] Instance failed block d
evice setup
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] Traceback (most recent call last):
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1387, in _prep_block_device
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] self._await_block_device_map_created) +
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] File "/usr/lib/python2.6/site-packages/nova/virt/block_device.py", line 283, in attach_block_devices
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] block_device_mapping)
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] File "/usr/lib/python2.6/site-packages/nova/virt/block_device.py", line 170, in attach
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] connector)
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] File "/usr/lib/python2.6/site-packages/nova/volume/cinder.py", line 176, in wrapper
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] res = method(self, ctx, volume_id, *args, **kwargs)
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] File "/usr/lib/python2.6/site-packages/nova/volume/cinder.py", line 274, in initialize_connection
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] connector)
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] File "/usr/lib/python2.6/site-packages/cinderclient/v1/volumes.py", line 321, in initialize_connection
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] {'connector': connector})[1]['connection_info']
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] File "/usr/lib/python2.6/site-packages/cinderclient/v1/volumes.py", line 250, in _action
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] return self.api.client.post(url, body=body)
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] File "/usr/lib/python2.6/site-packages/cinderclient/client.py", line 210, in post
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] return self._cs_request(url, 'POST', **kwargs)
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] File "/usr/lib/python2.6/site-packages/cinderclient/client.py", line 174, in _cs_request
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] **kwargs)
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] File "/usr/lib/python2.6/site-packages/cinderclient/client.py", line 157, in request
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] raise exceptions.from_response(resp, body)
2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-e990ac94-97d9-41f3-b1e1-ca63e7d1d2bc)

2014-03-12 18:03:40.289 9573 ERROR nova.openstack.common.rpc.amqp [req-f67dabd7-f013-483a-a386-d5a511b86be7 1654b1a85ba647df87fc9258962949fb 87761b8cc7d34be29063ad24073b2172] Exception during message handling
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/amqp.py", line 461, in _process_data
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp **args)
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/dispatcher.py", line 172, in dispatch
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp result = getattr(proxyobj, method)(ctxt, **kwargs)
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/exception.py", line 90, in wrapped
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp payload)
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/exception.py", line 73, in wrapped
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp return f(self, context, *args, **kw)
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 243, in decorated_function
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp pass
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 229, in decorated_function
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 294, in decorated_function
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp function(self, context, *args, **kwargs)
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 271, in decorated_function
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp e, sys.exc_info())
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 258, in decorated_function
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1630, in run_instance
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp do_run_instance()
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py", line 246, in inner
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp return f(*args, **kwargs)
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1629, in do_run_instance
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp legacy_bdm_in_spec)
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 968, in _run_instance
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp notify("error", msg=unicode(e)) # notify that build failed
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 952, in _run_instance
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp instance, image_meta, legacy_bdm_in_spec)
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1081, in _build_instance
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp LOG.exception(msg, instance=instance)
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1034, in _build_instance
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp context, instance, bdms)
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1409, in _prep_block_device
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp raise exception.InvalidBDM()
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp InvalidBDM: Block Device Mapping is Invalid.
2014-03-12 18:03:40.289 9573 TRACE nova.openstack.common.rpc.amqp

Version-Release number of selected component (if applicable):
python-novaclient-2.15.0-3.el6ost.noarch
python-nova-2013.2.2-2.el6ost.noarch
openstack-nova-common-2013.2.2-2.el6ost.noarch
openstack-nova-compute-2013.2.2-2.el6ost.noarch
python-cinderclient-1.0.7-2.el6ost.noarch
openstack-cinder-2013.2.2-2.el6ost.noarch
python-cinder-2013.2.2-2.el6ost.noarch

How reproducible:
100%

Steps to Reproduce:
1. install OS to a volume.
2. create a snapshot of the volume.
3. create a volume from the snapshot.
4. boot an instance from the volume.

Actual results:
the instance fail to boot.

Expected results:
the instance should boot.

[Yogev Rabl (yrabl)]

additional info:
- The Cinder's back end is GlusterFS.
- The env. topology is:
* Cloud controller server (nova services) + compute node.
* Stand alone compute node.
* Stand alone Cinder.
* Stand alone Glance.

[Nikola Đipanov (ndipanov)]

@yrabl - I was unable to reproduce this with trunk on eba85d7. I am thinking that maybe you did not wait for the newly created volume in your setup in step 3 to become available?

[Yogev Rabl (yrabl)]

@ndipanov - Step 4 was after the volume was in state of 'available'.

[Thang Pham (thang-pham)]

I cannot reproduce the bug described here. I was able to successfully:
    1. Install an OS to a volume
    2. Create a snapshot of that volume
    3. Create a volume from the snapshot
    4. Boot an instance from the volume (based off of the snapshot)
Could you check on your compute node that the gluster volume is mounted (via "mount" output)? Is the network between the computer - cinder - glance node active?

[Yogev Rabl (yrabl)]

There's no networking problem between the compute, Cinder, Glance and the GlusterFS. In addition other instances are working and are being booted from other volumes.

[Nikola Đipanov (ndipanov)]

So are you confirming that you are still seeing this issue with the latest master?

Two different people have been unable to reproduce it thus far. If it is indeed happening again - I will try to reproduce one more time, but if that comes back negative - I'm afraid there is not much we can do.

[Nikola Đipanov (ndipanov)]

Also looking at the packages you are using - this seems to be affecting Havana, not master/icehouse. If we can confirm that it's gone in Icehouse, we might be able to easily backport the patch that takes care of this.

[Yogev Rabl (yrabl)]

No, I will not need to test a bug on a newest version, in addition, Ice house is not as stable for me to create the same topology with the packstack, at the moment.

[Eric Harney (eharney)]

Since the Nova log shows an error from cinderclient:

2014-03-12 18:03:39.790 9573 TRACE nova.compute.manager [instance: 9f1a00b6-4b88-431e-a163-feaf06e0bfe3] ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-e990ac94-97d9-41f3-b1e1-ca63e7d1d2bc)

What do the Cinder server logs say for this request?

[Kanagaraj Manickam (kanagaraj-manickam)]

it could be because, cinder-api wsgi module is not
responding while cinder-api paste server reports
this kind of exception.

NOTE: The same error is being reported from nova
sometime, i see in the horizon while creating
the instance.

[Taras (shapovalovts)]

On such error in compute.log:

 "The server has either erred or is incapable of performing the requested operation"

it makes sense to check /var/log/cinder/api.log.

[Tracy Jones (tjones-i)]

please post the cinder/api logs.

[Sean Dague (sdague)]

3 months in Incomplete status waiting for info.

[Blane Bramble (blane)]

Just had a similar issue and a search led me here. In my case it turned out to be Cinder reporting an out of memory error. Restarting Cinder on the controller node cleared the issue.