Launching instance that creates a new volume fails

[LnxSlck]

I'm trying to launch instances from Horizon using the option Boot form image - Creates a new volume.

The instance fails with block_device_mapping ERROR.

On the controller cinder/api.log and cinder/volume.log shows no error or relevant information.

On the compute node, nova-compute.log does show the problem:

2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] Traceback (most recent call last):
2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1819, in _prep_block_device
2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] do_check_attach=do_check_attach) +
2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 407, in attach_block_devices
2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] map(_log_and_attach, block_device_mapping)
2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 405, in _log_and_attach
2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] bdm.attach(*attach_args, **attach_kwargs)
2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 333, in attach
2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] wait_func(context, vol['id'])
2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1263, in _await_block_device_map_created
2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] attempts=attempts)
2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] VolumeNotCreated: Volume abc781af-0960-4a65-87d2-a5cb15ce7273 did not finish being created even after we waited 250 seconds or 61 attempts.
2015-03-11 11:23:02.807 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c]
2015-03-11 11:23:02.809 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] Traceback (most recent call last):
2015-03-11 11:23:02.809 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2218, in _build_resources
2015-03-11 11:23:02.809 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] block_device_mapping)
2015-03-11 11:23:02.809 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1847, in _prep_block_device
2015-03-11 11:23:02.809 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] raise exception.InvalidBDM()
2015-03-11 11:23:02.809 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] InvalidBDM: Block Device Mapping is Invalid.
2015-03-11 11:23:02.809 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c]
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] Traceback (most recent call last):
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2030, in _do_build_and_run_instance
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] filter_properties)
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2129, in _build_and_run_instance
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] 'create.error', fault=e)
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 82, in __exit__
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] six.reraise(self.type_, self.value, self.tb)
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2102, in _build_and_run_instance
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] block_device_mapping) as resources:
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] return self.gen.next()
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2240, in _build_resources
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] reason=msg)
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c] BuildAbortException: Build of instance 2da2594d-e162-45ce-98b0-54d9563bbb1c aborted: Failure prepping block device.
2015-03-11 11:23:02.848 72172 TRACE nova.compute.manager [instance: 2da2594d-e162-45ce-98b0-54d9563bbb1c]

A new volume is created, and sometimes an IP gets assigned to the instance, other times it doesn't.

If i launch an instance choosing option Boot from image or simply boot from volume it works, the problems seems to be when it creates a new volume.

openstack --version
openstack 1.0.1
CentOS 7 64bits

storage mounted through nfs (wich seems to be working just fine)

Steps to reproduce the error

1 - Have storage through nfs
2 - Go to Horizon, Instances - Launch Instance - Boot form image - Creates a new volume
3 - Choose a Windows image (or an image that big)

[jichenjc (jichenjc)]

e162-45ce-98b0-54d9563bbb1c] VolumeNotCreated: Volume abc781af-0960-4a65-87d2-a5cb15ce7273 did not finish being created even after we waited 250 seconds or 61 attempts.

from this line, it indicated that create volume failed , nova did all he can do.
 you need to check whether something wrong in cinder from cinder api or other logs , please attach it , thanks

[jichenjc (jichenjc)]

oops, I missed API log you mentioned, so additional suggestion is please check other cinder logs
also, please confirm your settings and please attach your compute logs since there might be some helpful info.. thanks

[LnxSlck (brunomiguelqueiros)]

@jichenjc Thank you for your help on this. I'm attaching the cinder logs (api, volume and scheduler) and also the nova compute log. I did a test right now and the problem remains.

The weirdest thing is that, i can create a volume, attach an image to it, and the instance is OK, the only thing that is failing is when i choose the options (creates a new volume)

[Jon Bernard (jbernard)]

I hit a very similar failure yesterday, I have distinct hunch that the problem lies in Nova but I have yet to confirm that suspecion. I'll post additional info here if I can capture it.

[Jon Bernard (jbernard)]

Well, I might be wrong about my previous comment. Here's what I'm seeing:

I'm booting a volume-backed instance from an image stored in glance. Upon issuing the the nova-boot command, a cinder volume is created and the image is requested from glance. The cinder volume state becomes 'downloading'. It appears the the glance image request fails:

glance.registry.client.v1.client Registry client request GET /images/cirros-0.3.2-x86_64-uec raised NotFound
glance.registry.client.v1.client Traceback (most recent call last):
glance.registry.client.v1.client File "/opt/stack/glance/glance/registry/client/v1/client.py", line 117, in do_request
glance.registry.client.v1.client **kwargs)
glance.registry.client.v1.client File "/opt/stack/glance/glance/common/client.py", line 71, in wrapped
glance.registry.client.v1.client return func(self, *args, **kwargs)
glance.registry.client.v1.client File "/opt/stack/glance/glance/common/client.py", line 376, in do_request
glance.registry.client.v1.client headers=copy.deepcopy(headers))
glance.registry.client.v1.client File "/opt/stack/glance/glance/common/client.py", line 88, in wrapped
glance.registry.client.v1.client return func(self, method, url, body, headers)
glance.registry.client.v1.client File "/opt/stack/glance/glance/common/client.py", line 523, in _do_request
glance.registry.client.v1.client raise exception.NotFound(res.read())
glance.registry.client.v1.client NotFound: 404 Not Found
glance.registry.client.v1.client
glance.registry.client.v1.client The resource could not be found.

Cinder appears to not recognize the glance error, no exception is logged, and the volume remains in the 'downloading' state until nova times out the instance create request. And then we see:

nova.compute.manager Instance failed block device setup
nova.compute.manager Traceback (most recent call last):
nova.compute.manager File "/opt/stack/nova/nova/compute/manager.py", line 1906, in _prep_block_device
nova.compute.manager do_check_attach=do_check_attach) +
nova.compute.manager File "/opt/stack/nova/nova/virt/block_device.py", line 431, in attach_block_devices
nova.compute.manager map(_log_and_attach, block_device_mapping)
nova.compute.manager File "/opt/stack/nova/nova/virt/block_device.py", line 429, in _log_and_attach
nova.compute.manager bdm.attach(*attach_args, **attach_kwargs)
nova.compute.manager File "/opt/stack/nova/nova/virt/block_device.py", line 342, in attach
nova.compute.manager wait_func(context, vol['id'])
nova.compute.manager File "/opt/stack/nova/nova/compute/manager.py", line 1349, in _await_block_device_map_created
nova.compute.manager attempts=attempts)
nova.compute.manager VolumeNotCreated: Volume f8930f58-5c7e-4fc4-aae4-1cd68968807b did not finish being created even after we waited 190 seconds or 61 attempts.
nova.compute.manager
nova.compute.manager Traceback (most recent call last):
nova.compute.manager File "/opt/stack/nova/nova/compute/manager.py", line 2373, in _build_resources
nova.compute.manager block_device_mapping)
nova.compute.manager File "/opt/stack/nova/nova/compute/manager.py", line 1934, in _prep_bl...

[Jon Bernard (jbernard)]

I later see cinder-volume's taskflow job for volume creation complete successfully, and the volumes enters the 'available' state.

[Jon Bernard (jbernard)]

Creating a volume from the same image using cinderclient appears to work fine. If anyone has ideas on where to start looking or things to test, please let me know.

[Jon Bernard (jbernard)]

Also, the exact same nova-boot command succeeds later on, volume is created and instance boots.

[Sean McGinnis (sean-mcginnis)]

Closing stale bug. This has be Incomplete status for over 90 days. If this is still an issue please reopen.