Bug 1283287

Summary: Failed to hot unplug disk in VDSM which runs Python <= 2.7
Product: [oVirt] vdsm Reporter: Raz Tamir <ratamir>
Component: GeneralAssignee: Amit Aviram <aaviram>
Status: CLOSED CURRENTRELEASE QA Contact: Raz Tamir <ratamir>
Severity: urgent Docs Contact:
Priority: urgent    
Version: 4.16.29CC: amarchuk, amureini, bugs, danken, eedri, fdeutsch, gklein, ratamir, tnisan, ylavi
Target Milestone: ovirt-3.5.6Keywords: Automation, Regression
Target Release: 4.16.30Flags: rule-engine: ovirt-3.5.z+
rule-engine: blocker+
ylavi: planning_ack+
tnisan: devel_ack+
acanan: testing_ack+
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: storage
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-12-22 13:26:05 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Storage RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
engine log
none
vdsm rhevh 6.7
none
vdsm log rhel 6.7
none
rpm -qa none

Description Raz Tamir 2015-11-18 15:36:48 UTC
Description of problem:
When trying to hotunplug disk from vm with OS installed, I get the error :Failed to unplug disk X"
Occurs only on 3.5 environment

From vdsm log RHEL6.7:

Thread-128617::DEBUG::2015-11-18 17:29:24,099::libvirtconnection::151::root::(wrapper) Unknown libvirterror: ecode: 8 edom: 10 level: 2 message: invalid argument: invalid path: vdb
Thread-128617::ERROR::2015-11-18 17:29:24,099::sampling::488::vm.Vm::(collect) vmId=`091cb939-cb03-441d-b8d1-f241a10df67f`::Stats function failed: <AdvancedStatsFunction _sampleDisk at 0x1ef96f8>
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/sampling.py", line 484, in collect
    statsFunction()
  File "/usr/share/vdsm/virt/sampling.py", line 359, in __call__
    retValue = self._function(*args, **kwargs)
  File "/usr/share/vdsm/virt/vm.py", line 326, in _sampleDisk
    diskSamples[vmDrive.name] = self._vm._dom.blockStats(vmDrive.name)
  File "/usr/share/vdsm/virt/vm.py", line 703, in f
    ret = attr(*args, **kwargs)
  File "/usr/lib/python2.6/site-packages/vdsm/libvirtconnection.py", line 119, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1881, in blockStats
    if ret is None: raise libvirtError ('virDomainBlockStats() failed', dom=self)
libvirtError: invalid argument: invalid path: vdb
Thread-128617::DEBUG::2015-11-18 17:29:24,125::libvirtconnection::151::root::(wrapper) Unknown libvirterror: ecode: 8 edom: 10 level: 2 message: invalid argument: invalid path: vdb
Thread-128617::ERROR::2015-11-18 17:29:24,125::sampling::488::vm.Vm::(collect) vmId=`091cb939-cb03-441d-b8d1-f241a10df67f`::Stats function failed: <AdvancedStatsFunction _sampleDiskLatency at 0x1efc5b0>
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/sampling.py", line 484, in collect
    statsFunction()
  File "/usr/share/vdsm/virt/sampling.py", line 359, in __call__
    retValue = self._function(*args, **kwargs)
  File "/usr/share/vdsm/virt/vm.py", line 341, in _sampleDiskLatency
    vmDrive.name, flags=libvirt.VIR_TYPED_PARAM_STRING_OKAY)
  File "/usr/share/vdsm/virt/vm.py", line 703, in f
    ret = attr(*args, **kwargs)
  File "/usr/lib/python2.6/site-packages/vdsm/libvirtconnection.py", line 119, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1887, in blockStatsFlags
    if ret is None: raise libvirtError ('virDomainBlockStatsFlags() failed', dom=self)
libvirtError: invalid argument: invalid path: vdb
Thread-128617::DEBUG::2015-11-18 17:29:24,134::libvirtconnection::151::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present

From vdsm log RHEVH-6.7:

Thread-6504::DEBUG::2015-11-18 15:22:53,514::task::993::Storage.TaskManager.Task::(_decref) Task=`bd9717b9-0cce-4e4a-911e-1d6cb26f7ac5`::ref 0 aborting False
Thread-6504::DEBUG::2015-11-18 15:22:53,532::libvirtconnection::151::root::(wrapper) Unknown libvirterror: ecode: 8 edom: 10 level: 2 message: invalid argument: invalid path: vdb
Thread-6504::ERROR::2015-11-18 15:22:53,532::sampling::488::vm.Vm::(collect) vmId=`091cb939-cb03-441d-b8d1-f241a10df67f`::Stats function failed: <AdvancedStatsFunction _sampleDisk at 0x2bf33e8>
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/sampling.py", line 484, in collect
  File "/usr/share/vdsm/virt/sampling.py", line 359, in __call__
  File "/usr/share/vdsm/virt/vm.py", line 326, in _sampleDisk
  File "/usr/share/vdsm/virt/vm.py", line 703, in f
  File "/usr/lib/python2.6/site-packages/vdsm/libvirtconnection.py", line 119, in wrapper
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1881, in blockStats
libvirtError: invalid argument: invalid path: vdb
Thread-6504::DEBUG::2015-11-18 15:22:53,555::libvirtconnection::151::root::(wrapper) Unknown libvirterror: ecode: 8 edom: 10 level: 2 message: invalid argument: invalid path: vdb
Thread-6504::ERROR::2015-11-18 15:22:53,555::sampling::488::vm.Vm::(collect) vmId=`091cb939-cb03-441d-b8d1-f241a10df67f`::Stats function failed: <AdvancedStatsFunction _sampleDiskLatency at 0x2bf22f0>
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/sampling.py", line 484, in collect
  File "/usr/share/vdsm/virt/sampling.py", line 359, in __call__
  File "/usr/share/vdsm/virt/vm.py", line 341, in _sampleDiskLatency
  File "/usr/share/vdsm/virt/vm.py", line 703, in f
  File "/usr/lib/python2.6/site-packages/vdsm/libvirtconnection.py", line 119, in wrapper
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1887, in blockStatsFlags
libvirtError: invalid argument: invalid path: vdb
Thread-6504::DEBUG::2015-11-18 15:22:53,566::libvirtconnection::151::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present

From engine.log:

Thread-6504::DEBUG::2015-11-18 15:22:53,514::task::993::Storage.TaskManager.Task::(_decref) Task=`bd9717b9-0cce-4e4a-911e-1d6cb26f7ac5`::ref 0 aborting False
Thread-6504::DEBUG::2015-11-18 15:22:53,532::libvirtconnection::151::root::(wrapper) Unknown libvirterror: ecode: 8 edom: 10 level: 2 message: invalid argument: invalid path: vdb
Thread-6504::ERROR::2015-11-18 15:22:53,532::sampling::488::vm.Vm::(collect) vmId=`091cb939-cb03-441d-b8d1-f241a10df67f`::Stats function failed: <AdvancedStatsFunction _sampleDisk at 0x2bf33e8>
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/sampling.py", line 484, in collect
  File "/usr/share/vdsm/virt/sampling.py", line 359, in __call__
  File "/usr/share/vdsm/virt/vm.py", line 326, in _sampleDisk
  File "/usr/share/vdsm/virt/vm.py", line 703, in f
  File "/usr/lib/python2.6/site-packages/vdsm/libvirtconnection.py", line 119, in wrapper
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1881, in blockStats
libvirtError: invalid argument: invalid path: vdb
Thread-6504::DEBUG::2015-11-18 15:22:53,555::libvirtconnection::151::root::(wrapper) Unknown libvirterror: ecode: 8 edom: 10 level: 2 message: invalid argument: invalid path: vdb
Thread-6504::ERROR::2015-11-18 15:22:53,555::sampling::488::vm.Vm::(collect) vmId=`091cb939-cb03-441d-b8d1-f241a10df67f`::Stats function failed: <AdvancedStatsFunction _sampleDiskLatency at 0x2bf22f0>
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/sampling.py", line 484, in collect
  File "/usr/share/vdsm/virt/sampling.py", line 359, in __call__
  File "/usr/share/vdsm/virt/vm.py", line 341, in _sampleDiskLatency
  File "/usr/share/vdsm/virt/vm.py", line 703, in f
  File "/usr/lib/python2.6/site-packages/vdsm/libvirtconnection.py", line 119, in wrapper
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1887, in blockStatsFlags
libvirtError: invalid argument: invalid path: vdb
Thread-6504::DEBUG::2015-11-18 15:22:53,566::libvirtconnection::151::root::(wrapper) Unknown libvirterror: ecode: 80 edom: 20 level: 2 message: metadata not found: Requested metadata element is not present



Version-Release number of selected component (if applicable):
vdsm-4.16.29-1.el6ev.x86_64
libvirt-0.10.2-54.el6_7.2.x86_64
rhevm-3.5.6.2-0.1.el6ev.noarch


How reproducible:
90%

Steps to Reproduce:
1. vm + 1 bootable disk
2. Add new sparse disk (2GB)
3. Start the vm and hot unplug the second disk

Actual results:
Described above

Expected results:
Hot unplug should work when there is guest on the vm

Additional info:

Comment 1 Raz Tamir 2015-11-18 15:37:49 UTC
Created attachment 1096130 [details]
engine log

Comment 2 Raz Tamir 2015-11-18 15:41:34 UTC
Created attachment 1096131 [details]
vdsm rhevh 6.7

Comment 3 Raz Tamir 2015-11-18 15:44:13 UTC
Created attachment 1096132 [details]
vdsm log rhel 6.7

Comment 6 Dan Kenigsberg 2015-11-19 13:29:46 UTC
I think that a more relevant vdsm.log excerpt is

Thread-6596::DEBUG::2015-11-18 15:17:33,107::vm::4083::vm.Vm::(hotunplugDisk) vmId=`091cb939-cb03-441d-b8d1-f241a10df67f`::Hotunplug disk xml: <disk device="disk" snapshot="no" type="file">
	<address bus="0x00" domain="0x0000" function="0x0" slot="0x09" type="pci"/>
	<source file="/rhev/data-center/3c2f6b8c-8459-48f9-b578-ddab8133d2fb/8d4a21f6-f441-4b67-bda7-c2a31040a026/images/d284d796-ef9d-441e-add6-7b680d1ed55f/07720411-e1bf-4cf1-a34e-395304cd0477"/>
	<target bus="virtio" dev="vdb"/>
	<serial>d284d796-ef9d-441e-add6-7b680d1ed55f</serial>
	<driver cache="none" error_policy="stop" io="threads" name="qemu" type="raw"/>
</disk>

Thread-6596::DEBUG::2015-11-18 15:17:33,154::vm::4141::vm.Vm::(_waitForDriveRemoval) vmId=`091cb939-cb03-441d-b8d1-f241a10df67f`::Waiting for hotunplug to finish
Thread-6596::ERROR::2015-11-18 15:17:33,161::__init__::506::jsonrpc.JsonRpcServer::(_serveRequest) Internal server error
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/yajsonrpc/__init__.py", line 501, in _serveRequest
  File "/usr/share/vdsm/rpc/Bridge.py", line 271, in _dynamicMethod
  File "/usr/share/vdsm/API.py", line 467, in hotunplugDisk
  File "/usr/share/vdsm/virt/vm.py", line 4089, in hotunplugDisk
  File "/usr/share/vdsm/virt/vm.py", line 4145, in _waitForDriveRemoval
  File "/usr/share/vdsm/virt/vm.py", line 4155, in _isDriveAttached
  File "/usr/lib64/python2.6/xml/etree/ElementTree.py", line 355, in findall
  File "/usr/lib64/python2.6/xml/etree/ElementPath.py", line 198, in findall
  File "/usr/lib64/python2.6/xml/etree/ElementPath.py", line 176, in _compile
  File "/usr/lib64/python2.6/xml/etree/ElementPath.py", line 93, in __init__
SyntaxError: expected path separator ([)

Comment 7 Amit Aviram 2015-11-19 14:09:06 UTC
ratamir, can you please provide the "rpm -qa" output in your host?
(Dan, thanks)

Comment 8 Raz Tamir 2015-11-19 14:17:01 UTC
Created attachment 1096693 [details]
rpm -qa

Attached 'rpm -qa' output

Comment 9 Amit Aviram 2015-11-19 15:00:25 UTC
Thank you ratamir.
The problem here is that the code in "_isDriveAttached" in VDSM relies on python version >= 2.7, and the python version your host has is python-2.6.6-64.el6.x86_64..

Allon, We can demand a >= 2.7 version of python in vdsm spec- or implement this part differently. what do you think?

Comment 10 Amit Aviram 2015-11-22 08:16:16 UTC
We will fix the patch to be supported by python with a version lesser than 2.7

Comment 12 Raz Tamir 2015-11-25 07:24:44 UTC
Verified on vt18.3

Comment 13 Raz Tamir 2015-11-25 09:14:58 UTC
vdsm version - vdsm-4.16.30-1.el6ev.x86_64

Comment 14 Sandro Bonazzola 2015-12-22 13:26:05 UTC
oVirt 3.5.6 has been released and the bz verified, moving to closed current release.