Note: This is a beta release of Red Hat Bugzilla 5.0. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Also email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback here.
Bug 1509675 - Live merge with continuous I/O to the VM failed to deactivate logical volume (depends on platform bug 1516717)
Summary: Live merge with continuous I/O to the VM failed to deactivate logical volume ...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: vdsm
Classification: oVirt
Component: Core
Version: 4.19.35
Hardware: Unspecified
OS: Unspecified
urgent
urgent vote
Target Milestone: ovirt-4.2.1
: ---
Assignee: Ala Hino
QA Contact: Raz Tamir
URL:
Whiteboard:
Depends On: 1516717
Blocks: 1441941
TreeView+ depends on / blocked
 
Reported: 2017-11-05 15:28 UTC by Raz Tamir
Modified: 2018-02-12 11:52 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-02-12 11:52:50 UTC
oVirt Team: Storage
rule-engine: ovirt-4.2+
rule-engine: blocker+


Attachments (Terms of Use)
engine and vdsm logs (deleted)
2017-11-05 15:28 UTC, Raz Tamir
no flags Details
From scratch build engine and vdsm logs (deleted)
2017-12-03 09:16 UTC, Raz Tamir
no flags Details


Links
System ID Priority Status Summary Last Updated
oVirt gerrit 84896 master MERGED spec: Update libvirt-daemon-kvm required version 2017-12-07 16:19:42 UTC

Description Raz Tamir 2017-11-05 15:28:30 UTC
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:

Comment 1 Ala Hino 2017-11-05 20:08:44 UTC
@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"?

Comment 2 Raz Tamir 2017-11-06 09:23:18 UTC
Libvirt version: libvirt-3.2.0-14.el7_4.3.x86_64

Comment 3 Ala Hino 2017-11-06 10:43:05 UTC
@Raz,

Can you please provide qemu-kvm version?

Comment 4 Raz Tamir 2017-11-06 10:53:50 UTC
qemu-kvm-rhev-2.9.0-16.el7_4.10.x86_64

Comment 5 Ala Hino 2017-11-06 16:59:55 UTC
@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?

Comment 6 Raz Tamir 2017-11-12 15:35:23 UTC
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?

Comment 7 Ala Hino 2017-11-20 12:08:51 UTC
(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

Comment 8 Raz Tamir 2017-12-03 09:15:35 UTC
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)

Comment 9 Raz Tamir 2017-12-03 09:16:45 UTC
Created attachment 1362202 [details]
From scratch build engine and vdsm logs

Comment 10 Allon Mureinik 2017-12-03 10:39:56 UTC
Raz, can you please include version info for engine, vdsm, libvirt and qemu?
Thanks!

Comment 11 Raz Tamir 2017-12-03 10:43:28 UTC
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

Comment 12 Ala Hino 2017-12-03 12:02:13 UTC
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?

Comment 13 Ala Hino 2017-12-03 12:09:29 UTC
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'.

Comment 14 Raz Tamir 2017-12-03 12:10:40 UTC
(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

Comment 15 Ala Hino 2017-12-03 12:15:56 UTC
(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?

Comment 16 Ala Hino 2017-12-03 13:37:14 UTC
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?

Comment 17 Raz Tamir 2017-12-03 15:16:51 UTC
I don't see the "libvirtError" anymore with the scratch build and the snapshot was removed successfully

Comment 18 Gil Klein 2017-12-13 08:41:10 UTC
Moving to ON_QA based on the status of #1516717

Comment 19 Raz Tamir 2017-12-13 15:50:57 UTC
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

Comment 20 Sandro Bonazzola 2018-02-12 11:52:50 UTC
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.


Note You need to log in before you can comment on or make changes to this bug.