yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1359031] Re: xapi unplug VBD fail for 11 times when boot vm first time.

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Richard Lee <3630034@xxxxxx>
Date: Mon, 25 Aug 2014 03:55:19 -0000
Reply-to: Bug 1359031 <1359031@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
soryy, it is not a bug of openstack. It is because of something wrong
when install domU.

** Changed in: nova
       Status: New => Invalid

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1359031

Title:
  xapi unplug VBD fail for 11 times when boot vm first time.

Status in OpenStack Compute (Nova):
  Invalid

Bug description:
  when i first boot a vm in xenserver, i failed and get the log:
  2014-08-20 12:36:44.161 4352 AUDIT nova.compute.manager [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Starting instance...
  2014-08-20 12:36:44.259 4352 AUDIT nova.compute.claims [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Attempting claim: memory 521 MB, disk 1 GB, VCPUs 1
  2014-08-20 12:36:44.260 4352 AUDIT nova.compute.claims [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Total memory: 32737 MB, used: 512.00 MB
  2014-08-20 12:36:44.260 4352 AUDIT nova.compute.claims [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] memory limit: 49105.50 MB, free: 48593.50 MB
  2014-08-20 12:36:44.260 4352 AUDIT nova.compute.claims [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Total disk: 909 GB, used: 0.00 GB
  2014-08-20 12:36:44.260 4352 AUDIT nova.compute.claims [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] disk limit not specified, defaulting to unlimited
  2014-08-20 12:36:44.261 4352 AUDIT nova.compute.claims [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Total CPUs: 4 VCPUs, used: 0.00 VCPUs
  2014-08-20 12:36:44.261 4352 AUDIT nova.compute.claims [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] CPUs limit not specified, defaulting to unlimited
  2014-08-20 12:36:44.261 4352 AUDIT nova.compute.claims [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Claim successful
  2014-08-20 12:36:47.317 4352 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
  2014-08-20 12:36:47.791 4352 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 31704.0
  2014-08-20 12:36:47.791 4352 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 908
  2014-08-20 12:36:47.791 4352 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 3
  2014-08-20 12:36:47.845 4352 INFO nova.compute.resource_tracker [-] Compute_service record updated for compute2:openstack
  2014-08-20 12:36:56.278 4352 INFO nova.virt.xenapi.vm_utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85 uplug failed with "DEVICE_DETACH_REJECTED", attempt 1/11
  2014-08-20 12:36:57.318 4352 INFO nova.virt.xenapi.vm_utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85 uplug failed with "DEVICE_DETACH_REJECTED", attempt 2/11
  2014-08-20 12:36:58.349 4352 INFO nova.virt.xenapi.vm_utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85 uplug failed with "DEVICE_DETACH_REJECTED", attempt 3/11
  2014-08-20 12:36:59.392 4352 INFO nova.virt.xenapi.vm_utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85 uplug failed with "DEVICE_DETACH_REJECTED", attempt 4/11
  2014-08-20 12:37:00.436 4352 INFO nova.virt.xenapi.vm_utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85 uplug failed with "DEVICE_DETACH_REJECTED", attempt 5/11
  2014-08-20 12:37:01.483 4352 INFO nova.virt.xenapi.vm_utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85 uplug failed with "DEVICE_DETACH_REJECTED", attempt 6/11
  2014-08-20 12:37:02.527 4352 INFO nova.virt.xenapi.vm_utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85 uplug failed with "DEVICE_DETACH_REJECTED", attempt 7/11
  2014-08-20 12:37:03.573 4352 INFO nova.virt.xenapi.vm_utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85 uplug failed with "DEVICE_DETACH_REJECTED", attempt 8/11
  2014-08-20 12:37:04.620 4352 INFO nova.virt.xenapi.vm_utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85 uplug failed with "DEVICE_DETACH_REJECTED", attempt 9/11
  2014-08-20 12:37:05.664 4352 INFO nova.virt.xenapi.vm_utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85 uplug failed with "DEVICE_DETACH_REJECTED", attempt 10/11
  2014-08-20 12:37:06.709 4352 INFO nova.virt.xenapi.vm_utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85 uplug failed with "DEVICE_DETACH_REJECTED", attempt 11/11
  2014-08-20 12:37:06.714 4352 ERROR nova.virt.xenapi.vm_utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] ['OPERATION_NOT_ALLOWED', "VBD '75bd197b-0cbb-77ae-c75d-dbdd849e410b' still attached to 'e12ec469-c001-d64f-1389-84c16644eb68'"]
  2014-08-20 12:37:06.714 4352 TRACE nova.virt.xenapi.vm_utils Traceback (most recent call last):
  2014-08-20 12:37:06.714 4352 TRACE nova.virt.xenapi.vm_utils   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 454, in destroy_vbd
  2014-08-20 12:37:06.714 4352 TRACE nova.virt.xenapi.vm_utils     session.call_xenapi('VBD.destroy', vbd_ref)
  2014-08-20 12:37:06.714 4352 TRACE nova.virt.xenapi.vm_utils   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/client/session.py", line 189, in call_xenapi
  2014-08-20 12:37:06.714 4352 TRACE nova.virt.xenapi.vm_utils     return session.xenapi_request(method, args)
  2014-08-20 12:37:06.714 4352 TRACE nova.virt.xenapi.vm_utils   File "/usr/lib/python2.7/dist-packages/XenAPI.py", line 139, in xenapi_request
  2014-08-20 12:37:06.714 4352 TRACE nova.virt.xenapi.vm_utils     result = _parse_result(getattr(self, methodname)(*full_params))
  2014-08-20 12:37:06.714 4352 TRACE nova.virt.xenapi.vm_utils   File "/usr/lib/python2.7/dist-packages/XenAPI.py", line 209, in _parse_result
  2014-08-20 12:37:06.714 4352 TRACE nova.virt.xenapi.vm_utils     raise Failure(result['ErrorDescription'])
  2014-08-20 12:37:06.714 4352 TRACE nova.virt.xenapi.vm_utils Failure: ['OPERATION_NOT_ALLOWED', "VBD '75bd197b-0cbb-77ae-c75d-dbdd849e410b' still attached to 'e12ec469-c001-d64f-1389-84c16644eb68'"]
  2014-08-20 12:37:06.714 4352 TRACE nova.virt.xenapi.vm_utils 
  2014-08-20 12:37:06.715 4352 ERROR nova.utils [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Failed to spawn, rolling back
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Traceback (most recent call last):
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 504, in _spawn
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     name_label)
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 146, in inner
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     rv = f(*args, **kwargs)
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 345, in create_disks_step
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     disk_image_type, block_device_info=block_device_info)
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 606, in get_vdis_for_instance
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     context, session, instance, name_label, image, image_type)
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1371, in _create_image
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     image_id, image_type)
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1333, in _create_cached_image
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     name_label, image_id, image_type, sr_ref)
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py", line 249, in inner
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     return f(*args, **kwargs)
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1303, in _create_cached_image_impl
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     image_id, image_type)
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1394, in _fetch_image
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     image_id, image_type)
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1598, in _fetch_disk_image
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     with vdi_attached_here(session, vdi_ref, read_only=False) as dev:
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     return self.gen.next()
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 2208, in vdi_attached_here
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     unplug_vbd(session, vbd_ref, this_vm_ref)
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 448, in unplug_vbd
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     % vbd_ref)
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] StorageError: Reached maximum number of retries trying to unplug VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85
  2014-08-20 12:37:06.715 4352 TRACE nova.utils [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] 
  2014-08-20 12:37:06.717 4352 ERROR nova.compute.manager [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Instance failed to spawn
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Traceback (most recent call last):
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/compute/manager.py", line 1738, in _spawn
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     block_device_info)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/driver.py", line 230, in spawn
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     admin_password, network_info, block_device_info)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 357, in spawn
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     network_info, block_device_info, name_label, rescue)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 526, in _spawn
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     undo_mgr.rollback_and_reraise(msg=msg, instance=instance)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/utils.py", line 831, in rollback_and_reraise
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     self._rollback()
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/openstack/common/excutils.py", line 68, in __exit__
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     six.reraise(self.type_, self.value, self.tb)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 504, in _spawn
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     name_label)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 146, in inner
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     rv = f(*args, **kwargs)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 345, in create_disks_step
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     disk_image_type, block_device_info=block_device_info)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 606, in get_vdis_for_instance
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     context, session, instance, name_label, image, image_type)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1371, in _create_image
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     image_id, image_type)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1333, in _create_cached_image
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     name_label, image_id, image_type, sr_ref)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py", line 249, in inner
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     return f(*args, **kwargs)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1303, in _create_cached_image_impl
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     image_id, image_type)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1394, in _fetch_image
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     image_id, image_type)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1598, in _fetch_disk_image
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     with vdi_attached_here(session, vdi_ref, read_only=False) as dev:
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     return self.gen.next()
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 2208, in vdi_attached_here
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     unplug_vbd(session, vbd_ref, this_vm_ref)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 448, in unplug_vbd
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     % vbd_ref)
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] StorageError: Reached maximum number of retries trying to unplug VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85
  2014-08-20 12:37:06.717 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] 
  2014-08-20 12:37:06.916 4352 AUDIT nova.compute.manager [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Terminating instance
  2014-08-20 12:37:06.922 4352 INFO nova.virt.xenapi.vmops [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Destroying VM
  2014-08-20 12:37:06.926 4352 WARNING nova.virt.xenapi.vmops [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] VM is not present, skipping destroy...
  2014-08-20 12:37:06.952 4352 INFO nova.network.neutronv2.api [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Unable to reset device ID for port None
  2014-08-20 12:37:07.195 4352 ERROR nova.compute.manager [req-87219265-8e09-4323-9628-9cedd9478c30 9c97e81761234263822fe08c78faec7a 8112ee970f3047988f37f9e01c107165] [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Error: Reached maximum number of retries trying to unplug VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] Traceback (most recent call last):
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/compute/manager.py", line 1329, in _build_instance
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     set_access_ip=set_access_ip)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/compute/manager.py", line 393, in decorated_function
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     return function(self, context, *args, **kwargs)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/compute/manager.py", line 1741, in _spawn
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     LOG.exception(_('Instance failed to spawn'), instance=instance)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/openstack/common/excutils.py", line 68, in __exit__
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     six.reraise(self.type_, self.value, self.tb)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/compute/manager.py", line 1738, in _spawn
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     block_device_info)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/driver.py", line 230, in spawn
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     admin_password, network_info, block_device_info)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 357, in spawn
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     network_info, block_device_info, name_label, rescue)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 526, in _spawn
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     undo_mgr.rollback_and_reraise(msg=msg, instance=instance)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/utils.py", line 831, in rollback_and_reraise
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     self._rollback()
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/openstack/common/excutils.py", line 68, in __exit__
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     six.reraise(self.type_, self.value, self.tb)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 504, in _spawn
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     name_label)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 146, in inner
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     rv = f(*args, **kwargs)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vmops.py", line 345, in create_disks_step
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     disk_image_type, block_device_info=block_device_info)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 606, in get_vdis_for_instance
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     context, session, instance, name_label, image, image_type)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1371, in _create_image
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     image_id, image_type)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1333, in _create_cached_image
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     name_label, image_id, image_type, sr_ref)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py", line 249, in inner
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     return f(*args, **kwargs)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1303, in _create_cached_image_impl
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     image_id, image_type)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1394, in _fetch_image
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     image_id, image_type)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 1598, in _fetch_disk_image
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     with vdi_attached_here(session, vdi_ref, read_only=False) as dev:
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     return self.gen.next()
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 2208, in vdi_attached_here
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     unplug_vbd(session, vbd_ref, this_vm_ref)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]   File "/usr/local/lib/python2.7/dist-packages/nova/virt/xenapi/vm_utils.py", line 448, in unplug_vbd
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6]     % vbd_ref)
  2014-08-20 12:37:07.195 4352 TRACE nova.compute.manager [instance: 3ea9d91c-6997-4fd1-bed5-297a4712bac6] StorageError: Reached maximum number of retries trying to unplug VBD OpaqueRef:cafa4730-c623-9c60-a3cb-734e40722e85
  my nova-compute version is 2014.1.2 and XenServer is 6.2 SP1

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1359031/+subscriptions
References

[Bug 1359031] [NEW] xapi unplug VBD fail for 11 times when boot vm first time.
From: Richard Lee, 2014-08-20