XenAPI: resolve the failure VM_MISSING_PV_DRIVERS for PV VM

[Jianghua Wang]

When testing: tempest.api.compute.volumes.test_attach_volume.AttachVolumeTestJSON.test_attach_detach_volume
observed the error of "VM_MISSING_PV_DRIVERS"; But actually the VM does have PV drivers installed.

2017-10-25 02:17:29.566 ^[[01;31mERROR nova.virt.xenapi.vm_utils [^[[01;36mreq-7997faf5-5d5b-4312-a7c6-d5a45d431526 ^[[00;36mtempest-ServerActionsTestJSON-1628628303 tempest-ServerActionsTestJSON-1628628303^[[01;31m] ^[[01;35m^[[01;31mUnable to unplug VBD^[[00m^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00mTraceback (most recent call last):^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m File "/opt/stack/nova/nova/virt/xenapi/vm_utils.py", line 333, in unplug_vbd^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m greenthread.sleep(1)^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m File "/opt/stack/nova/nova/virt/xenapi/client/objects.py", line 94, in unplug^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m synchronized_unplug()^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 271, in inner^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m return f(*args, **kwargs)^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m File "/opt/stack/nova/nova/virt/xenapi/client/objects.py", line 89, in synchronized_unplug^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m self._call_method("unplug", vbd_ref)^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m File "/opt/stack/nova/nova/virt/xenapi/client/objects.py", line 59, in _call_method^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m return self.session.call_xenapi(call, *args)^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m File "/opt/stack/nova/nova/virt/xenapi/client/session.py", line 197, in call_xenapi^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m return session.xenapi_request(method, args)^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/XenAPI.py", line 133, in xenapi_request^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m result = _parse_result(getattr(self, methodname)(*full_params))^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/XenAPI.py", line 203, in _parse_result^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m raise Failure(result['ErrorDescription'])^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00mFailure: ['VM_MISSING_PV_DRIVERS', 'OpaqueRef:269c1940-69fd-c549-ed1d-1aefe725b967']^M
^[[01;31m2017-10-25 02:17:29.566 TRACE nova.virt.xenapi.vm_utils ^[[01;35m^[[00m^M

[Jianghua Wang (wjh-fresh)]

Per the analysis, it's a race condition. the unplug is done just after VM rebooting. It requires some time for PV driver loading.
Oct 25 02:04:26 xrtmia-03-08 xapi: [debug|xrtmia-03-08|105281 INET :::80|VBD.unplug R:358ec0d48f9a|xapi] Caught exception while marking VBD for VBD.unplug in message forwarder: VM_MISSING_PV_DRIVERS: [ OpaqueRef:9f79eef0-c5bc-6d0f-e2ef-e43f5557fff0 ]

The PV drivers were fully connected 2 seconds later:
xenstored-access.log:Oct 25 02:04:28 xrtmia-03-08 oxenstored: D0.62 write backend/vbd/8/832/state 4

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/514902
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=e18608d579ac28b3d30879d6e375f0c89a3e4ef1
Submitter: Zuul
Branch: master

commit e18608d579ac28b3d30879d6e375f0c89a3e4ef1
Author: Jianghua Wang <email address hidden>
Date: Wed Oct 25 03:04:16 2017 +0000

    XenAPI: resolve VBD unplug failure with VM_MISSING_PV_DRIVERS error

    The virtual block device(VBD) hot unplugging should be done when VM has
    paravirtualization(PV) driver installed. But we observed failures with
    VM_MISSING_PV_DRIVERS error on a real PV VM sometime.

    Actually it's a race condition. At VM booting, it needs some time for
    the PV driver to be connected. If the VBD.unplug operation goes before
    the PV driver connected to xen, it will failed with VM_MISSING_PV_DRIVERS.

    The fix is to retry unplug. If really there is no PV driver installed in
    VM, failed after the attempts.

    Change-Id: I6b788ba24aa3e7c061dac06c52570ff3818bc91a
    Closes-Bug: #1727134

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 17.0.0.0b2 development milestone.