Created attachment 1348166 [details] engine and vdsm logs Description of problem: In our automation (tier 2) I see that live merge with continuous I/O to the VM is fail to deactivate the logical volume before the merge: 2017-11-05 00:06:34,109+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-10) [] EVENT_ID: USER_REMOVE_SNAPSHOT(342), Correlation ID: snapshots_delete_026d2ba2-14b2-49a3, Job ID: 7b6df575-b778-4 df9-ae3e-382923a3f9f4, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: Snapshot 'snapshot_6052_iscsi_0' deletion for VM 'vm_TestCase6052_REST_ISCSI_0423581301' was initiated by admin@internal-authz. 2017-11-05 00:06:34,121+02 INFO [org.ovirt.engine.core.bll.storage.disk.RemoveDiskCommand] (pool-5-thread-8) [6f4d211] Lock Acquired to object 'EngineLock:{exclusiveLocks='[18781153-8218-4ef9-887a-7cb9439a416d=DISK]', sharedLocks=''}' 2017-11-05 00:06:34,123+02 INFO [org.ovirt.engine.core.bll.storage.disk.RemoveDiskCommand] (pool-5-thread-8) [6f4d211] Running command: RemoveDiskCommand internal: true. Entities affected : ID: 18781153-8218-4ef9-887a-7cb9439a416d Type: DiskAction group DELETE_DISK with role type USER 2017-11-05 00:06:34,128+02 INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (pool-5-thread-8) [6f4d211] Running command: RemoveImageCommand internal: true. Entities affected : ID: 5ca8f689-f221-4bb9-a40d-427e0842b5 e0 Type: Storage 2017-11-05 00:06:34,188+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (pool-5-thread-8) [6f4d211] START, DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{runAsync='true', storagePoolId='b a89c324-5818-4846-95f6-7fd7e29cc147', ignoreFailoverLimit='false', storageDomainId='5ca8f689-f221-4bb9-a40d-427e0842b5e0', imageGroupId='18781153-8218-4ef9-887a-7cb9439a416d', postZeros='false', discard='false', forceDelete='false'}), log id: cc94caa 2017-11-05 00:06:34,802+02 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler2) [snapshots_delete_026d2ba2-14b2-49a3] Executing Live Merge command step 'EXTEND' 2017-11-05 00:06:34,818+02 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler2) [snapshots_delete_026d2ba2-14b2-49a3] Executing Live Merge command step 'EXTEND' 2017-11-05 00:06:34,823+02 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (pool-5-thread-9) [snapshots_delete_026d2ba2-14b2-49a3] Running command: MergeExtendCommand internal: true. Entities affected : ID: 5ca8f689-f221-4bb9-a40d-4 27e0842b5e0 Type: Storage 2017-11-05 00:06:34,824+02 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (pool-5-thread-9) [snapshots_delete_026d2ba2-14b2-49a3] Base and top image sizes are the same; no extension required 2017-11-05 00:06:34,835+02 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler2) [snapshots_delete_026d2ba2-14b2-49a3] Executing Live Merge command step 'EXTEND' 2017-11-05 00:06:34,840+02 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (pool-5-thread-10) [snapshots_delete_026d2ba2-14b2-49a3] Running command: MergeExtendCommand internal: true. Entities affected : ID: 5ca8f689-f221-4bb9-a40d- 427e0842b5e0 Type: Storage 2017-11-05 00:06:34,840+02 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (pool-5-thread-10) [snapshots_delete_026d2ba2-14b2-49a3] Base and top image sizes are the same; no image size update required 2017-11-05 00:06:34,851+02 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler2) [snapshots_delete_026d2ba2-14b2-49a3] Executing Live Merge command step 'EXTEND' 2017-11-05 00:06:34,875+02 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler2) [snapshots_delete_026d2ba2-14b2-49a3] Command 'RemoveSnapshot' (id: '82b23698-504e-49b8-b982-bde4c2f202e3') waiting on child command id: '5da880ff-1c26-457c-9d4f-e6ffc5b2284a' type:'RemoveSnapshotSingleDiskLive' to complete 2017-11-05 00:06:34,877+02 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (pool-5-thread-1) [snapshots_delete_026d2ba2-14b2-49a3] Running command: MergeExtendCommand internal: true. Entities affected : ID: 5ca8f689-f221-4bb9-a40d-427e0842b5e0 Type: Storage 2017-11-05 00:06:34,877+02 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (pool-5-thread-1) [snapshots_delete_026d2ba2-14b2-49a3] Base and top image sizes are the same; no extension required 2017-11-05 00:06:34,880+02 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler2) [snapshots_delete_026d2ba2-14b2-49a3] Executing Live Merge command step 'EXTEND' 2017-11-05 00:06:34,880+02 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (pool-5-thread-3) [snapshots_delete_026d2ba2-14b2-49a3] Running command: MergeExtendCommand internal: true. Entities affected : ID: 5ca8f689-f221-4bb9-a40d-427e0842b5e0 Type: Storage 2017-11-05 00:06:34,880+02 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (pool-5-thread-3) [snapshots_delete_026d2ba2-14b2-49a3] Base and top image sizes are the same; no image size update required 2017-11-05 00:06:34,904+02 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (pool-5-thread-2) [snapshots_delete_026d2ba2-14b2-49a3] Running command: MergeExtendCommand internal: true. Entities affected : ID: 5ca8f689-f221-4bb9-a40d-427e0842b5e0 Type: Storage 2017-11-05 00:06:34,904+02 INFO [org.ovirt.engine.core.bll.MergeExtendCommand] (pool-5-thread-2) [snapshots_delete_026d2ba2-14b2-49a3] Base and top image sizes are the same; no image size update required 2017-11-05 00:06:35,900+02 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler4) [snapshots_delete_026d2ba2-14b2-49a3] Executing Live Merge command step 'MERGE' 2017-11-05 00:06:35,926+02 INFO [org.ovirt.engine.core.bll.MergeCommand] (pool-5-thread-4) [snapshots_delete_026d2ba2-14b2-49a3] Running command: MergeCommand internal: true. Entities affected : ID: 5ca8f689-f221-4bb9-a40d-427e0842b5e0 Type: Storage 2017-11-05 00:06:35,927+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-4) [snapshots_delete_026d2ba2-14b2-49a3] START, MergeVDSCommand(HostName = host_mixed_2, MergeVDSCommandParameters:{runAsync='true', hostId='fe556f2e-c5aa-411f-b113-bdb6815921f8', vmId='a697823e-3edf-4fa0-baa7-b57a509cbc9e', storagePoolId='ba89c324-5818-4846-95f6-7fd7e29cc147', storageDomainId='5ca8f689-f221-4bb9-a40d-427e0842b5e0', imageGroupId='d81ef79b-5eed-4af0-a5a5-b0205cf5ef90', imageId='c704290f-0be7-45e2-a223-a9da81ffd605', baseImageId='8a5b1082-5c18-4685-9671-0a233e22af1e', topImageId='23f403d2-3122-48c9-b024-983fef2a2d1d', bandwidth='0'}), log id: 37d47c81 2017-11-05 00:06:35,930+02 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler4) [snapshots_delete_026d2ba2-14b2-49a3] Executing Live Merge command step 'MERGE' 2017-11-05 00:06:35,947+02 INFO [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler4) [snapshots_delete_026d2ba2-14b2-49a3] Executing Live Merge command step 'MERGE' 2017-11-05 00:06:35,956+02 INFO [org.ovirt.engine.core.bll.MergeCommand] (pool-5-thread-5) [snapshots_delete_026d2ba2-14b2-49a3] Running command: MergeCommand internal: true. Entities affected : ID: 5ca8f689-f221-4bb9-a40d-427e0842b5e0 Type: Storage 2017-11-05 00:06:35,957+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-5) [snapshots_delete_026d2ba2-14b2-49a3] START, MergeVDSCommand(HostName = host_mixed_2, MergeVDSCommandParameters:{runAsync='true', hostId='fe556f2e-c5aa-411f-b113-bdb6815921f8', vmId='a697823e-3edf-4fa0-baa7-b57a509cbc9e', storagePoolId='ba89c324-5818-4846-95f6-7fd7e29cc147', storageDomainId='5ca8f689-f221-4bb9-a40d-427e0842b5e0', imageGroupId='8e760f97-b373-4fb8-b728-6f3cd49c7d35', imageId='1dcbe294-91b4-4dde-a08d-df7b640428f7', baseImageId='fc56d6a1-7691-4fd6-a57d-2d3c0fce160e', topImageId='035ee374-0c13-4b3f-9111-396adc9ceea9', bandwidth='0'}), log id: 1d49939e 2017-11-05 00:06:35,971+02 INFO [org.ovirt.engine.core.bll.MergeCommand] (pool-5-thread-6) [snapshots_delete_026d2ba2-14b2-49a3] Running command: MergeCommand internal: true. Entities affected : ID: 5ca8f689-f221-4bb9-a40d-427e0842b5e0 Type: Storage 2017-11-05 00:06:35,971+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-6) [snapshots_delete_026d2ba2-14b2-49a3] START, MergeVDSCommand(HostName = host_mixed_2, MergeVDSCommandParameters:{runAsync='true', hostId='fe556f2e-c5aa-411f-b113-bdb6815921f8', vmId='a697823e-3edf-4fa0-baa7-b57a509cbc9e', storagePoolId='ba89c324-5818-4846-95f6-7fd7e29cc147', storageDomainId='5ca8f689-f221-4bb9-a40d-427e0842b5e0', imageGroupId='1dc5df63-7b25-4f8d-8e0d-4f343c9527d2', imageId='7ba7c5ae-7bdf-46cb-bc59-87f69c879d08', baseImageId='571e1c03-697b-4753-be0b-1508bf378aaa', topImageId='d2e3d27b-46ac-46bc-a9ee-c6e49c8d1973', bandwidth='0'}), log id: 1264fa78 2017-11-05 00:06:36,687+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-5) [snapshots_delete_026d2ba2-14b2-49a3] Failed in 'MergeVDS' method 2017-11-05 00:06:36,693+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-5-thread-5) [snapshots_delete_026d2ba2-14b2-49a3] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), Correlation ID: null, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: VDSM host_mixed_2 command MergeVDS failed: Merge failed 2017-11-05 00:06:36,693+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-5) [snapshots_delete_026d2ba2-14b2-49a3] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand' return value 'StatusOnlyReturn [status=Status [code=52, message=Merge failed]]' 2017-11-05 00:06:36,694+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-5) [snapshots_delete_026d2ba2-14b2-49a3] HostName = host_mixed_2 2017-11-05 00:06:36,694+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-5) [snapshots_delete_026d2ba2-14b2-49a3] Command 'MergeVDSCommand(HostName = host_mixed_2, MergeVDSCommandParameters:{runAsync='true', hostId='fe556f2e-c5aa-411f-b113-bdb6815921f8', vmId='a697823e-3edf-4fa0-baa7-b57a509cbc9e', storagePoolId='ba89c324-5818-4846-95f6-7fd7e29cc147', storageDomainId='5ca8f689-f221-4bb9-a40d-427e0842b5e0', imageGroupId='8e760f97-b373-4fb8-b728-6f3cd49c7d35', imageId='1dcbe294-91b4-4dde-a08d-df7b640428f7', baseImageId='fc56d6a1-7691-4fd6-a57d-2d3c0fce160e', topImageId='035ee374-0c13-4b3f-9111-396adc9ceea9', bandwidth='0'})' execution failed: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52 2017-11-05 00:06:36,694+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-5) [snapshots_delete_026d2ba2-14b2-49a3] FINISH, MergeVDSCommand, log id: 1d49939e 2017-11-05 00:06:36,694+02 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-5-thread-5) [snapshots_delete_026d2ba2-14b2-49a3] Engine exception thrown while sending merge command: org.ovirt.engine.core.common.errors.EngineException: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52 (Failed with error mergeErr and code 52) at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:118) [bll.jar:] In vdsm.log: 2017-11-05 00:05:53,729+0200 DEBUG (jsonrpc/0) [storage.Misc.excCmd] FAILED: <err> = ' Logical volume 5ca8f689-f221-4bb9-a40d-427e0842b5e0/8a5b1082-5c18-4685-9671-0a233e22af1e in use.\n Logical volume 5ca8f689-f221-4bb9-a40d-427e0842b5e 0/23f403d2-3122-48c9-b024-983fef2a2d1d in use.\n Logical volume 5ca8f689-f221-4bb9-a40d-427e0842b5e0/96b8ff51-6f78-4d45-8ec5-2c34869ea3b0 in use.\n Logical volume 5ca8f689-f221-4bb9-a40d-427e0842b5e0/c704290f-0be7-45e2-a223-a9da81ffd605 in use.\n'; <rc> = 5 (commands:93) 2017-11-05 00:05:53,729+0200 INFO (jsonrpc/0) [vdsm.api] FINISH teardownImage error=Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\' Logical volume 5ca8f689-f221-4bb9-a40d-427e0842b5e0/8a5b1082-5c18-4685-9671-0a 233e22af1e in use.\', \' Logical volume 5ca8f689-f221-4bb9-a40d-427e0842b5e0/23f403d2-3122-48c9-b024-983fef2a2d1d in use.\', \' Logical volume 5ca8f689-f221-4bb9-a40d-427e0842b5e0/96b8ff51-6f78-4d45-8ec5-2c34869ea3b0 in use.\', \' Logi cal volume 5ca8f689-f221-4bb9-a40d-427e0842b5e0/c704290f-0be7-45e2-a223-a9da81ffd605 in use.\']\\n5ca8f689-f221-4bb9-a40d-427e0842b5e0/[\'c704290f-0be7-45e2-a223-a9da81ffd605\', \'23f403d2-3122-48c9-b024-983fef2a2d1d\', \'8a5b1082-5c18-46 85-9671-0a233e22af1e\', \'96b8ff51-6f78-4d45-8ec5-2c34869ea3b0\']",)',) from=::ffff:10.35.69.94,46012, flow_id=snapshots_create_348e3da8-9f44-482f, task_id=ff0b6860-c43f-4423-8d6e-a898def7a001 (api:50) 2017-11-05 00:05:53,730+0200 ERROR (jsonrpc/0) [storage.TaskManager.Task] (Task='ff0b6860-c43f-4423-8d6e-a898def7a001') Unexpected error (task:872) Traceback (most recent call last): File "/usr/share/vdsm/storage/task.py", line 879, in _run return fn(*args, **kargs) File "<string>", line 2, in teardownImage File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs) File "/usr/share/vdsm/storage/hsm.py", line 3189, in teardownImage dom.deactivateImage(imgUUID) File "/usr/share/vdsm/storage/blockSD.py", line 1289, in deactivateImage lvm.deactivateLVs(self.sdUUID, volUUIDs) File "/usr/share/vdsm/storage/lvm.py", line 1304, in deactivateLVs _setLVAvailability(vgName, toDeactivate, "n") File "/usr/share/vdsm/storage/lvm.py", line 843, in _setLVAvailability raise error(str(e)) CannotDeactivateLogicalVolume: Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\' Logical volume 5ca8f689-f221-4bb9-a40d-427e0842b5e0/8a5b1082-5c18-4685-9671-0a233e22af1e in use.\', \' Logical volume 5ca8f689-f221-4bb9-a40d-427e0842b5e0/23f403d2-3122-48c9-b024-983fef2a2d1d in use.\', \' Logical volume 5ca8f689-f221-4bb9-a40d-427e0842b5e0/96b8ff51-6f78-4d45-8ec5-2c34869ea3b0 in use.\', \' Logical volume 5ca8f689-f221-4bb9-a40d-427e0842b5e0/c704290f-0be7-45e2-a223-a9da81ffd605 in use.\']\\n5ca8f689-f221-4bb9-a40d-427e0842b5e0/[\'c704290f-0be7-45e2-a223-a9da81ffd605\', \'23f403d2-3122-48c9-b024-983fef2a2d1d\', \'8a5b1082-5c18-4685-9671-0a233e22af1e\', \'96b8ff51-6f78-4d45-8ec5-2c34869ea3b0\']",)',) Version-Release number of selected component (if applicable): vdsm-4.19.36-1.el7ev.x86_64 ovirt-engine-4.1.7.6-0.1.el7.noarch How reproducible: Unknown Steps to Reproduce: 1. Create VM with disk + OS 2. Add 4 disks to VM 3. Create live snapshot 4. Perform dd from the OS disk to one of the other disks 5. Try to live merge the snapshot Actual results: Expected results: Additional info:
@Raz, The CannotDeactivateLogicalVolume reported above happened at 00:05:53, while the merge command started at 00:06:35, see below: 2017-11-05 00:06:35,926+0200 INFO (jsonrpc/6) [vdsm.api] START merge(driveSpec={'poolID': 'ba89c324-5818-4846-95f6-7fd7e29cc147', 'volumeID': 'c704290f-0be7-45e2-a223-a9da81ffd605', 'domain Looking at vdsm log, I see a different error failing live merge: 2017-11-05 00:06:36,747+0200 ERROR (jsonrpc/6) [virt.vm] (vmId='a697823e-3edf-4fa0-baa7-b57a509cbc9e') Live merge failed (job: e268d75b-aaaf-462e-affa-513ce57ce5f3) (vm:4926) Traceback (most recent call last): File "/usr/share/vdsm/virt/vm.py", line 4924, in merge bandwidth, flags) File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 69, in f ret = attr(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line 123, in wrapper ret = f(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 1006, in wrapper return func(inst, *args, **kwargs) File "/usr/lib64/python2.7/site-packages/libvirt.py", line 678, in blockCommit if ret == -1: raise libvirtError ('virDomainBlockCommit() failed', dom=self) libvirtError: internal error: unable to execute QEMU command 'block-commit': Could not reopen file: Permission denied The error here looks very similar to the one reported in BZ 1506072. Which libvirt version are you using? Can you please upload the output of "rpm -qa | grep libvirt"?
Libvirt version: libvirt-3.2.0-14.el7_4.3.x86_64
@Raz, Can you please provide qemu-kvm version?
qemu-kvm-rhev-2.9.0-16.el7_4.10.x86_64
@Raz, There is a KBase describing a workaround: https://access.redhat.com/solutions/3223871 The KBase suggests executing the following commands: # ausearch -c 'qemu-kvm' --raw | audit2allow -M my-qemukvm # semodule -i my-qemukvm.pp Can you please try these commands and see if issue resolved?
The output I get is: [root@storage-ge5-vdsm1 ~]# ausearch -c 'qemu-kvm' --raw | audit2allow -M my-qemukvm Nothing to do [root@storage-ge5-vdsm1 ~]# semodule -i my-qemukvm.pp libsemanage.map_file: Unable to open my-qemukvm.pp (No such file or directory). libsemanage.semanage_direct_install_file: Unable to read file my-qemukvm.pp (No such file or directory). semodule: Failed on my-qemukvm.pp! So I guess this won't solve the issue Any suggestions?
(In reply to Raz Tamir from comment #6) > The output I get is: > [root@storage-ge5-vdsm1 ~]# ausearch -c 'qemu-kvm' --raw | audit2allow -M > my-qemukvm > Nothing to do > [root@storage-ge5-vdsm1 ~]# semodule -i my-qemukvm.pp > libsemanage.map_file: Unable to open my-qemukvm.pp > (No such file or directory). > libsemanage.semanage_direct_install_file: Unable to read file my-qemukvm.pp > (No such file or directory). > semodule: Failed on my-qemukvm.pp! > > So I guess this won't solve the issue > > Any suggestions? Not that I can see; I just followed the bug this one depends on
Testing this bug with the scratch build, this bug depends on, did not solve the issue. we still see the same failure: engine.log: 2017-11-30 17:00:04,367+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-143849) [snapshots_delete_ece827c1-3f4e-43d0] EVENT_ID: VDS_BROKER_COMM AND_FAILURE(10,802), VDSM host_mixed_3 command TeardownImageVDS failed: Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\' Logical volume c8068666-b0b9-43a4-a66e-d4cfb0518032/2b1f3157-1559-4 f0f-9e7e-d6d7ca712432 in use.\']\\nc8068666-b0b9-43a4-a66e-d4cfb0518032/[\'57d6a876-6505-430a-98d2-bf119861bee6\', \'5e723213-3700-44b1-b69a-2209c455b11d\', \'2b1f3157-1559-4f0f-9e7e-d6d7ca712432\', \'af0919df-4623 -4254-9f46-664588f38d86\']",)',) 2017-11-30 17:00:04,367+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (EE-ManagedThreadFactory-engine-Thread-143849) [snapshots_delete_ece827c1-3f4e-43d0] Command 'TeardownImageVDSCom mand(HostName = host_mixed_3, ImageActionsVDSCommandParameters:{hostId='f93fda10-7d8e-4550-a8e3-1e99a3333389'})' execution failed: VDSGenericException: VDSErrorException: Failed in vdscommand to TeardownImageVDS, e rror = Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\' Logical volume c8068666-b0b9-43a4-a66e-d4cfb0518032/2b1f3157-1559-4f0f-9e7e-d6d7ca712432 in use.\']\\nc8068666-b0b9-43a4-a66e-d4cfb0 518032/[\'57d6a876-6505-430a-98d2-bf119861bee6\', \'5e723213-3700-44b1-b69a-2209c455b11d\', \'2b1f3157-1559-4f0f-9e7e-d6d7ca712432\', \'af0919df-4623-4254-9f46-664588f38d86\']",)',) 2017-11-30 17:00:04,367+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (EE-ManagedThreadFactory-engine-Thread-143849) [snapshots_delete_ece827c1-3f4e-43d0] FINISH, TeardownImageVDSComm and, log id: 7b035184 2017-11-30 17:00:04,367+02 ERROR [org.ovirt.engine.core.bll.ReduceImageCommand] (EE-ManagedThreadFactory-engine-Thread-143849) [snapshots_delete_ece827c1-3f4e-43d0] Failed to teardown image dde4e6e4-812a-4dd0-9ca3- d68673e6d120/5e723213-3700-44b1-b69a-2209c455b11d on the SPM 2017-11-30 17:00:04,370+02 INFO [org.ovirt.engine.core.bll.RefreshVolumeCommand] (EE-ManagedThreadFactory-engine-Thread-143849) [snapshots_delete_ece827c1-3f4e-43d0] Running command: RefreshVolumeCommand internal: true. 2017-11-30 17:00:04,372+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.RefreshVolumeVDSCommand] (EE-ManagedThreadFactory-engine-Thread-143849) [snapshots_delete_ece827c1-3f4e-43d0] START, RefreshVolumeVDSComma nd(HostName = host_mixed_1, RefreshVolumeVDSCommandParameters:{hostId='6b988809-10b3-4d01-87cb-392e19e1573d', storagePoolId='999d2b71-820d-46cb-a878-ef4ef419ef2c', storageDomainId='c8068666-b0b9-43a4-a66e-d4cfb0518 032', imageGroupId='dde4e6e4-812a-4dd0-9ca3-d68673e6d120', imageId='5e723213-3700-44b1-b69a-2209c455b11d'}), log id: 2d032e3d 2017-11-30 17:00:04,421+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-143850) [snapshots_delete_ece827c1-3f4e-43d0] EVENT_ID: VDS_BROKER_COMM AND_FAILURE(10,802), VDSM host_mixed_3 command TeardownImageVDS failed: Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\' Logical volume c8068666-b0b9-43a4-a66e-d4cfb0518032/50ed2981-1b8b-4 783-b3b0-155c9dbc2a8f in use.\']\\nc8068666-b0b9-43a4-a66e-d4cfb0518032/[\'5bb8d16c-5570-4fb4-b861-606e31233a5b\', \'b5af93c4-742f-473d-af00-017066b44ae0\', \'cc895200-721d-46f8-a6bf-eb545b3f27ff\', \'50ed2981-1b8b -4783-b3b0-155c9dbc2a8f\']",)',) 2017-11-30 17:00:04,421+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (EE-ManagedThreadFactory-engine-Thread-143850) [snapshots_delete_ece827c1-3f4e-43d0] Command 'TeardownImageVDSCommand(HostName = host_mixed_3, ImageActionsVDSCommandParameters:{hostId='f93fda10-7d8e-4550-a8e3-1e99a3333389'})' execution failed: VDSGenericException: VDSErrorException: Failed in vdscommand to TeardownImageVDS, error = Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\' Logical volume c8068666-b0b9-43a4-a66e-d4cfb0518032/50ed2981-1b8b-4783-b3b0-155c9dbc2a8f in use.\']\\nc8068666-b0b9-43a4-a66e-d4cfb0518032/[\'5bb8d16c-5570-4fb4-b861-606e31233a5b\', \'b5af93c4-742f-473d-af00-017066b44ae0\', \'cc895200-721d-46f8-a6bf-eb545b3f27ff\', \'50ed2981-1b8b-4783-b3b0-155c9dbc2a8f\']",)',) 2017-11-30 17:00:04,421+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (EE-ManagedThreadFactory-engine-Thread-143850) [snapshots_delete_ece827c1-3f4e-43d0] FINISH, TeardownImageVDSCommand, log id: 7ab53099 2017-11-30 17:00:04,421+02 ERROR [org.ovirt.engine.core.bll.ReduceImageCommand] (EE-ManagedThreadFactory-engine-Thread-143850) [snapshots_delete_ece827c1-3f4e-43d0] Failed to teardown image e6c2f057-3151-480a-a6e0-59f908a24057/cc895200-721d-46f8-a6bf-eb545b3f27ff on the SPM vdsm.log: 2017-11-30 17:00:04,361+0200 INFO (jsonrpc/6) [vdsm.api] FINISH teardownImage error=Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\' Logical volume c8068666-b0b9-43a4-a66e-d4cfb0518032/2b1f3157-1559-4f0f-9e7e-d6d7ca712432 in use.\']\\nc8068666-b0b9-43a4-a66e-d4cfb0518032/[\'57d6a876-6505-430a-98d2-bf119861bee6\', \'5e723213-3700-44b1-b69a-2209c455b11d\', \'2b1f3157-1559-4f0f-9e7e-d6d7ca712432\', \'af0919df-4623-4254-9f46-664588f38d86\']",)',) from=::ffff:10.35.69.167,44620, flow_id=snapshots_delete_ece827c1-3f4e-43d0, task_id=e77e3628-dd3d-464b-a4da-587c425b70f1 (api:50) 2017-11-30 17:00:04,362+0200 ERROR (jsonrpc/6) [storage.TaskManager.Task] (Task='e77e3628-dd3d-464b-a4da-587c425b70f1') 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 "<string>", line 2, in teardownImage File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 3211, in teardownImage dom.deactivateImage(imgUUID) File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 1278, in deactivateImage lvm.deactivateLVs(self.sdUUID, volUUIDs) File "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 1310, in deactivateLVs _setLVAvailability(vgName, toDeactivate, "n") File "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 842, in _setLVAvailability raise error(str(e)) CannotDeactivateLogicalVolume: Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\' Logical volume c8068666-b0b9-43a4-a66e-d4cfb0518032/2b1f3157-1559-4f0f-9e7e-d6d7ca712432 in use.\']\\nc8068666-b0b9-43a4-a66e-d4cfb0518032/[\'57d6a876-6505-430a-98d2-bf119861bee6\', \'5e723213-3700-44b1-b69a-2209c455b11d\', \'2b1f3157-1559-4f0f-9e7e-d6d7ca712432\', \'af0919df-4623-4254-9f46-664588f38d86\']",)',) 2017-11-30 17:00:04,364+0200 INFO (jsonrpc/6) [storage.TaskManager.Task] (Task='e77e3628-dd3d-464b-a4da-587c425b70f1') aborting: Task is aborted: 'Cannot deactivate Logical Volume: (\'General Storage Exception: ("5 [] [\\\' Logical volume c8068666-b0b9-43a4-a66e-d4cfb0518032/2b1f3157-1559-4f0f-9e7e-d6d7ca712432 in use.\\\']\\\\nc8068666-b0b9-43a4-a66e-d4cfb0518032/[\\\'57d6a876-6505-430a-98d2-bf119861bee6\\\', \\\'5e723213-3700-44b1-b69a-2209c455b11d\\\', \\\'2b1f3157-1559-4f0f-9e7e-d6d7ca712432\\\', \\\'af0919df-4623-4254-9f46-664588f38d86\\\']",)\',)' - code 552 (task:1181) 2017-11-30 17:00:04,365+0200 ERROR (jsonrpc/6) [storage.Dispatcher] FINISH teardownImage error=Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\' Logical volume c8068666-b0b9-43a4-a66e-d4cfb0518032/2b1f3157-1559-4f0f-9e7e-d6d7ca712432 in use.\']\\nc8068666-b0b9-43a4-a66e-d4cfb0518032/[\'57d6a876-6505-430a-98d2-bf119861bee6\', \'5e723213-3700-44b1-b69a-2209c455b11d\', \'2b1f3157-1559-4f0f-9e7e-d6d7ca712432\', \'af0919df-4623-4254-9f46-664588f38d86\']",)',) (dispatcher:82) 2017-11-30 17:00:04,366+0200 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Image.teardown failed (error 552) in 10.34 seconds (__init__:573) 2017-11-30 17:00:04,416+0200 INFO (jsonrpc/7) [vdsm.api] FINISH teardownImage error=Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\' Logical volume c8068666-b0b9-43a4-a66e-d4cfb0518032/50ed2981-1b8b-4783-b3b0-155c9dbc2a8f in use.\']\\nc8068666-b0b9-43a4-a66e-d4cfb0518032/[\'5bb8d16c-5570-4fb4-b861-606e31233a5b\', \'b5af93c4-742f-473d-af00-017066b44ae0\', \'cc895200-721d-46f8-a6bf-eb545b3f27ff\', \'50ed2981-1b8b-4783-b3b0-155c9dbc2a8f\']",)',) from=::ffff:10.35.69.167,44620, flow_id=snapshots_delete_ece827c1-3f4e-43d0, task_id=8009dcaa-2000-4246-9f67-66439e41126e (api:50) 2017-11-30 17:00:04,417+0200 ERROR (jsonrpc/7) [storage.TaskManager.Task] (Task='8009dcaa-2000-4246-9f67-66439e41126e') 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 "<string>", line 2, in teardownImage File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 3211, in teardownImage dom.deactivateImage(imgUUID) File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 1278, in deactivateImage lvm.deactivateLVs(self.sdUUID, volUUIDs) File "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 1310, in deactivateLVs _setLVAvailability(vgName, toDeactivate, "n") File "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 842, in _setLVAvailability raise error(str(e)) CannotDeactivateLogicalVolume: Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\' Logical volume c8068666-b0b9-43a4-a66e-d4cfb0518032/50ed2981-1b8b-4783-b3b0-155c9dbc2a8f in use.\']\\nc8068666-b0b9-43a4-a66e-d4cfb0518032/[\'5bb8d16c-5570-4fb4-b861-606e31233a5b\', \'b5af93c4-742f-473d-af00-017066b44ae0\', \'cc895200-721d-46f8-a6bf-eb545b3f27ff\', \'50ed2981-1b8b-4783-b3b0-155c9dbc2a8f\']",)',) 2017-11-30 17:00:04,419+0200 INFO (jsonrpc/7) [storage.TaskManager.Task] (Task='8009dcaa-2000-4246-9f67-66439e41126e') aborting: Task is aborted: 'Cannot deactivate Logical Volume: (\'General Storage Exception: ("5 [] [\\\' Logical volume c8068666-b0b9-43a4-a66e-d4cfb0518032/50ed2981-1b8b-4783-b3b0-155c9dbc2a8f in use.\\\']\\\\nc8068666-b0b9-43a4-a66e-d4cfb0518032/[\\\'5bb8d16c-5570-4fb4-b861-606e31233a5b\\\', \\\'b5af93c4-742f-473d-af00-017066b44ae0\\\', \\\'cc895200-721d-46f8-a6bf-eb545b3f27ff\\\', \\\'50ed2981-1b8b-4783-b3b0-155c9dbc2a8f\\\']",)\',)' - code 552 (task:1181) 2017-11-30 17:00:04,420+0200 ERROR (jsonrpc/7) [storage.Dispatcher] FINISH teardownImage error=Cannot deactivate Logical Volume: ('General Storage Exception: ("5 [] [\' Logical volume c8068666-b0b9-43a4-a66e-d4cfb0518032/50ed2981-1b8b-4783-b3b0-155c9dbc2a8f in use.\']\\nc8068666-b0b9-43a4-a66e-d4cfb0518032/[\'5bb8d16c-5570-4fb4-b861-606e31233a5b\', \'b5af93c4-742f-473d-af00-017066b44ae0\', \'cc895200-721d-46f8-a6bf-eb545b3f27ff\', \'50ed2981-1b8b-4783-b3b0-155c9dbc2a8f\']",)',) (dispatcher:82) 2017-11-30 17:00:04,420+0200 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Image.teardown failed (error 552) in 10.35 seconds (__init__:573)
Created attachment 1362202 [details] From scratch build engine and vdsm logs
Raz, can you please include version info for engine, vdsm, libvirt and qemu? Thanks!
ovirt-engine-4.2.0-0.0.master.20171124141652.gita5b4f9b.el7.centos.noarch vdsm-4.20.8-29.git6ceb389.el7.centos.x86_64 libvirt-3.2.0-14.el7_4.5_rc.4f094ff0ae.x86_64 qemu-kvm-common-ev-2.9.0-16.el7_4.8.1.x86_64
Raz, When did you test this? In the logs, I see the time (at the end of the log) is 2017-11-30 17:04:29 (engine), and 2017-11-30 17:11:45 (vdsm). Is this the correct time/log? Did you notice whether the snapshot was removed? I see a failure in ReduceImageCommand; however, any failure here shouldn't fail live merge. In any case, can you please try a minimal test to reproduce this?
The only failure of deleting a snapshot is snapshot_6038_glusterfs_1: 2017-11-30 05:17:19,209+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-54) [snapshots_delete_09352696-1227-4bc7] EVENT_ID: USER_REMOVE_SNAPSHOT_FINISHED_FAILURE(357), Failed to delete snapshot 'snapshot_6038_glusterfs_1' for VM 'vm_TestCase6038_3005090962'.
(In reply to Ala Hino from comment #12) > Raz, > > When did you test this? > In the logs, I see the time (at the end of the log) is 2017-11-30 17:04:29 > (engine), and 2017-11-30 17:11:45 (vdsm). Is this the correct time/log? Yes. What is the issue with the timing? > > Did you notice whether the snapshot was removed? I see a failure in > ReduceImageCommand; however, any failure here shouldn't fail live merge. > > In any case, can you please try a minimal test to reproduce this? Minimal how? The steps to reproduce are very straightforward
(In reply to Raz Tamir from comment #14) > (In reply to Ala Hino from comment #12) > > Raz, > > > > When did you test this? > > In the logs, I see the time (at the end of the log) is 2017-11-30 17:04:29 > > (engine), and 2017-11-30 17:11:45 (vdsm). Is this the correct time/log? > Yes. > What is the issue with the timing? > > > > Did you notice whether the snapshot was removed? I see a failure in > > ReduceImageCommand; however, any failure here shouldn't fail live merge. > > > > In any case, can you please try a minimal test to reproduce this? > > Minimal how? > > The steps to reproduce are very straightforward No issues with the time. Wanted to make sure I am looking at the correct logs. Can you tell what merge fails - nfs, iscsi, or gluster (see comment #13)? Does fail mean, there are errors in the logs (not saying it is OK to have the errors), or you failed to verify that the snapshot indeed was merged?
Please note that libvirt error that we hit was: libvirtError: internal error: unable to execute QEMU command 'block-commit': Could not reopen file: Permission denied I don't see this error in the log now. Despite the CannotDeactivateLogicalVolume (it is a bad noise that I looking into), can you please verify that the snapshots were removed?
I don't see the "libvirtError" anymore with the scratch build and the snapshot was removed successfully
Moving to ON_QA based on the status of #1516717
Passed automation run with: rhvm-4.2.0.2-0.1.el7.noarch vdsm-4.20.9.1-1.el7ev.x86_64 libvirt-3.2.0-14.el7_4.5.x86_64 Verified
This bugzilla is included in oVirt 4.2.1 release, published on Feb 12th 2018. Since the problem described in this bug report should be resolved in oVirt 4.2.1 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.