OpenStack Compute (nova)

rebuild with volume attached leaves instance without the volume and in an inconsistent state

Bug #1241615 reported by Dafna Ron on 2013-10-18

This bug affects 4 people

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Compute (nova)	Fix Released	High	Nikola Đipanov	OpenStack Compute (nova) 2014.1 "icehouse"
	Havana	Won't Fix	High	Nikola Đipanov

Bug Description

I created a backup to an instance which had no volume attached.

attached a volume -> rebuild the instance from the backup.

It appears as though the volume is not attached anymore after the rebuild, but if we try to attach it to the same device we get an error that a device is already attached:

2013-10-18 16:54:36.632 2478 DEBUG qpid.messaging [-] RETR[2fca830]: Message(properties={'x-amqp-0-10.routing-key': u'reply_70fb16e321724b38b3d3face4e83f363'}, content={u'oslo.message': u'{"_unique_id": "dd2a85b63c56498c8f2835f9b96e9bb9"
, "failure": null, "_msg_id": "7ce524cebbb34aecab9d608a48103a1c", "result": null, "ending": true}', u'oslo.version': u'2.0'}) _get /usr/lib/python2.6/site-packages/qpid/messaging/endpoints.py:654
2013-10-18 16:54:36.633 2478 DEBUG qpid.messaging.io.ops [-] SENT[2fa6cb0]: MessageFlow(destination='0', unit=0, value=1L, id=serial(5206)) write_op /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:686
2013-10-18 16:54:36.634 2478 DEBUG qpid.messaging.io.ops [-] SENT[2fa6cb0]: SessionCompleted(commands=[0-5199]) write_op /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:686
2013-10-18 16:54:36.639 2478 ERROR nova.openstack.common.rpc.amqp [req-4a884bb4-5ba6-403d-8be7-df1eeebc1324 bbce236d5aac4d1dbc086a8835ed0ebc d09f3bf0f9224affa92ab97010b37270] Exception during message handling
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/amqp.py", line 461, in _process_data
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp **args)
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/dispatcher.py", line 172, in dispatch
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp result = getattr(proxyobj, method)(ctxt, **kwargs)
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/exception.py", line 90, in wrapped
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp payload)
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/exception.py", line 73, in wrapped
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp return f(self, context, *args, **kw)
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 243, in decorated_function
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp pass
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 229, in decorated_function
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 271, in decorated_function
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp e, sys.exc_info())
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 258, in decorated_function
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 3624, in reserve_block_device_name
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp return do_reserve()
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py", line 246, in inner
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp return f(*args, **kwargs)
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 3613, in do_reserve
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp context, instance, bdms, device)
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/utils.py", line 135, in get_device_name_for_instance
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp mappings['root'], device)
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/utils.py", line 217, in get_next_device_name
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp raise exception.DevicePathInUse(path=device)
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp DevicePathInUse: The supplied device path (/dev/vdc) is in use.
2013-10-18 16:54:36.639 2478 TRACE nova.openstack.common.rpc.amqp
2013-10-18 16:54:36.641 2478 ERROR nova.openstack.common.rpc.common [req-4a884bb4-5ba6-403d-8be7-df1eeebc1324 bbce236d5aac4d1dbc086a8835ed0ebc d09f3bf0f9224affa92ab97010b37270] Returning exception The supplied device path (/dev/vdc) is i
n use. to caller
2013-10-18 16:54:36.642 2478 ERROR nova.openstack.common.rpc.common [req-4a884bb4-5ba6-403d-8be7-df1eeebc1324 bbce236d5aac4d1dbc086a8835ed0ebc d09f3bf0f9224affa92ab97010b37270] ['Traceback (most recent call last):\n', ' File "/usr/lib/p
ython2.6/site-packages/nova/openstack/common/rpc/amqp.py", line 461, in _process_data\n **args)\n', ' File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/dispatcher.py", line 172, in dispatch\n result = getattr(proxyo
bj, method)(ctxt, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/nova/exception.py", line 90, in wrapped\n payload)\n', ' File "/usr/lib/python2.6/site-packages/nova/exception.py", line 73, in wrapped\n return f(self, con
text, *args, **kw)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 243, in decorated_function\n pass\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 229, in decorated_function\
n return function(self, context, *args, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 271, in decorated_function\n e, sys.exc_info())\n', ' File "/usr/lib/python2.6/site-packages/nova/compu
te/manager.py", line 258, in decorated_function\n return function(self, context, *args, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 3624, in reserve_block_device_name\n return do_reserve()
\n', ' File "/usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py", line 246, in inner\n return f(*args, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 3613, in do_reserve\n c
ontext, instance, bdms, device)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/utils.py", line 135, in get_device_name_for_instance\n mappings[\'root\'], device)\n', ' File "/usr/lib/python2.6/site-packages/nova/compute/u
tils.py", line 217, in get_next_device_name\n raise exception.DevicePathInUse(path=device)\n', 'DevicePathInUse: The supplied device path (/dev/vdc) is in use.\n']
2013-10-18 16:54:36.642 2478 DEBUG nova.openstack.common.rpc.amqp [req-4a884bb4-5ba6-403d-8be7-df1eeebc1324 bbce236d5aac4d1dbc086a8835ed0ebc d09f3bf0f9224affa92ab97010b37270] UNIQUE_ID is 5d08dde3f40e4186b50e28a9dad5385b. _add_unique_id
/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/amqp.py:341

If I try to attach the same volume to the same instance on a different device it seems to be working, however, when we try to detach it we get the following error:

2013-10-18 16:58:11.288 2478 DEBUG qpid.messaging [-] RCVD[2fca830]: Message(properties={'x-amqp-0-10.routing-key': u'reply_70fb16e321724b38b3d3face4e83f363'}, content={u'oslo.message': u'{"_unique_id": "20a035f66eac46f7b44e8420cd5a2d14"
, "failure": null, "_msg_id": "27d7abfd907146c4a0e052cf067a4d69", "result": null, "ending": true}', u'oslo.version': u'2.0'}) do_message_transfer /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:1295
2013-10-18 16:58:11.289 2478 DEBUG qpid.messaging [-] RETR[2fca830]: Message(properties={'x-amqp-0-10.routing-key': u'reply_70fb16e321724b38b3d3face4e83f363'}, content={u'oslo.message': u'{"_unique_id": "20a035f66eac46f7b44e8420cd5a2d14"
, "failure": null, "_msg_id": "27d7abfd907146c4a0e052cf067a4d69", "result": null, "ending": true}', u'oslo.version': u'2.0'}) _get /usr/lib/python2.6/site-packages/qpid/messaging/endpoints.py:654
2013-10-18 16:58:11.289 2478 DEBUG qpid.messaging.io.ops [-] SENT[2fa6cb0]: MessageFlow(destination='0', unit=0, value=1L, id=serial(5308)) write_op /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:686
2013-10-18 16:58:11.290 2478 DEBUG qpid.messaging.io.ops [-] SENT[2fa6cb0]: SessionCompleted(commands=[0-5301]) write_op /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:686
2013-10-18 16:58:11.296 2478 ERROR nova.openstack.common.rpc.amqp [req-62e56d8a-9dc1-447c-acef-2b2dafdd5079 bbce236d5aac4d1dbc086a8835ed0ebc d09f3bf0f9224affa92ab97010b37270] Exception during message handling
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/amqp.py", line 461, in _process_data
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp **args)
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/dispatcher.py", line 172, in dispatch
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp result = getattr(proxyobj, method)(ctxt, **kwargs)
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/exception.py", line 90, in wrapped
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp payload)
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/exception.py", line 73, in wrapped
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp return f(self, context, *args, **kw)
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 243, in decorated_function
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp pass
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 229, in decorated_function
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 271, in decorated_function
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp e, sys.exc_info())
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 258, in decorated_function
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp return function(self, context, *args, **kwargs)
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 3760, in detach_volume
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp self._detach_volume(context, instance, bdm)
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 3732, in _detach_volume
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp self.volume_api.roll_detaching(context, volume_id)
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 3725, in _detach_volume
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp encryption=encryption)
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 1205, in detach_volume
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp raise exception.DiskNotFound(location=disk_dev)
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp DiskNotFound: No disk at vdc
2013-10-18 16:58:11.296 2478 TRACE nova.openstack.common.rpc.amqp
2013-10-18 16:58:11.298 2478 DEBUG qpid.messaging.io.raw [-] SENT[2fa6cb0]: '\x0f\x01\x00\x19\x00\x01\x00\x00\x00\x00\x00\x00\x04\n\x01\x00\x07\x00\x010\x00\x00\x00\x00\x01\x0f\x00\x00\x1a\x00\x00\x00\x00\x00\x00\x00\x00\x02\n\x01\x00\x0
0\x08\x00\x00\x00\x00\x00\x00\x14\xb5' writeable /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:480
2013-10-18 16:58:14.265 2478 DEBUG qpid.messaging.io.raw [-] READ[2fa6cb0]: '\x0f\x00\x00\x10\x00\x00\x00\x00\x00\x00\x00\x00\x01\n\x00\x00' readable /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:416
2013-10-18 16:58:14.266 2478 DEBUG qpid.messaging.io.ops [-] RCVD[2fa6cb0]: ConnectionHeartbeat() write /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:654
2013-10-18 16:58:14.291 2478 DEBUG qpid.messaging.io.raw [-] READ[2fca998]: '\x0f\x00\x00\x10\x00\x00\x00\x00\x00\x00\x00\x00\x01\n\x00\x00' readable /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:416
2013-10-18 16:58:14.291 2478 DEBUG qpid.messaging.io.ops [-] RCVD[2fca998]: ConnectionHeartbeat() write /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:654
2013-10-18 16:58:15.019 2478 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:176
2013-10-18 16:58:15.024 2478 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:176
2013-10-18 16:58:15.024 2478 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.6/site-packages/nova/openstack/common/periodic_task.py:176
2013-10-18 16:58:15.025 2478 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:166
2013-10-18 16:58:15.025 2478 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:245
2013-10-18 16:58:15.025 2478 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources

Tags:

Nikola Đipanov (ndipanov) on 2013-10-29

tags:	added: volumes
summary:	- rebuild backup which had no volume attach will detach volume in - cinder/nova but not in instance + rebuild with volume attached leaves instance without the volume and in + an inconsistent state
Changed in nova:
milestone:	none → icehouse-1
status:	New → Confirmed
importance:	Undecided → High

Revision history for this message

Nikola Đipanov (ndipanov) wrote on 2013-10-29:

Was able to reproduce this - the issue is that in compute manager's rebuild_instance method does

if bdms is None:
                bdms = self.conductor_api.\
                        block_device_mapping_get_all_by_instance(
                                context, instance)

Which will return the old style (legacy) bdm format if called without legacy=True. Since https://review.openstack.org/#/c/39086/ - it is only possible to pass the new format to _prep_block_device (whcih follows soon after in the control flow of the method) and this causes the volume to be disregarded.

Changed in nova:
assignee:	nobody → Nikola Đipanov (ndipanov)

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2013-10-30: Fix proposed to nova (master)

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

Changed in nova:
status:	Confirmed → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2013-10-30: Fix proposed to nova (stable/havana)

Fix proposed to branch: stable/havana
Review: https://review.openstack.org/54572

Russell Bryant (russellb) on 2013-12-03

Changed in nova:
milestone:	icehouse-1 → icehouse-2

Thierry Carrez (ttx) on 2014-01-22

Changed in nova:
milestone:	icehouse-2 → icehouse-3

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-01-30: Fix proposed to nova (master)

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

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-03-04: Fix merged to nova (master)

Reviewed: https://review.openstack.org/70136
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=effa12e8711ff6e23aa2d4b40f4e9f248e141915
Submitter: Jenkins
Branch: master

commit effa12e8711ff6e23aa2d4b40f4e9f248e141915
Author: Nikola Dipanov <email address hidden>
Date: Thu Jan 30 14:31:11 2014 +0100

Move rebuild to BDM objects

This patch makes the rebuild code path use new-world block device
mapping objects.

    Closes-bug: #1241615
    Part of blueprint: clean-up-legacy-block-device-mapping
    Part of blueprint: icehouse-objects

Change-Id: Id09dba6560b6c0624f9b7fbfa893360a2a3d41b6

Changed in nova:
status:	In Progress → Fix Committed

Thierry Carrez (ttx) on 2014-03-05

Changed in nova:
status:	Fix Committed → Fix Released

Thierry Carrez (ttx) on 2014-04-17

Changed in nova:
milestone:	icehouse-3 → 2014.1

Report a bug

This report contains Public information

Everyone can see this information.

Duplicates of this bug

Bug #1278533

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.