Bug 879167

Created attachment 649592 [details]
image does not exist logs

The removal of the src image failed since the LVs were still open.
Afterwards the destination image was succefully removed.
Engine still look for the image at the destination.


Thread-16680::INFO::2012-11-21 16:44:45,322::logUtils::37::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='d40978c8-3fab-483b-b786-2f1e1c5cf130', spUUID='edf0ee04-0cc2-4e13-877d-1e89541aea55', imgUUID='270835d7-b3bb-4e1c-a34d-f09d0538affd', size='16106127360', volFormat=4, preallocate=2, diskType=2, volUUID='34ff2273-e1cd-41b9-9c30-61defdc85948', desc='', srcImgUUID='a8eb3963-520a-435d-aba4-80a0dd2d9983', srcVolUUID='39f89a6a-7fbb-43c0-a5ea-19b271f51829')
Thread-17083::INFO::2012-11-21 16:51:17,001::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='d40978c8-3fab-483b-b786-2f1e1c5cf130', spUUID='edf0ee04-0cc2-4e13-877d-1e89541aea55', imgUUID='270835d7-b3bb-4e1c-a34d-f09d0538affd', volUUID='34ff2273-e1cd-41b9-9c30-61defdc85948')
Thread-17083::INFO::2012-11-21 16:51:17,419::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/edf0ee04-0cc2-4e13-877d-1e89541aea55/d40978c8-3fab-483b-b786-2f1e1c5cf130/images/270835d7-b3bb-4e1c-a34d-f09d0538affd/34ff2273-e1cd-41b9-9c30-61defdc85948', 'chain': [{'path': '/rhev/data-center/edf0ee04-0cc2-4e13-877d-1e89541aea55/d40978c8-3fab-483b-b786-2f1e1c5cf130/images/270835d7-b3bb-4e1c-a34d-f09d0538affd/39f89a6a-7fbb-43c0-a5ea-19b271f51829', 'domainID': 'd40978c8-3fab-483b-b786-2f1e1c5cf130', 'volumeID': '39f89a6a-7fbb-43c0-a5ea-19b271f51829', 'imageID': '270835d7-b3bb-4e1c-a34d-f09d0538affd'}, {'path': '/rhev/data-center/edf0ee04-0cc2-4e13-877d-1e89541aea55/d40978c8-3fab-483b-b786-2f1e1c5cf130/images/270835d7-b3bb-4e1c-a34d-f09d0538affd/34ff2273-e1cd-41b9-9c30-61defdc85948', 'domainID': 'd40978c8-3fab-483b-b786-2f1e1c5cf130', 'volumeID': '34ff2273-e1cd-41b9-9c30-61defdc85948', 'imageID': '270835d7-b3bb-4e1c-a34d-f09d0538affd'}]}
Thread-17595::INFO::2012-11-21 17:00:27,241::logUtils::37::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='d40978c8-3fab-483b-b786-2f1e1c5cf130', spUUID='edf0ee04-0cc2-4e13-877d-1e89541aea55', imgUUID='270835d7-b3bb-4e1c-a34d-f09d0538affd', size='16106127360', volFormat=4, preallocate=2, diskType=2, volUUID='98d1cf94-5e59-4f85-8696-698b0269e347', desc='', srcImgUUID='270835d7-b3bb-4e1c-a34d-f09d0538affd', srcVolUUID='34ff2273-e1cd-41b9-9c30-61defdc85948')
Thread-17639::INFO::2012-11-21 17:00:56,601::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='d40978c8-3fab-483b-b786-2f1e1c5cf130', spUUID='edf0ee04-0cc2-4e13-877d-1e89541aea55', imgUUID='270835d7-b3bb-4e1c-a34d-f09d0538affd', volUUID='98d1cf94-5e59-4f85-8696-698b0269e347')
Thread-17639::INFO::2012-11-21 17:00:58,525::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/edf0ee04-0cc2-4e13-877d-1e89541aea55/d40978c8-3fab-483b-b786-2f1e1c5cf130/images/270835d7-b3bb-4e1c-a34d-f09d0538affd/98d1cf94-5e59-4f85-8696-698b0269e347', 'chain': [{'path': '/rhev/data-center/edf0ee04-0cc2-4e13-877d-1e89541aea55/d40978c8-3fab-483b-b786-2f1e1c5cf130/images/270835d7-b3bb-4e1c-a34d-f09d0538affd/39f89a6a-7fbb-43c0-a5ea-19b271f51829', 'domainID': 'd40978c8-3fab-483b-b786-2f1e1c5cf130', 'volumeID': '39f89a6a-7fbb-43c0-a5ea-19b271f51829', 'imageID': '270835d7-b3bb-4e1c-a34d-f09d0538affd'}, {'path': '/rhev/data-center/edf0ee04-0cc2-4e13-877d-1e89541aea55/d40978c8-3fab-483b-b786-2f1e1c5cf130/images/270835d7-b3bb-4e1c-a34d-f09d0538affd/34ff2273-e1cd-41b9-9c30-61defdc85948', 'domainID': 'd40978c8-3fab-483b-b786-2f1e1c5cf130', 'volumeID': '34ff2273-e1cd-41b9-9c30-61defdc85948', 'imageID': '270835d7-b3bb-4e1c-a34d-f09d0538affd'}, {'path': '/rhev/
data-center/edf0ee04-0cc2-4e13-877d-1e89541aea55/d40978c8-3fab-483b-b786-2f1e1c5cf130/images/270835d7-b3bb-4e1c-a34d-f09d0538affd/98d1cf94-5e59-4f85-8696-698b0269e347', 'domainID': 'd40978c8-3fab-483b-b786-2f1e1c5cf130', 'volumeID': '98d1cf94-5e59-4f85-8696-698b0269e347', 'imageID': '270835d7-b3bb-4e1c-a34d-f09d0538affd'}]}
Thread-17662::INFO::2012-11-21 17:01:26,372::logUtils::37::dispatcher::(wrapper) Run and protect: cloneImageStructure(spUUID='edf0ee04-0cc2-4e13-877d-1e89541aea55', sdUUID='d40978c8-3fab-483b-b786-2f1e1c5cf130', imgUUID='270835d7-b3bb-4e1c-a34d-f09d0538affd', dstSdUUID='8c0ef67f-03c1-4fbf-b099-3e3668405cfc')
Thread-17705::INFO::2012-11-21 17:02:01,007::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='8c0ef67f-03c1-4fbf-b099-3e3668405cfc', spUUID='edf0ee04-0cc2-4e13-877d-1e89541aea55', imgUUID='270835d7-b3bb-4e1c-a34d-f09d0538affd', volUUID='98d1cf94-5e59-4f85-8696-698b0269e347')
Thread-17705::INFO::2012-11-21 17:02:01,731::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/edf0ee04-0cc2-4e13-877d-1e89541aea55/8c0ef67f-03c1-4fbf-b099-3e3668405cfc/images/270835d7-b3bb-4e1c-a34d-f09d0538affd/98d1cf94-5e59-4f85-8696-698b0269e347', 'chain': [{'path': '/rhev/data-center/edf0ee04-0cc2-4e13-877d-1e89541aea55/8c0ef67f-03c1-4fbf-b099-3e3668405cfc/images/270835d7-b3bb-4e1c-a34d-f09d0538affd/39f89a6a-7fbb-43c0-a5ea-19b271f51829', 'domainID': '8c0ef67f-03c1-4fbf-b099-3e3668405cfc', 'volumeID': '39f89a6a-7fbb-43c0-a5ea-19b271f51829', 'imageID': '270835d7-b3bb-4e1c-a34d-f09d0538affd'}, {'path': '/rhev/data-center/edf0ee04-0cc2-4e13-877d-1e89541aea55/8c0ef67f-03c1-4fbf-b099-3e3668405cfc/images/270835d7-b3bb-4e1c-a34d-f09d0538affd/34ff2273-e1cd-41b9-9c30-61defdc85948', 'domainID': '8c0ef67f-03c1-4fbf-b099-3e3668405cfc', 'volumeID': '34ff2273-e1cd-41b9-9c30-61defdc85948', 'imageID': '270835d7-b3bb-4e1c-a34d-f09d0538affd'}, {'path': '/rhev/
data-center/edf0ee04-0cc2-4e13-877d-1e89541aea55/8c0ef67f-03c1-4fbf-b099-3e3668405cfc/images/270835d7-b3bb-4e1c-a34d-f09d0538affd/98d1cf94-5e59-4f85-8696-698b0269e347', 'domainID': '8c0ef67f-03c1-4fbf-b099-3e3668405cfc', 'volumeID': '98d1cf94-5e59-4f85-8696-698b0269e347', 'imageID': '270835d7-b3bb-4e1c-a34d-f09d0538affd'}]}
Thread-17705::INFO::2012-11-21 17:02:31,017::logUtils::37::dispatcher::(wrapper) Run and protect: teardownImage(sdUUID='8c0ef67f-03c1-4fbf-b099-3e3668405cfc', spUUID='edf0ee04-0cc2-4e13-877d-1e89541aea55', imgUUID='270835d7-b3bb-4e1c-a34d-f09d0538affd', volUUID=None)
Thread-17722::INFO::2012-11-21 17:02:32,872::logUtils::37::dispatcher::(wrapper) Run and protect: syncImageData(spUUID='edf0ee04-0cc2-4e13-877d-1e89541aea55', sdUUID='d40978c8-3fab-483b-b786-2f1e1c5cf130', imgUUID='270835d7-b3bb-4e1c-a34d-f09d0538affd', dstSdUUID='8c0ef67f-03c1-4fbf-b099-3e3668405cfc', syncType='INTERNAL')
Thread-17922::INFO::2012-11-21 17:04:52,415::logUtils::37::dispatcher::(wrapper) Run and protect: deleteImage(sdUUID='d40978c8-3fab-483b-b786-2f1e1c5cf130', spUUID='edf0ee04-0cc2-4e13-877d-1e89541aea55', imgUUID='270835d7-b3bb-4e1c-a34d-f09d0538affd', postZero='false', force='false')
Thread-17939::INFO::2012-11-21 17:05:04,896::logUtils::37::dispatcher::(wrapper) Run and protect: deleteImage(sdUUID='8c0ef67f-03c1-4fbf-b099-3e3668405cfc', spUUID='edf0ee04-0cc2-4e13-877d-1e89541aea55', imgUUID='270835d7-b3bb-4e1c-a34d-f09d0538affd', postZero='false', force='false')

patch merged:
http://gerrit.ovirt.org/#/c/10154/
Change-Id: Iadcffa5748b58b1af40535b0447487dde6c2d6cb

tested on sf3 with vdsm-4.10.2-3.0.el6ev.x86_64

I live migrated two disks of the same vm and after the move started I added disks to a second vm on src domain so that we will have low disk space. 

we failed to delete volumes on one of the disks: 

2013-01-20 17:20:05,964 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (pool-3-thread-40) [3e493079] START, DeleteImageGroupVDSCommand( storagePoolId = afcde1c5-6022-4077-ab06-2beed7e5e404, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 8bcf7e0d-a418-4210-a79d-8a7888a26c5c, imageGroupId = d4e4d029-d9c5-47ee-8df9-06b70e2536f4, postZeros = false, forceDelete = false), log id: 5a354ebc
2013-01-20 17:20:12,316 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (pool-3-thread-40) [3e493079] Failed in DeleteImageGroupVDS method
2013-01-20 17:20:12,316 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (pool-3-thread-40) [3e493079] Error code CannotRemoveLogicalVolume and error message IRSGenericException: IRSErrorException: Failed to DeleteImageGroupVDS, error = Cannot remove Logical Volume: ('8bcf7e0d-a418-4210-a79d-8a7888a26c5c', "('f4d19fed-171f-46d1-a403-8d9736a6c280', 'adcc64f2-f4d7-4e4e-8a96-ee90f592e217')")
2013-01-20 17:20:12,316 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (pool-3-thread-40) [3e493079] IrsBroker::Failed::DeleteImageGroupVDS due to: IRSErrorException: IRSGenericException: IRSErrorException: Failed to DeleteImageGroupVDS, error = Cannot remove Logical Volume: ('8bcf7e0d-a418-4210-a79d-8a7888a26c5c', "('f4d19fed-171f-46d1-a403-8d9736a6c280', 'adcc64f2-f4d7-4e4e-8a96-ee90f592e217')")
2013-01-20 17:20:12,366 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (pool-3-thread-40) [3e493079] FINISH, DeleteImageGroupVDSCommand, log id: 5a354ebc
2013-01-20 17:20:12,681 ERROR [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-3-thread-40) EntityAsyncTask::EndCommandAction [within thread]: EndAction for action type LiveMigrateDisk threw an exception: org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException: org.ovirt.engine.core.vdsbroker.irsbroker.IRSErrorException: IRSGenericException: IRSErrorException: Failed to DeleteImageGroupVDS, error = Cannot remove Logical Volume: ('8bcf7e0d-a418-4210-a79d-8a7888a26c5c', "('f4d19fed-171f-46d1-a403-8d9736a6c280', 'adcc64f2-f4d7-4e4e-8a96-ee90f592e217')")


we also have exception in the logs: 

2013-01-20 17:20:12,681 ERROR [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-3-thread-40) EntityAsyncTask::EndCommandAction [within thread]: EndAction for action type LiveMigrateDisk threw an exception: org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException: org.ovirt.engine.core.vdsbroker.irsbroker.IRSErrorException: IRSGenericException: IRSErrorException: Failed to DeleteImageGroupVDS, error = Cannot remove Logical Volume: ('8bcf7e0d-a418-4210-a79d-8a7888a26c5c', "('f4d19fed-171f-46d1-a403-8d9736a6c280', 'adcc64f2-f4d7-4e4e-8a96-ee90f592e217')")
        at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:168) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.RunVdsCommand(VDSBrokerFrontendImpl.java:33) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.AbstractSPMAsyncTaskHandler.compensate(AbstractSPMAsyncTaskHandler.java:51) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.revertPreviousHandlers(CommandBase.java:595) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.internalEndWithFailure(CommandBase.java:535) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:472) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1465) [engine-bll.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:166) [engine-utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:108) [engine-utils.jar:]
        at org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:416) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.Backend.endAction(Backend.java:376) [engine-bll.jar:]
        at sun.reflect.GeneratedMethodAccessor218.invoke(Unknown Source) [:1.7.0_09-icedtea]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_09-icedtea]
        at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_09-icedtea]
        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee.jar:7.1.3.Final-redhat-4]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.ovirt.engine.core.utils.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:11) [engine-utils.jar:]


the UI is reporting the action as rolled back - moving back to devel.

Created attachment 683755 [details]
logs and dbdump

The issue described in comment #6 is during roll-back/cleanup phase (i.e. deleting the target image). The original bug fix is to prevent rollback on failure of source image deletion. Moving to ON_QA for verification.

Dafna, can you please open a seperate bug on the issue described in the comment?

I tested this scenario on vdsm-4.10.2-5.0.el6ev.x86_64 with libvirt-0.10.2-18.el6.x86_64 and qemu-kvm-rhev-0.12.1.2-2.348.el6.x86_64

we seem to be hitting multiple issues with this scenario with the same result - cannot run a vm after live storage migration. 

two examples - one vm is getting the below error below after running the vm

Thread-76880::ERROR::2013-02-06 15:25:48,795::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Logical volume does not exist: ('04a91189-8741-4589-900b-3adbe0908d63/04512717-e9a9-4fdc-8c2c-a0adf845e09f',)", 'code': 610}}
Thread-76880::DEBUG::2013-02-06 15:25:48,797::vm::676::vm.Vm::(_startUnderlyingVm) vmId=`9f4dbd09-e734-496e-8ba7-64297082912e`::_ongoingCreations released
Thread-76880::ERROR::2013-02-06 15:25:48,800::vm::700::vm.Vm::(_startUnderlyingVm) vmId=`9f4dbd09-e734-496e-8ba7-64297082912e`::The vm start process failed
Traceback (most recent call last):
  File "/usr/share/vdsm/vm.py", line 662, in _startUnderlyingVm
    self._run()
  File "/usr/share/vdsm/libvirtvm.py", line 1441, in _run
    devices = self.buildConfDevices()
  File "/usr/share/vdsm/vm.py", line 499, in buildConfDevices
    self._normalizeVdsmImg(drv)
  File "/usr/share/vdsm/vm.py", line 406, in _normalizeVdsmImg
    drv['truesize'] = res['truesize']
KeyError: 'truesize'
Thread-76880::DEBUG::2013-02-06 15:25:48,883::vm::1047::vm.Vm::(setDownStatus) vmId=`9f4dbd09-e734-496e-8ba7-64297082912e`::Changed state to Down: 'truesize'

here is the failure to delete (the storage domain is a different UUID) 

Thread-74494::ERROR::2013-02-06 14:44:08,816::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Cannot remove Logical Volume: (\'e7d6614c-a33b-4e9d-82b5-34bfd12d390b\', "(\'c481dc85-6289-4215-bb66-3bcf03b00460\',
 \'04512717-e9a9-4fdc-8c2c-a0adf845e09f\')")', 'code': 551}}


other vm's are giving a libvirt error about running vms with snapshot: 

https://bugzilla.redhat.com/show_bug.cgi?id=903248

since the big issue was not fixed (can't run the vm after live storage migration), and I think that we might hit several more issues with this scenario I suggest that we make this bug a tracker bug and start opening bugs for each underline issue.

Created attachment 693942 [details]
new logs from 3.2

Dafna, any update on this?

(In reply to comment #15)
> (In reply to comment #14)
> > Dafna, any update on this?
> 
Discussed with Haim, bug was VERIFIED with the libvirt scratch build.

we will verify this bug once official libvirt build with fix will be released.
moving back to ON_QA.

verified on sf10 with vdsm-4.10.2-11.0.el6ev.x86_64 and libvirt-0.10.2-18.el6_4.eblake.2.x86_64

3.2 has been released

3.2 has been released

3.2 has been released