Created attachment 1675729 [details] engine and vdsm logs Description of problem: Clone(deep copy not thin copy) VM from a template (which was created from another VM created from scratch) fails. Same test ran also on NFS and gluster and failed ONLY on ISCSI ! Looks like the issue start in the measure function not finding the volume(see below) VDSM log: 2020-03-27 22:20:24,931+0300 ERROR (jsonrpc/5) [storage.TaskManager.Task] (Task='dd7fc9d3-cb6a-4591-9038-fcd334679933') 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-161>", line 2, in measure 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 3155, in measure output_format=sc.fmt2str(dest_format) File "/usr/lib/python3.6/site-packages/vdsm/storage/qemuimg.py", line 160, in measure out = _run_cmd(cmd) File "/usr/lib/python3.6/site-packages/vdsm/storage/qemuimg.py", line 464, in _run_cmd raise cmdutils.Error(cmd, rc, out, err) vdsm.common.cmdutils.Error: Command ['/usr/bin/qemu-img', 'measure', '--output', 'json', '-f', 'qcow2', '-O', 'qcow2', '/rhev/data-center/mnt/blockSD/709af3b5-2ac9-42fb-80d1-b04a1295a439/images/f07a91d4-1e4f-4787-b99c-cfbdcf6ae7c5/a54282cc-0bb0-4f0a-b356-7a404cef1a3a'] failed with rc=1 out=b'' err=b"qemu-img: Could not open '/rhev/data-center/mnt/blockSD/709af3b5-2ac9-42fb-80d1-b04a1295a439/images/f07a91d4-1e4f-4787-b99c-cfbdcf6ae7c5/a54282cc-0bb0-4f0a-b356-7a404cef1a3a': Could not open '/rhev/data-center/mnt/blockSD/709af3b5-2ac9-42fb-80d1-b04a1295a439/images/f07a91d4-1e4f-4787-b99c-cfbdcf6ae7c5/a54282cc-0bb0-4f0a-b356-7a404cef1a3a': No such file or directory\n" Engine log: 2020-03-27 22:20:24,859+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MeasureVolumeVDSCommand] (default task-8) [vms_create_02e3064e-b942-4896] START, MeasureVolumeVDSCommand(HostName = host_mixed_1, Meas ureVolumeVDSCommandParameters:{hostId='6ce16313-1321-42fd-8b96-144ad72d0d14', storagePoolId='d01aad6f-4c60-4afe-858d-9d278ba0268c', storageDomainId='709af3b5-2ac9-42fb-80d1-b04a1295a439', imageGroupId='f07a91d4 -1e4f-4787-b99c-cfbdcf6ae7c5', imageId='a54282cc-0bb0-4f0a-b356-7a404cef1a3a'}), log id: 72c21a75 2020-03-27 22:20:24,943+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MeasureVolumeVDSCommand] (default task-8) [vms_create_02e3064e-b942-4896] Failed in 'MeasureVolumeVDS' method 2020-03-27 22:20:24,951+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-8) [vms_create_02e3064e-b942-4896] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_m ixed_1 command MeasureVolumeVDS failed: Command ['/usr/bin/qemu-img', 'measure', '--output', 'json', '-f', 'qcow2', '-O', 'qcow2', '/rhev/data-center/mnt/blockSD/709af3b5-2ac9-42fb-80d1-b04a1295a439/images/f07a 91d4-1e4f-4787-b99c-cfbdcf6ae7c5/a54282cc-0bb0-4f0a-b356-7a404cef1a3a'] failed with rc=1 out=b'' err=b"qemu-img: Could not open '/rhev/data-center/mnt/blockSD/709af3b5-2ac9-42fb-80d1-b04a1295a439/images/f07a91d 4-1e4f-4787-b99c-cfbdcf6ae7c5/a54282cc-0bb0-4f0a-b356-7a404cef1a3a': Could not open '/rhev/data-center/mnt/blockSD/709af3b5-2ac9-42fb-80d1-b04a1295a439/images/f07a91d4-1e4f-4787-b99c-cfbdcf6ae7c5/a54282cc-0bb0- 4f0a-b356-7a404cef1a3a': No such file or directory\n" 2020-03-27 22:20:24,951+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MeasureVolumeVDSCommand] (default task-8) [vms_create_02e3064e-b942-4896] Command 'MeasureVolumeVDSCommand(HostName = host_mixed_1, Me asureVolumeVDSCommandParameters:{hostId='6ce16313-1321-42fd-8b96-144ad72d0d14', storagePoolId='d01aad6f-4c60-4afe-858d-9d278ba0268c', storageDomainId='709af3b5-2ac9-42fb-80d1-b04a1295a439', imageGroupId='f07a91 d4-1e4f-4787-b99c-cfbdcf6ae7c5', imageId='a54282cc-0bb0-4f0a-b356-7a404cef1a3a'})' execution failed: VDSGenericException: VDSErrorException: Failed to MeasureVolumeVDS, error = Command ['/usr/bin/qemu-img', 'me asure', '--output', 'json', '-f', 'qcow2', '-O', 'qcow2', '/rhev/data-center/mnt/blockSD/709af3b5-2ac9-42fb-80d1-b04a1295a439/images/f07a91d4-1e4f-4787-b99c-cfbdcf6ae7c5/a54282cc-0bb0-4f0a-b356-7a404cef1a3a'] f ailed with rc=1 out=b'' err=b"qemu-img: Could not open '/rhev/data-center/mnt/blockSD/709af3b5-2ac9-42fb-80d1-b04a1295a439/images/f07a91d4-1e4f-4787-b99c-cfbdcf6ae7c5/a54282cc-0bb0-4f0a-b356-7a404cef1a3a': Coul d not open '/rhev/data-center/mnt/blockSD/709af3b5-2ac9-42fb-80d1-b04a1295a439/images/f07a91d4-1e4f-4787-b99c-cfbdcf6ae7c5/a54282cc-0bb0-4f0a-b356-7a404cef1a3a': No such file or directory\n", code = 100 2020-03-27 22:20:24,951+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MeasureVolumeVDSCommand] (default task-8) [vms_create_02e3064e-b942-4896] FINISH, MeasureVolumeVDSCommand, return: , log id: 72c21a75 2020-03-27 22:20:24,951+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.MeasureVolumeCommand] (default task-8) [vms_create_02e3064e-b942-4896] Command 'org.ovirt.engine.core.bll.storage.disk.image.Measur eVolumeCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MeasureVolumeVDS, error = Command ['/usr/bin/qemu-img', 'm easure', '--output', 'json', '-f', 'qcow2', '-O', 'qcow2', '/rhev/data-center/mnt/blockSD/709af3b5-2ac9-42fb-80d1-b04a1295a439/images/f07a91d4-1e4f-4787-b99c-cfbdcf6ae7c5/a54282cc-0bb0-4f0a-b356-7a404cef1a3a'] failed with rc=1 out=b'' err=b"qemu-img: Could not open '/rhev/data-center/mnt/blockSD/709af3b5-2ac9-42fb-80d1-b04a1295a439/images/f07a91d4-1e4f-4787-b99c-cfbdcf6ae7c5/a54282cc-0bb0-4f0a-b356-7a404cef1a3a': Cou ld not open '/rhev/data-center/mnt/blockSD/709af3b5-2ac9-42fb-80d1-b04a1295a439/images/f07a91d4-1e4f-4787-b99c-cfbdcf6ae7c5/a54282cc-0bb0-4f0a-b356-7a404cef1a3a': No such file or directory\n", code = 100 (Failed with error GeneralException and code 100) 2020-03-27 22:20:24,959+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand] (default task-8) [vms_create_02e3064e-b942-4896] Command 'org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand' failed: Could not measure volume 2020-03-27 22:20:24,959+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand] (default task-8) [vms_create_02e3064e-b942-4896] Exception: java.lang.RuntimeException: Could not measure volume at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand.determineTotalImageInitialSize(CopyImageGroupWithDataCommand.java:222) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand.createVolume(CopyImageGroupWithDataCommand.java:140) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand.executeCommand(CopyImageGroupWithDataCommand.java:81) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1169) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1327) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:2003) at org.ovirt.engine.core.utils//org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:140) at org.ovirt.engine.core.utils//org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:79) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1387) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:419) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.executor.DefaultBackendActionExecutor.execute(DefaultBackendActionExecutor.java:13) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.Backend.runAction(Backend.java:442) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:424) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.Backend.runInternalAction(Backend.java:630) at jdk.internal.reflect.GeneratedMethodAccessor727.invoke(Unknown Source) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ……………………………………………………………………………………………………………………... at io.undertow.servlet.28.SP1-redhat-00002//io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:78) at io.undertow.servlet.28.SP1-redhat-00002//io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:99) at io.undertow.core.28.SP1-redhat-00002//io.undertow.server.Connectors.executeRootHandler(Connectors.java:376) at io.undertow.core.28.SP1-redhat-00002//io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830) at org.jboss.threads.3.Final-redhat-00001//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35) at org.jboss.threads.3.Final-redhat-00001//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982) at org.jboss.threads.3.Final-redhat-00001//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486) at org.jboss.threads.3.Final-redhat-00001//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377) at java.base/java.lang.Thread.run(Thread.java:834) 2020-03-27 22:20:25,054+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-8) [vms_create_02e3064e-b942-4896] EVENT_ID: USER_ADD_VM_STARTED(37), VM vm_type_2722202310 creation was initiated by admin@internal-authz. mand 'CreateCloneOfTemplate' (id: '9a90bf23-b5ff-4e01-8a73-811d6fad7176') waiting on child command id: '1519b59a-be6d-40ce-90e6-16cb24a047b2' type:'CopyImageGroupWithData' to complete 2020-03-27 22:20:27,235+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-34) [vms_create_02e3064e-b942-4896] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand' with failure. s to poll now 2020-03-27 22:20:37,565+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-96) [] SPMAsyncTask::PollTask: Polling task '6241d2d0-96f3-43 ee-bf7f-af5b04f3f5d2' (Parent Command 'Unknown', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'. 2020-03-27 22:20:37,565+03 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-96) [] BaseAsyncTask::logEndTaskFailure: Task '6241d2d0-96f3- 43ee-bf7f-af5b04f3f5d2' (Parent Command 'Unknown', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure: -- Result: 'cleanSuccess' -- Message: 'VDSGenericException: VDSErrorException: Failed in vdscommand to HSMGetAllTasksStatusesVDS, error = value=Shared Volume cannot be deleted: ('img 80bf8d67-4b68-4840-8593-ddbf1cab0c7e vol a54282cc-0bb 0-4f0a-b356-7a404cef1a3a',) abortedcode=223', -- Exception: 'VDSGenericException: VDSErrorException: Failed in vdscommand to HSMGetAllTasksStatusesVDS, error = value=Shared Volume cannot be deleted: ('img 80bf8d67-4b68-4840-8593-ddbf1cab0c7e vol a54282cc-0 bb0-4f0a-b356-7a404cef1a3a',) abortedcode=223' Version-Release number of selected component (if applicable): rhv-4.4.0-27 ovirt-engine-4.4.0-0.29.master.el8ev.noarch vdsm-4.40.9-1.el8ev.x86_64 libvirt-6.0.0-15.module+el8.2.0+6106+b6345808.x86_64 qemu-img-4.2.0-16.module+el8.2.0+6092+4f2391c1.x86_64 How reproducible: 2 out of 3 times in automation only on ISCSI SD. Did not try manually yet. Steps to Reproduce: Short scenario done via REST: Create VM A(named in this TC run ‘vm_TestCase11987_2722192940’) from scratch with nic and a qcow disk from ISCSI SD. Create a template A (named in this TC run ‘templ_TestCase11987_2722195137’)from that VM Clone(deep copy not thin) a new VM B ( named in this TC run ‘vm_type_2722202310’) from template A (templ_TestCase11987_2722195137) Long scenario with timestamps: 19:19:16 art/tests/rhevmtests/storage/storage_full_import_export/test_export_import.py 2020-03-27 22:19:29,402 INFO ================================================================================ 19:19:16 2020-03-27 22:19:29,403 INFO Test Setup 1: Creating VM vm_TestCase11987_2722192940 19:19:16 2020-03-27 22:19:29,500 INFO Test Setup 2: [class] Create new vm with nic nic1, disk and OS with {'diskActive': True, 'wipe_after_delete': 'false', 'slim': False, 'cluster': 'golden_env_mixed_1', 'linked': 'true', 'network': 'ovirtmgmt', 'provisioned_size': 6442450944, 'cpu_socket': 1, 'nicType': 'virtio', 'cpu_cores': 1, 'plugged': 'true', 'start': 'false', 'vmDescription': '', 'memory': 1073741824, 'vmName': 'vm_TestCase11987_2722192940', 'template': 'Blank', 'volumeFormat': 'cow', 'display_type': 'spice', 'installation': False, 'storageDomainName': 'iscsi_0', 'attempt': 60, 'diskInterface': 'virtio', 'bootable': True, 'type': 'server', 'copy_permissions': False, 'interval': 60, 'volumeType': True, 'diskType': 'data', 'useAgent': True, 'async': False, 'os_type': 'RHEL6x64'} 19:19:16 2020-03-27 22:19:29,504 INFO Test Setup 3: [class] Description vm_TestCase11987_2722192940: add new vm (without starting it) with {'name': 'vm_TestCase11987_2722192940', 'cpu_socket': 1, 'copy_permissions': False, 'cpu_cores': 1, 'cluster': 'golden_env_mixed_1', 'display_type': 'spice', 'template': 'Blank', 'memory': 1073741824, 'async': False, 'os_type': 'RHEL6x64', 'type': 'server', 'wait': True} 19:19:17 2020-03-27 22:19:30,036 INFO Test Setup 4: [class] Add vNIC name nic1 to VM vm_TestCase11987_2722192940 with {'interface': 'virtio', 'vnic_profile': 'ovirtmgmt', 'linked': 'true', 'network': 'ovirtmgmt', 'plugged': 'true'} 19:19:38 2020-03-27 22:19:51,379 INFO Test Setup 5: Creating template templ_TestCase11987_2722195137 19:19:38 2020-03-27 22:19:51,382 INFO Test Setup 6: [class] create new template with {'name': 'templ_TestCase11987_2722195137', 'vm': 'vm_TestCase11987_2722192940', 'cluster': 'golden_env_mixed_1', 'storagedomain': 'iscsi_0', 'timeout': 900, 'wait': True} 19:20:10 2020-03-27 22:20:23,108 INFO Test Setup 7: Clone VM vm_type_2722202310 from template templ_TestCase11987_2722195137 19:20:10 2020-03-27 22:20:23,111 INFO Test Setup 8: [class] Description: clone vm from a pre-defined template templ_TestCase11987_2722195137 with {'vol_sparse': True, 'name': 'vm_type_2722202310', 'clone': True, 'cluster': 'golden_env_mixed_1', 'timeout': 900, 'vol_format': 'cow', 'wait': True} 19:20:22 2020-03-27 22:20:35,420 INFO 276: storage/rhevmtests.storage.storage_full_import_export.test_export_import.TestCase11987.test_export_vm[iscsi] 19:20:22 2020-03-27 22:20:35,421 INFO Sanity export from Blank 19:20:22 2020-03-27 22:20:35,421 INFO Sanity export from another template 19:20:22 2020-03-27 22:20:35,421 INFO STORAGE: ISCSI 19:20:22 2020-03-27 22:20:35,421 ERROR NOTE: Test failed on setup phase! 19:20:22 2020-03-27 22:20:35,422 ERROR Result: FAILED 19:20:22 E2020-03-27 22:20:35,472 INFO Actual results: VM creation from template fails. Expected results: Additional info: Test is run also on NFS and cluster and works without issue. Issue introduced in rhv-4.4.0-27(was not there at rhv-4.4.0-24)
This bug report has Keywords: Regression or TestBlocker. Since no regressions or test blockers are allowed between releases, it is also being identified as a blocker for this release. Please resolve ASAP.
Looks like the image is prepared (LV activation) not on the host running the measure, I'll send a patch now
I can see that this scenario [1] is failing on: ovirt-engine-4.4.0-0.32.master.el8ev.noarch vdsm-4.40.13-1.el8ev.x86_64 BUT the failure is seen only for the FIRST attempt of migrating the disk. On the second attempt of the same disk and exactly the same ISCSI domains, the migration works without any errors. Here you can see that the first attempt has failed: 2020-04-12 16:35:18,168+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorSe rvice-engineScheduledThreadPool-Thread-42) [] EVENT_ID: USER_MOVED_DISK_FINISHED_FAILURE(2,011), User admin@internal-authz have failed to move disk test_ilan_Disk1 to domain iscsi_2. Here you can see that the second attempt is working fine: 2020-04-12 16:43:56,459+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-16) [5a87258a-1a27-4d7f-9d91-6cadf59a7905] EVENT_ID: USER_MOVED_DISK_FINISHED_SUCCESS(2,010), User admin@internal-authz finished moving disk test_ilan_Disk1 to domain iscsi_2. Attaching engine and vdsm logs. [1]: 1. create blank vm 2. create 10g thin disk on ISCSI and attach it to the vm 3. start the vm 4. migrate to disk to other iscsi domain actual result: fails after the snapshot creation. (snap succeeds) with the following on engine log [2]. [2]: 2020-04-12 16:35:16,002+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.MeasureVolumeCommand] (EE-ManagedScheduledExecutorServi ce-engineScheduledThreadPool-Thread-76) [5912ac07-80b8-4d7a-8187-3c21af73a3c9] Command 'org.ovirt.engine.core.bll.storage.disk.image.M easureVolumeCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErr orException: Failed to MeasureVolumeVDS, error = Command ['/usr/bin/qemu-img', 'measure', '--output', 'json', '-f', 'qcow2', '-O', 'qc ow2', '/rhev/data-center/mnt/blockSD/4f7277b0-a1a0-4010-86a2-3de179fb58b8/images/dadd1588-b481-4ba9-b813-16bdfbeebb99/0d9bbdc2-e772-42 74-aa95-0f4bece7d433'] failed with rc=1 out=b'' err=b"qemu-img: Could not open '/rhev/data-center/mnt/blockSD/4f7277b0-a1a0-4010-86a2- 3de179fb58b8/images/dadd1588-b481-4ba9-b813-16bdfbeebb99/0d9bbdc2-e772-4274-aa95-0f4bece7d433': Could not open '/rhev/data-center/mnt/ blockSD/4f7277b0-a1a0-4010-86a2-3de179fb58b8/images/dadd1588-b481-4ba9-b813-16bdfbeebb99/0d9bbdc2-e772-4274-aa95-0f4bece7d433': No suc h file or directory\n", code = 100 (Failed with error GeneralException and code 100) 2020-04-12 16:35:16,007+03 ERROR [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService- engineScheduledThreadPool-Thread-76) [5912ac07-80b8-4d7a-8187-3c21af73a3c9] Command 'CloneImageGroupVolumesStructure' id: 'f1947953-f8 cc-4dc9-b335-061bdc01ac01' with children [] failed when attempting to perform the next operation, marking as 'ACTIVE' 2020-04-12 16:35:16,007+03 ERROR [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService- engineScheduledThreadPool-Thread-76) [5912ac07-80b8-4d7a-8187-3c21af73a3c9] Could not measure volume: java.lang.RuntimeException: Coul d not measure volume at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.CloneImageGroupVolumesStructureCommand.determin eImageInitialSize(CloneImageGroupVolumesStructureCommand.java:214) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.CloneImageGroupVolumesStructureCommand.createIm age(CloneImageGroupVolumesStructureCommand.java:163) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.CloneImageGroupVolumesStructureCommand.performN extOperation(CloneImageGroupVolumesStructureCommand.java:133) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback.childCommandsExecutionEnded(S erialChildCommandsExecutionCallback.java:32) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.ChildCommandsCallbackBase.doPolling(ChildCommandsCallbackBase.java :80) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:175) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:109) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) at org.glassfish.javax.enterprise.concurrent.0.redhat-1//org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383) at org.glassfish.javax.enterprise.concurrent.0.redhat-1//org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) at org.glassfish.javax.enterprise.concurrent.0.redhat-1//org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250)
I've seen the same errors also with LSM flows in our automation rans on: ovirt-engine-4.4.0-0.32.master.el8ev.noarch vdsm-4.40.13-1.el8ev.x86_64 Engine: 2020-04-10 09:39:35,931+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MeasureVolumeVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [disks_syncAction_a462dd75-f602-4315] Failed in 'MeasureVolumeVDS' method 2020-04-10 09:39:35,936+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [disks_syncAction_a462dd75-f602-4315] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command MeasureVolumeVDS failed: Command ['/usr/bin/qemu-img', 'measure', '--output', 'json', '-f', 'qcow2', '-O', 'qcow2', '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45'] failed with rc=1 out=b'' err=b"qemu-img: Could not open '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45': Could not open '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45': No such file or directory\n" 2020-04-10 09:39:35,936+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MeasureVolumeVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [disks_syncAction_a462dd75-f602-4315] Command 'MeasureVolumeVDSCommand(HostName = host_mixed_1, MeasureVolumeVDSCommandParameters:{hostId='4910e09a-2a21-47cb-a3b0-d2e96de40fd4', storagePoolId='ce534d57-c1e2-4b84-bd59-405c56f30160', storageDomainId='69bdd640-605b-4987-9aac-7e389576f3dc', imageGroupId='c2767b0f-f37a-4c33-9a70-162db91867da', imageId='3b3f36e3-8092-40dc-a4a8-35a27ee98c45'})' execution failed: VDSGenericException: VDSErrorException: Failed to MeasureVolumeVDS, error = Command ['/usr/bin/qemu-img', 'measure', '--output', 'json', '-f', 'qcow2', '-O', 'qcow2', '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45'] failed with rc=1 out=b'' err=b"qemu-img: Could not open '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45': Could not open '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45': No such file or directory\n", code = 100 2020-04-10 09:39:35,936+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MeasureVolumeVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [disks_syncAction_a462dd75-f602-4315] FINISH, MeasureVolumeVDSCommand, return: , log id: 76a07dd2 2020-04-10 09:39:35,936+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.MeasureVolumeCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [disks_syncAction_a462dd75-f602-4315] Command 'org.ovirt.engine.core.bll.storage.disk.image.MeasureVolumeCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MeasureVolumeVDS, error = Command ['/usr/bin/qemu-img', 'measure', '--output', 'json', '-f', 'qcow2', '-O', 'qcow2', '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45'] failed with rc=1 out=b'' err=b"qemu-img: Could not open '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45': Could not open '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45': No such file or directory\n", code = 100 (Failed with error GeneralException and code 100) 2020-04-10 09:39:35,942+03 ERROR [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [disks_syncAction_a462dd75-f602-4315] Command 'CloneImageGroupVolumesStructure' id: 'b3e23002-9ffb-4ef2-be22-44b31fbc7a54' with children [] failed when attempting to perform the next operation, marking as 'ACTIVE' 2020-04-10 09:39:35,942+03 ERROR [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [disks_syncAction_a462dd75-f602-4315] Could not measure volume: java.lang.RuntimeException: Could not measure volume at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.CloneImageGroupVolumesStructureCommand.determineImageInitialSize(CloneImageGroupVolumesStructureCommand.java:214) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.CloneImageGroupVolumesStructureCommand.createImage(CloneImageGroupVolumesStructureCommand.java:163) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.CloneImageGroupVolumesStructureCommand.performNextOperation(CloneImageGroupVolumesStructureCommand.java:133) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback.childCommandsExecutionEnded(SerialChildCommandsExecutionCallback.java:32) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.ChildCommandsCallbackBase.doPolling(ChildCommandsCallbackBase.java:80) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:175) at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:109) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) at org.glassfish.javax.enterprise.concurrent.0.redhat-1//org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383) at org.glassfish.javax.enterprise.concurrent.0.redhat-1//org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) at org.glassfish.javax.enterprise.concurrent.0.redhat-1//org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250) VDSM: 2020-04-10 09:39:35,920+0300 INFO (jsonrpc/3) [vdsm.api] FINISH measure error=Command ['/usr/bin/qemu-img', 'measure', '--output', 'json', '-f', 'qcow2', '-O', 'qcow2', '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45'] failed with rc=1 out=b'' err=b"qemu-img: Could not open '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45': Could not open '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45': No such file or directory\n" from=::ffff:10.46.16.131,36538, flow_id=disks_syncAction_a462dd75-f602-4315, task_id=00882e57-aed1-448a-a151-c41f1d612e92 (api:52) 2020-04-10 09:39:35,921+0300 ERROR (jsonrpc/3) [storage.TaskManager.Task] (Task='00882e57-aed1-448a-a151-c41f1d612e92') 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-161>", line 2, in measure 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 3155, in measure output_format=sc.fmt2str(dest_format) File "/usr/lib/python3.6/site-packages/vdsm/storage/qemuimg.py", line 160, in measure out = _run_cmd(cmd) File "/usr/lib/python3.6/site-packages/vdsm/storage/qemuimg.py", line 481, in _run_cmd raise cmdutils.Error(cmd, rc, out, err) vdsm.common.cmdutils.Error: Command ['/usr/bin/qemu-img', 'measure', '--output', 'json', '-f', 'qcow2', '-O', 'qcow2', '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45'] failed with rc=1 out=b'' err=b"qemu-img: Could not open '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45': Could not open '/rhev/data-center/mnt/blockSD/69bdd640-605b-4987-9aac-7e389576f3dc/images/c2767b0f-f37a-4c33-9a70-162db91867da/3b3f36e3-8092-40dc-a4a8-35a27ee98c45': No such file or directory\n" Attaching relevant logs.
I missed a case where the VM is running (no need to prepare the image), but the host performing the measure is not the host the VM is running on. I'll post a patch now.
*** Bug 1823331 has been marked as a duplicate of this bug. ***
Verified on engine-4.4.0-0.33.master.el8ev and vdsm-4.40.13-1.el8ev.x86_64
This bugzilla is included in oVirt 4.4.0 release, published on May 20th 2020. Since the problem described in this bug report should be resolved in oVirt 4.4.0 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.