Bug 1486347 - Live merge fails with KeyError: 'name' in __refreshDriveVolume
Summary: Live merge fails with KeyError: 'name' in __refreshDriveVolume
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: vdsm
Classification: oVirt
Component: Core
Version: 4.19.15
Hardware: x86_64
OS: Unspecified
unspecified
high
Target Milestone: ovirt-4.1.6
: 4.19.31
Assignee: Ala Hino
QA Contact: Elad
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-08-29 14:13 UTC by Elad
Modified: 2017-09-19 10:03 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-09-19 10:03:48 UTC
oVirt Team: Storage
Embargoed:
rule-engine: ovirt-4.1+
rule-engine: blocker+


Attachments (Terms of Use)
Logs from hypervisor and engine (6.19 MB, application/x-gzip)
2017-08-29 14:13 UTC, Elad
no flags Details
live disk resize failure (16.33 MB, text/plain)
2017-08-29 14:18 UTC, Elad
no flags Details


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 81188 0 master MERGED vm: Fix invocations to __refreshDriveVolume 2017-08-30 13:53:26 UTC
oVirt gerrit 81223 0 ovirt-4.1 MERGED vm: Fix invocations to __refreshDriveVolume 2017-08-30 14:17:57 UTC

Description Elad 2017-08-29 14:13:13 UTC
Created attachment 1319548 [details]
Logs from hypervisor and engine

Description of problem:
Live snapshot deletion fails after disk resize with the following error:

2017-08-28 14:17:28,060+0300 INFO  (jsonrpc/1) [vdsm.api] FINISH merge error='name' from=::ffff:10.35.69.107,53536, flow_id=snapshots_delete_526e83f9-8a81-41b5 (api:50)
2017-08-28 14:17:28,061+0300 ERROR (jsonrpc/1) [jsonrpc.JsonRpcServer] Internal server error (__init__:577)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 572, in _handle_request
    res = method(**params)
  File "/usr/lib/python2.7/site-packages/vdsm/rpc/Bridge.py", line 202, in _dynamicMethod
    result = fn(*methodArgs)
  File "/usr/share/vdsm/API.py", line 838, in merge
    return v.merge(drive, baseVolUUID, topVolUUID, bandwidth, jobUUID)
  File "<string>", line 2, in merge
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method
    ret = func(*args, **kwargs)
  File "/usr/share/vdsm/virt/vm.py", line 4895, in merge
    'imageID': drive.imageID, 'volumeID': baseVolUUID,
  File "/usr/share/vdsm/virt/vm.py", line 945, in __refreshDriveVolume
    "volumeID: %s)", volInfo['name'], volInfo['domainID'],
KeyError: 'name'


2017-08-28 14:17:28,087+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-4) [snapshots_delete_526e83f9-8a81-41b5] Command 'MergeVDSCommand(HostName = host_mixed_2, MergeVDSCommandParameters:{runAsync='true', hostId='78f64e92-390d-43f7-98c3-0e9a662cdcfc', vmId='461fb991-d614-4077-bf18-756921a488e4', storagePoolId='4192728b-13f1-430e-a1d1-30070fc04b35', storageDomainId='fc17035f-8a44-45de-9902-a7079db8a4f9', imageGroupId='dcc89730-096c-413c-8ddf-9b240a56fd08', imageId='18ef3320-e900-46c8-92c3-e10c17e407bf', baseImageId='1a7981e3-8131-4bd8-a9e4-c913291d4f5c', topImageId='18ef3320-e900-46c8-92c3-e10c17e407bf', bandwidth='0'})' execution failed: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = 'name', code = -32603
2017-08-28 14:17:28,087+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-5-thread-4) [snapshots_delete_526e83f9-8a81-41b5] FINISH, MergeVDSCommand, log id: f74347c
2017-08-28 14:17:28,087+03 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-5-thread-4) [snapshots_delete_526e83f9-8a81-41b5] 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 = 'name', code = -32603 (Failed with error unexpected and code 16)
        at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:118) [bll.jar:]
        at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runVdsCommand(CommandBase.java:2166) [bll.jar:]
        at org.ovirt.engine.core.bll.MergeCommand.executeCommand(MergeCommand.java:45) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1251) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1391) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:2055) [bll.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202) [utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137) [utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105) [utils.jar:]
        at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1451) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:397) [bll.jar:]
        at org.ovirt.engine.core.bll.executor.DefaultBackendActionExecutor.execute(DefaultBackendActionExecutor.java:13) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:511) [bll.jar:]



Version-Release number of selected component (if applicable):
vdsm-4.19.29-1.el7ev.x86_64.rpm
ovirt-engine-4.1.6-0.1.el7.noarch.rpm

How reproducible:
Found in automation during execution of [1]

Steps to Reproduce:
Steps from [1], not sure all are needed, probably live merge after resize disk is enough:

1. Create a VM with 4 disks and OS installed
2. Write file 1 to all disks
3. Create a snapshot of the VM with all disks
4. Write file 2 to all disks
5. Create a snapshot 2 of the VM with all disks
6. Write file 3 to all disks
7. Create snapshot 3 fo the VM with all disks
8. Delete snapshot 2
9. Delete snapshot 3
10. Delete snapshot 1


[1] https://polarion.engineering.redhat.com/polarion/redirect/project/RHEVM3/workitem?id=RHEVM3-12216

Actual results:
Live merge fails with the mentioned exception.

Expected results:
Should succeed

Additional info:
Logs from hypervisor and engine

Comment 1 Elad 2017-08-29 14:18:24 UTC
Created attachment 1319549 [details]
live disk resize failure

Causing also for live disk resize to fail:

2017-08-28 16:56:33,017+0300 ERROR (jsonrpc/1) [virt.vm] (vmId='66087e88-4ba3-4c17-9272-8a0c1399525b') Unable to extend disk vdb to size 2147483648 (vm:4039)
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/vm.py", line 4036, in diskSizeExtend
    return self._diskSizeExtendRaw(drive, newSizeBytes)
  File "/usr/share/vdsm/virt/vm.py", line 3992, in _diskSizeExtendRaw
    'imageID': drive.imageID, 'volumeID': drive.volumeID,
  File "/usr/share/vdsm/virt/vm.py", line 945, in __refreshDriveVolume
    "volumeID: %s)", volInfo['name'], volInfo['domainID'],
KeyError: 'name'
2017-08-28 16:56:33,018+0300 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call VM.diskSizeExtend failed (error 56) in 0.00 seconds (__init__:539)

Comment 3 Elad 2017-09-11 15:18:26 UTC
Live merge succeeds after VM disk resize.

Tested using vdsm-4.19.31-1.el7ev.x86_64


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