Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1506608

Summary: Hot unplug a disk with a VIRTIO interface fails
Product: [oVirt] ovirt-engine Reporter: Avihai <aefrat>
Component: BLL.StorageAssignee: Daniel Erez <derez>
Status: CLOSED NOTABUG QA Contact: Raz Tamir <ratamir>
Severity: high Docs Contact:
Priority: unspecified    
Version: 4.2.0CC: aefrat, amureini, bugs, derez, fromani, michal.skrivanek, nsoffer
Target Milestone: ovirt-4.2.0Flags: rule-engine: ovirt-4.2+
rule-engine: blocker+
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-10-31 07:28:55 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 , vdsm ,libvirt_short logs none

Description Avihai 2017-10-26 12:39:00 UTC
Created attachment 1343709 [details]
engine , vdsm ,libvirt_short logs

Description of problem:
Hot unplug VIRTIO interface disk fails (checked on all storage doamin types ISCSI/NFS/GLUSTER)

Version-Release number of selected component (if applicable):
Engine:
ovirt-engine-4.2.0-0.0.master.20171025204923.git6f4cbc5.el7.centos.noarch 

VDSM:
4.20.3-224.gitef2ce4

How reproducible:
100%

Steps to Reproduce:
1. Create VM + it's bootable disk
2. Create a new disk on a storage domain with 1G size & VIRTIO interface
3. Start VM
4. Attach new disk to VM - OK.
5. Deactivate new disk 

Actual results:
Hot unplug VIRTIO interface disk fails.

Expected results:


Additional info:
Engine:
0x00, domain=0x0000, function=0x0, slot=0x07, type=pci]'}), log id: 49b4b344
2017-10-26 15:18:34,131+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-8187) [1a183cdb-416e-46f1-829c-b03e2ad660ca] Failed in 'HotUnPlugDiskVD
S' method
2017-10-26 15:18:34,142+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-8187) [1a183cdb-416e-46f1-829c-b03e2ad660ca] EVENT_ID: VDS_BROKER_CO
MMAND_FAILURE(10,802), VDSM host_mixed_1 command HotUnPlugDiskVDS failed: Timeout detaching <Drive name=vda, type=network, path=storage_local_ge8_volume_0/125f026f-0e6c-45bb-bc3c-36d49e8a8ef4/images/1bb7f3a7-85f
8-4f06-b361-c9a4d47ed4cd/1b736727-a906-4217-b1ee-7fc2bd1bb759 at 0x7f8e9c02b720>
2017-10-26 15:18:34,142+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-8187) [1a183cdb-416e-46f1-829c-b03e2ad660ca] Command 'org.ovirt.engine.
core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand' return value 'StatusOnlyReturn [status=Status [code=46, message=Timeout detaching <Drive name=vda, type=network, path=storage_local_ge8_volume_0/125f026f-0e6c-45
bb-bc3c-36d49e8a8ef4/images/1bb7f3a7-85f8-4f06-b361-c9a4d47ed4cd/1b736727-a906-4217-b1ee-7fc2bd1bb759 at 0x7f8e9c02b720>]]'
2017-10-26 15:18:34,143+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-8187) [1a183cdb-416e-46f1-829c-b03e2ad660ca] HostName = host_mixed_1
2017-10-26 15:18:34,143+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-8187) [1a183cdb-416e-46f1-829c-b03e2ad660ca] Command 'HotUnPlugDiskVDSC
ommand(HostName = host_mixed_1, HotPlugDiskVDSParameters:{hostId='8c188005-b476-4837-b147-4dc84d2caac1', vmId='775416b4-6658-49b3-8410-0e3393c14eb9', diskId='1bb7f3a7-85f8-4f06-b361-c9a4d47ed4cd', addressMap='[b
us=0x00, domain=0x0000, function=0x0, slot=0x07, type=pci]'})' execution failed: VDSGenericException: VDSErrorException: Failed to HotUnPlugDiskVDS, error = Timeout detaching <Drive name=vda, type=network, path=
storage_local_ge8_volume_0/125f026f-0e6c-45bb-bc3c-36d49e8a8ef4/images/1bb7f3a7-85f8-4f06-b361-c9a4d47ed4cd/1b736727-a906-4217-b1ee-7fc2bd1bb759 at 0x7f8e9c02b720>, code = 46
2017-10-26 15:18:34,143+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-8187) [1a183cdb-416e-46f1-829c-b03e2ad660ca] FINISH, HotUnPlugDiskVDSCo
mmand, log id: 49b4b344
2017-10-26 15:18:34,143+03 ERROR [org.ovirt.engine.core.bll.storage.disk.HotUnPlugDiskFromVmCommand] (EE-ManagedThreadFactory-engine-Thread-8187) [1a183cdb-416e-46f1-829c-b03e2ad660ca] Command 'org.ovirt.engine.
core.bll.storage.disk.HotUnPlugDiskFromVmCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to HotUnPlugDiskVDS, error =
 Timeout detaching <Drive name=vda, type=network, path=storage_local_ge8_volume_0/125f026f-0e6c-45bb-bc3c-36d49e8a8ef4/images/1bb7f3a7-85f8-4f06-b361-c9a4d47ed4cd/1b736727-a906-4217-b1ee-7fc2bd1bb759 at 0x7f8e9c
02b720>, code = 46 (Failed with error FailedToUnPlugDisk and code 46)
2017-10-26 15:18:34,169+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-8187) [1a183cdb-416e-46f1-829c-b03e2ad660ca] EVENT_ID: USER_FAILED_HOTUNPLUG_DISK(2,003), Failed to unplug disk test_disk1 from VM vm1_test (User: admin@internal-authz).



VDSM:
2017-10-26 15:18:34,120+0300 ERROR (jsonrpc/6) [virt.vm] (vmId='775416b4-6658-49b3-8410-0e3393c14eb9') Timeout detaching <Drive name=vda, type=network, path=storage_local_ge8_volume_0/125f026f-0e6c-45bb-bc3c-36d49e8a8ef4/images/1bb7f3a7-85f8-4f06-b361-c9a4d47ed4cd/1b736727-a906-4217-b1ee-7fc2bd1bb759 at 0x7f8e9c02b720> (vm:3623)

Libvirt log:
2017-10-26 12:17:10.559+0000: 16739: info : qemuMonitorSend:1034 : QEMU_MONITOR_SEND_MSG: mon=0x7f3ddc8592a0 msg={"execute":"__com.redhat_drive_add","arguments":{"file":"gluster://gluster01.scl.lab.tlv.redhat.co
m/storage_local_ge8_volume_0/125f026f-0e6c-45bb-bc3c-36d49e8a8ef4/images/1bb7f3a7-85f8-4f06-b361-c9a4d47ed4cd/1b736727-a906-4217-b1ee-7fc2bd1bb759","file.debug":"4","format":"raw","id":"drive-virtio-disk0","seri
al":"1bb7f3a7-85f8-4f06-b361-c9a4d47ed4cd","cache":"none","werror":"stop","rerror":"stop","aio":"threads"},"id":"libvirt-126"}
 fd=-1
2017-10-26 12:17:10.559+0000: 22147: info : virObjectRef:296 : OBJECT_REF: obj=0x56244d045110
2017-10-26 12:17:10.559+0000: 22147: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x56244d045110
2017-10-26 12:17:10.559+0000: 22147: info : virObjectRef:296 : OBJECT_REF: obj=0x7f3f0010b590
2017-10-26 12:17:10.559+0000: 22142: info : virEventPollDispatchHandles:506 : EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
2017-10-26 12:17:10.559+0000: 22142: info : virEventPollRunOnce:640 : EVENT_POLL_RUN: nhandles=14 timeout=-1
2017-10-26 12:17:10.559+0000: 22142: info : virEventPollDispatchHandles:506 : EVENT_POLL_DISPATCH_HANDLE: watch=93 events=2
2017-10-26 12:17:10.559+0000: 22142: info : virObjectRef:296 : OBJECT_REF: obj=0x7f3ddc8592a0
2017-10-26 12:17:10.559+0000: 22142: info : qemuMonitorIOWrite:536 : QEMU_MONITOR_IO_WRITE: mon=0x7f3ddc8592a0 buf={"execute":"__com.redhat_drive_add","arguments":{"file":"gluster://gluster01.scl.lab.tlv.redhat.
com/storage_local_ge8_volume_0/125f026f-0e6c-45bb-bc3c-36d49e8a8ef4/images/1bb7f3a7-85f8-4f06-b361-c9a4d47ed4cd/1b736727-a906-4217-b1ee-7fc2bd1bb759","file.debug":"4","format":"raw","id":"drive-virtio-disk0","se
rial":"1bb7f3a7-85f8-4f06-b361-c9a4d47ed4cd","cache":"none","werror":"stop","rerror":"stop","aio":"threads"},"id":"libvirt-126"}
 len=437 ret=437 errno=0

Comment 1 Avihai 2017-10-26 12:58:20 UTC
Regression, checked in 4.1.7.3 engine & this issue does not occur.

Comment 2 Allon Mureinik 2017-10-26 15:49:35 UTC
Daniel, weren't you already looking at such an issue?

Comment 3 Allon Mureinik 2017-10-26 15:49:54 UTC
Daniel, weren't you already looking at such an issue?

Comment 4 Daniel Erez 2017-10-29 16:35:34 UTC
Seems that the timeout error is thrown from _waitForDeviceRemoval (vm.py),
which polls device's status using 'device.is_attached_to'.
@Nir - do we check for volume lease on hotunplugDisk? does it require a running guest agent? any special behavior for virtio interface?

Comment 5 Nir Soffer 2017-10-29 17:04:39 UTC
(In reply to Daniel Erez from comment #4)
> Seems that the timeout error is thrown from _waitForDeviceRemoval (vm.py),
> which polls device's status using 'device.is_attached_to'.
> @Nir - do we check for volume lease on hotunplugDisk? does it require a
> running guest agent? any special behavior for virtio interface?

I don't know about special behavior, and we did not make any changes in the 
relevant storage code in vdsm. However they were huges changes in virt, so
I suggest to move this to virt.

Francesco, can you take a look at this?

Comment 6 Michal Skrivanek 2017-10-30 10:44:50 UTC
I do not see any error anywhere, the request for removal in libvirt log is
2017-10-26 12:17:57.546+0000: 16740: info : qemuMonitorSend:1034 : QEMU_MONITOR_SEND_MSG: mon=0x7f3ddc8592a0 msg={"execute":"device_del","arguments":{"id":"virtio-disk0"},"id":"libvirt-162"}

which seem to time out eventually. Was the drive actually unplugged or not, do we have guest side logs? Can you get logs from non-gluster storage to rule out a gluster issue?

Comment 7 Daniel Erez 2017-10-30 11:22:00 UTC
(In reply to Michal Skrivanek from comment #6)
> I do not see any error anywhere, the request for removal in libvirt log is
> 2017-10-26 12:17:57.546+0000: 16740: info : qemuMonitorSend:1034 :
> QEMU_MONITOR_SEND_MSG: mon=0x7f3ddc8592a0
> msg={"execute":"device_del","arguments":{"id":"virtio-disk0"},"id":"libvirt-
> 162"}
> 
> which seem to time out eventually. Was the drive actually unplugged or not,
> do we have guest side logs? Can you get logs from non-gluster storage to
> rule out a gluster issue?

@Avihai - can you please also check which version of libvirt/qemu is in the 4.1 env that worked.

Comment 8 Daniel Erez 2017-10-30 13:46:15 UTC
(In reply to Daniel Erez from comment #7)
> (In reply to Michal Skrivanek from comment #6)
> > I do not see any error anywhere, the request for removal in libvirt log is
> > 2017-10-26 12:17:57.546+0000: 16740: info : qemuMonitorSend:1034 :
> > QEMU_MONITOR_SEND_MSG: mon=0x7f3ddc8592a0
> > msg={"execute":"device_del","arguments":{"id":"virtio-disk0"},"id":"libvirt-
> > 162"}
> > 
> > which seem to time out eventually. Was the drive actually unplugged or not,
> > do we have guest side logs? Can you get logs from non-gluster storage to
> > rule out a gluster issue?
> 
> @Avihai - can you please also check which version of libvirt/qemu is in the
> 4.1 env that worked.

Another thing, did you install an OS on the VM. Hot unplug with virtio is applicable only with guest installed.

Comment 9 Avihai 2017-10-31 05:32:00 UTC
(In reply to Daniel Erez from comment #7)
> (In reply to Michal Skrivanek from comment #6)
> > I do not see any error anywhere, the request for removal in libvirt log is
> > 2017-10-26 12:17:57.546+0000: 16740: info : qemuMonitorSend:1034 :
> > QEMU_MONITOR_SEND_MSG: mon=0x7f3ddc8592a0
> > msg={"execute":"device_del","arguments":{"id":"virtio-disk0"},"id":"libvirt-
> > 162"}
> > 
> > which seem to time out eventually. Was the drive actually unplugged or not,
> > do we have guest side logs? Can you get logs from non-gluster storage to
> > rule out a gluster issue?
> 
> @Avihai - can you please also check which version of libvirt/qemu is in the
> 4.1 env that worked.

libvirt - 3.2.0-14.el7_4.3
qemu - 2.9.0-16.el7_4.9

Comment 10 Avihai 2017-10-31 06:54:06 UTC
(In reply to Daniel Erez from comment #8)
> (In reply to Daniel Erez from comment #7)
> > (In reply to Michal Skrivanek from comment #6)
> > > I do not see any error anywhere, the request for removal in libvirt log is
> > > 2017-10-26 12:17:57.546+0000: 16740: info : qemuMonitorSend:1034 :
> > > QEMU_MONITOR_SEND_MSG: mon=0x7f3ddc8592a0
> > > msg={"execute":"device_del","arguments":{"id":"virtio-disk0"},"id":"libvirt-
> > > 162"}
> > > 
> > > which seem to time out eventually. Was the drive actually unplugged or not,
> > > do we have guest side logs? Can you get logs from non-gluster storage to
> > > rule out a gluster issue?
> > 
> > @Avihai - can you please also check which version of libvirt/qemu is in the
> > 4.1 env that worked.
> 
> Another thing, did you install an OS on the VM. Hot unplug with virtio is
> applicable only with guest installed.

I rechecked hot-unplug with VIRTIO interface on lastest 4.2:
- VM with OS -> issue does not occur.
- VM without OS -> issue occur.

I also rechecked the same scenario on 4.1 & got the same behavior so this is not a regression as I thought.

Last Q: -about VM without OS scenario:
Hot plug does work but hot unplug does not - Is this known/by design?


Anyway, If this behavior is by design - please close the bug.

Comment 11 Daniel Erez 2017-10-31 07:28:55 UTC
(In reply to Avihai from comment #10)
> (In reply to Daniel Erez from comment #8)
> > (In reply to Daniel Erez from comment #7)
> > > (In reply to Michal Skrivanek from comment #6)
> > > > I do not see any error anywhere, the request for removal in libvirt log is
> > > > 2017-10-26 12:17:57.546+0000: 16740: info : qemuMonitorSend:1034 :
> > > > QEMU_MONITOR_SEND_MSG: mon=0x7f3ddc8592a0
> > > > msg={"execute":"device_del","arguments":{"id":"virtio-disk0"},"id":"libvirt-
> > > > 162"}
> > > > 
> > > > which seem to time out eventually. Was the drive actually unplugged or not,
> > > > do we have guest side logs? Can you get logs from non-gluster storage to
> > > > rule out a gluster issue?
> > > 
> > > @Avihai - can you please also check which version of libvirt/qemu is in the
> > > 4.1 env that worked.
> > 
> > Another thing, did you install an OS on the VM. Hot unplug with virtio is
> > applicable only with guest installed.
> 
> I rechecked hot-unplug with VIRTIO interface on lastest 4.2:
> - VM with OS -> issue does not occur.
> - VM without OS -> issue occur.
> 
> I also rechecked the same scenario on 4.1 & got the same behavior so this is
> not a regression as I thought.
> 
> Last Q: -about VM without OS scenario:
> Hot plug does work but hot unplug does not - Is this known/by design?

Indeed, disk hot unplug requires a running OS. Closing..

> 
> 
> Anyway, If this behavior is by design - please close the bug.

Comment 12 Michal Skrivanek 2017-10-31 07:33:34 UTC
I still wonder how did you check it as a regression. Do you have different OSes? Is it automation? Please make sure the test is reproducible in the same conditions!

Comment 13 Avihai 2017-10-31 08:00:25 UTC
(In reply to Michal Skrivanek from comment #12)
> I still wonder how did you check it as a regression. Do you have different
> OSes? Is it automation? Please make sure the test is reproducible in the
> same conditions!

I had no idea that we have a known issue/by design with hot-unplug with VIRTIO ONLY when VM bootable disk is without VM so I did not pay attention to how I create the VM .

Anyway It's my bad & I'll pay more attention next time.