Created attachment 1765061 [details]
Logs

Description of problem:
When trying to delete snapshot of VM with several disks after extend operation, live merge fails with the following errors:

Engine:
2021-03-10 09:57:41,326+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedExecutorService-commandCoordinator-Thread-9) [snapshots_delete_fc4f383d-016e-48b8] Failed in 'MergeVDS' method
2021-03-10 09:57:41,332+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedExecutorService-commandCoordinator-Thread-6) [snapshots_delete_fc4f383d-016e-48b8] Failed in 'MergeVDS' method
2021-03-10 09:57:41,333+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedExecutorService-commandCoordinator-Thread-6) [snapshots_delete_fc4f383d-016e-48b8] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand' return value 'StatusOnlyReturn [status=Status [code=100, message=General Exception: ("'Vm' object has no attribute 'refreshDriveVolume'",)]]'
2021-03-10 09:57:41,333+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedExecutorService-commandCoordinator-Thread-6) [snapshots_delete_fc4f383d-016e-48b8] HostName = host_mixed_3
2021-03-10 09:57:41,333+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedExecutorService-commandCoordinator-Thread-6) [snapshots_delete_fc4f383d-016e-48b8] Command 'MergeVDSCommand(HostName = host_mixed_3, MergeVDSCommandParameters:{hostId='abc4755a-322a-47e0-a14a-0a08ac6a482e', vmId='eb5bbc06-b3c1-4e1f-b1f2-d172300c0122', storagePoolId='d083f2af-96f8-4460-8127-84d783c61ec3', storageDomainId='9db4826b-9246-4612-9dbc-d0577f137efd', imageGroupId='9875d766-d3f7-4832-a62b-249d99ef2628', imageId='93d5af21-bd36-4942-9e2e-0443deb10fc0', baseImageId='23abc283-a3b9-40be-8a55-8cfe2108d338', topImageId='93d5af21-bd36-4942-9e2e-0443deb10fc0', bandwidth='0'})' execution failed: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = General Exception: ("'Vm' object has no attribute 'refreshDriveVolume'",), code = 100
2021-03-10 09:57:41,334+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedExecutorService-commandCoordinator-Thread-9) [snapshots_delete_fc4f383d-016e-48b8] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_3 command MergeVDS failed: General Exception: ("'Vm' object has no attribute 'refreshDriveVolume'",)
2021-03-10 09:57:41,333+02 ERROR [org.ovirt.engine.core.bll.MergeCommand] (EE-ManagedExecutorService-commandCoordinator-Thread-6) [snapshots_delete_fc4f383d-016e-48b8] 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 = General Exception: ("'Vm' object has no attribute 'refreshDriveVolume'",), code = 100 (Failed with error GeneralException and code 100)
	at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:114)
	at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33)
	at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.CommandBase.runVdsCommand(CommandBase.java:2119)
	at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.MergeCommand.executeCommand(MergeCommand.java:45)
	at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1174)
	at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1332)
	at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:2008)
	at org.ovirt.engine.core.utils//org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:181)
	at 
.
.
.
.
org.ovirt.engine.core.bll.tasks.CommandExecutor.lambda$executeAsyncCommand$0(CommandExecutor.java:49)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at org.glassfish.javax.enterprise.concurrent.0.redhat-1//org.glassfish.enterprise.concurrent.internal.ManagedFutureTask.run(ManagedFutureTask.java:141)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)
	at org.glassfish.javax.enterprise.concurrent.0.redhat-1//org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250)
Caused by: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = General Exception: ("'Vm' object has no attribute 'refreshDriveVolume'",), code = 100
	at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createDefaultConcreteException(VdsBrokerCommand.java:81)
	at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.createException(BrokerCommandBase.java:224)
	at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:194)
	at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand.executeVdsBrokerCommand(MergeVDSCommand.java:26)
	at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVdsCommandWithNetworkEvent(VdsBrokerCommand.java:123)
.
.
.
	at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand(Unknown Source)
	... 93 more
2021-03-10 09:57:41,335+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (EE-ManagedExecutorService-commandCoordinator-Thread-9) [snapshots_delete_fc4f383d-016e-48b8] Command 'MergeVDSCommand(HostName = host_mixed_3, MergeVDSCommandParameters:{hostId='abc4755a-322a-47e0-a14a-0a08ac6a482e', vmId='eb5bbc06-b3c1-4e1f-b1f2-d172300c0122', storagePoolId='d083f2af-96f8-4460-8127-84d783c61ec3', storageDomainId='9db4826b-9246-4612-9dbc-d0577f137efd', imageGroupId='ab59d457-74e0-4928-8faf-fd8589a3da5d', imageId='a35783b3-4f38-4bca-90ff-44dadb4308f4', baseImageId='81607526-f498-4740-835c-3b5b36cb71ed', topImageId='a35783b3-4f38-4bca-90ff-44dadb4308f4', bandwidth='0'})' execution failed: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = General Exception: ("'Vm' object has no attribute 'refreshDriveVolume'",), code = 100

(Full engine log is attached)

vdsm:
2021-03-10 09:57:41,243+0200 INFO  (jsonrpc/3) [storage.VolumeManifest] Info request: sdUUID=9db4826b-9246-4612-9dbc-d0577f137efd imgUUID=ab59d457-74e0-4928-8faf-fd8589a3da5d volUUID = a35783b3-4f38-4bca-90ff-44dadb4308f4  (volume:239)
2021-03-10 09:57:41,244+0200 DEBUG (jsonrpc/3) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-11 /usr/bin/dd iflag=direct skip=2288 bs=512 if=/dev/9db4826b-9246-4612-9dbc-d0577f137efd/metadata count=1 (cwd None) (commands:211)
2021-03-10 09:57:41,283+0200 DEBUG (jsonrpc/0) [storage.Misc.excCmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n512 bytes copied, 0.0116887 s, 43.8 kB/s\n'; <rc> = 0 (commands:224)
2021-03-10 09:57:41,284+0200 DEBUG (jsonrpc/0) [storage.Misc] err: [b'1+0 records in', b'1+0 records out', b'512 bytes copied, 0.0116887 s, 43.8 kB/s'], size: 512 (misc:114)
2021-03-10 09:57:41,318+0200 DEBUG (jsonrpc/3) [storage.Misc.excCmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n512 bytes copied, 0.0166466 s, 30.8 kB/s\n'; <rc> = 0 (commands:224)
2021-03-10 09:57:41,318+0200 DEBUG (jsonrpc/3) [storage.Misc] err: [b'1+0 records in', b'1+0 records out', b'512 bytes copied, 0.0166466 s, 30.8 kB/s'], size: 512 (misc:114)
2021-03-10 09:57:41,322+0200 INFO  (jsonrpc/3) [storage.VolumeManifest] 9db4826b-9246-4612-9dbc-d0577f137efd/ab59d457-74e0-4928-8faf-fd8589a3da5d/a35783b3-4f38-4bca-90ff-44dadb4308f4 info is {'uuid': 'a35783b3-4f38-4bca-90ff-44dadb4308f4', 'type': 'SPARSE', 'format': 'COW', 'disktype': 'DATA', 'voltype': 'LEAF', 'capacity': '2147483648', 'parent': '81607526-f498-4740-835c-3b5b36cb71ed', 'description': '', 'pool': '', 'domain': '9db4826b-9246-4612-9dbc-d0577f137efd', 'image': 'ab59d457-74e0-4928-8faf-fd8589a3da5d', 'ctime': '1615362845', 'mtime': '0', 'legality': 'LEGAL', 'generation': 0, 'apparentsize': '1073741824', 'truesize': '1073741824', 'status': 'OK', 'lease': {'path': '/dev/9db4826b-9246-4612-9dbc-d0577f137efd/leases', 'offset': 120586240, 'owners': [], 'version': None}, 'children': []} (volume:278)
2021-03-10 09:57:41,322+0200 INFO  (jsonrpc/3) [vdsm.api] FINISH getVolumeInfo return={'info': {'uuid': 'a35783b3-4f38-4bca-90ff-44dadb4308f4', 'type': 'SPARSE', 'format': 'COW', 'disktype': 'DATA', 'voltype': 'LEAF', 'capacity': '2147483648', 'parent': '81607526-f498-4740-835c-3b5b36cb71ed', 'description': '', 'pool': '', 'domain': '9db4826b-9246-4612-9dbc-d0577f137efd', 'image': 'ab59d457-74e0-4928-8faf-fd8589a3da5d', 'ctime': '1615362845', 'mtime': '0', 'legality': 'LEGAL', 'generation': 0, 'apparentsize': '1073741824', 'truesize': '1073741824', 'status': 'OK', 'lease': {'path': '/dev/9db4826b-9246-4612-9dbc-d0577f137efd/leases', 'offset': 120586240, 'owners': [], 'version': None}, 'children': []}} from=::ffff:10.46.16.252,44762, flow_id=snapshots_delete_fc4f383d-016e-48b8, task_id=b5c233a3-d267-499b-9331-094c12ab3bec (api:54)
2021-03-10 09:57:41,322+0200 DEBUG (jsonrpc/3) [storage.TaskManager.Task] (Task='b5c233a3-d267-499b-9331-094c12ab3bec') finished: {'info': {'uuid': 'a35783b3-4f38-4bca-90ff-44dadb4308f4', 'type': 'SPARSE', 'format': 'COW', 'disktype': 'DATA', 'voltype': 'LEAF', 'capacity': '2147483648', 'parent': '81607526-f498-4740-835c-3b5b36cb71ed', 'description': '', 'pool': '', 'domain': '9db4826b-9246-4612-9dbc-d0577f137efd', 'image': 'ab59d457-74e0-4928-8faf-fd8589a3da5d', 'ctime': '1615362845', 'mtime': '0', 'legality': 'LEGAL', 'generation': 0, 'apparentsize': '1073741824', 'truesize': '1073741824', 'status': 'OK', 'lease': {'path': '/dev/9db4826b-9246-4612-9dbc-d0577f137efd/leases', 'offset': 120586240, 'owners': [], 'version': None}, 'children': []}} (task:1210)
2021-03-10 09:57:41,322+0200 DEBUG (jsonrpc/3) [storage.TaskManager.Task] (Task='b5c233a3-d267-499b-9331-094c12ab3bec') moving from state finished -> state finished (task:624)
2021-03-10 09:57:41,322+0200 DEBUG (jsonrpc/3) [storage.ResourceManager.Owner] Owner.releaseAll resources %s (resourceManager:742)
2021-03-10 09:57:41,322+0200 DEBUG (jsonrpc/3) [storage.ResourceManager] Trying to release resource '00_storage.9db4826b-9246-4612-9dbc-d0577f137efd' (resourceManager:546)
2021-03-10 09:57:41,322+0200 DEBUG (jsonrpc/3) [storage.ResourceManager] Released resource '00_storage.9db4826b-9246-4612-9dbc-d0577f137efd' (1 active users) (resourceManager:564)
2021-03-10 09:57:41,322+0200 DEBUG (jsonrpc/3) [storage.TaskManager.Task] (Task='b5c233a3-d267-499b-9331-094c12ab3bec') ref 0 aborting False (task:1008)
2021-03-10 09:57:41,323+0200 INFO  (jsonrpc/3) [virt.livemerge] Refreshing base volume '81607526-f498-4740-835c-3b5b36cb71ed' (apparentsize=1073741824, capacity=2147483648) (livemerge:336)
2021-03-10 09:57:41,323+0200 ERROR (jsonrpc/3) [api] FINISH merge error='Vm' object has no attribute 'refreshDriveVolume' (api:134)
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 124, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/vdsm/API.py", line 767, in merge
    drive, baseVolUUID, topVolUUID, bandwidth, jobUUID)
  File "/usr/lib/python3.6/site-packages/vdsm/virt/vm.py", line 5644, in merge
    driveSpec, baseVolUUID, topVolUUID, bandwidth, jobUUID)
  File "/usr/lib/python3.6/site-packages/vdsm/virt/livemerge.py", line 288, in merge
    self._refresh_base(drive, base_info)
  File "/usr/lib/python3.6/site-packages/vdsm/virt/livemerge.py", line 338, in _refresh_base
    self._vm.refreshDriveVolume({
AttributeError: 'Vm' object has no attribute 'refreshDriveVolume'
2021-03-10 09:57:41,323+0200 INFO  (jsonrpc/3) [api.virt] FINISH merge return={'status': {'code': 100, 'message': 'General Exception: ("\'Vm\' object has no attribute \'refreshDriveVolume\'",)'}} from=::ffff:10.46.16.252,44762, flow_id=snapshots_delete_fc4f383d-016e-48b8, vmId=eb5bbc06-b3c1-4e1f-b1f2-d172300c0122 (api:54)
2021-03-10 09:57:41,323+0200 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call VM.merge failed (error 100) in 0.25 seconds (__init__:312)

(Full vdsm log is attached)

Version-Release number of selected component (if applicable):
rhv-4.4.5-9:
ovirt-engine-4.4.5.9-0.1.el8ev.noarch
vdsm-4.40.50.8-1.el8ev.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Create a VM from rhel8.3 template
2. Add another disk: virtio-scsi preallocated on iscsi/fc
3. Create sanoshot 1
4. Run VM
5. Extend both disks (+1G)
6. delete snapshot 1 (live merge)

Actual results:
Opeartion fails.

Expected results:
Operation should succeed.

Additional info:
logs are attched.