nova-compute intermittently fail to detach vbd

Bug #999953 reported by Armando Migliaccio on 2012-05-15
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Undecided
Armando Migliaccio
Essex
Undecided
Unassigned

Bug Description

Steps to reproduce:
Spawn multiple instances, using XenServer

What you see:
Some will boot, some don't. You'll find many ephemeral disks attached to the compute domU(s)

What you'd expect:
all of them will start.

Nova release: 2012.1-0ubuntu2.1

There is a retry logic to handle with this, but it wrongly expect a XenAPI.Failure exception whilst the unplug_vbd method raises a StorageError exception. The problem does not occur on Folsom trunk, and a fix would be needed to be ported to Essex/Stable

stack-trace from nova-compute:

2012-05-14 17:20:14 ERROR nova.virt.xenapi.vm_utils [req-ab3c1b32-8208-4ba6-9791-2040518e2a59 7cbacc62f59b41faacd3fc75ba5bbb70 5b8dacd7169e4273956d36b6d791c5c8] ['DEVICE_DETACH_REJECTED', 'VBD', 'OpaqueRef:cee99ae2-db47-d7a3-ba86-005ed98652c9', '16 Device in use; refusing to close']
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils Traceback (most recent call last):
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 251, in unplug_vbd
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils vbd_ref = session.call_xenapi('VBD.unplug', vbd_ref)
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi_conn.py", line 574, in call_xenapi
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils return tpool.execute(f, *args)
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils File "/usr/lib/python2.7/dist-packages/eventlet/tpool.py", line 76, in tworker
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils rv = meth(*args,**kwargs)
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils File "/usr/local/lib/python2.7/dist-packages/XenAPI-1.2-py2.7.egg/XenAPI.py", line 229, in __call__
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils return self.__send(self.__name, args)
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils File "/usr/local/lib/python2.7/dist-packages/XenAPI-1.2-py2.7.egg/XenAPI.py", line 133, in xenapi_request
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils result = _parse_result(getattr(self, methodname)(*full_params))
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils File "/usr/local/lib/python2.7/dist-packages/XenAPI-1.2-py2.7.egg/XenAPI.py", line 203, in _parse_result
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils raise Failure(result['ErrorDescription'])
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils Failure: ['DEVICE_DETACH_REJECTED', 'VBD', 'OpaqueRef:cee99ae2-db47-d7a3-ba86-005ed98652c9', '16 Device in use; refusing to close']
2012-05-14 17:20:14 TRACE nova.virt.xenapi.vm_utils
2012-05-14 17:20:15 ERROR nova.virt.xenapi.vm_utils [req-ab3c1b32-8208-4ba6-9791-2040518e2a59 7cbacc62f59b41faacd3fc75ba5bbb70 5b8dacd7169e4273956d36b6d791c5c8] ['OPERATION_NOT_ALLOWED', "VBD '32654e4b-0128-109d-5fdb-1789acb3063c' still attached to '5961429b-a9d7-6334-eedc-daf612719438'"]
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils Traceback (most recent call last):
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 262, in destroy_vbd
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils session.call_xenapi('VBD.destroy', vbd_ref)
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi_conn.py", line 574, in call_xenapi
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils return tpool.execute(f, *args)
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils File "/usr/lib/python2.7/dist-packages/eventlet/tpool.py", line 76, in tworker
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils rv = meth(*args,**kwargs)
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils File "/usr/local/lib/python2.7/dist-packages/XenAPI-1.2-py2.7.egg/XenAPI.py", line 229, in __call__
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils return self.__send(self.__name, args)
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils File "/usr/local/lib/python2.7/dist-packages/XenAPI-1.2-py2.7.egg/XenAPI.py", line 133, in xenapi_request
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils result = _parse_result(getattr(self, methodname)(*full_params))
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils File "/usr/local/lib/python2.7/dist-packages/XenAPI-1.2-py2.7.egg/XenAPI.py", line 203, in _parse_result
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils raise Failure(result['ErrorDescription'])
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils Failure: ['OPERATION_NOT_ALLOWED', "VBD '32654e4b-0128-109d-5fdb-1789acb3063c' still attached to '5961429b-a9d7-6334-eedc-daf612719438'"]
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils
2012-05-14 17:20:15 DEBUG nova.virt.xenapi.vm_utils [req-ab3c1b32-8208-4ba6-9791-2040518e2a59 7cbacc62f59b41faacd3fc75ba5bbb70 5b8dacd7169e4273956d36b6d791c5c8] Destroying VBD for VDI OpaqueRef:8c08b3bd-ff20-8975-d9e5-d94099341416 done. from (pid=2782) vdi_attached_here /usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py:1487
2012-05-14 17:20:15 ERROR nova.virt.xenapi.vm_utils [req-ab3c1b32-8208-4ba6-9791-2040518e2a59 7cbacc62f59b41faacd3fc75ba5bbb70 5b8dacd7169e4273956d36b6d791c5c8] ['VDI_IN_USE', 'OpaqueRef:8c08b3bd-ff20-8975-d9e5-d94099341416']
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils Traceback (most recent call last):
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 295, in destroy_vdi
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils session.call_xenapi('VDI.destroy', vdi_ref)
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi_conn.py", line 574, in call_xenapi
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils return tpool.execute(f, *args)
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils File "/usr/lib/python2.7/dist-packages/eventlet/tpool.py", line 76, in tworker
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils rv = meth(*args,**kwargs)
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils File "/usr/local/lib/python2.7/dist-packages/XenAPI-1.2-py2.7.egg/XenAPI.py", line 229, in __call__
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils return self.__send(self.__name, args)
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils File "/usr/local/lib/python2.7/dist-packages/XenAPI-1.2-py2.7.egg/XenAPI.py", line 133, in xenapi_request
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils result = _parse_result(getattr(self, methodname)(*full_params))
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils File "/usr/local/lib/python2.7/dist-packages/XenAPI-1.2-py2.7.egg/XenAPI.py", line 203, in _parse_result
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils raise Failure(result['ErrorDescription'])
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils Failure: ['VDI_IN_USE', 'OpaqueRef:8c08b3bd-ff20-8975-d9e5-d94099341416']
2012-05-14 17:20:15 TRACE nova.virt.xenapi.vm_utils
2012-05-14 17:20:15 ERROR nova.utils [req-ab3c1b32-8208-4ba6-9791-2040518e2a59 7cbacc62f59b41faacd3fc75ba5bbb70 5b8dacd7169e4273956d36b6d791c5c8] Original exception being dropped
2012-05-14 17:20:15 TRACE nova.utils Traceback (most recent call last):
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 530, in _generate_disk
2012-05-14 17:20:15 TRACE nova.utils run_as_root=True)
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-05-14 17:20:15 TRACE nova.utils self.gen.next()
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1480, in vdi_attached_here
2012-05-14 17:20:15 TRACE nova.utils vbd_unplug_with_retry(session, vbd_ref)
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1497, in vbd_unplug_with_retry
2012-05-14 17:20:15 TRACE nova.utils VMHelper.unplug_vbd(session, vbd_ref)
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 256, in unplug_vbd
2012-05-14 17:20:15 TRACE nova.utils _('Unable to unplug VBD %s') % vbd_ref)
2012-05-14 17:20:15 TRACE nova.utils StorageError: Unable to unplug VBD OpaqueRef:cee99ae2-db47-d7a3-ba86-005ed98652c9
2012-05-14 17:20:15 TRACE nova.utils
2012-05-14 17:20:15 ERROR nova.utils [req-ab3c1b32-8208-4ba6-9791-2040518e2a59 7cbacc62f59b41faacd3fc75ba5bbb70 5b8dacd7169e4273956d36b6d791c5c8] Instance aa386b2c-401a-4029-8a57-3d0eec11f7a5: Failed to spawn, rolling back.
2012-05-14 17:20:15 TRACE nova.utils Traceback (most recent call last):
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 349, in spawn
2012-05-14 17:20:15 TRACE nova.utils vm_ref = create_vm_step(undo_mgr, vdis, kernel_file, ramdisk_file)
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 138, in inner
2012-05-14 17:20:15 TRACE nova.utils rv = f(*args, **kwargs)
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 312, in create_vm_step
2012-05-14 17:20:15 TRACE nova.utils ramdisk_file=ramdisk_file)
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 419, in _create_vm
2012-05-14 17:20:15 TRACE nova.utils vdis)
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 491, in _attach_disks
2012-05-14 17:20:15 TRACE nova.utils vm_ref, userdevice, ephemeral_gb)
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 554, in generate_ephemeral
2012-05-14 17:20:15 TRACE nova.utils FLAGS.default_ephemeral_format)
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 537, in _generate_disk
2012-05-14 17:20:15 TRACE nova.utils cls.destroy_vdi(session, vdi_ref)
2012-05-14 17:20:15 TRACE nova.utils File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 299, in destroy_vdi
2012-05-14 17:20:15 TRACE nova.utils _('Unable to destroy VDI %s') % vdi_ref)
2012-05-14 17:20:15 TRACE nova.utils StorageError: Unable to destroy VDI OpaqueRef:8c08b3bd-ff20-8975-d9e5-d94099341416
2012-05-14 17:20:15 TRACE nova.utils
2012-05-14 17:20:15 DEBUG nova.virt.xenapi.vmops [req-ab3c1b32-8208-4ba6-9791-2040518e2a59 7cbacc62f59b41faacd3fc75ba5bbb70 5b8dacd7169e4273956d36b6d791c5c8] Removing VDI OpaqueRef:e1755a26-3f80-bf23-bf0d-85dfcb3b00e7(uuid:d642424e-523f-4e6a-9234-0b0e262c52f7) from (pid=2782) undo_create_disks /usr/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py:274
2012-05-14 17:20:15 ERROR nova.compute.manager [req-ab3c1b32-8208-4ba6-9791-2040518e2a59 7cbacc62f59b41faacd3fc75ba5bbb70 5b8dacd7169e4273956d36b6d791c5c8] [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] Instance failed to spawn
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] Traceback (most recent call last):
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 592, in _spawn
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] self._legacy_nw_info(network_info), block_device_info)
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi_conn.py", line 184, in spawn
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] self._vmops.spawn(context, instance, image_meta, network_info)
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 359, in spawn
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] undo_mgr.rollback_and_reraise(msg=msg)
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/dist-packages/nova/utils.py", line 1714, in rollback_and_reraise
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] self._rollback()
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] self.gen.next()
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 349, in spawn
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] vm_ref = create_vm_step(undo_mgr, vdis, kernel_file, ramdisk_file)
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 138, in inner
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] rv = f(*args, **kwargs)
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 312, in create_vm_step
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] ramdisk_file=ramdisk_file)
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 419, in _create_vm
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] vdis)
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 491, in _attach_disks
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] vm_ref, userdevice, ephemeral_gb)
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 554, in generate_ephemeral
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] FLAGS.default_ephemeral_format)
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 537, in _generate_disk
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] cls.destroy_vdi(session, vdi_ref)
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] File "/usr/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 299, in destroy_vdi
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] _('Unable to destroy VDI %s') % vdi_ref)
2012-05-14 17:20:15 TRACE nova.compute.manager [instance: aa386b2c-401a-4029-8a57-3d0eec11f7a5] StorageError: Unable to destroy VDI OpaqueRef:8c08b3bd-ff20-8975-d9e5-d94099341416

Related branches

Changed in nova:
assignee: nobody → Armando Migliaccio (armando-migliaccio)

this duplicates this bug: #960655

Changed in nova:
status: New → Invalid

Reviewed: https://review.openstack.org/7551
Committed: http://github.com/openstack/nova/commit/1a838e2e99a75a7fb245ae9f46c57fc0fc507fd4
Submitter: Jenkins
Branch: stable/essex

commit 1a838e2e99a75a7fb245ae9f46c57fc0fc507fd4
Author: Armando Migliaccio <email address hidden>
Date: Thu May 17 18:34:58 2012 +0100

    bug #999953 xenapi driver intermittently fail to detach vbd

    ensure that unplug_vbd raises XenAPI.Failure as required by
    vbd_unplug_with_retry(session, vbd_ref).

    Change-Id: If689da4ebc5d9042f26c765afb02ae611967a66b

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers