Bug 982654

Summary:

[engine-backend] disk remains in DB after vdsm finished to remove it

Product:

Red Hat Enterprise Virtualization Manager

Reporter:

Elad <ebenahar>

Component:

ovirt-engine

Assignee:

Liron Aravot <laravot>

Status:

CLOSED NOTABUG

QA Contact:

Severity:

high

Docs Contact:

Priority:

unspecified

Version:

3.3.0

CC:

acanan, acathrow, amureini, ebenahar, iheim, jkt, laravot, lpeer, Rhev-m-bugs, yeylon

Target Milestone:

---

Keywords:

Reopened, Triaged

Target Release:

3.3.0

Hardware:

x86_64

OS:

Unspecified

Whiteboard:

storage

Fixed In Version:

Doc Type:

Bug Fix

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2013-07-10 14:47:22 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	none

Description Elad 2013-07-09 13:48:25 UTC

Created attachment 771028 [details]
logs

Description of problem:
Engine is not updated about a deleted image, because vdsm finished the deleteImage task before ovirt-engine came up.



Version-Release number of selected component (if applicable):
rhevm-3.3.0-0.6.master.el6ev.noarch

How reproducible:
100%

Steps to Reproduce: 
1. have a vm with disks
2. remove the vm and restart ovirt-engine service right after engine send DeleteImageGroupVDSCommand


Actual results:
Engine comes up and is not updated about the removed image. the disk is still existing in DB and reported as 'illegal' in the UI.



2013-07-09 16:13:51,954 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (pool-5-thread-50) [5a2467fb] START, DeleteImageGroupVDSCommand( storagePoolId = 8510a3ba-2457-4df6-9140-8257f12
7bca5, ignoreFailoverLimit = false, compatabilityVersion = 3.3, storageDomainId = 283c1cc8-1d44-47f6-970d-5df9f4b4dedf, imageGroupId = 99a58eeb-ceec-473f-a900-e0e6a532b74b, postZeros = false, forceDelete = false),
 log id: 3efb6f89
2013-07-09 16:13:53,890 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (pool-5-thread-50) [5a2467fb] FINISH, DeleteImageGroupVDSCommand, log id: 3efb6f89
2013-07-09 16:13:53,897 ERROR [org.ovirt.engine.core.bll.RemoveImageCommand] (pool-5-thread-50) [5a2467fb] Command org.ovirt.engine.core.bll.RemoveImageCommand throw exception: java.lang.RuntimeException: Unable t
o suspend transaction
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.suspend(TransactionSupport.java:40) [utils.jar:]
        at org.ovirt.engine.core.bll.CommandBase.createTask(CommandBase.java:1335) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.createTask(CommandBase.java:1275) [bll.jar:]
        at org.ovirt.engine.core.bll.RemoveImageCommand.executeCommand(RemoveImageCommand.java:81) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1064) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1149) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1612) [bll.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:174) [utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:116) [utils.jar:]
        at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1167) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:315) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:348) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runInternalAction(Backend.java:550) [bll.jar:]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_25]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_25]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
        at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee.jar:7.2.0.Final-redhat-8]




Expected results:
Engine should poll the finished tasks from vdsm when it comes up

Additional info:
logs

Comment 1 Elad 2013-07-10 07:03:48 UTC

I think that the new async task improvement would solve this issue:
 
https://bugzilla.redhat.com/show_bug.cgi?id=968900

Comment 2 Liron Aravot 2013-07-10 12:49:30 UTC

Elad, this is not a bug - when the engine doesn't know the outcome of the operation - the disk intentionally changes to be in ILLEGAL status which means what we don't know if it exists on the storage or not- then the disk can be deleted again. the behaviour is as expected..therefore i'm closing this one.

Comment 3 Elad 2013-07-10 14:16:29 UTC

When trying to remove the 'illegal' disk, engine fails and throws:

2013-07-10 17:11:37,060 ERROR [org.ovirt.engine.core.bll.RemoveDiskCommand] (ajp-/127.0.0.1:8702-9) [22780274] Error during CanDoActionFailure.: java.lang.NullPointerException
        at org.ovirt.engine.core.bll.RemoveDiskCommand.getSharedLocks(RemoveDiskCommand.java:360) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.buildLock(CommandBase.java:1556) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.acquireLockInternal(CommandBase.java:1517) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.acquireLock(CommandBase.java:1490) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.internalCanDoAction(CommandBase.java:680) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.canDoActionOnly(CommandBase.java:294) [bll.jar:]
        at org.ovirt.engine.core.bll.MultipleActionsRunner.Execute(MultipleActionsRunner.java:75) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runMultipleActionsImpl(Backend.java:460) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runMultipleActionsImpl(Backend.java:475) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.RunMultipleActions(Backend.java:432) [bll.jar:]
        at sun.reflect.GeneratedMethodAccessor142.invoke(Unknown Source) [:1.7.0_25]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
        at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee.jar:7.2.0.Final-redh
at-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:58) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        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.bll.interceptors.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:13) [bll.jar:]
        at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source) [:1.7.0_25]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
        at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
        at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptorFactory$ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptorFactory.java:123) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:58) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:52) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:235) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:374) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:218) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-rat org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:235) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:374) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:218) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:182) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72) [jboss-as-ee.jar:7.2.0.Final-redhat-8]
        at org.ovirt.engine.core.common.interfaces.BackendLocal$$$view9.RunMultipleActions(Unknown Source) [common.jar:]
        at org.ovirt.engine.ui.frontend.server.gwt.GenericApiGWTServiceImpl.RunMultipleActions(GenericApiGWTServiceImpl.java:112)
        at sun.reflect.GeneratedMethodAccessor144.invoke(Unknown Source) [:1.7.0_25]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
        at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
        at com.google.gwt.rpc.server.RPC.invokeAndStreamResponse(RPC.java:196)
        at com.google.gwt.rpc.server.RpcServlet.processCall(RpcServlet.java:161)
        at com.google.gwt.rpc.server.RpcServlet.processPost(RpcServlet.java:222)
        at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:62)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:754) [jboss-servlet-api_3.0_spec.jar:1.0.2.Final-redhat-1]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec.jar:1.0.2.Final-redhat-1]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:295)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.ovirt.engine.ui.frontend.server.gwt.GwtCachingFilter.doFilter(GwtCachingFilter.java:132)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.ovirt.engine.core.utils.servlet.LocaleFilter.doFilter(LocaleFilter.java:59) [utils.jar:]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:149)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:481)
        at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:145)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97)
        at org.jboss.web.rewrite.RewriteValve.invoke(RewriteValve.java:465)
edhat-2]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:336)
        at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:488)
        at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:420)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:920)
        at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_25]

Comment 4 Liron Aravot 2013-07-10 14:30:46 UTC

Elad, the log you pasted here is not related to illegal disk, but general issue when removing a floating disk, there's a bug on that :
https://bugzilla.redhat.com/show_bug.cgi?id=982258

please close this one if that's the issue caused you to re-open it,