Bug 1486347

Summary: Live merge fails with KeyError: 'name' in __refreshDriveVolume
Product: [oVirt] vdsm Reporter: Elad <ebenahar>
Component: CoreAssignee: Ala Hino <ahino>
Status: CLOSED CURRENTRELEASE QA Contact: Elad <ebenahar>
Severity: high Docs Contact:
Priority: unspecified    
Version: 4.19.15CC: amureini, bugs, tnisan
Target Milestone: ovirt-4.1.6Keywords: Automation, Regression
Target Release: 4.19.31Flags: rule-engine: ovirt-4.1+
rule-engine: blocker+
Hardware: x86_64   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-09-19 10:03:48 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:
Description Flags
Logs from hypervisor and engine
none
live disk resize failure none

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