This service will be undergoing maintenance at 00:00 UTC, 2017-10-23 It is expected to last about 30 minutes
Bug 1287771 - [cinder] image is locked infinitely after engine restart was performed, during a make template of a VM with cinder disks
[cinder] image is locked infinitely after engine restart was performed, durin...
Status: CLOSED CURRENTRELEASE
Product: ovirt-engine
Classification: oVirt
Component: BLL.Storage (Show other bugs)
3.6.1
Unspecified Unspecified
unspecified Severity high (vote)
: ovirt-3.6.2
: 3.6.2.5
Assigned To: Daniel Erez
Natalie Gavrielov
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2015-12-02 10:57 EST by Natalie Gavrielov
Modified: 2016-02-18 06:03 EST (History)
8 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-02-18 06:03:52 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Storage
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
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 10:57 EST, Natalie Gavrielov
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
oVirt gerrit 49706 master ABANDONED core: restore parentParameters jackson serialization Never
oVirt gerrit 49956 master MERGED core: add template with Cinder disks - failure flow Never
oVirt gerrit 49995 master MERGED core: remove VM with Cinder disks - failure flow Never
oVirt gerrit 49996 master MERGED core: create snapshot with Cinder disks - failure flow Never
oVirt gerrit 49997 master MERGED core: remove snapshot with Cinder disks - failure flow Never
oVirt gerrit 50007 master MERGED core: preview snapshot with Cinder disks - failure flow 2015-12-16 06:13 EST
oVirt gerrit 50008 master MERGED core: restore snapshot with Cinder disks - failure flow 2015-12-16 06:14 EST
oVirt gerrit 50030 master ABANDONED core: restore snapshot with Cinder disks - failure flow Never
oVirt gerrit 50031 master MERGED core: remove obsolete parentHasTasks 2015-12-16 06:45 EST
oVirt gerrit 50401 master MERGED core: remove template with Cinder disks - failure flow Never
oVirt gerrit 50635 ovirt-engine-3.6 MERGED core: add template with Cinder disks - failure flow 2015-12-18 02:53 EST
oVirt gerrit 50636 ovirt-engine-3.6 MERGED core: remove template with Cinder disks - failure flow 2015-12-18 02:53 EST
oVirt gerrit 50637 ovirt-engine-3.6 MERGED core: create snapshot with Cinder disks - failure flow 2015-12-18 02:53 EST
oVirt gerrit 50638 ovirt-engine-3.6 MERGED core: remove snapshot with Cinder disks - failure flow 2015-12-18 02:54 EST
oVirt gerrit 50639 ovirt-engine-3.6 MERGED core: restore snapshot with Cinder disks - failure flow 2015-12-18 02:56 EST
oVirt gerrit 50640 ovirt-engine-3.6 MERGED core: preview snapshot with Cinder disks - failure flow 2015-12-18 02:56 EST
oVirt gerrit 50641 ovirt-engine-3.6 MERGED core: remove obsolete parentHasTasks 2015-12-18 03:38 EST
oVirt gerrit 50898 ovirt-engine-3.6 MERGED core: remove VM with Cinder disks - failure flow 2015-12-22 11:12 EST
oVirt gerrit 50900 ovirt-engine-3.6.2 MERGED core: remove VM with Cinder disks - failure flow 2015-12-22 11:18 EST
oVirt gerrit 51014 master MERGED core: fix creation of stateless snapshot 2015-12-23 13:00 EST
oVirt gerrit 51030 ovirt-engine-3.6 MERGED core: fix creation of stateless snapshot 2015-12-24 04:17 EST
oVirt gerrit 51042 ovirt-engine-3.6.2 MERGED core: fix creation of stateless snapshot 2015-12-24 05:40 EST

  None (edit)
Description Natalie Gavrielov 2015-12-02 10:57:55 EST
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 03:07:39 EST
negative scenario, with an easy workaround for the customer - reducing severity.
Comment 2 Red Hat Bugzilla Rules Engine 2015-12-03 03:07:40 EST
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 08:44:36 EST
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 10:07:56 EST
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 11:49:57 EST
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 11:49:06 EST
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.