Description of problem: Hot-Unplug disk from VM failed with error code 46 (Timeout detaching) while running automation TC on HE environment. According to the engine log, the timeout error appears after ~35 seconds from the start of the command "HotUnPlugDiskFromVmCommand". From the engine log: 2018-07-26 00:19:25,809+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-20) [diskattachments_update_98ed372a-4a77] EVENT_ID: USER_UPDATE_VM_DISK(88), VM vm_TestCase11503_2600071788 disk_virtio_scsiraw_2600073100 disk was updated by admin@internal-authz. 2018-07-26 00:19:27,031+03 INFO [org.ovirt.engine.core.bll.storage.disk.DetachDiskFromVmCommand] (default task-49) [diskattachments_delete_f0ed24c1-cabc] Running command: DetachDiskFromVmCommand internal: false. Entities affected : ID: 05b04cb5-7c2f-44da-bc31-9e587adc8ad4 Type: VMAction group CONFIGURE_VM_STORAGE with role type USER 2018-07-26 00:19:27,036+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-49) [diskattachments_delete_f0ed24c1-cabc] START, HotUnPlugDiskVDSCommand(HostName = host_mixed_3, HotPlugDiskVDSParameters:{hostId='6fbf48e6-dbf1-4b5c-b04d-37e4a29a93e7', vmId='05b04cb5-7c2f-44da-bc31-9e587adc8ad4', diskId='1c3268b0-ef37-4676-9e21-82676c3440f8', addressMap='[bus=0x00, domain=0x0000, function=0x0, slot=0x09, type=pci]'}), log id: 1a5be321 2018-07-26 00:19:27,041+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-49) [diskattachments_delete_f0ed24c1-cabc] Disk hot-unplug: <?xml version="1.0" encoding="UTF-8"?><hotunplug> <devices> <disk> <alias name="ua-1c3268b0-ef37-4676-9e21-82676c3440f8"/> </disk> </devices> </hotunplug> 2018-07-26 00:20:02,452+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-49) [diskattachments_delete_f0ed24c1-cabc] Failed in 'HotUnPlugDiskVDS' method 2018-07-26 00:20:02,459+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-49) [diskattachments_delete_f0ed24c1-cabc] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_3 command HotUnPlugDiskVDS failed: Timeout detaching <Drive name=vdc, type=block, path=/rhev/data-center/mnt/blockSD/361aa12e-ab3a-45c1-b487-ff6ee0101513/images/1c3268b0-ef37-4676-9e21-82676c3440f8/0a80618f-8e44-443b-a3a9-69adf1ef4b6f threshold=unset at 0x7f2418049220> 2018-07-26 00:20:02,459+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-49) [diskattachments_delete_f0ed24c1-cabc] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand' return value 'StatusOnlyReturn [status=Status [code=46, message=Timeout detaching <Drive name=vdc, type=block, path=/rhev/data-center/mnt/blockSD/361aa12e-ab3a-45c1-b487-ff6ee0101513/images/1c3268b0-ef37-4676-9e21-82676c3440f8/0a80618f-8e44-443b-a3a9-69adf1ef4b6f threshold=unset at 0x7f2418049220>]]' 2018-07-26 00:20:02,460+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-49) [diskattachments_delete_f0ed24c1-cabc] HostName = host_mixed_3 2018-07-26 00:20:02,460+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-49) [diskattachments_delete_f0ed24c1-cabc] Command 'HotUnPlugDiskVDSCommand(HostName = host_mixed_3, HotPlugDiskVDSParameters:{hostId='6fbf48e6-dbf1-4b5c-b04d-37e4a29a93e7', vmId='05b04cb5-7c2f-44da-bc31-9e587adc8ad4', diskId='1c3268b0-ef37-4676-9e21-82676c3440f8', addressMap='[bus=0x00, domain=0x0000, function=0x0, slot=0x09, type=pci]'})' execution failed: VDSGenericException: VDSErrorException: Failed to HotUnPlugDiskVDS, error = Timeout detaching <Drive name=vdc, type=block, path=/rhev/data-center/mnt/blockSD/361aa12e-ab3a-45c1-b487-ff6ee0101513/images/1c3268b0-ef37-4676-9e21-82676c3440f8/0a80618f-8e44-443b-a3a9-69adf1ef4b6f threshold=unset at 0x7f2418049220>, code = 46 2018-07-26 00:20:02,460+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-49) [diskattachments_delete_f0ed24c1-cabc] FINISH, HotUnPlugDiskVDSCommand, log id: 1a5be321 2018-07-26 00:20:02,460+03 ERROR [org.ovirt.engine.core.bll.storage.disk.DetachDiskFromVmCommand] (default task-49) [diskattachments_delete_f0ed24c1-cabc] Command 'org.ovirt.engine.core.bll.storage.disk.DetachDiskFromVmCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to HotUnPlugDiskVDS, error = Timeout detaching <Drive name=vdc, type=block, path=/rhev/data-center/mnt/blockSD/361aa12e-ab3a-45c1-b487-ff6ee0101513/images/1c3268b0-ef37-4676-9e21-82676c3440f8/0a80618f-8e44-443b-a3a9-69adf1ef4b6f threshold=unset at 0x7f2418049220>, code = 46 (Failed with error FailedToUnPlugDisk and code 46) 2018-07-26 00:20:02,476+03 ERROR [org.ovirt.engine.core.bll.storage.disk.DetachDiskFromVmCommand] (default task-49) [diskattachments_delete_f0ed24c1-cabc] Transaction rolled-back for command 'org.ovirt.engine.core.bll.storage.disk.DetachDiskFromVmCommand'. 2018-07-26 00:20:02,487+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-49) [diskattachments_delete_f0ed24c1-cabc] EVENT_ID: USER_FAILED_DETACH_DISK_FROM_VM(2,019), Failed to detach Disk disk_virtio_scsiraw_2600073100 from VM vm_TestCase11503_2600071788 (User: admin@internal-authz). 2018-07-26 00:20:02,488+03 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-49) [] Operation Failed: [Failed to hot-unplug disk] From vdms log: 2018-07-26 00:19:27,048+0300 INFO (jsonrpc/6) [api.virt] START hotunplugDisk(params={'xml': '<?xml version="1.0" encoding="UTF-8" standalone="yes"?><hotunplug><devices><disk><alias name="ua-1c3268b0-ef37-4676-9e21-82676c3440f8"/></disk></devices></hotunplug>', 'vmId': '05b04cb5-7c2f-44da-bc31-9e587adc8ad4'}) from=::ffff:10.46.16.248,33718, flow_id=diskattachments_delete_f0ed24c1-cabc, vmId=05b04cb5-7c2f-44da-bc31-9e587adc8ad4 (api:46) 2018-07-26 00:19:27,053+0300 INFO (jsonrpc/6) [virt.vm] (vmId='05b04cb5-7c2f-44da-bc31-9e587adc8ad4') Hotunplug disk xml: <?xml version='1.0' encoding='utf-8'?> <disk device="disk" snapshot="no" type="block"> <address bus="0x00" domain="0x0000" function="0x0" slot="0x09" type="pci" /> <source dev="/rhev/data-center/mnt/blockSD/361aa12e-ab3a-45c1-b487-ff6ee0101513/images/1c3268b0-ef37-4676-9e21-82676c3440f8/0a80618f-8e44-443b-a3a9-69adf1ef4b6f" /> <target bus="virtio" dev="vdc" /> <serial>1c3268b0-ef37-4676-9e21-82676c3440f8</serial> <driver cache="none" error_policy="stop" io="native" iothread="1" name="qemu" type="raw" /> <alias name="ua-1c3268b0-ef37-4676-9e21-82676c3440f8" /> </disk> ...... other debug logs 2018-07-26 00:20:02,453+0300 ERROR (jsonrpc/6) [virt.vm] (vmId='05b04cb5-7c2f-44da-bc31-9e587adc8ad4') Timeout detaching <Drive name=vdc, type=block, path=/rhev/data-center/mnt/blockSD/361aa12e-ab3a-45c1-b487-ff6ee0101513/images/1c3268b0-ef37-4676-9e21-82676c3440f8/0a80618f-8e44-443b-a3a9-69adf1ef4b6f threshold=unset at 0x7f2418049220> (vm:3930) 2018-07-26 00:20:02,454+0300 INFO (jsonrpc/6) [api.virt] FINISH hotunplugDisk return={'status': {'message': 'Timeout detaching <Drive name=vdc, type=block, path=/rhev/data-center/mnt/blockSD/361aa12e-ab3a-45c1-b487-ff6ee0101513/images/1c3268b0-ef37-4676-9e21-82676c3440f8/0a80618f-8e44-443b-a3a9-69adf1ef4b6f threshold=unset at 0x7f2418049220>', 'code': 46}} from=::ffff:10.46.16.248,33718, flow_id=diskattachments_delete_f0ed24c1-cabc, vmId=05b04cb5-7c2f-44da-bc31-9e587adc8ad4 (api:52) Version-Release number of selected component (if applicable): ovirt-engine-4.2.5.2-0.1.el7ev.noarch vdsm-4.20.35-1.el7ev.x86_64 libvirt-3.9.0-14.el7_5.6.x86_64 qemu-img-rhev-2.10.0-21.el7_5.4.x86_64 How reproducible: Didn't manage to reproduce it. Steps to Reproduce (according to the TC): 1. Add VM with a disk, run the VM and add a description while the VM is powered on 2. Remove the Disk 3. Hot plug the disk into a new VM, verify that the description is still valid Actual results: The hot-unplug operation failed. Expected results: The hot-unplug operation should succeed Additional info: A user encountered this bug also. see here: https://lists.ovirt.org/archives/list/users@ovirt.org/message/6VWU3RCP4JEEGGQLMPV7XS4BBSTW72F5/ I ran the other TC (5504) on nested environment and filed with other error: code 100, "Unrecognized device name" From the engine log: 2018-08-06 16:41:14,223+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-14) [diskattachments_update_3b80f1f5-f9ca] EVENT_ID: USER_UPDATE_VM_DISK(88), VM vm_iscsi_1_iscsi_0616373501 disk_to_plug_iscsi_4 disk was updated by admin@internal-authz. 2018-08-06 16:41:16,707+03 INFO [org.ovirt.engine.core.bll.storage.disk.HotUnPlugDiskFromVmCommand] (default task-16) [diskattachments_update_7e41b6f7-06b8] Lock Acquired to object 'EngineLock:{exclusiveLocks='[9dc09a84-5a0e-4753-964c-300f233c3fbb=DISK]', sharedLocks='[985736b1-1c3f-4a5f-8dc9-53d5f8778e40=VM]'}' 2018-08-06 16:41:16,865+03 INFO [org.ovirt.engine.core.bll.storage.disk.HotUnPlugDiskFromVmCommand] (default task-16) [diskattachments_update_7e41b6f7-06b8] Running command: HotUnPlugDiskFromVmCommand internal: false. Entities affected : ID: 985736b1-1c3f-4a5f-8dc9-53d5f8778e40 Type: VMAction group CONFIGURE_VM_STORAGE with role type USER 2018-08-06 16:41:16,972+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-16) [diskattachments_update_7e41b6f7-06b8] START, HotUnPlugDiskVDSCommand(HostName = host_mixed_2, HotPlugDiskVDSParameters:{hostId='8432ea0c-adcd-4648-9bf2-897de7742dfd', vmId='985736b1-1c3f-4a5f-8dc9-53d5f8778e40', diskId='9dc09a84-5a0e-4753-964c-300f233c3fbb', addressMap='null'}), log id: 472803ba 2018-08-06 16:41:17,028+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-16) [diskattachments_update_7e41b6f7-06b8] Disk hot-unplug: <?xml version="1.0" encoding="UTF-8"?><hotunplug> <devices> <disk> <alias name=""/> </disk> </devices> </hotunplug> 2018-08-06 16:41:17,057+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-16) [diskattachments_update_7e41b6f7-06b8] Failed in 'HotUnPlugDiskVDS' method 2018-08-06 16:41:17,090+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-16) [diskattachments_update_7e41b6f7-06b8] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_2 command HotUnPlugDiskVDS failed: General Exception: ("('Unrecognized device name: %s', '')",) 2018-08-06 16:41:17,090+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-16) [diskattachments_update_7e41b6f7-06b8] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand' return value 'StatusOnlyReturn [status=Status [code=100, message=General Exception: ("('Unrecognized device name: %s', '')",)]]' 2018-08-06 16:41:17,091+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-16) [diskattachments_update_7e41b6f7-06b8] HostName = host_mixed_2 2018-08-06 16:41:17,091+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-16) [diskattachments_update_7e41b6f7-06b8] Command 'HotUnPlugDiskVDSCommand(HostName = host_mixed_2, HotPlugDiskVDSParameters:{hostId='8432ea0c-adcd-4648-9bf2-897de7742dfd', vmId='985736b1-1c3f-4a5f-8dc9-53d5f8778e40', diskId='9dc09a84-5a0e-4753-964c-300f233c3fbb', addressMap='null'})' execution failed: VDSGenericException: VDSErrorException: Failed to HotUnPlugDiskVDS, error = General Exception: ("('Unrecognized device name: %s', '')",), code = 100 2018-08-06 16:41:17,091+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HotUnPlugDiskVDSCommand] (default task-16) [diskattachments_update_7e41b6f7-06b8] FINISH, HotUnPlugDiskVDSCommand, log id: 472803ba 2018-08-06 16:41:17,092+03 ERROR [org.ovirt.engine.core.bll.storage.disk.HotUnPlugDiskFromVmCommand] (default task-16) [diskattachments_update_7e41b6f7-06b8] Command 'org.ovirt.engine.core.bll.storage.disk.HotUnPlugDiskFromVmCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to HotUnPlugDiskVDS, error = General Exception: ("('Unrecognized device name: %s', '')",), code = 100 (Failed with error GeneralException and code 100) 2018-08-06 16:41:17,156+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-16) [diskattachments_update_7e41b6f7-06b8] EVENT_ID: USER_FAILED_HOTUNPLUG_DISK(2,003), Failed to unplug disk disk_to_plug_iscsi_4 from VM vm_iscsi_1_iscsi_0616373501 (User: admin@internal-authz). 2018-08-06 16:41:17,158+03 INFO [org.ovirt.engine.core.bll.storage.disk.HotUnPlugDiskFromVmCommand] (default task-16) [diskattachments_update_7e41b6f7-06b8] Lock freed to object 'EngineLock:{exclusiveLocks='[9dc09a84-5a0e-4753-964c-300f233c3fbb=DISK]', sharedLocks='[985736b1-1c3f-4a5f-8dc9-53d5f8778e40=VM]'}' 2018-08-06 16:41:17,208+03 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-16) [] Operation Failed: [General Exception]
Moving to Virt for inspection as it might be related to DomainXML changes
Created attachment 1473977 [details] logs
The first error is not related. I would suspect guest cooperation issue first as it seems to just time out. Libvirt and guest logs would help. The second item about upstream user report is unrelated. Seems to be about inability to hot add a disk due to underlying (and likely pre-existing) libvirt issue. Without logs or any other details there's nothing to look at. Users list discussion points to the -U parameter of qemu-img which is long fixed I believe. The third item about the missing alias should be tracked separately, please do not mix two issues in one bug. There's nothing about that in attached logs anyway. Please do not mix up unrelated issues in one report So if we talk about the first issue only then please provide additional logs/reproduction scenario. Without further data this bug will likely get closed.
Created attachment 1474372 [details] engine + vdsm + libvirt + art logs Hi Michal, we will keep this bug for the third issue (for QE info - reproduced using TestCase 5044). Attached logs for this issue. In vdsm log we see the next exception: 2018-07-25 23:36:02,978+0300 INFO (jsonrpc/4) [api.virt] START hotunplugDisk(params={'xml': '<?xml version="1.0" encoding="UTF-8" standalone="yes"?><hotunplug><devices><disk><alias name=""/></disk></devices></hotunplug>', 'vmId': '58e0bb05-f526-4e59-8cfd-0bd497a07dc3'}) from=::ffff:10.46.16.248,33718, flow_id=diskattachments_update_0472abcd-b37f, vmId=58e0bb05-f526-4e59-8cfd-0bd497a07dc3 (api:46) 2018-07-25 23:36:02,980+0300 ERROR (jsonrpc/4) [api] FINISH hotunplugDisk error=('Unrecognized device name: %s', '') (api:132) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 122, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/API.py", line 419, in hotunplugDisk return self.vm.hotunplugDisk(params) File "<string>", line 2, in hotunplugDisk File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 99, in method return func(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 3902, in hotunplugDisk diskParams = storagexml.parse(elem, meta) File "/usr/lib/python2.7/site-packages/vdsm/virt/vmdevices/storagexml.py", line 91, in parse add_vdsm_parameters(params) File "/usr/lib/python2.7/site-packages/vdsm/virt/vmdevices/storagexml.py", line 98, in add_vdsm_parameters _, params['index'] = drivename.split(params['name']) File "/usr/lib/python2.7/site-packages/vdsm/virt/vmdevices/drivename.py", line 51, in split raise ValueError('Unrecognized device name: %s', devname) ValueError: ('Unrecognized device name: %s', '') 2018-07-25 23:36:02,982+0300 INFO (jsonrpc/4) [api.virt] FINISH hotunplugDisk return={'status': {'message': 'General Exception: ("(\'Unrecognized device name: %s\', \'\')",)', 'code': 100}} The steps to reproduce are: 1. Create and start VM 2. Create 8 thin provisioned of 1GB disks 3. Attach all disks to the VM 4. Deactivate a randomly selected disk (x) from the vm 5. Activate disk x
Arik, this is likely related to your recent change. How is it possible that the alias is empty?
(In reply to Michal Skrivanek from comment #5) > Arik, this is likely related to your recent change. How is it possible that > the alias is empty? I see two possible reasons for this: 1. The correlation logic is incorrect. 2. The unplug operation was triggered before the engine managed to receive the up-to-date devices. The right fix for this though is changing the hot-plug disk command to work like hot-plug NIC - we can update the alias without waiting for the devices monitoring as in 4.2 clusters (and above) we know the device alias is based on the device-id.
What's your estimation on time required for a fix?
Hi Ryan, this bug is marked as a regression, therefore it should be targeted for 4.2.6.
(In reply to Ryan Barry from comment #7) > What's your estimation on time required for a fix? Should be fairly simple, something like an hour or two. (In reply to Elad from comment #8) > Hi Ryan, this bug is marked as a regression, therefore it should be targeted > for 4.2.6. Note that the test does not represent a realistic scenario though - the disk is unplugged 3 seconds after it was plugged... so it is unlikely to affect users.
Verified on: ovirt-engine-4.2.6.4-0.0.master.20180821115903.git1327b2f.el7.noarch vdsm-4.20.37-3.git924eec4.el7.x86_64 Steps of reproduce: Run TestCase5044 of storage team. 1. Create and start VM 2. Create 8 thin provisioned of 1GB disks 3. Attach all disks to the VM 4. Deactivate a randomly selected disk (x) from the vm 5. Activate disk x Results: No errors, hot unplugging the disk from the VM succeeded.
QE verification bot: the bug was verified upstream