Bug 788023

Summary: [ovirt] [engine-core] vm remains in image locked in case merge snapshot fails
Product: [Retired] oVirt Reporter: Haim <hateya>
Component: ovirt-engine-coreAssignee: lpeer <lpeer>
Status: CLOSED CURRENTRELEASE QA Contact:
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: unspecifiedCC: acathrow, hateya, iheim, mgoldboi, mkublin, yeylon, ykaul
Target Milestone: ---   
Target Release: 3.1   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: storage
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Storage RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On:    
Bug Blocks: 817520    
Attachments:
Description Flags
engine log none

Description Haim 2012-02-07 09:16:31 UTC
Description of problem:

- start merge snapshot task
- make vdsm return an exception for it
- engine core will fence SPM 
- engine core will try the command again 
- engine core will fail again 
- engine core tries to roll-back the command, but vm stays in image locked. 


[root@rhevm-a8c-03 ovirt-engine]# psql -U postgres -d engine -c "SELECT vm_guid, status  from vm_dynamic where status = '15'"   
               vm_guid                | status 
--------------------------------------+--------
 30b47a9e-70c7-4ea0-9c1f-4de71ea78835 |     15


exception: 

2012-02-06 10:19:41,039 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (http--0.0.0.0-8080-5) IrsBroker::Failed::MergeSnapshotsVDS due to: XmlRpcException: <type 'exceptions.Exception'>:method "mergeSnapshots" is not supported

Flow:

2012-02-06 10:19:10,431 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (http--0.0.0.0-8080-5) START, IsValidVDSCommand(storagePoolId = d962cf18-3592-4726-8d0e-d73e3622b21e, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 464fc7bc
2012-02-06 10:19:10,432 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (http--0.0.0.0-8080-5) FINISH, IsValidVDSCommand, return: true, log id: 464fc7bc
2012-02-06 10:19:10,438 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (http--0.0.0.0-8080-5) START, GetImageInfoVDSCommand(storagePoolId = d962cf18-3592-4726-8d0e-d73e3622b21e, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 3cb398c7-397f-4e80-8bfd-d21b10600d35, imageGroupId = 9ef0ccf9-a114-4357-b03c-00ab2d2fd8ec, imageId = e23fa236-a564-4867-b7f5-5b24e4dcffa6), log id: 65d6a4a8
2012-02-06 10:19:11,321 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (http--0.0.0.0-8080-5) FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.DiskImage@49267b55, log id: 65d6a4a8
2012-02-06 10:19:11,330 INFO  [org.ovirt.engine.core.bll.MergeSnapshotCommand] (http--0.0.0.0-8080-5) Running command: MergeSnapshotCommand internal: false. Entities affected :  ID: 30b47a9e-70c7-4ea0-9c1f-4de71ea78835 Type: VM
2012-02-06 10:19:11,333 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (http--0.0.0.0-8080-5) START, SetVmStatusVDSCommand(vmId = 30b47a9e-70c7-4ea0-9c1f-4de71ea78835, status = ImageLocked), log id: 6cafc2f5
2012-02-06 10:19:11,338 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (http--0.0.0.0-8080-5) FINISH, SetVmStatusVDSCommand, log id: 6cafc2f5
2012-02-06 10:19:11,347 INFO  [org.ovirt.engine.core.bll.MergeSnapshotSingleDiskCommand] (http--0.0.0.0-8080-5) Running command: MergeSnapshotSingleDiskCommand internal: true. Entities affected :  ID: 00000000-0000-0000-0000-000000000000 Type: Storage
2012-02-06 10:19:11,349 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.MergeSnapshotsVDSCommand] (http--0.0.0.0-8080-5) START, MergeSnapshotsVDSCommand(storagePoolId = d962cf18-3592-4726-8d0e-d73e3622b21e, ignoreFailoverLimit = false, compatabilityVersion = 3.0, storageDomainId = 3cb398c7-397f-4e80-8bfd-d21b10600d35, imageGroupId = 9ef0ccf9-a114-4357-b03c-00ab2d2fd8ec, imageId = aa274382-b4a2-4ce0-a830-5e65c98a1495, imageId2 = e23fa236-a564-4867-b7f5-5b24e4dcffa6, vmId = 30b47a9e-70c7-4ea0-9c1f-4de71ea78835, postZero = true), log id: 2e46efc0
2012-02-06 10:19:11,982 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (http--0.0.0.0-8080-5) IrsBroker::Failed::MergeSnapshotsVDS due to: XmlRpcException: <type 'exceptions.Exception'>:method "mergeSnapshots" is not supported
2012-02-06 10:19:12,619 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (http--0.0.0.0-8080-5) START, SpmStopVDSCommand(vdsId = 95ec7922-508b-11e1-aa8e-179b2aa6c4ed, storagePoolId = d962cf18-3592-4726-8d0e-d73e3622b21e), log id: 4045348b
2012-02-06 10:19:13,261 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (http--0.0.0.0-8080-5) SpmStopVDSCommand::Stopping SPM on vds nott-vds3, pool id d962cf18-3592-4726-8d0e-d73e3622b21e
2012-02-06 10:19:15,047 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (http--0.0.0.0-8080-5) FINISH, SpmStopVDSCommand, log id: 4045348b
2012-02-06 10:19:15,047 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (http--0.0.0.0-8080-5) Irs placed on server null failed. Proceed Failover
2012-02-06 10:19:15,050 INFO  [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (http--0.0.0.0-8080-5) Running command: SetStoragePoolStatusCommand internal: true. Entities affected :  ID: d962cf18-3592-4726-8d0e-d73e3622b21e Type: StoragePool
2012-02-06 10:19:15,709 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (http--0.0.0.0-8080-5) hostFromVds::selectedVds - nott-vds2, spmStatus Free, storage pool StorageResize
2012-02-06 10:19:16,545 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (http--0.0.0.0-8080-5) SpmStatus on vds 95ec7922-508b-11e1-aa8e-179b2aa6c4ed: Free
2012-02-06 10:19:16,550 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (http--0.0.0.0-8080-5) starting spm on vds nott-vds2, storage pool StorageResize, prevId 2, LVER 1
2012-02-06 10:19:16,551 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (http--0.0.0.0-8080-5) START, SpmStartVDSCommand(vdsId = 89a9d20e-508b-11e1-897a-ab0c759be3e9, storagePoolId = d962cf18-3592-4726-8d0e-d73e3622b21e, prevId=2, prevLVER=1, storagePoolFormatType=V2, recoveryMode=Manual, SCSIFencing=false), log id: 301bc23a
2012-02-06 10:19:17,224 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (http--0.0.0.0-8080-5) spmStart polling started: taskId = 3dde2367-2ff4-418b-abc3-62eef4e0cdb6
2012-02-06 10:19:38,981 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (http--0.0.0.0-8080-5) spmStart polling ended: taskId = 3dde2367-2ff4-418b-abc3-62eef4e0cdb6 task status = finished
2012-02-06 10:19:39,618 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (http--0.0.0.0-8080-5) spmStart polling ended. spm status: SPM
2012-02-06 10:19:39,619 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (http--0.0.0.0-8080-5) START, HSMClearTaskVDSCommand(vdsId = 89a9d20e-508b-11e1-897a-ab0c759be3e9, taskId=3dde2367-2ff4-418b-abc3-62eef4e0cdb6), log id: 4c33794c
2012-02-06 10:19:40,389 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (http--0.0.0.0-8080-5) FINISH, HSMClearTaskVDSCommand, log id: 4c33794c
2012-02-06 10:19:40,389 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (http--0.0.0.0-8080-5) FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@2ce78337, log id: 301bc23a
2012-02-06 10:19:40,390 INFO  [org.ovirt.engine.core.vdsbroker.ResourceManager] (http--0.0.0.0-8080-5) ResourceManager:StoragePoolStatusChange - no event listener defined, nothing done.
2012-02-06 10:19:40,390 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (http--0.0.0.0-8080-5) Initialize Irs proxy from vds: nott-vds2.qa.lab.tlv.redhat.com
2012-02-06 10:19:41,039 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (http--0.0.0.0-8080-5) IrsBroker::Failed::MergeSnapshotsVDS due to: XmlRpcException: <type 'exceptions.Exception'>:method "mergeSnapshots" is not supported
2012-02-06 10:19:41,040 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.MergeSnapshotsVDSCommand] (http--0.0.0.0-8080-5) FINISH, MergeSnapshotsVDSCommand, log id: 2e46efc0
2012-02-06 10:19:41,040 ERROR [org.ovirt.engine.core.bll.MergeSnapshotSingleDiskCommand] (http--0.0.0.0-8080-5) Command org.ovirt.engine.core.bll.MergeSnapshotSingleDiskCommand throw Vdc Bll exception. With error message VdcBLLException: java.lang.reflect.UndeclaredThrowableException
2012-02-06 10:19:41,044 ERROR [org.ovirt.engine.core.bll.MergeSnapshotSingleDiskCommand] (http--0.0.0.0-8080-5) Transaction rolled-back for command: org.ovirt.engine.core.bll.MergeSnapshotSingleDiskCommand.
2012-02-06 10:19:41,044 ERROR [org.ovirt.engine.core.bll.MergeSnapshotCommand] (http--0.0.0.0-8080-5) Transaction rolled-back for command: org.ovirt.engine.core.bll.MergeSnapshotCommand.
2012-02-06 10:19:41,044 INFO  [org.ovirt.engine.core.utils.transaction.TransactionSupport] (http--0.0.0.0-8080-5) transaction rolled back

git hash: 9dacd053d6d011b374b8fc83b88f8e7de368aabf

Comment 1 Haim 2012-02-07 09:18:52 UTC
Created attachment 559896 [details]
engine log

Comment 2 mkublin 2012-06-11 09:13:46 UTC
Please recheck again, the flow was rewritten

Comment 3 Itamar Heim 2012-08-09 08:03:17 UTC
closing ON_QA bugs as oVirt 3.1 was released:
http://www.ovirt.org/get-ovirt/

Comment 4 Itamar Heim 2012-08-09 08:04:00 UTC
closing ON_QA bugs as oVirt 3.1 was released:
http://www.ovirt.org/get-ovirt/