Bug 1941311
| Summary: | Live merge after extend disk fails - 'Vm' object has no attribute 'refreshDriveVolume' | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [oVirt] vdsm | Reporter: | Evelina Shames <eshames> | ||||
| Component: | Core | Assignee: | Eyal Shenitzky <eshenitz> | ||||
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Evelina Shames <eshames> | ||||
| Severity: | high | Docs Contact: | |||||
| Priority: | unspecified | ||||||
| Version: | 4.40.50.8 | CC: | aefrat, aoconnor, bugs, lsvaty, nsoffer | ||||
| Target Milestone: | ovirt-4.4.5-1 | Keywords: | Automation, Regression, TestBlocker | ||||
| Target Release: | 4.40.50.9 | Flags: | aoconnor:
blocker+
|
||||
| Hardware: | Unspecified | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | vdsm-4.40.50.9 | Doc Type: | If docs needed, set a value | ||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2021-04-15 07:31:31 UTC | Type: | Bug | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | Storage | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Embargoed: | |||||||
| Attachments: |
|
||||||
Since this is a regression, and the fix is trivial, I suggest to resolve this in 4.4.5. I think we need some blocker or exception flag. Verified on vdsm-4.40.50.10-1.el8ev.x86_64. |
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.