Description of problem: Live migration of VM with disks of the following types: - virtio_scsicow - virtio_scsiraw - virtio_cow - virtio_raw fails with the following errors: Engine log: 2020-09-05 06:20:44,785+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateLiveSnapshotForVmCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-35) [disks_syncAction_5a889e0c-57b4-444d] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateLiveSnapshotForVmCommand' with failure. 2020-09-05 06:20:46,875+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-81) [disks_syncAction_5a889e0c-57b4-444d] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand' with failure. 2020-09-05 06:20:46,879+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-81) [disks_syncAction_5a889e0c-57b4-444d] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotDiskCommand' with failure. 2020-09-05 06:20:46,885+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-81) [disks_syncAction_5a889e0c-57b4-444d] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand' with failure. 2020-09-05 06:20:46,894+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMRevertTaskVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-81) [disks_syncAction_5a889e0c-57b4-444d] Trying to revert unknown task 'a0fd526c-f94a-4d0f-9d51-dcbec345fdd1' 2020-09-05 06:20:47,225+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-81) [] EVENT_ID: USER_CREATE_SNAPSHOT_FINISHED_FAILURE(69), Failed to complete snapshot 'disk_virtiocow_0506173346 Auto-generated for Live Storage Migration' creation for VM 'vm_TestCase21907_0506171564'. 2020-09-05 06:20:47,225+03 WARN [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-81) [] Command 'CreateSnapshotForVm' id: '8e6d56c6-48aa-4783-af3c-527e7319c0b8' end method execution failed, as the command isn't marked for endAction() retries silently ignoring VDSM Log: 2020-09-05 06:20:28,747+0300 ERROR (virt/424ece27) [storage.TaskManager.Task] (Task='45b9a01a-0d7f-44db-949a-e9e48d1e9e7f') Unexpected error (task:880) Traceback (most recent call last): File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 887, in _run return fn(*args, **kargs) File "<decorator-gen-167>", line 2, in prepareImage File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 50, in method ret = func(*args, **kwargs) File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 3229, in prepareImage raise se.VolumeDoesNotExist(leafUUID) vdsm.storage.exception.VolumeDoesNotExist: Volume does not exist: ('eb4e455f-0280-4fbe-83bd-69113b4a9f8c',) 2020-09-05 06:20:28,748+0300 DEBUG (virt/424ece27) [storage.TaskManager.Task] (Task='45b9a01a-0d7f-44db-949a-e9e48d1e9e7f') Task._run: 45b9a01a-0d7f-44db-949a-e9e48d1e9e7f ('0994d031-4385-4fba-850a-f020f62bf373', '90f6929e-c0d1-4043-b69b-0c04f563f96c', 'fed1fa70-8e60-4fdc-ae00-3541a8552809', 'eb4e455f-0280-4fbe-83bd-69113b4a9f8c') {} failed - stopping task (task:899) 2020-09-05 06:20:28,748+0300 ERROR (virt/424ece27) [storage.Dispatcher] FINISH prepareImage error=Volume does not exist: ('eb4e455f-0280-4fbe-83bd-69113b4a9f8c',) (dispatcher:83) 2020-09-05 06:20:28,748+0300 ERROR (virt/424ece27) [virt.vm] (vmId='a24fbeb9-0266-4b3c-bbc9-34ff6e8b290a') unable to prepare the volume path for disk vdb (snapshot:386) Traceback (most recent call last): File "/usr/lib/python3.6/site-packages/vdsm/virt/jobs/snapshot.py", line 383, in snapshot self._vm.cif.prepareVolumePath(new_drives[vm_dev_name]) File "/usr/lib/python3.6/site-packages/vdsm/clientIF.py", line 428, in prepareVolumePath raise vm.VolumeError(drive) vdsm.virt.vm.VolumeError: Bad volume specification {'device': 'disk', 'domainID': '0994d031-4385-4fba-850a-f020f62bf373', 'imageID': 'fed1fa70-8e60-4fdc-ae00-3541a8552809', 'volumeID': 'eb4e455f-0280-4fbe-83bd-69113b4a9f8c', 'type': 'disk', 'diskType': 'block', 'poolID': '90f6929e-c0d1-4043-b69b-0c04f563f96c', 'name': 'vdb', 'format': 'cow'} Version-Release number of selected component (if applicable): ovirt-engine-4.4.3.1-0.7.el8ev.noarch vdsm-4.40.28-1.el8ev.x86_64 How reproducible: 100% Steps to Reproduce: 1. Create VM from template (RHEL 8.2) 2. Create 4 disks on iSCSI: - virtio_scsicow - virtio_scsiraw - virtio_cow - virtio_raw 3. Run VM 4. Try to LSM -> Operation fails. Actual results: Operation fails with the above results. Expected results: Operation should succeed. Additional info: Engine+VDSM logs are attached.
Created attachment 1713882 [details] logs
host: lynx24 2020-09-05 03:17:46,100+0300 INFO (tasks/1) [storage.LVM] Creating LV (vg=1ffa9213-21c2-4701-9bc7-ede83bc52749, lv=8367b9cc-8bd9-474e-96fc-ebd0d5a8a151, size=1024m, activate=True, contiguous=False, initialTags=('OVIRT_VOL_INITIALIZING',), device=None) (lvm:1558) 2020-09-05 03:17:46,712+0300 INFO (tasks/1) [storage.LVM] Change LVs tags (vg=1ffa9213-21c2-4701-9bc7-ede83bc52749, lvs=('8367b9cc-8bd9-474e-96fc-ebd0d5a8a151',), delTags=['OVIRT_VOL_INITIALIZING'], addTags=['MD_9', 'PU_52a92989-bb17-4f50-9100-f6e3cd5c2954', 'IU_a2a35ef6-5332-47cb-9059-f49699124539']) (lvm:1770) 2020-09-05 03:17:47,245+0300 DEBUG (tasks/1) [storage.TaskManager.Task] (Task='06bcf447-deb0-4425-bd21-276195862a83') Task.run: exit - success: result {'uuid': '8367b9cc-8bd9-474e-96fc-ebd0d5a8a151'} (task:932) host: lynx23 2020-09-05 03:17:55,470+0300 ERROR (virt/bbc52ab9) [storage.TaskManager.Task] (Task='b0458b77-893f-4a0c-9b6c-a6fb60d86f6a') Unexpected error (task:880) Traceback (most recent call last): File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 887, in _run return fn(*args, **kargs) File "<decorator-gen-167>", line 2, in prepareImage File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 50, in method ret = func(*args, **kwargs) File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 3229, in prepareImage raise se.VolumeDoesNotExist(leafUUID) vdsm.storage.exception.VolumeDoesNotExist: Volume does not exist: ('8367b9cc-8bd9-474e-96fc-ebd0d5a8a151',) Looks like an issue with our LVM cache Nir, should be resolved by https://gerrit.ovirt.org/#/c/111131/ ?
(In reply to Benny Zlotnik from comment #2) > Looks like an issue with our LVM cache > > Nir, should be resolved by https://gerrit.ovirt.org/#/c/111131/ ? Yes, this looks like the same issue, I'll add this bug to the patch.
Reproduced this issue while running Automation with the following steps: 1. clone vm from a pre-defined template 2. Adding new disk (direct lun) 3. Start VM 4. Suspend VM From vdsm log: 2020-09-08 21:04:12,406+0300 DEBUG (migsrc/a3393511) [storage.TaskManager.Task] (Task='e5b910e6-09f1-4de1-84d6-9f291cdad701') moving from state preparing -> state preparing (task:624) Small remark: Why does it say: moving from state preparing -> state preparing ?? Isnt that supposed to be: moving from state preparing -> state suspended ? 2020-09-08 21:04:12,409+0300 INFO (migsrc/a3393511) [vdsm.api] FINISH prepareImage error=Volume does not exist: ('4f132be4-9623-40f0-9dcf-df123892affc',) from=internal, task_id=e5b910e6-09f1-4de1-84d6-9f291cdad701 (api:52) 2020-09-08 21:04:12,411+0300 ERROR (migsrc/a3393511) [storage.TaskManager.Task] (Task='e5b910e6-09f1-4de1-84d6-9f291cdad701') Unexpected error (task:880) Traceback (most recent call last): File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 887, in _run return fn(*args, **kargs) File "<decorator-gen-167>", line 2, in prepareImage File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 50, in method ret = func(*args, **kwargs) File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 3229, in prepareImage raise se.VolumeDoesNotExist(leafUUID) vdsm.storage.exception.VolumeDoesNotExist: Volume does not exist: ('4f132be4-9623-40f0-9dcf-df123892affc',) Attaching logs.
Created attachment 1714400 [details] Reproduced when moving vm to 'suspended' state
(In reply to Ilan Zuckerman from comment #7) Which version did you test? this was fixed in vdsm-4.40.29. > 2020-09-08 21:04:12,406+0300 DEBUG (migsrc/a3393511) > [storage.TaskManager.Task] (Task='e5b910e6-09f1-4de1-84d6-9f291cdad701') > moving from state preparing -> state preparing (task:624) > > Small remark: Why does it say: > moving from state preparing -> state preparing ?? > Isnt that supposed to be: > moving from state preparing -> state suspended ? This is task manager debug log. The state is not related to the vm state or image, but task state.
(In reply to Nir Soffer from comment #9) > (In reply to Ilan Zuckerman from comment #7) > Which version did you test? this was fixed in vdsm-4.40.29. > Tested on: rhv-4.4.3-2 vdsm-4.40.28-1
(In reply to Ilan Zuckerman from comment #10) > Tested on: > rhv-4.4.3-2 > vdsm-4.40.28-1 Ok, we know that this version is broken. Please test again with vdsm >= 4.40.29.
Verified on vdsm-4.40.30-1.el8ev.x86_64.
This bugzilla is included in oVirt 4.4.3 release, published on November 10th 2020. Since the problem described in this bug report should be resolved in oVirt 4.4.3 release, it has been closed with a resolution of CURRENT RELEASE. If the solution does not work for you, please open a new bug report.
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 1000 days