Message timeout leads to inconsistant disk attachments

Bug #1806711 reported by Gary Kotton on 2018-12-04
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Undecided
Gary Kotton

Bug Description

A message timeout causes a disk attachment to fail (which is legit). The problem is that the disk is actually attached to the VM and the rollback does not remove the disk from the VM and only sets the cinder/nova stats as available for the volume.
Subsequent attachments will fail.

Original stack is:

2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] Traceback (most recent call last):
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/virt/block_device.py", line 306, in attach
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] encryption=encryption)
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/virt/vmwareapi/driver.py", line 465, in detach_volume
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] if self._check_vio_import(instance):
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/virt/vmwareapi/driver.py", line 458, in _check_vio_import
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] instance_meta = instance_metadata.InstanceMetadata(instance)
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/api/metadata/base.py", line 141, in __init__
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] self.mappings = _format_instance_mapping(ctxt, instance)
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/api/metadata/base.py", line 700, in _format_instance_mapping
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] ctxt, instance.uuid)
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 177, in wrapper
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] args, kwargs)
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/conductor/rpcapi.py", line 239, in object_class_action_versions
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] args=args, kwargs=kwargs)
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 169, in call
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] retry=self.retry)
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 97, in _send
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] timeout=timeout, retry=retry)
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 458, in send
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] retry=retry)
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 447, in _send
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] result = self._waiter.wait(msg_id, timeout)
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 339, in wait
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] message = self.waiters.get(msg_id, timeout=timeout)
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 238, in get
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] 'to message ID %s' % msg_id)
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9] MessagingTimeout: Timed out waiting for a reply to message ID 1d358510329e41db90e87f6ff5176179
2018-12-03 04:30:58.003 2442 ERROR nova.virt.block_device [instance: 500f5906-1385-4afb-9317-bbab4599dad9]

Subsequent attaches:
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] six.reraise(self.type_, self.value, self.tb)
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/virt/block_device.py", line 273, in attach
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] device_type=self['device_type'], encryption=encryption)
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/virt/vmwareapi/driver.py", line 454, in attach_volume
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] return self._volumeops.attach_volume(connection_info, instance)
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/virt/vmwareapi/volumeops.py", line 431, in attach_volume
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] self._attach_volume_vmdk(connection_info, instance, datastore)
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/virt/vmwareapi/volumeops.py", line 389, in _attach_volume_vmdk
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] vmdk_path=vmdk.path, profile_id=profile_id)
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/virt/vmwareapi/volumeops.py", line 112, in attach_disk_to_vm
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] vm_util.reconfigure_vm(self._session, vm_ref, vmdk_attach_config_spec)
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/virt/vmwareapi/vm_util.py", line 2681, in reconfigure_vm
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] session._wait_for_task(reconfig_task)
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/nova/virt/vmwareapi/driver.py", line 720, in _wait_for_task
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] return self.wait_for_task(task_ref)
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/oslo_vmware/api.py", line 396, in wait_for_task
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] return evt.wait()
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/eventlet/event.py", line 121, in wait
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] return hubs.get_hub().switch()
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 294, in switch
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] return self.greenlet.switch()
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/oslo_vmware/common/loopingcall.py", line 76, in _inner
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] self.f(*self.args, **self.kw)
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] File "/usr/lib/python2.7/dist-packages/oslo_vmware/api.py", line 449, in _poll_task
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] raise task_ex
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] VimFaultException: Failed to add disk 'scsi0:3'.
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9] Faults: ['GenericVmConfigFault']
2018-12-03 08:09:13.528 5325 ERROR nova.compute.manager [instance: 500f5906-1385-4afb-9317-bbab4599dad9]

Gary Kotton (garyk) on 2018-12-04
Changed in nova:
assignee: nobody → Gary Kotton (garyk)
Changed in nova:
status: New → In Progress
tags: added: cinder volumes

Change abandoned by garyk (<email address hidden>) on branch: master
Review: https://review.openstack.org/622207

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

Other bug subscribers