Bug 885441 - Deleted VMs stuck on Image Locked forever
Deleted VMs stuck on Image Locked forever
Status: CLOSED CURRENTRELEASE
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine (Show other bugs)
3.1.0
Unspecified Unspecified
high Severity urgent
: ---
: 3.2.0
Assigned To: Yair Zaslavsky
Rami Vaknin
infra
:
Depends On:
Blocks: 915537
  Show dependency treegraph
 
Reported: 2012-12-09 09:26 EST by Rami Vaknin
Modified: 2016-02-10 14:14 EST (History)
10 users (show)

See Also:
Fixed In Version: sf2
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Infra
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
logs and threads dump (3.28 MB, application/x-tar)
2012-12-09 09:26 EST, Rami Vaknin
no flags Details

  None (edit)
Description Rami Vaknin 2012-12-09 09:26:26 EST
Created attachment 660277 [details]
logs and threads dump

Version:
si24.5

Scenario:
I've tried to delete 250 vms, I marked them in webadmin (each time one page of vms) and clicked on Remove, all 250 vms changed to Image Locked and remain in that status forever.
vdsm reports that all deleteImage jobs completed successfully

Additional Information:
It looks like all RemoveVm operartions got MAC_POOL_NOT_INITIALIZED exception during freeMac method and rollback started.

From GetAllTasksInfo
====================
3e9a5e01-0961-4fc6-9420-fa0609b1739b :
	verb = deleteImage
	id = 3e9a5e01-0961-4fc6-9420-fa0609b1739b

From GetAllTasksStatuses
========================
'a3ceac69-caea-4ede-8a8d-fe7a3501d61d': {'message': '1 jobs completed successfully', 'code': 0, 'taskID': 'a3ceac69-caea-4ede-8a8d-fe7a3501d61d', 'taskResult': 'success', 'taskState': 'finished'

From server.log
===============
2012-12-09 14:20:24,247 ERROR [org.jboss.as.ejb3.invocation] (pool-3-thread-1832) JBAS014134: EJB Invocation failed on component Backend for method public abstract org.ovirt.engine.core.common.action.VdcReturnValueBase org.ovirt.engine.core.bll.interfaces.BackendInternal.endAction(org.ovirt.engine.core.common.action.VdcActionType,org.ovirt.engine.core.common.action.VdcActionParametersBase,org.ovirt.engine.core.bll.context.CommandContext): org.ovirt.engine.core.common.errors.VdcBLLException: VdcBLLException: MAC_POOL_NOT_INITIALIZED
        at org.ovirt.engine.core.bll.MacPoolManager.freeMac(MacPoolManager.java:169) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.VmCommand.RemoveVmNetwork(VmCommand.java:217) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.RemoveVmCommand.RemoveVmFromDb(RemoveVmCommand.java:206) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.RemoveVmCommand.EndVmCommand(RemoveVmCommand.java:235) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.VmCommand.endSuccessfully(VmCommand.java:275) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.internalEndSuccessfully(CommandBase.java:512) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:459) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1374) [engine-bll.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:204) [engine-utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:142) [engine-utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:109) [engine-utils.jar:]
        at org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:405) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.Backend.endAction(Backend.java:368) [engine-bll.jar:]
        at sun.reflect.GeneratedMethodAccessor653.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-3]
        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:]
        at sun.reflect.GeneratedMethodAccessor494.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.ManagedReferenceLifecycleMethodInterceptorFactory$ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptorFactory.java:123) [jboss-as-ee.jar:7.1.3.Final-redhat-3]
        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:36) [jboss-as-ee.jar:7.1.3.Final-redhat-3]
        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.1.3.Final-redhat-3]
        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.1.3.Final-redhat-3]
        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:53) [jboss-as-ejb3.jar:7.1.3.Final-redhat-3]
        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:209) [jboss-as-ejb3.jar:7.1.3.Final-redhat-3]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:361) [jboss-as-ejb3.jar:7.1.3.Final-redhat-3]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:192) [jboss-as-ejb3.jar:7.1.3.Final-redhat-3]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2]
        at org.ovirt.engine.core.utils.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:11) [engine-utils.jar:]
        at sun.reflect.GeneratedMethodAccessor494.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.ManagedReferenceLifecycleMethodInterceptorFactory$ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptorFactory.java:123) [jboss-as-ee.jar:7.1.3.Final-redhat-3]
        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:36) [jboss-as-ee.jar:7.1.3.Final-redhat-3]
        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.1.3.Final-redhat-3]
        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.1.3.Final-redhat-3]
        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:53) [jboss-as-ejb3.jar:7.1.3.Final-redhat-3]
        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:209) [jboss-as-ejb3.jar:7.1.3.Final-redhat-3]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:361) [jboss-as-ejb3.jar:7.1.3.Final-redhat-3]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:192) [jboss-as-ejb3.jar:7.1.3.Final-redhat-3]
        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.1.3.Final-redhat-3]
        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:42) [jboss-as-ejb3.jar:7.1.3.Final-redhat-3]
        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.1.3.Final-redhat-3]
        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.1.3.Final-redhat-3]
        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.1.3.Final-redhat-3]
        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.1.3.Final-redhat-3]
        at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:181) [jboss-as-ee.jar:7.1.3.Final-redhat-3]
        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.1.3.Final-redhat-3]
        at org.ovirt.engine.core.bll.interfaces.BackendInternal$$$view9.endAction(Unknown Source) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.EntityAsyncTask.EndCommandAction(EntityAsyncTask.java:135) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.EntityAsyncTask.access$000(EntityAsyncTask.java:23) [engine-bll.jar:]
        at org.ovirt.engine.core.bll.EntityAsyncTask$1.run(EntityAsyncTask.java:104) [engine-bll.jar:]
        at org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil$InternalWrapperRunnable.run(ThreadPoolUtil.java:64) [engine-utils.jar:]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_09-icedtea]
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) [rt.jar:1.7.0_09-icedtea]
        at java.util.concurrent.FutureTask.run(FutureTask.java:166) [rt.jar:1.7.0_09-icedtea]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [rt.jar:1.7.0_09-icedtea]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) [rt.jar:1.7.0_09-icedtea]
        at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_09-icedtea]
Comment 1 Rami Vaknin 2012-12-09 09:55:02 EST
btw, restart to ovirt-engine solves the issue all removed vms (that were stuck on Image Locked) disappear from webadmin.
Comment 3 lpeer 2012-12-13 08:02:17 EST
The 'MAC_POOL_NOT_INITIALIZED' error is there because the MAC pool was not initialized, I'm not sure why, as the log starts from this error -  no previous data. (it could be because of wrong parameters in the vdc-options (wrong mac range or not enough/too many MACs in range - the log is cut so I can't tell the exact issue).

scenario -
1. The MAC range failed to get initialized 
2. deleting the VMs failed - because of a failure to release the MAC address
3. roll back process started
4. VMs stayed in image lock

Not sure why the VMs stayed in image lock but if the pool initialization was fine after a restart could it be that the MAC ranges were wrong and fixed in between reboots? - Rami? (or maybe fixed before hand but reboot caused the correct value to load)

The other option is that there is a race between the delete VM and the initialization of the MAc pool, this can only be the case if the VM deletion happened right after jboss service start (where the pool initialization takes place) - but the bug description does not indicate this is the case.

The issue that should be investigated (IMO) is why the VMs stayed in image lock status (which does not seem to be related to network)
Comment 4 Rami Vaknin 2012-12-13 10:01:37 EST
(In reply to comment #3)
> The 'MAC_POOL_NOT_INITIALIZED' error is there because the MAC pool was not
> initialized, I'm not sure why, as the log starts from this error -  no
> previous data. (it could be because of wrong parameters in the vdc-options
> (wrong mac range or not enough/too many MACs in range - the log is cut so I
> can't tell the exact issue).
> 
> scenario -
> 1. The MAC range failed to get initialized 
> 2. deleting the VMs failed - because of a failure to release the MAC address
> 3. roll back process started
> 4. VMs stayed in image lock
> 
> Not sure why the VMs stayed in image lock but if the pool initialization was
> fine after a restart could it be that the MAC ranges were wrong and fixed in
> between reboots? - Rami? (or maybe fixed before hand but reboot caused the
> correct value to load)

No, values were ok, no changes made without ovirt-engine restart.

BTW, I've already encountered with this issue before and I thought that "MaxMacsCountInPool" is the culprit.
> 
> The other option is that there is a race between the delete VM and the
> initialization of the MAc pool, this can only be the case if the VM deletion
> happened right after jboss service start (where the pool initialization
> takes place) - but the bug description does not indicate this is the case.

No, that's not the scenario.

> 
> The issue that should be investigated (IMO) is why the VMs stayed in image
> lock status (which does not seem to be related to network)

It looks like the Macs-list object "disappears" from memory rather than a configuration issue.

I would focus on the initialization exception cause and not on the VMs status.
Comment 10 Dafna Ron 2012-12-27 11:04:36 EST
I tested on 200 vms which is all the range of mac pools my setup has and had no exceptions (sf2)
this needs to be tested by Rami who has the resources for this test
moving to scale
Comment 11 Rami Vaknin 2012-12-30 06:53:04 EST
Validation on 200 vms' env is more than enough, this issue also occurred on much smaller setups.
Moving this bug to VERIFIED per comment #10.

Yair, could you please fill in the "Fixed in Version" field?
Comment 12 Itamar Heim 2013-06-11 05:26:29 EDT
3.2 has been released
Comment 13 Itamar Heim 2013-06-11 05:30:48 EDT
3.2 has been released
Comment 14 Itamar Heim 2013-06-11 05:46:24 EDT
3.2 has been released

Note You need to log in before you can comment on or make changes to this bug.