Created attachment 1517092 [details] engine + vdsm logs Description of problem: Cloning a VM from the 'Active VM' snapshot is allowed (bug?) but fails with 'Failed to get shared "write" lock\\nIs another process using the image?' From engine.log: 2018-12-27 18:38:04,164+02 INFO [org.ovirt.engine.core.bll.AddVmFromSnapshotCommand] (default task-32) [] Running command: AddVmFromSnapshotCommand internal: false. Entities affected : ID: 8c4a50a0-7bf2-442a-a5c0 -cb27f4e86b5b Type: ClusterAction group CREATE_VM with role type USER, ID: 477bcbc4-dfc5-4e10-831a-4d21207bd6fa Type: StorageAction group CREATE_DISK with role type USER, ID: 4000c700-6dbb-4515-9685-c9adc9f595fd Type: VMAction group CREATE_VM with role type USER 2018-12-27 18:38:04,333+02 INFO [org.ovirt.engine.core.bll.AddVmFromSnapshotCommand] (default task-32) [] Locking VM(id = '1a6358e0-7129-4d35-ae00-10ce0a923494') with compensation. 2018-12-27 18:38:04,338+02 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-32) [] START, SetVmStatusVDSCommand( SetVmStatusVDSCommandParameters:{vmId='1a6358e0-7129-4d35-ae00-10ce0a92349 4', status='ImageLocked', exitStatus='Normal'}), log id: 796ef0ca 2018-12-27 18:38:04,347+02 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-32) [] FINISH, SetVmStatusVDSCommand, return: , log id: 796ef0ca 2018-12-27 18:38:04,359+02 INFO [org.ovirt.engine.core.bll.AddVmFromSnapshotCommand] (default task-32) [] Lock freed to object 'EngineLock:{exclusiveLocks='[4000c700-6dbb-4515-9685-c9adc9f595fd=VM, test_clone_from _active_snap=VM_NAME]', sharedLocks=''}' 2018-12-27 18:38:04,485+02 INFO [org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] Running command: CopyImageGroupCommand internal: true. Entities affected : ID: 477bcbc4-dfc5-4e10-831a-4d21207bd6fa Type: Storage 2018-12-27 18:38:04,616+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] START, CopyImageVDSCommand( CopyImageVDSCommandParameters:{s toragePoolId='e29849e3-d38a-460d-aac2-e6f8c44a3615', ignoreFailoverLimit='false', storageDomainId='477bcbc4-dfc5-4e10-831a-4d21207bd6fa', imageGroupId='268bd036-fa42-4af2-a59b-75830e69bca1', imageId='ba8e2406-08cd- 4cdb-9ccf-bce8f13599a2', dstImageGroupId='6a3b6bc2-f851-485f-8464-8ed49f960ea3', vmId='1a6358e0-7129-4d35-ae00-10ce0a923494', dstImageId='a57ece86-813a-44b8-8cce-f821b7950e98', imageDescription='', dstStorageDomain Id='477bcbc4-dfc5-4e10-831a-4d21207bd6fa', copyVolumeType='LeafVol', volumeFormat='COW', preallocate='Sparse', postZero='false', discard='true', force='false'}), log id: 4598a54d 2018-12-27 18:38:04,620+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] -- executeIrsBrokerCommand: calling 'copyImage' with two new parameters: description and UUID. Parameters: 2018-12-27 18:38:04,620+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] ++ sdUUID=477bcbc4-dfc5-4e10-831a-4d21207bd6fa 2018-12-27 18:38:04,620+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] ++ spUUID=e29849e3-d38a-460d-aac2-e6f8c44a3615 2018-12-27 18:38:04,620+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] ++ vmGUID=1a6358e0-7129-4d35-ae00-10ce0a923494 2018-12-27 18:38:04,620+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] ++ srcImageGUID=268bd036-fa42-4af2-a59b-75830e69bca1 2018-12-27 18:38:04,620+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] ++ srcVolUUID=ba8e2406-08cd-4cdb-9ccf-bce8f13599a2 2018-12-27 18:38:04,620+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] ++ dstImageGUID=6a3b6bc2-f851-485f-8464-8ed49f960ea3 2018-12-27 18:38:04,620+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] ++ dstVolUUID=a57ece86-813a-44b8-8cce-f821b7950e98 2018-12-27 18:38:04,620+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] ++ descr= 2018-12-27 18:38:04,620+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] ++ dstSdUUID=477bcbc4-dfc5-4e10-831a-4d21207bd6fa 2018-12-27 18:38:05,777+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] FINISH, CopyImageVDSCommand, return: 2e865c4a-b696-41bb-aec6-ad539e132635, log id: 4598a54d 2018-12-27 18:38:05,789+02 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command '955f8a73-0039-47ea-b282-e58f0fcf6524' 2018-12-27 18:38:05,789+02 INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] CommandMultiAsyncTasks::attachTask: Attaching task '2e865c4a-b696-41bb-aec6-ad539e132635' to command '955f8a73-0039-47ea-b282-e58f0fcf6524'. 2018-12-27 18:38:05,818+02 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] Adding task '2e865c4a-b696-41bb-aec6-ad539e132635' (Parent Command 'AddVmFromSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet.. 2018-12-27 18:38:05,959+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] EVENT_ID: USER_ADD_VM_STARTED(37), VM test_clone_from_active_snap creation was initiated by admin@internal-authz. 2018-12-27 18:38:05,960+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (default task-32) [1dfec5d8-0c0b-479f-9604-212525e7ed0a] BaseAsyncTask::startPollingTask: Starting to poll task '2e865c4a-b696-41bb-aec6-ad539e132635'. 2018-12-27 18:38:06,032+02 INFO [org.ovirt.engine.core.bll.aaa.LogoutSessionCommand] (default task-32) [41150a2c] Running command: LogoutSessionCommand internal: false. 2018-12-27 18:38:06,044+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-32) [41150a2c] EVENT_ID: USER_VDC_LOGOUT(31), User admin@internal-authz connected from '10.35.20 6.52' using session 'x+l3zJkGZfImwtGmNfAc45v1bYIlam80Hy5h/llhV+8HKN0DNyy5EwG00NpFK7ICVnMuTBAmCB2e/RKM3eE9jQ==' logged out. 2018-12-27 18:38:08,471+02 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-18) [] Setting new tasks map. The map contains now 4 tasks 2018-12-27 18:38:09,923+02 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-75) [] Polling and updating Async Tasks: 4 tasks, 1 tasks to poll now 2018-12-27 18:38:09,951+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-75) [] Failed in 'HSMGetAllTasksStatusesVDS' method 2018-12-27 18:38:09,954+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-75) [] SPMAsyncTask::PollTask: Polling task '2e865c4a-b696-41bb-aec6-ad539e132635' (Pa rent Command 'AddVmFromSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'running'. 2018-12-27 18:38:09,954+02 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-75) [] Finished polling Tasks, will poll again in 10 seconds. 2018-12-27 18:38:19,991+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-92) [] Failed in 'HSMGetAllTasksStatusesVDS' method 2018-12-27 18:38:20,006+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-92) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host _mixed_2 command HSMGetAllTasksStatusesVDS failed: low level Image copy failed: ('Command [\'/usr/bin/qemu-img\', \'convert\', \'-p\', \'-t\', \'none\', \'-T\', \'none\', \'-f\', \'qcow2\', u\'/rhev/data-center/mnt /yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/55fd67de-db7c-447f-b75f-4b34f8e51df4/42b2d93f-2aa6-49fd-8d42-3e5097bb2b6c\', \'-O\', \'qcow2\ ', \'-o\', \'compat=1.1\', u\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/1dd5b042-828b-4415-a62e-3da743be4ead/688fa 83e-d223-4fa6-864f-fd4903c810f5\'] failed with rc=1 out=\'\' err=bytearray(b\'qemu-img: Could not open \\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a- a457-4e11-92f3-bc4d8e4eaccc/images/55fd67de-db7c-447f-b75f-4b34f8e51df4/42b2d93f-2aa6-49fd-8d42-3e5097bb2b6c\\\': Failed to get shared "write" lock\\nIs another process using the image?\\n\')',) 2018-12-27 18:38:30,048+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-81) [] Failed in 'HSMGetAllTasksStatusesVDS' method 2018-12-27 18:38:40,077+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-51) [] Failed in 'HSMGetAllTasksStatusesVDS' method 2018-12-27 18:38:50,105+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-86) [] Failed in 'HSMGetAllTasksStatusesVDS' method 2018-12-27 18:38:50,116+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-86) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host _mixed_2 command HSMGetAllTasksStatusesVDS failed: low level Image copy failed: ('Command [\'/usr/bin/qemu-img\', \'convert\', \'-p\', \'-t\', \'none\', \'-T\', \'none\', \'-f\', \'qcow2\', u\'/rhev/data-center/mnt /yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/55fd67de-db7c-447f-b75f-4b34f8e51df4/42b2d93f-2aa6-49fd-8d42-3e5097bb2b6c\', \'-O\', \'qcow2\ ', \'-o\', \'compat=1.1\', u\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/1dd5b042-828b-4415-a62e-3da743be4ead/688fa 83e-d223-4fa6-864f-fd4903c810f5\'] failed with rc=1 out=\'\' err=bytearray(b\'qemu-img: Could not open \\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a- a457-4e11-92f3-bc4d8e4eaccc/images/55fd67de-db7c-447f-b75f-4b34f8e51df4/42b2d93f-2aa6-49fd-8d42-3e5097bb2b6c\\\': Failed to get shared "write" lock\\nIs another process using the image?\\n\')',) vdsm.log: 2018-12-27 18:38:19,966+0200 DEBUG (jsonrpc/5) [storage.TaskManager] Return. Response: {'code': 261, 'message': 'low level Image copy failed: (\'Command [\\\'/usr/bin/qemu-img\\\', \\\'convert\\\', \\\'-p\\\', \\\'-t\\\', \\\'none\\\', \\\'-T\\\', \\\'none\\\', \\\'-f\\\', \\\'qcow2\\\', u\\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/55fd67de-db7c-447f-b75f-4b34f8e51df4/42b2d93f-2aa6-49fd-8d42-3e5097bb2b6c\\\', \\\'-O\\\', \\\'qcow2\\\', \\\'-o\\\', \\\'compat=1.1\\\', u\\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/1dd5b042-828b-4415-a62e-3da743be4ead/688fa83e-d223-4fa6-864f-fd4903c810f5\\\'] failed with rc=1 out=\\\'\\\' err=bytearray(b\\\'qemu-img: Could not open \\\\\\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/55fd67de-db7c-447f-b75f-4b34f8e51df4/42b2d93f-2aa6-49fd-8d42-3e5097bb2b6c\\\\\\\': Failed to get shared "write" lock\\\\nIs another process using the image?\\\\n\\\')\',)', 'taskState': 'finished', 'taskResult': 'cleanSuccess', 'taskID': '09289b8e-3655-46a3-9f93-633528aa2bba'} (taskManager:106) 2018-12-27 18:38:19,966+0200 DEBUG (jsonrpc/5) [storage.TaskManager] Entry. taskID: 2e865c4a-b696-41bb-aec6-ad539e132635 (taskManager:103) 2018-12-27 18:38:19,967+0200 DEBUG (jsonrpc/5) [storage.TaskManager] Return. Response: {'code': 0, 'message': 'running job 1 of 1', 'taskState': 'running', 'taskResult': '', 'taskID': '2e865c4a-b696-41bb-aec6-ad539e132635'} (taskManager:106) 2018-12-27 18:38:19,967+0200 DEBUG (jsonrpc/5) [storage.TaskManager] Return: {'09289b8e-3655-46a3-9f93-633528aa2bba': {'code': 261, 'message': 'low level Image copy failed: (\'Command [\\\'/usr/bin/qemu-img\\\', \\\'convert\\\', \\\'-p\\\', \\\'-t\\\', \\\'none\\\', \\\'-T\\\', \\\'none\\\', \\\'-f\\\', \\\'qcow2\\\', u\\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/55fd67de-db7c-447f-b75f-4b34f8e51df4/42b2d93f-2aa6-49fd-8d42-3e5097bb2b6c\\\', \\\'-O\\\', \\\'qcow2\\\', \\\'-o\\\', \\\'compat=1.1\\\', u\\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/1dd5b042-828b-4415-a62e-3da743be4ead/688fa83e-d223-4fa6-864f-fd4903c810f5\\\'] failed with rc=1 out=\\\'\\\' err=bytearray(b\\\'qemu-img: Could not open \\\\\\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/55fd67de-db7c-447f-b75f-4b34f8e51df4/42b2d93f-2aa6-49fd-8d42-3e5097bb2b6c\\\\\\\': Failed to get shared "write" lock\\\\nIs another process using the image?\\\\n\\\')\',)', 'taskState': 'finished', 'taskResult': 'cleanSuccess', 'taskID': '09289b8e-3655-46a3-9f93-633528aa2bba'}, '2e865c4a-b696-41bb-aec6-ad539e132635': {'code': 0, 'message': 'running job 1 of 1', 'taskState': 'running', 'taskResult': '', 'taskID': '2e865c4a-b696-41bb-aec6-ad539e132635'}, '1e89842b-3c9d-46e2-aac9-21f52a50522a': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '1e89842b-3c9d-46e2-aac9-21f52a50522a'}} (taskManager:123) 2018-12-27 18:38:19,967+0200 INFO (jsonrpc/5) [vdsm.api] FINISH getAllTasksStatuses return={'allTasksStatus': {'09289b8e-3655-46a3-9f93-633528aa2bba': {'code': 261, 'message': 'low level Image copy failed: (\'Command [\\\'/usr/bin/qemu-img\\\', \\\'convert\\\', \\\'-p\\\', \\\'-t\\\', \\\'none\\\', \\\'-T\\\', \\\'none\\\', \\\'-f\\\', \\\'qcow2\\\', u\\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/55fd67de-db7c-447f-b75f-4b34f8e51df4/42b2d93f-2aa6-49fd-8d42-3e5097bb2b6c\\\', \\\'-O\\\', \\\'qcow2\\\', \\\'-o\\\', \\\'compat=1.1\\\', u\\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/1dd5b042-828b-4415-a62e-3da743be4ead/688fa83e-d223-4fa6-864f-fd4903c810f5\\\'] failed with rc=1 out=\\\'\\\' err=bytearray(b\\\'qemu-img: Could not open \\\\\\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/55fd67de-db7c-447f-b75f-4b34f8e51df4/42b2d93f-2aa6-49fd-8d42-3e5097bb2b6c\\\\\\\': Failed to get shared "write" lock\\\\nIs another process using the image?\\\\n\\\')\',)', 'taskState': 'finished', 'taskResult': 'cleanSuccess', 'taskID': '09289b8e-3655-46a3-9f93-633528aa2bba'}, '2e865c4a-b696-41bb-aec6-ad539e132635': {'code': 0, 'message': 'running job 1 of 1', 'taskState': 'running', 'taskResult': '', 'taskID': '2e865c4a-b696-41bb-aec6-ad539e132635'}, '1e89842b-3c9d-46e2-aac9-21f52a50522a': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '1e89842b-3c9d-46e2-aac9-21f52a50522a'}}} from=::ffff:10.35.161.131,55256, task_id=7ba905e0-7970-4d1f-af2e-3104bcac2ac7 (api:54) 2018-12-27 18:38:19,967+0200 DEBUG (jsonrpc/5) [storage.TaskManager.Task] (Task='7ba905e0-7970-4d1f-af2e-3104bcac2ac7') finished: {'allTasksStatus': {'09289b8e-3655-46a3-9f93-633528aa2bba': {'code': 261, 'message': 'low level Image copy failed: (\'Command [\\\'/usr/bin/qemu-img\\\', \\\'convert\\\', \\\'-p\\\', \\\'-t\\\', \\\'none\\\', \\\'-T\\\', \\\'none\\\', \\\'-f\\\', \\\'qcow2\\\', u\\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/55fd67de-db7c-447f-b75f-4b34f8e51df4/42b2d93f-2aa6-49fd-8d42-3e5097bb2b6c\\\', \\\'-O\\\', \\\'qcow2\\\', \\\'-o\\\', \\\'compat=1.1\\\', u\\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/1dd5b042-828b-4415-a62e-3da743be4ead/688fa83e-d223-4fa6-864f-fd4903c810f5\\\'] failed with rc=1 out=\\\'\\\' err=bytearray(b\\\'qemu-img: Could not open \\\\\\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge5__nfs__0/b47c573a-a457-4e11-92f3-bc4d8e4eaccc/images/55fd67de-db7c-447f-b75f-4b34f8e51df4/42b2d93f-2aa6-49fd-8d42-3e5097bb2b6c\\\\\\\': Failed to get shared "write" lock\\\\nIs another process using the image?\\\\n\\\')\',)', 'taskState': 'finished', 'taskResult': 'cleanSuccess', 'taskID': '09289b8e-3655-46a3-9f93-633528aa2bba'}, '2e865c4a-b696-41bb-aec6-ad539e132635': {'code': 0, 'message': 'running job 1 of 1', 'taskState': 'running', 'taskResult': '', 'taskID': '2e865c4a-b696-41bb-aec6-ad539e132635'}, '1e89842b-3c9d-46e2-aac9-21f52a50522a': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '1e89842b-3c9d-46e2-aac9-21f52a50522a'}}} (task:1201) Version-Release number of selected component (if applicable): ovirt-engine-4.3.0-0.6.alpha2.el7 How reproducible: 100% Steps to Reproduce: 1. Clone VM A from template as thin copy 2. Clone VM B from 'Active VM' snapshot of VM A 3. Actual results: Expected results: Additional info: This is a regression as there were many bugs in the past that already fixed (https://bugzilla.redhat.com/show_bug.cgi?id=1654804 , https://bugzilla.redhat.com/show_bug.cgi?id=1431613 )
Created attachment 1517521 [details] logs and db dump After the attempt to clone a VM out of an Active VM snapshot, the cloned VM is left in locked state engine=# select status, vm_name from vms; -[ RECORD 1 ]---------------------- status | 15 vm_name | vm_random_test_3021101806 -[ RECORD 2 ]---------------------- status | 1 vm_name | vm_random_test_3020553723 -[ RECORD 3 ]---------------------- status | 0 vm_name | vm_random_test_3021040024 2018-12-30 21:10:23,535+0200 ERROR (tasks/5) [storage.TaskManager.Task] (Task='7534ab53-ecaf-4dbd-9503-84a7c5f91a72') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 336, in run return self.cmd(*self.argslist, **self.argsdict) File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line 79, in wrapper return method(self, *args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/sp.py", line 1622, in copyImage postZero, force, discard) File "/usr/lib/python2.7/site-packages/vdsm/storage/image.py", line 836, in copyCollapsed raise se.CopyImageError(str(e)) CopyImageError: low level Image copy failed: ('Command [\'/usr/bin/qemu-img\', \'convert\', \'-p\', \'-t\', \'none\', \'-T\', \'none\', \'-f\', \'qcow2\', u\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.c om:_Storage__NFS_storage__local__ge6__nfs__2/5328b0ae-7b2e-41dc-b726-4bc5425867b4/images/cdfc2480-e2bf-4316-8b51-928ab347950f/2de67c2e-d3ab-482d-88a0-fd12138c4264\', \'-O\', \'qcow2\', \'-o\', \'compat=1.1\', u\ '/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge6__nfs__2/5328b0ae-7b2e-41dc-b726-4bc5425867b4/images/f4346334-0291-4fde-a861-b8a49023847f/6b856072-f558-4be4-857b-2516a45 d8e9e\'] failed with rc=1 out=\'\' err=bytearray(b\'qemu-img: Could not open \\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge6__nfs__2/5328b0ae-7b2e-41dc-b726-4bc54258 67b4/images/cdfc2480-e2bf-4316-8b51-928ab347950f/2de67c2e-d3ab-482d-88a0-fd12138c4264\\\': Failed to get shared "write" lock\\nIs another process using the image?\\n\')',) 2018-12-30 21:38:43,614+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] Failed in 'HSMGetAllTasksStatusesVDS' method 2018-12-30 21:38:43,626+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM h ost_mixed_2 command HSMGetAllTasksStatusesVDS failed: low level Image copy failed: ('Command [\'/usr/bin/qemu-img\', \'convert\', \'-p\', \'-t\', \'none\', \'-T\', \'none\', \'-f\', \'qcow2\', u\'/rhev/data-cent er/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge6__nfs__2/5328b0ae-7b2e-41dc-b726-4bc5425867b4/images/cdfc2480-e2bf-4316-8b51-928ab347950f/2de67c2e-d3ab-482d-88a0-fd12138c4264\', \'-O\', \'qcow2\', \'-o\', \'compat=1.1\', u\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge6__nfs__2/5328b0ae-7b2e-41dc-b726-4bc5425867b4/images/f4346334-0291-4fde-a861-b8a490 23847f/6b856072-f558-4be4-857b-2516a45d8e9e\'] failed with rc=1 out=\'\' err=bytearray(b\'qemu-img: Could not open \\\'/rhev/data-center/mnt/yellow-vdsb.qa.lab.tlv.redhat.com:_Storage__NFS_storage__local__ge6__n fs__2/5328b0ae-7b2e-41dc-b726-4bc5425867b4/images/cdfc2480-e2bf-4316-8b51-928ab347950f/2de67c2e-d3ab-482d-88a0-fd12138c4264\\\': Failed to get shared "write" lock\\nIs another process using the image?\\n\')',) 2018-12-30 21:38:43,628+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] SPMAsyncTask::PollTask: Polling task '923c36c1-66c4-487c-8813-3ccfd47ce369' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'success'.
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.
Thanks Shani. Please consider adding validation also for cloning a VM out of the 'Active VM before preview' and the 'Next run configuration' snapshots (reported in bug 1575913 and bug 1626278).
This patch should deal with those (as those snapshots are not regular snapshots)
Verified on engine 4.3.0-0.8.rc2.el7
This bugzilla is included in oVirt 4.3.0 release, published on February 4th 2019. Since the problem described in this bug report should be resolved in oVirt 4.3.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.