Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1161127

Summary: [JSONRPC]Live merge - failed to delete snapshot on 2nd attempt - first attempt was interrupted with shutdown of vm
Product: Red Hat Enterprise Virtualization Manager Reporter: Kevin Alon Goldblatt <kgoldbla>
Component: ovirt-engineAssignee: Greg Padgett <gpadgett>
Status: CLOSED CURRENTRELEASE QA Contact: Kevin Alon Goldblatt <kgoldbla>
Severity: urgent Docs Contact:
Priority: unspecified    
Version: 3.5.0CC: acanan, alitke, amureini, gklein, gpadgett, lpeer, lsurette, oourfali, rbalakri, Rhev-m-bugs, scohen, tnisan, yeylon, ykaul
Target Milestone: ovirt-3.6.0-rcKeywords: ZStream
Target Release: 3.6.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: ovirt-engine-3.6.0_qa1 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 1177221 (view as bug list) Environment:
Last Closed: 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:
Bug Depends On:    
Bug Blocks: 1177221    
Attachments:
Description Flags
engine vdsm and server logs none

Description Kevin Alon Goldblatt 2014-11-06 13:02:33 UTC
Created attachment 954433 [details]
engine vdsm and server logs

Description of problem:
Power off the vm during a Live merge operation as part of the delete snapshot operation causes the images to to be set to illegal. After the vm comes up fail to delete the snapshot related to these illegal images


Version-Release number of selected component (if applicable):
rhevm-3.5.0-0.17.beta.el6ev.noarch
vdsm-4.16.7.2-1.el7.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Create a vm with 4 disks (2 thin provisioned and 2 preallocated nfs disks)
2. Created snapshots 1, 2, 3 
3. Select to delete snapshot 2 and during the delete and live merge operation I Powered of the vm. The delete snapshot fails and the images are set to illegal.
4. After starting the vm again I try deleting the same snapshot again but FAIL as the immages related to the snapshot are illegal

Actual results:
Failed to delete snapshot. 

Expected results:
A cleanup should have be performed. Either a rollback or the delete operation must be resume when the vm comes up again.

Additional info:
From engine.log:  SEE MY COMMENTS IN THE LOG BELOW>
-------------------------

2014-11-05 18:29:32,569 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-14) Correlation ID: 786fcd9a, Job ID: bad9b1fd-4bd7-4c98-a0ae-26117fa28b7d, Call Stack: null, Custom Event ID: -1, Message: VM nfs12 started on Host nott-vds1
2014-11-05 18:33:09,634 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-4) Correlation ID: df65174, Job ID: 17a11b4a-8ce7-470f-a399-07332d376471, Call Stack: null, Custom Event ID: -1, Message: Snapshot '2' deletion for VM 'nfs12' was initiated by admin.
2014-11-05 18:33:21,461 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-83) FINISH, FullListVdsCommand, return: [{acpiEnable=true, emulatedMachine=rhel6.5.0, pid=20696, memGuaranteedSize=1024, transparentHugePages=true, displaySecurePort=5902, spiceSslCipherSuite=DEFAULT, cpuType=Conroe, smp=1, pauseCode=NOERR, custom={}, vmType=kvm, memSize=1024, smpCoresPerSocket=1, vmName=nfs12, nice=0, status=Up, bootMenuEnable=false, guestDiskMapping={}, vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, copyPasteEnable=true, displayIp=10.35.115.10, displayPort=-1, smartcardEnable=false, spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard, fileTransferEnable=true, nicModel=rtl8139,pv, keyboardLayout=en-us, kvmEnable=true, displayNetwork=rhevm, devices=[Ljava.lang.Object;@3c8b0b69, timeOffset=0, maxVCpus=16, clientIp=, display=qxl}], log id: 50c028c1
2014-11-05 18:33:24,532 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-100) FINISH, FullListVdsCommand, return: [{acpiEnable=true, emulatedMachine=rhel6.5.0, pid=20696, memGuaranteedSize=1024, transparentHugePages=true, displaySecurePort=5902, spiceSslCipherSuite=DEFAULT, cpuType=Conroe, smp=1, pauseCode=NOERR, custom={}, vmType=kvm, memSize=1024, smpCoresPerSocket=1, vmName=nfs12, nice=0, status=Up, bootMenuEnable=false, guestDiskMapping={}, vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, copyPasteEnable=true, displayIp=10.35.115.10, displayPort=-1, smartcardEnable=false, spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard, fileTransferEnable=true, nicModel=rtl8139,pv, keyboardLayout=en-us, kvmEnable=true, displayNetwork=rhevm, devices=[Ljava.lang.Object;@554b0887, timeOffset=0, maxVCpus=16, clientIp=, display=qxl}], log id: 15a06510
2014-11-05 18:33:38,180 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-7-thread-17) [2b1ab045] Correlation ID: 2b1ab045, Job ID: f1347e37-6ee2-4b54-8c84-19840c06a1c9, Call Stack: null, Custom Event ID: -1, Message: VM nfs12 powered off by admin (Host: nott-vds1) (Reason: Not Specified).
2014-11-05 18:34:09,910 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-91) [df65174] Correlation ID: df65174, Call Stack: null, Custom Event ID: -1, Message: Failed to delete snapshot '2' for VM 'nfs12'.
2014-11-05 18:34:17,467 INFO  [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (org.ovirt.thread.pool-7-thread-34) [369f3491] START, CreateVmVDSCommand(HostName = nott-vds1, HostId = 8413a492-41a0-41d6-af68-6ac9e005fdbd, vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, vm=VM [nfs12]), log id: 453d6213
2014-11-05 18:34:17,470 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-7-thread-34) [369f3491] START, CreateVDSCommand(HostName = nott-vds1, HostId = 8413a492-41a0-41d6-af68-6ac9e005fdbd, vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, vm=VM [nfs12]), log id: 32e295de
2014-11-05 18:34:17,510 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-7-thread-34) [369f3491] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand kvmEnable=true,keyboardLayout=en-us,nice=0,displayNetwork=rhevm,copyPasteEnable=true,timeOffset=0,transparentHugePages=true,vmId=6275a347-2715-4013-aad4-9c4e66c76eb9,acpiEnable=true,custom={device_9b82d536-a989-4efa-b5ed-199417b00614device_2efddec2-b88d-42f6-969d-86823dd05034=VmDevice {vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, deviceId=2efddec2-b88d-42f6-969d-86823dd05034, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={bus=0, controller=0, type=virtio-serial, port=1}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null}, device_9b82d536-a989-4efa-b5ed-199417b00614device_2efddec2-b88d-42f6-969d-86823dd05034device_d269a959-eca9-4c53-9e7a-cfa2fc3becf9device_61831608-6c17-4995-b6b5-0bb2c11e6622=VmDevice {vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, deviceId=61831608-6c17-4995-b6b5-0bb2c11e6622, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={bus=0, controller=0, type=virtio-serial, port=3}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}, snapshotId=null}, device_9b82d536-a989-4efa-b5ed-199417b00614device_2efddec2-b88d-42f6-969d-86823dd05034device_d269a959-eca9-4c53-9e7a-cfa2fc3becf9=VmDevice {vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, deviceId=d269a959-eca9-4c53-9e7a-cfa2fc3becf9, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={bus=0, controller=0, type=virtio-serial, port=2}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null}, device_9b82d536-a989-4efa-b5ed-199417b00614=VmDevice {vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, deviceId=9b82d536-a989-4efa-b5ed-199417b00614, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={slot=0x01, bus=0x00, domain=0x0000, type=pci, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}},spiceSslCipherSuite=DEFAULT,memSize=1024,smp=1,emulatedMachine=rhel6.5.0,vmType=kvm,memGuaranteedSize=1024,display=qxl,smartcardEnable=false,bootMenuEnable=false,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,smpCoresPerSocket=1,maxVCpus=16,devices=[{address={bus=0x00, domain=0x0000, type=pci, slot=0x02, function=0x0}, specParams={vram=32768, heads=1}, device=qxl, type=video, deviceId=5e82d795-173a-49f6-893e-7b791cecb564}, {shared=false, iface=ide, index=2, address={unit=0, bus=1, target=0, controller=0, type=drive}, specParams={path=}, path=, device=cdrom, type=disk, readonly=true, deviceId=c6c620c4-905d-4718-a198-d0cd418a8da1}, {shared=false, index=0, volumeID=307d7e8d-3b65-4c5f-aede-5cc31dc4bacc, propagateErrors=off, format=cow, type=disk, iface=virtio, bootOrder=1, address={bus=0x00, domain=0x0000, type=pci, slot=0x06, function=0x0}, domainID=b8fec445-9ee1-42df-ab4f-f5269d22311d, imageID=b750d0cb-30f2-42c6-b630-b333af473d14, specParams={}, optional=false, device=disk, poolID=059d21c6-7b13-4082-ab62-3251a68dac0f, readonly=false, deviceId=b750d0cb-30f2-42c6-b630-b333af473d14}, {shared=false, volumeID=8a115bf5-6d91-4aea-a201-0c075231199d, iface=virtio, imageID=fd1b0481-88b2-4eb0-9dd4-6e8ebf215b10, domainID=b8fec445-9ee1-42df-ab4f-f5269d22311d, address={bus=0x00, domain=0x0000, type=pci, slot=0x07, function=0x0}, specParams={}, optional=false, propagateErrors=off, device=disk, poolID=059d21c6-7b13-4082-ab62-3251a68dac0f, format=cow, type=disk, readonly=false, deviceId=fd1b0481-88b2-4eb0-9dd4-6e8ebf215b10}, {shared=false, volumeID=61528c49-d831-4e7f-95a1-79e0dd4906f5, iface=scsi, imageID=b1cbf16d-d3e5-48ce-abfe-b6b545de8299, domainID=b8fec445-9ee1-42df-ab4f-f5269d22311d, address={unit=1, bus=0, target=0, controller=0, type=drive}, specParams={}, optional=false, propagateErrors=off, device=disk, poolID=059d21c6-7b13-4082-ab62-3251a68dac0f, format=cow, type=disk, readonly=false, deviceId=b1cbf16d-d3e5-48ce-abfe-b6b545de8299}, {shared=false, volumeID=0dc9d4b7-3fb3-4866-a1b9-84a99e8f5d91, iface=scsi, imageID=a7f89787-73ff-4004-bd21-528ad2c7d96d, domainID=b8fec445-9ee1-42df-ab4f-f5269d22311d, address={unit=0, bus=0, target=0, controller=0, type=drive}, specParams={}, optional=false, propagateErrors=off, device=disk, poolID=059d21c6-7b13-4082-ab62-3251a68dac0f, format=cow, type=disk, readonly=false, deviceId=a7f89787-73ff-4004-bd21-528ad2c7d96d}, {nicModel=pv, address={bus=0x00, domain=0x0000, type=pci, slot=0x03, function=0x0}, specParams={outbound={}, inbound={}}, macAddr=00:1a:4a:ae:b3:05, device=bridge, linkActive=true, type=interface, filter=vdsm-no-mac-spoofing, network=rhevm, deviceId=1fd9406b-bbc9-486d-891b-62456cda3005}, {address={bus=0x00, domain=0x0000, type=pci, slot=0x08, function=0x0}, specParams={model=virtio}, device=memballoon, type=balloon, deviceId=37272ea1-cb76-4794-8bbd-a3dacd2a0f93}, {index=0, model=virtio-scsi, address={bus=0x00, domain=0x0000, type=pci, slot=0x04, function=0x0}, specParams={}, device=scsi, type=controller, deviceId=a560a38e-6fb7-4057-8280-3fb9722ae300}, {address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, specParams={}, device=virtio-serial, type=controller, deviceId=dc29b1cb-6dff-4a29-ad3f-aafb97430786}],vmName=nfs12,cpuType=Conroe,fileTransferEnable=true

STARTED VM HERE !!!!!!--------------------------------------------------
=====================================
2014-11-05 18:34:17,547 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-7-thread-34) [369f3491] Correlation ID: 369f3491, Job ID: 4f8d5b58-b170-4a7c-bc5d-a75503cb902d, Call Stack: null, Custom Event ID: -1, Message: VM nfs12 was started by admin (Host: nott-vds1).


DELETED THE SNAPSHOT A SECOND TIME !!!!!!-------------------
====================================
2014-11-05 18:35:38,170 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8702-14) Correlation ID: 234a9779, Job ID: e50e0f4e-d103-486d-95c8-8bee3dfe1a82, Call Stack: null, Custom Event ID: -1, 
Message: Snapshot '2' deletion for VM 'nfs12' was initiated by admin.
2014-11-05 18:35:39,937 INFO  [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-34) [72358537] Executing Live Merge command step MERGE
2014-11-05 18:35:39,961 INFO  [org.ovirt.engine.core.bll.MergeCommand] (pool-6-thread-9) [112e28f8] Running command: MergeCommand internal: true. Entities affected :  ID: b8fec445-9ee1-42df-ab4f-f5269d22311d Type: Storage
2014-11-05 18:35:39,967 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-9) [112e28f8] START, MergeVDSCommand(HostName = nott-vds1, MergeVDSCommandParameters{HostId = 8413a492-41a0-41d6-af68-6ac9e005fdbd, 
vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, storagePoolId=059d21c6-7b13-4082-ab62-3251a68dac0f, storageDomainId=b8fec445-9ee1-42df-ab4f-f5269d22311d, imageGroupId=b750d0cb-30f2-42c6-b630-b333af473d14, imageId=307d7e8d-3b65-4c5f-aede-5cc31
dc4bacc, baseImageId=3b59517c-da8a-47fc-a236-d8310bdc5ef7, topImageId=37a8a7c6-712b-40c2-8b95-2e6e12d154c2, bandwidth=0}), log id: 37ade868
2014-11-05 18:35:39,970 INFO  [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-34) [47e2d665] Executing Live Merge command step MERGE
2014-11-05 18:35:39,999 INFO  [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-34) [3013d620] Executing Live Merge command step MERGE
2014-11-05 18:35:40,002 INFO  [org.ovirt.engine.core.bll.MergeCommand] (pool-6-thread-10) [3c2d6d12] Running command: MergeCommand internal: true. Entities affected :  ID: b8fec445-9ee1-42df-ab4f-f5269d22311d Type: Storage
2014-11-05 18:35:40,004 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-10) [3c2d6d12] START, MergeVDSCommand(HostName = nott-vds1, MergeVDSCommandParameters{HostId = 8413a492-41a0-41d6-af68-6ac9e005fdbd,
 vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, storagePoolId=059d21c6-7b13-4082-ab62-3251a68dac0f, storageDomainId=b8fec445-9ee1-42df-ab4f-f5269d22311d, imageGroupId=a7f89787-73ff-4004-bd21-528ad2c7d96d, imageId=0dc9d4b7-3fb3-4866-a1b9-84a9
9e8f5d91, baseImageId=24b7a30d-b3fe-4246-ac41-6754b731312b, topImageId=a270a059-61c0-4dbb-8116-4ed336807a3a, bandwidth=0}), log id: 20525fd3
2014-11-05 18:35:40,024 INFO  [org.ovirt.engine.core.bll.RemoveSnapshotCommandCallback] (DefaultQuartzScheduler_Worker-34) Waiting on Live Merge child commands to complete
2014-11-05 18:35:40,029 INFO  [org.ovirt.engine.core.bll.MergeCommand] (pool-6-thread-4) [6542e3de] Running command: MergeCommand internal: true. Entities affected :  ID: b8fec445-9ee1-42df-ab4f-f5269d22311d Type: Storage
2014-11-05 18:35:40,034 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-4) [6542e3de] START, MergeVDSCommand(HostName = nott-vds1, MergeVDSCommandParameters{HostId = 8413a492-41a0-41d6-af68-6ac9e005fdbd, 
vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, storagePoolId=059d21c6-7b13-4082-ab62-3251a68dac0f, storageDomainId=b8fec445-9ee1-42df-ab4f-f5269d22311d, imageGroupId=fd1b0481-88b2-4eb0-9dd4-6e8ebf215b10, imageId=8a115bf5-6d91-4aea-a201-0c075
231199d, baseImageId=8f232570-d886-465c-96b9-d9a499dc474a, topImageId=336d6d60-6e4b-4ae5-b781-92406024fa12, bandwidth=0}), log id: b8bf2ba
2014-11-05 18:35:40,040 INFO  [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-34) [401029d9] Executing Live Merge command step MERGE
2014-11-05 18:35:40,070 INFO  [org.ovirt.engine.core.bll.MergeCommand] (pool-6-thread-2) [873ecd3] Running command: MergeCommand internal: true. Entities affected :  ID: b8fec445-9ee1-42df-ab4f-f5269d22311d Type: Storage
2014-11-05 18:35:40,076 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-2) [873ecd3] START, MergeVDSCommand(HostName = nott-vds1, MergeVDSCommandParameters{HostId = 8413a492-41a0-41d6-af68-6ac9e005fdbd, v
mId=6275a347-2715-4013-aad4-9c4e66c76eb9, storagePoolId=059d21c6-7b13-4082-ab62-3251a68dac0f, storageDomainId=b8fec445-9ee1-42df-ab4f-f5269d22311d, imageGroupId=b1cbf16d-d3e5-48ce-abfe-b6b545de8299, imageId=61528c49-d831-4e7f-95a1-79e0dd
4906f5, baseImageId=cc6fc8f9-020d-44dd-a248-457b7652579f, topImageId=83335262-2c84-4625-86b8-2b0df5155f99, bandwidth=0}), log id: 32d8aa89
2014-11-05 18:35:41,079 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-9) [112e28f8] Failed in MergeVDS method
2014-11-05 18:35:41,079 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-9) [112e28f8] Command org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand return value 
 StatusOnlyReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=52, mMessage=Merge failed]]
2014-11-05 18:35:41,079 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-9) [112e28f8] HostName = nott-vds1
2014-11-05 18:35:41,079 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-9) [112e28f8] Command MergeVDSCommand(HostName = nott-vds1, MergeVDSCommandParameters{HostId = 8413a492-41a0-41d6-af68-6ac9e005fdbd,
 vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, storagePoolId=059d21c6-7b13-4082-ab62-3251a68dac0f, storageDomainId=b8fec445-9ee1-42df-ab4f-f5269d22311d, imageGroupId=b750d0cb-30f2-42c6-b630-b333af473d14, imageId=307d7e8d-3b65-4c5f-aede-5cc3
1dc4bacc, baseImageId=3b59517c-da8a-47fc-a236-d8310bdc5ef7, topImageId=37a8a7c6-712b-40c2-8b95-2e6e12d154c2, bandwidth=0}) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error 
= Merge failed, code = 52
2014-11-05 18:35:41,080 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-9) [112e28f8] FINISH, MergeVDSCommand, log id: 37ade868
2014-11-05 18:35:41,080 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-6-thread-9) [112e28f8] Command org.ovirt.engine.core.bll.MergeCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbrok
er.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52 (Failed with error mergeErr and code 52)
2014-11-05 18:35:41,086 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-6-thread-9) [112e28f8] Transaction rolled-back for command: org.ovirt.engine.core.bll.MergeCommand.
2014-11-05 18:35:41,288 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-10) [3c2d6d12] Failed in MergeVDS method
2014-11-05 18:35:41,289 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-10) [3c2d6d12] Command org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand return value 
 StatusOnlyReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=52, mMessage=Merge failed]]
2014-11-05 18:35:41,289 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-10) [3c2d6d12] HostName = nott-vds1
2014-11-05 18:35:41,289 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-10) [3c2d6d12] Command MergeVDSCommand(HostName = nott-vds1, MergeVDSCommandParameters{HostId = 8413a492-41a0-41d6-af68-6ac9e005fdbd
, vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, storagePoolId=059d21c6-7b13-4082-ab62-3251a68dac0f, storageDomainId=b8fec445-9ee1-42df-ab4f-f5269d22311d, imageGroupId=a7f89787-73ff-4004-bd21-528ad2c7d96d, imageId=0dc9d4b7-3fb3-4866-a1b9-84a
99e8f5d91, baseImageId=24b7a30d-b3fe-4246-ac41-6754b731312b, topImageId=a270a059-61c0-4dbb-8116-4ed336807a3a, bandwidth=0}) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error
 = Merge failed, code = 52
2014-11-05 18:35:41,289 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-10) [3c2d6d12] FINISH, MergeVDSCommand, log id: 20525fd3
2014-11-05 18:35:41,289 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-6-thread-10) [3c2d6d12] Command org.ovirt.engine.core.bll.MergeCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbro
ker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52 (Failed with error mergeErr and code 52)
2014-11-05 18:35:41,295 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-6-thread-10) [3c2d6d12] Transaction rolled-back for command: org.ovirt.engine.core.bll.MergeCommand.
2014-11-05 18:35:41,333 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-4) [6542e3de] Failed in MergeVDS method
2014-11-05 18:35:41,333 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-4) [6542e3de] Command org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand return value 
 StatusOnlyReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=52, mMessage=Merge failed]]
2014-11-05 18:35:41,333 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-4) [6542e3de] HostName = nott-vds1
2014-11-05 18:35:41,334 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-4) [6542e3de] Command MergeVDSCommand(HostName = nott-vds1, MergeVDSCommandParameters{HostId = 8413a492-41a0-41d6-af68-6ac9e005fdbd, vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, storagePoolId=059d21c6-7b13-4082-ab62-3251a68dac0f, storageDomainId=b8fec445-9ee1-42df-ab4f-f5269d22311d, imageGroupId=fd1b0481-88b2-4eb0-9dd4-6e8ebf215b10, imageId=8a115bf5-6d91-4aea-a201-0c075231199d, baseImageId=8f232570-d886-465c-96b9-d9a499dc474a, topImageId=336d6d60-6e4b-4ae5-b781-92406024fa12, bandwidth=0}) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52
2014-11-05 18:35:41,334 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-4) [6542e3de] FINISH, MergeVDSCommand, log id: b8bf2ba
2014-11-05 18:35:41,334 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-6-thread-4) [6542e3de] Command org.ovirt.engine.core.bll.MergeCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52 (Failed with error mergeErr and code 52)
2014-11-05 18:35:41,341 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-6-thread-4) [6542e3de] Transaction rolled-back for command: org.ovirt.engine.core.bll.MergeCommand.
2014-11-05 18:35:41,443 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-2) [873ecd3] Failed in MergeVDS method
2014-11-05 18:35:41,443 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-2) [873ecd3] Command org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand return value 
 StatusOnlyReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=52, mMessage=Merge failed]]
2014-11-05 18:35:41,443 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-2) [873ecd3] HostName = nott-vds1
2014-11-05 18:35:41,444 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-2) [873ecd3] Command MergeVDSCommand(HostName = nott-vds1, MergeVDSCommandParameters{HostId = 8413a492-41a0-41d6-af68-6ac9e005fdbd, vmId=6275a347-2715-4013-aad4-9c4e66c76eb9, storagePoolId=059d21c6-7b13-4082-ab62-3251a68dac0f, storageDomainId=b8fec445-9ee1-42df-ab4f-f5269d22311d, imageGroupId=b1cbf16d-d3e5-48ce-abfe-b6b545de8299, imageId=61528c49-d831-4e7f-95a1-79e0dd4906f5, baseImageId=cc6fc8f9-020d-44dd-a248-457b7652579f, topImageId=83335262-2c84-4625-86b8-2b0df5155f99, bandwidth=0}) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52
2014-11-05 18:35:41,444 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MergeVDSCommand] (pool-6-thread-2) [873ecd3] FINISH, MergeVDSCommand, log id: 32d8aa89
2014-11-05 18:35:41,444 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-6-thread-2) [873ecd3] Command org.ovirt.engine.core.bll.MergeCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to MergeVDS, error = Merge failed, code = 52 (Failed with error mergeErr and code 52)
2014-11-05 18:35:41,449 ERROR [org.ovirt.engine.core.bll.MergeCommand] (pool-6-thread-2) [873ecd3] Transaction rolled-back for command: org.ovirt.engine.core.bll.MergeCommand.
2014-11-05 18:35:50,085 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-45) [72358537] Failed child command status for step MERGE
2014-11-05 18:35:50,095 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-45) [47e2d665] Failed child command status for step MERGE
2014-11-05 18:35:50,101 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-45) [3013d620] Failed child command status for step MERGE
2014-11-05 18:35:50,107 INFO  [org.ovirt.engine.core.bll.RemoveSnapshotCommandCallback] (DefaultQuartzScheduler_Worker-45) [3013d620] Waiting on Live Merge child commands to complete
2014-11-05 18:35:50,117 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-45) [401029d9] Failed child command status for step MERGE

HERE THE ERROR REPORTING THAT THE IMAGES ARE ILLEGAL !!!!!
=======================================
2014-11-05 18:36:00,132 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-72) [72358537] Merging of snapshot 565772d2-d3f3-41bf-8124-4ecafe79ad74 images 3b59517c-da8a-47fc-a236-d8310bdc5ef7..37a8a7c6-712b-40c2-8b95-2e6e12d154c2 failed. Images have been marked illegal and can no longer be previewed or reverted to. Please retry Live Merge on the snapshot to complete the operation.
2014-11-05 18:36:00,154 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-72) [47e2d665] Merging of snapshot 565772d2-d3f3-41bf-8124-4ecafe79ad74 images 24b7a30d-b3fe-4246-ac41-6754b731312b..a270a059-61c0-4dbb-8116-4ed336807a3a failed. Images have been marked illegal and can no longer be previewed or reverted to. Please retry Live Merge on the snapshot to complete the operation.
2014-11-05 18:36:00,165 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-72) [3013d620] Merging of snapshot 565772d2-d3f3-41bf-8124-4ecafe79ad74 images 8f232570-d886-465c-96b9-d9a499dc474a..336d6d60-6e4b-4ae5-b781-92406024fa12 failed. Images have been marked illegal and can no longer be previewed or reverted to. Please retry Live Merge on the snapshot to complete the operation.
2014-11-05 18:36:00,174 INFO  [org.ovirt.engine.core.bll.RemoveSnapshotCommandCallback] (DefaultQuartzScheduler_Worker-72) [234a9779] All Live Merge child commands have completed, status FAILED
2014-11-05 18:36:00,185 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-72) [401029d9] Merging of snapshot 565772d2-d3f3-41bf-8124-4ecafe79ad74 images cc6fc8f9-020d-44dd-a248-457b7652579f..83335262-2c84-4625-86b8-2b0df5155f99 failed. Images have been marked illegal and can no longer be previewed or reverted to. Please retry Live Merge on the snapshot to complete the operation.
2014-11-05 18:36:10,200 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotCommand] (DefaultQuartzScheduler_Worker-65) [234a9779] Ending command with failure: org.ovirt.engine.core.bll.RemoveSnapshotCommand
2014-11-05 18:36:10,231 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-65) [234a9779] Correlation ID: 234a9779, Call Stack: null, Custom Event ID: -1, Message: Failed to delete snapshot '2' for VM 'nfs12'.

Comment 2 Adam Litke 2014-11-06 16:06:56 UTC
Assigning to Greg to address the engine side...

This seems to be an engine problem.  During the first attempt to live merge there were 4 calls to vdsm.  All 4 merges completed successfully but the volumes have not been deleted yet.  Then, engine tries to update job status and finds the VM gone.  The jobs are cleaned up but we improperly resolve the job status as failed.  The correct action should be to lock the VM and call vdsm's reconcileVolumeChain() SPM verb to determine the final status of the merge.  In this scenario, we would discover that the merges had in fact completed successfully and we could move on to the deleteVolume step.

Comment 3 Adam Litke 2014-11-06 16:28:37 UTC
2014-11-05 18:33:39,500 WARN  [org.ovirt.engine.core.vdsbroker.irsbroker.ReconcileVolumeChainVDSCommand] (pool-6-thread-4) [2f383a10] Unexpected return value: StatusForXmlRpc [mCode=-32601, mMessage=The method does not exist / is not available.]

The command to call on the vdsm side is: Image.reconcileVolumeChain, not VM.reconcileVolumeChain.

Comment 4 Kevin Alon Goldblatt 2014-12-14 15:58:42 UTC
I ran the original scenario again and I was able to delete the snapshot the second time successfully. Moving to VERIFIED!

Used libvirt version as follows:
libvirt-client-1.2.8-10.el7ost.x86_64
libvirt-daemon-driver-qemu-1.2.8-10.el7ost.x86_64
libvirt-daemon-driver-storage-1.2.8-10.el7ost.x86_64
libvirt-python-1.2.8-6.el7ost.x86_64
libvirt-daemon-1.2.8-10.el7ost.x86_64
libvirt-daemon-driver-nwfilter-1.2.8-10.el7ost.x86_64
libvirt-daemon-driver-interface-1.2.8-10.el7ost.x86_64
libvirt-daemon-driver-secret-1.2.8-10.el7ost.x86_64
libvirt-daemon-kvm-1.2.8-10.el7ost.x86_64
libvirt-lock-sanlock-1.2.8-10.el7ost.x86_64
libvirt-daemon-driver-network-1.2.8-10.el7ost.x86_64
libvirt-daemon-driver-nodedev-1.2.8-10.el7ost.x86_64
libvirt-daemon-config-nwfilter-1.2.8-10.el7ost.x86_64

Used engine and vdsm as follows:
vdsm-4.16.8.1-2.el7ev.x86_64
rhevm-3.5.0-0.23.beta.el6ev.noarch

Comment 6 Kevin Alon Goldblatt 2015-04-28 12:29:52 UTC
Verified with version:
v3.6
ovirt-engine-3.6.0-0.0.master.20150412172306.git55ba764.el6.noarch
vdsm-4.17.0-632.git19a83a2.el7.x86_64


Verified with scenario:

Steps to Reproduce:
1. Create a vm with 4 disks (2 thin provisioned and 2 preallocated nfs disks)
2. Created snapshots 1, 2, 3 
3. Select to delete snapshot 2 and during the delete and live merge operation I Powered of the vm. The delete snapshot fails and the images are set to illegal.
4. After starting the vm again I was able to to delete the same snapshot.

Moving to verified!!

Comment 7 Allon Mureinik 2016-03-10 10:39:02 UTC
RHEV 3.6.0 has been released, setting status to CLOSED CURRENTRELEASE

Comment 8 Allon Mureinik 2016-03-10 10:39:02 UTC
RHEV 3.6.0 has been released, setting status to CLOSED CURRENTRELEASE

Comment 9 Allon Mureinik 2016-03-10 10:44:53 UTC
RHEV 3.6.0 has been released, setting status to CLOSED CURRENTRELEASE

Comment 10 Allon Mureinik 2016-03-10 12:01:33 UTC
RHEV 3.6.0 has been released, setting status to CLOSED CURRENTRELEASE