Bug 1287771 - [cinder] image is locked infinitely after engine restart was performed, during a make template of a VM with cinder disks
Summary: [cinder] image is locked infinitely after engine restart was performed, durin...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: BLL.Storage
Version: 3.6.1
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ovirt-3.6.2
: 3.6.2.5
Assignee: Daniel Erez
QA Contact: Natalie Gavrielov
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-12-02 15:57 UTC by Natalie Gavrielov
Modified: 2016-02-18 11:03 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-02-18 11:03:52 UTC
oVirt Team: Storage
Embargoed:
rule-engine: ovirt-3.6.z+
rule-engine: blocker+
ylavi: planning_ack+
tnisan: devel_ack+
rule-engine: testing_ack+

Attachments (Terms of Use)
snapshot, engine.log, vdsm.log, cinder logs, ceph.log (3.57 MB, application/x-gzip)
2015-12-02 15:57 UTC, Natalie Gavrielov 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 49706 0 master ABANDONED core: restore parentParameters jackson serialization Never
oVirt gerrit 49956 0 master MERGED core: add template with Cinder disks - failure flow Never
oVirt gerrit 49995 0 master MERGED core: remove VM with Cinder disks - failure flow Never
oVirt gerrit 49996 0 master MERGED core: create snapshot with Cinder disks - failure flow Never
oVirt gerrit 49997 0 master MERGED core: remove snapshot with Cinder disks - failure flow Never
oVirt gerrit 50007 0 master MERGED core: preview snapshot with Cinder disks - failure flow 2015-12-16 11:13:38 UTC
oVirt gerrit 50008 0 master MERGED core: restore snapshot with Cinder disks - failure flow 2015-12-16 11:14:47 UTC
oVirt gerrit 50030 0 master ABANDONED core: restore snapshot with Cinder disks - failure flow Never
oVirt gerrit 50031 0 master MERGED core: remove obsolete parentHasTasks 2015-12-16 11:45:59 UTC
oVirt gerrit 50401 0 master MERGED core: remove template with Cinder disks - failure flow Never
oVirt gerrit 50635 0 ovirt-engine-3.6 MERGED core: add template with Cinder disks - failure flow 2015-12-18 07:53:10 UTC
oVirt gerrit 50636 0 ovirt-engine-3.6 MERGED core: remove template with Cinder disks - failure flow 2015-12-18 07:53:36 UTC
oVirt gerrit 50637 0 ovirt-engine-3.6 MERGED core: create snapshot with Cinder disks - failure flow 2015-12-18 07:53:59 UTC
oVirt gerrit 50638 0 ovirt-engine-3.6 MERGED core: remove snapshot with Cinder disks - failure flow 2015-12-18 07:54:29 UTC
oVirt gerrit 50639 0 ovirt-engine-3.6 MERGED core: restore snapshot with Cinder disks - failure flow 2015-12-18 07:56:23 UTC
oVirt gerrit 50640 0 ovirt-engine-3.6 MERGED core: preview snapshot with Cinder disks - failure flow 2015-12-18 07:56:36 UTC
oVirt gerrit 50641 0 ovirt-engine-3.6 MERGED core: remove obsolete parentHasTasks 2015-12-18 08:38:43 UTC
oVirt gerrit 50898 0 ovirt-engine-3.6 MERGED core: remove VM with Cinder disks - failure flow 2015-12-22 16:12:36 UTC
oVirt gerrit 50900 0 ovirt-engine-3.6.2 MERGED core: remove VM with Cinder disks - failure flow 2015-12-22 16:18:11 UTC
oVirt gerrit 51014 0 master MERGED core: fix creation of stateless snapshot 2015-12-23 18:00:06 UTC
oVirt gerrit 51030 0 ovirt-engine-3.6 MERGED core: fix creation of stateless snapshot 2015-12-24 09:17:09 UTC
oVirt gerrit 51042 0 ovirt-engine-3.6.2 MERGED core: fix creation of stateless snapshot 2015-12-24 10:40:35 UTC

Description Natalie Gavrielov 2015-12-02 15:57:55 UTC 
Created attachment 1101539 [details]
snapshot, engine.log, vdsm.log, cinder logs, ceph.log

Description of problem:

When performing an engine restart during template creation of a VM with cinder/ceph disks, operation locks the image infinitely (webadmin shows image is locked, and engine.log shows EJBTransactionRolledbackException)

Version-Release number of selected component (if applicable):
rhevm-3.6.1-0.2.el6.noarch


How reproducible:

Not always, because it depends on when performing the engine restart.

Steps to Reproduce:
1. Create a VM, with a few cinder-ceph disks, and install an OS.
2. Make a template out of the VM.
3. Meanwhile restart the engine.

Actual results:

* Webadmin shows image is locked (foerever). 
* Cinder / Ceph shows volumes were created:
volume-4d2906a1-b1f6-4ca3-bef6-a00399126a89
volume-64b93e0d-2390-4e3d-9ea6-37ff4667488a
volume-a65fd80f-2b4e-4312-9351-56b3497d078a
volume-b167c930-3f27-4701-8cde-600ff97e7886
volume-c5ed6936-ea56-49e6-af4f-268de57bf110
volume-e2a1e8cf-aab2-4f6e-a076-c689102594df
+--------------------------------------+-----------+--------------+------+-------------+----------+-------------+
|                  ID                  |   Status  | Display Name | Size | Volume Type | Bootable | Attached to |
+--------------------------------------+-----------+--------------+------+-------------+----------+-------------+
| 4d2906a1-b1f6-4ca3-bef6-a00399126a89 | available |  svr_Disk2   |  7   |     ceph    |  false   |             |
| 64b93e0d-2390-4e3d-9ea6-37ff4667488a | available |  svr_Disk3   |  5   |     ceph    |  false   |             |
| a65fd80f-2b4e-4312-9351-56b3497d078a | available |  svr_Disk1   |  12  |     ceph    |  false   |             |
| b167c930-3f27-4701-8cde-600ff97e7886 | available |  svr_Disk1   |  12  |     ceph    |  false   |             |
| c5ed6936-ea56-49e6-af4f-268de57bf110 | available |  svr_Disk3   |  5   |     ceph    |  false   |             |
| e2a1e8cf-aab2-4f6e-a076-c689102594df | available |  svr_Disk2   |  7   |     ceph    |  false   |             |
+--------------------------------------+-----------+--------------+------+-------------+----------+-------------+ 


* Rollback failed, engine.log:

2015-12-02 14:31:25,671 ERROR [org.ovirt.engine.core.bll.tasks.CommandExecutor] (DefaultQuartzScheduler_Worker-17) [] Error invoking callback method 'onFailed' for 'FAILED' command 'ac3f98af-e171-418a-9972-4a2bbb6f679f'

2015-12-02 14:31:24,230 ERROR [org.ovirt.engine.core.bll.tasks.CommandExecutor] (DefaultQuartzScheduler_Worker-13) [] Exception: javax.ejb.EJBTransactionRolledbackException
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleInCallerTx(CMTTxInterceptor.java:160) [jboss-as-ejb3.jar:7.5.5.Final-redhat-3]
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:259) [jboss-as-ejb3.jar:7.5.5.Final-redhat-3]
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:379) [jboss-as-ejb3.jar:7.5.5.Final-redhat-3]
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:246) [jboss-as-ejb3.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:43) [jboss-as-ejb3.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [jboss-as-ejb3.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:185) [jboss-as-ee.jar:7.5.5.Final-redhat-3]
	at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185) [jboss-as-ee.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:73) [jboss-as-ee.jar:7.5.5.Final-redhat-3]
	at org.ovirt.engine.core.bll.interfaces.BackendInternal$$$view3.endAction(Unknown Source) [bll.jar:]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.8.0_65]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [rt.jar:1.8.0_65]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_65]
	at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_65]
	at org.jboss.weld.util.reflection.SecureReflections$13.work(SecureReflections.java:267) [weld-core.jar:1.1.31.Final-redhat-1]
	at org.jboss.weld.util.reflection.SecureReflectionAccess.run(SecureReflectionAccess.java:52) [weld-core.jar:1.1.31.Final-redhat-1]
	at org.jboss.weld.util.reflection.SecureReflectionAccess.runAsInvocation(SecureReflectionAccess.java:137) [weld-core.jar:1.1.31.Final-redhat-1]
	at org.jboss.weld.util.reflection.SecureReflections.invoke(SecureReflections.java:263) [weld-core.jar:1.1.31.Final-redhat-1]
	at org.jboss.weld.bean.proxy.EnterpriseBeanProxyMethodHandler.invoke(EnterpriseBeanProxyMethodHandler.java:115) [weld-core.jar:1.1.31.Final-redhat-1]
	at org.jboss.weld.bean.proxy.EnterpriseTargetBeanInstance.invoke(EnterpriseTargetBeanInstance.java:56) [weld-core.jar:1.1.31.Final-redhat-1]
	at org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:105) [weld-core.jar:1.1.31.Final-redhat-1]
	at org.ovirt.engine.core.bll.BackendCommandObjectsHandler$BackendInternal$BackendLocal$142795634$Proxy$_$$_Weld$Proxy$.endAction(BackendCommandObjectsHandler$BackendInternal$BackendLocal$142795634$Proxy$_$$_Weld$Proxy$.java) [bll.jar:]
	at org.ovirt.engine.core.bll.storage.CloneCinderDisksCommand.endSuccessfully(CloneCinderDisksCommand.java:86) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.internalEndSuccessfully(CommandBase.java:647) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:591) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1981) [bll.jar:]
	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:210) [utils.jar:]
	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:149) [utils.jar:]
	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:118) [utils.jar:]
	at org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:520) [bll.jar:]
	at org.ovirt.engine.core.bll.storage.CloneCinderDisksCommandCallback.onSucceeded(CloneCinderDisksCommandCallback.java:49) [bll.jar:]
	at org.ovirt.engine.core.bll.tasks.CommandExecutor.invokeCallbackMethods(CommandExecutor.java:100) [bll.jar:]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.8.0_65]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [rt.jar:1.8.0_65]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_65]
	at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_65]
	at org.ovirt.engine.core.utils.timer.JobWrapper.invokeMethod(JobWrapper.java:81) [scheduler.jar:]
	at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:52) [scheduler.jar:]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557) [quartz.jar:]
Caused by: java.lang.NullPointerException
	at org.ovirt.engine.core.bll.Backend.endAction(Backend.java:500) [bll.jar:]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.8.0_65]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [rt.jar:1.8.0_65]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_65]
	at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_65]
	at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52) [jboss-as-ee.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63) [jboss-as-ee.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:74) [jboss-as-weld.jar:7.5.5.Final-redhat-3]
	at org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:84) [jboss-as-weld.jar:7.5.5.Final-redhat-3]
	at org.jboss.as.weld.ejb.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:97) [jboss-as-weld.jar:7.5.5.Final-redhat-3]
	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63) [jboss-as-ee.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.ovirt.engine.core.bll.interceptors.CorrelationIdTrackerInterceptor.aroundInvoke(CorrelationIdTrackerInterceptor.java:13) [bll.jar:]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.8.0_65]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [rt.jar:1.8.0_65]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_65]
	at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_65]
	at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptor.java:89) [jboss-as-ee.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63) [jboss-as-ee.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [jboss-as-ejb3.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:93) [jboss-as-weld.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:52) [jboss-as-ejb3.jar:7.5.5.Final-redhat-3]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.2.Final-redhat-1]
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:257) [jboss-as-ejb3.jar:7.5.5.Final-redhat-3]
	... 52 more

Expected results:

Either rollback or roll forward.
Comment 1 Allon Mureinik 2015-12-03 08:07:39 UTC 
negative scenario, with an easy workaround for the customer - reducing severity.
Comment 2 Red Hat Bugzilla Rules Engine 2015-12-03 08:07:40 UTC 
This bug is marked for z-stream, yet the milestone is for a major version, therefore the milestone has been reset.
Please set the correct milestone or drop the z stream flag.
Comment 3 Red Hat Bugzilla Rules Engine 2015-12-22 13:44:36 UTC 
Target release should be placed once a package build is known to fix a issue. Since this bug is not modified, the target version has been reset. Please use target milestone to plan a fix for a oVirt release.
Comment 4 Sandro Bonazzola 2015-12-23 15:07:56 UTC 
This bug has target milestone 3.6.2 and is on modified without a target release.
This may be perfectly correct, but please check if the patch fixing this bug is included in ovirt-engine-3.6.2. If it's included, please set target-release to 3.6.2 and move to ON_QA. Thanks.
Comment 5 Red Hat Bugzilla Rules Engine 2015-12-23 16:49:57 UTC 
Target release should be placed once a package build is known to fix a issue. Since this bug is not modified, the target version has been reset. Please use target milestone to plan a fix for a oVirt release.
Comment 6 Natalie Gavrielov 2016-02-07 16:49:06 UTC 
Verified, rhevm-3.6.3-0.1.el6.noarch
Ran the scenario (described in comment #0) 4 times:
In one of the runs a template wasn't created (probably restarted too early, so it rolled back).
and rest of the runs created templates.
Note You need to log in before you can comment on or make changes to this bug.