Bug 1680368

Summary: Failed to create VM from template in CreateVolumeContainerCommand when stopping VDSM service in a single host environment
Product: [oVirt] vdsm Reporter: Evelina Shames <eshames>
Component: CoreAssignee: shani <sleviim>
Status: CLOSED CURRENTRELEASE QA Contact: Evelina Shames <eshames>
Severity: low Docs Contact:
Priority: unspecified    
Version: 4.30.17CC: abawer, aefrat, bugs, eshames, fsun, lleistne, lsvaty, nsoffer, rdlugyhe, sgoodman, sleviim, tnisan
Target Milestone: ovirt-4.4.0Keywords: Automation
Target Release: 4.40.13Flags: pm-rhel: ovirt-4.4+
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: vdsm-4.40.13 Doc Type: Bug Fix
Doc Text:
Previously, the `slot` parameter was parsed as a string, causing disk rollback to fail during the creation of a virtual machine from a template when using an Ansible script. Note that there was no such failure when using the Administration Portal to create a virtual machine from a template. With this update, the `slot` parameter is parsed as an int, so disk rollback and virtual machine creation succeed.
 Story Points: ---
Clone Of:
: 1836609 (view as bug list) Environment:
Last Closed: 2020-04-16 10:30:01 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:
Bug Depends On:    
Bug Blocks: 1836609    
Attachments:
Description Flags
logs
none
Logs
none
Logs none

Description Evelina Shames 2019-02-24 11:18:40 UTC 
Created attachment 1538123 [details]
logs

Description of problem:
Failed to create VM from template on FC with the following errors:


Engine:
2019-02-05 15:14:28,420+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CreateVolumeContainerCommand] (EE-ManagedThreadFactory-engine-Thread-39026) [vms_create_97c47ef1-d6f2-40c8] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.CreateVolumeContainerCommand' with failure.
2019-02-05 15:14:36,994+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-84) [vms_create_97c47ef1-d6f2-40c8] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand' with failure.
2019-02-05 15:14:40,055+02 ERROR [org.ovirt.engine.core.bll.AddVmFromTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [vms_create_97c47ef1-d6f2-40c8] Ending command 'org.ovirt.engine.core.bll.AddVmFromTemplateCommand' with failure.
2019-02-05 15:14:40,058+02 ERROR [org.ovirt.engine.core.bll.CreateCloneOfTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [vms_create_97c47ef1-d6f2-40c8] Ending command 'org.ovirt.engine.core.bll.CreateCloneOfTemplateCommand' with failure.
2019-02-05 15:14:40,443+02 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [vms_create_97c47ef1-d6f2-40c8] ERROR, DestroyImageVDSCommand( DestroyImageVDSCommandParameters:{storagePoolId='00000000-0000-0000-0000-000000000000', ignoreFailoverLimit='false', storageDomainId='277c9c90-4b40-4920-b0d6-5e140f3ad0a5', imageGroupId='00000000-0000-0000-0000-000000000000', imageId='00000000-0000-0000-0000-000000000000', imageList='[a2c3b0dd-4241-4b28-8855-dc743a1931ac]', postZero='false', force='false'}), exception: null, log id: 4fb92a34
2019-02-05 15:14:40,444+02 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [vms_create_97c47ef1-d6f2-40c8] Exception
2019-02-05 15:14:40,451+02 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DestroyImageVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [vms_create_97c47ef1-d6f2-40c8] FINISH, DestroyImageVDSCommand, return: , log id: 4fb92a34
2019-02-05 15:14:40,452+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [vms_create_97c47ef1-d6f2-40c8] Failed to delete image 00000000-0000-0000-0000-000000000000/a2c3b0dd-4241-4b28-8855-dc743a1931ac: org.ovirt.engine.core.common.errors.EngineException: EngineException: java.lang.NullPointerException (Failed with error ENGINE and code 5001)
        at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:118) [bll.jar:]
        at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runVdsCommand(CommandBase.java:2065) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand.executeCommand(DestroyImageCommand.java:56) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1147) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1305) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1954) [bll.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:139) [utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105) [utils.jar:]
        at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1365) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:413) [bll.jar:]
        at org.ovirt.engine.core.bll.executor.DefaultBackendActionExecutor.execute(DefaultBackendActionExecutor.java:13) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:450) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:432) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runInternalAction(Backend.java:638) [bll.jar:]
        at sun.reflect.GeneratedMethodAccessor471.invoke(Unknown Source) [:1.8.0_191]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_191]
        at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_191]
        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
        at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:78)
        at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:88)
        at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:101)
        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [wildfly-ejb3-7.2.0.GA-redhat-00005.jar:7.
2.0.GA-redhat-00005]
.
.
.
2019-02-05 15:14:40,461+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-43) [vms_create_97c47ef1-d6f2-40c8] Command 'org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand' failed: EngineException: java.lang.NullPointerException (Failed with error ENGINE and code 5001)

2019-02-05 15:14:42,568+02 ERROR [org.ovirt.engine.core.bll.AddVmFromTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-45) [vms_create_97c47ef1-d6f2-40c8] Ending
 command 'org.ovirt.engine.core.bll.AddVmFromTemplateCommand' with failure.
2019-02-05 15:14:42,573+02 ERROR [org.ovirt.engine.core.bll.CreateCloneOfTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-45) [vms_create_97c47ef1-d6f2-40c8] Ending command 'org.ovirt.engine.core.bll.CreateCloneOfTemplateCommand' with failure.
2019-02-05 15:14:42,837+02 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-45) [vms_create_97c47ef1-d6f2-40c8] ERROR, DestroyImageVDSCommand( DestroyImageVDSCommandParameters:{storagePoolId='00000000-0000-0000-0000-000000000000', ignoreFailoverLimit='false', storageDomainId='277c9c90-4b40-4920-b0d6-5e140f3ad0a5', imageGroupId='00000000-0000-0000-0000-000000000000', imageId='00000000-0000-0000-0000-000000000000', imageList='[a2c3b0dd-4241-4b28-8855-dc743a1931ac]', postZero='false', force='false'}), exception: null, log id: 7ffddfc
2019-02-05 15:14:42,837+02 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-45) [vms_create_97c47ef1-d6f2-40c8] Exception
2019-02-05 15:14:42,844+02 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DestroyImageVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-45) [vms_create_97c47ef1-d6f2-40c8] FINISH, DestroyImageVDSCommand, return: , log id: 7ffddfc
2019-02-05 15:14:42,844+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-45) [vms_create_97c47ef1-d6f2-40c8] Failed to delete image 00000000-0000-0000-0000-000000000000/a2c3b0dd-4241-4b28-8855-dc743a1931ac: org.ovirt.engine.core.common.errors.EngineException: EngineException: java.lang.NullPointerException (Failed with error ENGINE and code 5001)
        at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:118) [bll.jar:]
        at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runVdsCommand(CommandBase.java:2065) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand.executeCommand(DestroyImageCommand.java:56) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1147) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1305) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1954) [bll.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:139) [utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105) [utils.jar:]
        at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1365) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:413) [bll.jar:]
        at org.ovirt.engine.core.bll.executor.DefaultBackendActionExecutor.execute(DefaultBackendActionExecutor.java:13) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:450) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:432) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runInternalAction(Backend.java:638) [bll.jar:]
        at sun.reflect.GeneratedMethodAccessor471.invoke(Unknown Source) [:1.8.0_191]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_191]
        at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_191]
        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
        at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:78)
        at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:88)
        at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:101)
        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [wildfly-ejb3-7.2.0.GA-redhat-00005.jar:7.2.0.GA-redhat-00005]
.
.
.
2019-02-05 15:15:16,695+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [] EVENT_ID: USER_ADD
_VM_FINISHED_FAILURE(60), Failed to complete VM vm_TestCase18982_0515085674 creation.
2019-02-05 15:15:16,726+02 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [vms_create_97c47ef1-d6f2-40c8] Fai
led invoking callback end method 'onFailed' for command 'e4650913-8066-4c4c-8767-d82d2be8d412' with exception 'CallableStatementCallback; uncategorized SQLException for SQL [{c
all deleteimage_storage_domain_map_by_image_id(?)}]; SQL state [null]; error code [0]; IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK; nested exception is java.sq
l.SQLException: IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK', the callback is marked for end method retries but max number of retries have been attempted. The 
command will be marked as Failed.
2019-02-05 15:15:16,726+02 INFO  [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [vms_create_97c47ef1-d6f2-40c8] Exc
eption in invoking callback of command AddVmFromTemplate (e4650913-8066-4c4c-8767-d82d2be8d412): SQLException: IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK
2019-02-05 15:15:16,730+02 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [vms_create_97c47ef1-d6f2-40c8] Err
or invoking callback method 'onFailed' for 'FAILED' command 'e4650913-8066-4c4c-8767-d82d2be8d412'
2019-02-05 15:15:16,730+02 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [vms_create_97c47ef1-d6f2-40c8] Exc
eption: javax.ejb.EJBTransactionRolledbackException: CallableStatementCallback; uncategorized SQLException for SQL [{call deleteimage_storage_domain_map_by_image_id(?)}]; SQL s
tate [null]; error code [0]; IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK; nested exception is java.sql.SQLException: IJ031070: Transaction cannot proceed: STAT
US_MARKED_ROLLBACK
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:203) [wildfly-ejb3-7.2.0.GA-redhat-00005.jar:7.2.0.GA-redhat-00005]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:420) [wildfly-ejb3-7.2.0.GA-redhat-00005.jar:7.2.0.GA-redhat-00005]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:148) [wildfly-ejb3-7.2.0.GA-redhat-00005.jar:7.2.0.GA-redhat-00005]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
        at org.jboss.weld.module.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:81) [weld-ejb.jar:3.0.5.Final-r
edhat-00001]
        at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:89)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [wildfly-ejb3-7.2.0.GA-re
dhat-00005.jar:7.2.0.GA-redhat-00005]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47) [wildfly-ejb3-7.2.0.GA-redhat-00005.jar:7.2.0.GA-red
hat-00005]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) [wildfly-ejb3-7.2.0.GA-redhat-00005.jar:7.2.0.GA-redhat-
00005]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22) [wildfly-ejb3-7.2.0.GA-redhat-00005.jar:7.2.0.GA-r
edhat-00005]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [wildfly-ejb3-7.2.0.GA-redhat-00005.jar:7
.2.0.GA-redhat-00005]
:\        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67) [wildfly-ejb3-7.2.0.GA-redhat-00005.jar:7.2.0.GA-redhat-000
05]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438)
        at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:619)
        at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
        at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198)
        at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185)
        at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81)
        at org.ovirt.engine.core.bll.interfaces.BackendInternal$$$view3.endAction(Unknown Source) [bll.jar:]
        at sun.reflect.GeneratedMethodAccessor1214.invoke(Unknown Source) [:1.8.0_191]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_191]
        at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_191]
        at org.jboss.weld.util.reflection.Reflections.invokeAndUnwrap(Reflections.java:410) [weld-core-impl.jar:3.0.5.Final-redhat-00001]
        at org.jboss.weld.module.ejb.EnterpriseBeanProxyMethodHandler.invoke(EnterpriseBeanProxyMethodHandler.java:134) [weld-ejb.jar:3.0.5.Final-redhat-00001]
        at org.jboss.weld.bean.proxy.EnterpriseTargetBeanInstance.invoke(EnterpriseTargetBeanInstance.java:56) [weld-core-impl.jar:3.0.5.Final-redhat-00001]
        at org.jboss.weld.module.ejb.InjectionPointPropagatingEnterpriseTargetBeanInstance.invoke(InjectionPointPropagatingEnterpriseTargetBeanInstance.java:68) [weld-ejb.jar:3.0.5.Final-redhat-00001]
at org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:106) [weld-core-impl.jar:3.0.5.Final-redhat-00001]
        at org.ovirt.engine.core.bll.BackendCommandObjectsHandler$BackendInternal$BackendLocal$2049259618$Proxy$_$$_Weld$EnterpriseProxy$.endAction(Unknown Source) [bll.jar:]
        at org.ovirt.engine.core.bll.VmCommand.endActionOnDisks(VmCommand.java:249) [bll.jar:]
        at org.ovirt.engine.core.bll.AddVmCommand.endWithFailure(AddVmCommand.java:1440) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.internalEndWithFailure(CommandBase.java:729) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:651) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1956) [bll.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202) [utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137) [utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105) [utils.jar:]
        at org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:513) [bll.jar:]
        at org.ovirt.engine.core.bll.ChildCommandsCallbackBase.endAction(ChildCommandsCallbackBase.java:134) [bll.jar:]
        at org.ovirt.engine.core.bll.ChildCommandsCallbackBase.onFailed(ChildCommandsCallbackBase.java:174) [bll.jar:]
        at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.endCallback(CommandCallbacksPoller.java:67) [bll.jar:]
        at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:166) [bll.jar:]
        at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:109) [bll.jar:]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_191]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [rt.jar:1.8.0_191]
        at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383) [javax.enterprise.concurrent.jar:1.0.0.redhat-1]
        at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534) [javax.enterprise.concurrent.jar:1.0.0.redhat-1]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_191]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_191]
        at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_191]
        at org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250) [javax.enterprise.concurrent.jar:1.0.0.redhat-1]
        at org.jboss.as.ee.concurrent.service.ElytronManagedThreadFactory$ElytronManagedThread.run(ElytronManagedThreadFactory.java:78)
Caused by: org.springframework.jdbc.UncategorizedSQLException: CallableStatementCallback; uncategorized SQLException for SQL [{call deleteimage_storage_domain_map_by_image_id(?)}]; SQL state [null]; error code [0]; IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK; nested exception is java.sql.SQLException: IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK
.
.
.

RELEVANT LOGS ARE ATTACHED.


Version-Release number of selected component (if applicable):
ovirt-engine-4.3.0.4-0.1.el7.noarch


How reproducible:
Once (automation TC18982)

Steps to Reproduce:
Create VM from Template and kill 'vdsmd' on SPM with only SPM and no HSM available.


Actual results:
Failed to complete vm creation.

Expected results:
Operation should succeed.

Additional info:
Comment 3 Evelina Shames 2019-04-28 08:51:48 UTC 
Created attachment 1559608 [details]
Logs
Comment 4 Evelina Shames 2019-06-13 12:39:10 UTC 
*** Bug 1720096 has been marked as a duplicate of this bug. ***
Comment 5 Evelina Shames 2019-06-13 12:41:36 UTC 
Happened again on  ovirt-engine-4.3.4.3-0.1.el7.noarch

VDSM errors:
2019-06-13 01:16:30,992+0300 ERROR (jsonrpc/4) [storage.TaskManager.Task] (Task='c2eddfbb-0980-4007-84dd-f9856dd0d52d') Unexpected error (task:875)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run
    return fn(*args, **kargs)
  File "<string>", line 2, in getAllTasksStatuses
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 50, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 2195, in getAllTasksStatuses
    allTasksStatus = self._pool.getAllTasksStatuses()
  File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line 77, in wrapper
    raise SecureError("Secured object is not in safe state")
SecureError: Secured object is not in safe state

2019-06-13 01:16:30,993+0300 ERROR (jsonrpc/4) [storage.Dispatcher] FINISH getAllTasksStatuses error=Secured object is not in safe state (dispatcher:87)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/dispatcher.py", line 74, in wrapper
    result = ctask.prepare(func, *args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 108, in wrapper
    return m(self, *a, **kw)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 1189, in prepare
    raise self.error
SecureError: Secured object is not in safe state

2019-06-13 01:16:32,397+0300 ERROR (tasks/0) [storage.TaskManager.Task] (Task='07a52d43-1568-452b-8219-63c77512dd91') Unexpected error (task:875)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run
    return fn(*args, **kargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 405, in run
    return function(self.task, *argslist)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/blockVolume.py", line 487, in createVolumeMetadataRollback
    sd.clear_metadata_block(slot)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 1015, in clear_metadata_block
    self.write_metadata_block(slot, data)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 1007, in write_metadata_block
    f.seek(self.metadata_offset(slot))
  File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 985, in metadata_offset
    return METADATA_BASE_V5 + slot * METADATA_SLOT_SIZE_V5
TypeError: unsupported operand type(s) for +: 'int' and 'str'

2019-06-13 01:16:32,397+0300 WARN  (tasks/0) [storage.TaskManager.Task] (Task='07a52d43-1568-452b-8219-63c77512dd91') task 07a52d43-1568-452b-8219-63c77512dd91: recovery failed: Task is aborted: u"unsupported operand type(s) for +: 'int' and 'str'" - code 100 (task:818)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 815, in _recover
    self._run(rec.run)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 896, in _run
    raise se.TaskAborted(message, code)
TaskAborted: Task is aborted: u"unsupported operand type(s) for +: 'int' and 'str'" - code 100

2019-06-13 01:16:49,950+0300 ERROR (jsonrpc/4) [storage.HSM] Empty or not found image 2131ad0f-247e-4587-a807-881f0975aba8 in SD 1a57359e-00e3-4a4d-91aa-b07411129095. {'35af7a19-624b-4d2c-82de-fa8ba9dbf353': ImgsPar(imgs=['7fea4c43-a8e4-4f54-909d-7bb8a47e8b25'], parent='00000000-0000-0000-0000-000000000000'), '02ed7239-778d-4f81-aa01-8e50d73f977c': ImgsPar(imgs=['4c8dc5ca-2150-4826-a391-faa16e2f6948'], parent='00000000-0000-0000-0000-000000000000'), '14f57504-dd6b-4a29-b225-3f135b9a279f': ImgsPar(imgs=['440e8bb0-c07c-4849-ac9d-90f043f08e41'], parent='00000000-0000-0000-0000-000000000000'), 'a4755c18-24ff-4c86-b617-8515032d1e15': ImgsPar(imgs=['fc87c630-ba31-440c-b9c5-b6064e82a122'], parent='00000000-0000-0000-0000-000000000000'), 'e2f2a031-3d4e-404a-a181-6e3e36e5f17a': ImgsPar(imgs=['6159e770-56b6-4e4a-b5e9-261f762de636'], parent='00000000-0000-0000-0000-000000000000'), '8242be59-32f7-4580-a034-f020fdc4842d': ImgsPar(imgs=['6d0a63ff-f7ed-45ce-a300-bc5ab16f2a86'], parent='00000000-0000-0000-0000-000000000000'), '0cfb6c62-34f9-4587-9f06-06a15d58a8db': ImgsPar(imgs=['bfce4f1d-0609-4475-b257-5cfc3c916670'], parent='00000000-0000-0000-0000-000000000000'), '182d2082-6c94-479e-b3ed-73bb4a4f5c47': ImgsPar(imgs=['72c3e0c5-a52c-485f-b4e2-6f8e7cd0c698'], parent='00000000-0000-0000-0000-000000000000'), 'c8a0ce16-315b-4af8-80b4-8a626f6a1721': ImgsPar(imgs=['5d7235e6-75f9-420b-8280-1da9e45c5c73'], parent='00000000-0000-0000-0000-000000000000'), '95edeef8-1800-48eb-9c7b-7aef179161d6': ImgsPar(imgs=['7e00d20e-a4d8-4ca7-8fdd-7ba39066d122'], parent='00000000-0000-0000-0000-000000000000'), '048988d6-45b4-4f3f-baea-89a1a4cacafd': ImgsPar(imgs=['f3994a13-9c1f-4b6f-b8ee-ab66513363d4'], parent='00000000-0000-0000-0000-000000000000'), 'd2e4c945-47bd-44bb-ab92-a027785cb1c7': ImgsPar(imgs=['0581791a-4113-45e5-ac64-924d8287ed76'], parent='00000000-0000-0000-0000-000000000000'), 'b91ee811-d1da-4ee1-87de-0942ed8b1fda': ImgsPar(imgs=['bf2db155-9fe8-4474-aee9-d25f2de863e0'], parent='00000000-0000-0000-0000-000000000000'), '15f1acfa-6383-46ae-b561-3f01492501b7': ImgsPar(imgs=['09dadc7d-1edb-4b36-b9a1-451dcd4f6e9b'], parent='00000000-0000-0000-0000-000000000000'), 'ee3e5394-92f8-4701-84b2-fb7c55dff703': ImgsPar(imgs=['df8a4ef8-6755-42f8-8ae6-121bae95a699'], parent='00000000-0000-0000-0000-000000000000'), '24c3877e-81d0-47ba-be65-16762bf77935': ImgsPar(imgs=['b7a9c870-bb32-464b-850e-ab6738920290'], parent='00000000-0000-0000-0000-000000000000')} (hsm:1501)
2019-06-13 01:16:49,951+0300 INFO  (jsonrpc/4) [vdsm.api] FINISH deleteImage error=Image does not exist in domain: u'image=2131ad0f-247e-4587-a807-881f0975aba8, domain=1a57359e-00e3-4a4d-91aa-b07411129095' from=::ffff:10.46.16.251,58206, flow_id=37c1fb15, task_id=7275a222-30c7-4604-a1e1-346de04f6465 (api:52)
2019-06-13 01:16:49,951+0300 ERROR (jsonrpc/4) [storage.TaskManager.Task] (Task='7275a222-30c7-4604-a1e1-346de04f6465') Unexpected error (task:875)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run
    return fn(*args, **kargs)
  File "<string>", line 2, in deleteImage
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 50, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 1502, in deleteImage
    raise se.ImageDoesNotExistInSD(imgUUID, sdUUID)
ImageDoesNotExistInSD: Image does not exist in domain: u'image=2131ad0f-247e-4587-a807-881f0975aba8, domain=1a57359e-00e3-4a4d-91aa-b07411129095'

2019-06-13 01:16:49,954+0300 ERROR (jsonrpc/4) [storage.Dispatcher] FINISH deleteImage error=Image does not exist in domain: u'image=2131ad0f-247e-4587-a807-881f0975aba8, domain=1a57359e-00e3-4a4d-91aa-b07411129095' (dispatcher:83)

Engine errors:
2019-06-13 01:16:16,073+03 ERROR [org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient] (SSL Stomp Reactor) [] Connection timeout for host 'lynx12.lab.eng.tlv2.redhat.com', last response arrived 12658 ms ago.
2019-06-13 01:16:16,080+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-44) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command SpmStatusVDS failed: Connection timeout for host 'lynx12.lab.eng.tlv2.redhat.com', last response arrived 12658 ms ago.
2019-06-13 01:16:16,081+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStatusVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-44) [] Command 'SpmStatusVDSCommand(HostName = host_mixed_1, SpmStatusVDSCommandParameters:{hostId='b88d30f8-21ea-4215-b67d-04d026ed5016', storagePoolId='f7d05048-70f3-4aab-9063-1d3eedf2378f'})' execution failed: VDSGenericException: VDSNetworkException: Connection timeout for host 'lynx12.lab.eng.tlv2.redhat.com', last response arrived 12658 ms ago.
2019-06-13 01:16:16,081+03 WARN  [org.ovirt.engine.core.vdsbroker.VdsManager] (EE-ManagedThreadFactory-engine-Thread-43507) [] Host 'host_mixed_1' is not responding.

2019-06-13 01:16:21,251+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-54) [] HostName = host_mixed_1
2019-06-13 01:16:21,251+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-54) [] Command 'HSMGetAllTasksStatusesVDSCommand(HostName = host_mixed_1, VdsIdVDSCommandParametersBase:{hostId='b88d30f8-21ea-4215-b67d-04d026ed5016'})' execution failed: Recovering from crash or Initializing
2019-06-13 01:16:21,368+03 ERROR [org.ovirt.engine.core.vdsbroker.monitoring.HostMonitoring] (EE-ManagedThreadFactory-engineScheduled-Thread-65) [] Unable to RefreshCapabilities: VDSRecoveringException: Recovering from crash or Initializing
2019-06-13 01:16:29,207+03 ERROR [org.ovirt.engine.core.bll.pm.FenceProxyLocator] (EE-ManagedThreadFactory-engineScheduled-Thread-51) [4fad8c3e] Can not run fence action on host 'host_mixed_1', no suitable proxy host was found.
2019-06-13 01:16:30,996+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-94) [] Command 'HSMGetAllTasksStatusesVDSCommand(HostName = host_mixed_1, VdsIdVDSCommandParametersBase:{hostId='b88d30f8-21ea-4215-b67d-04d026ed5016'})' execution failed: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM

'07a52d43-1568-452b-8219-63c77512dd91' (Parent Command 'CreateVolumeContainer', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure:
-- Result: 'cleanFailure'
-- Message: 'VDSGenericException: VDSTaskResultNotSuccessException: TaskState contained successful return code, but a non-success result ('cleanFailure').',
-- Exception: 'VDSGenericException: VDSTaskResultNotSuccessException: TaskState contained successful return code, but a non-success result ('cleanFailure').'
2019-06-13 01:16:32,967+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CreateVolumeContainerCommand] (EE-ManagedThreadFactory-engine-Thread-43515) [vms_create_5e19f3cf-f6f1-45cb] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.CreateVolumeContainerCommand' with failure.

2019-06-13 01:16:47,611+03 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [vms_create_5e19f3cf-f6f1-45cb] ERROR, DestroyImageVDSCommand( DestroyImageVDSCommandParameters:{storagePoolId='00000000-0000-0000-0000-000000000000', ignoreFailoverLimit='false', storageDomainId='1a57359e-00e3-4a4d-91aa-b07411129095', imageGroupId='00000000-0000-0000-0000-000000000000', imageId='00000000-0000-0000-0000-000000000000', imageList='[15f1acfa-6383-46ae-b561-3f01492501b7]', postZero='false', force='false'}), exception: null, log id: 6d5f27e6
2019-06-13 01:16:47,611+03 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [vms_create_5e19f3cf-f6f1-45cb] Exception
2019-06-13 01:16:47,620+03 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DestroyImageVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [vms_create_5e19f3cf-f6f1-45cb] FINISH, DestroyImageVDSCommand, return: , log id: 6d5f27e6
2019-06-13 01:16:47,621+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [vms_create_5e19f3cf-f6f1-45cb] Failed to delete image 00000000-0000-0000-0000-000000000000/15f1acfa-6383-46ae-b561-3f01492501b7: org.ovirt.engine.core.common.errors.EngineException: EngineException: java.lang.NullPointerException (Failed with error ENGINE and code 5001)
	at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:118) [bll.jar:]
	at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.runVdsCommand(CommandBase.java:2075) [bll.jar:]
	at org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand.executeCommand(DestroyImageCommand.java:56) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1157) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1315) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1964) [bll.jar:]
	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:139) [utils.jar:]
	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105) [utils.jar:]
	at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1375) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:419) [bll.jar:]
	at org.ovirt.engine.core.bll.executor.DefaultBackendActionExecutor.execute(DefaultBackendActionExecutor.java:13) [bll.jar:]
	at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:451) [bll.jar:]
	at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:433) [bll.jar:]
	at org.ovirt.engine.core.bll.Backend.runInternalAction(Backend.java:639) [bll.jar:]
	at sun.reflect.GeneratedMethodAccessor566.invoke(Unknown Source) [:1.8.0_212]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_212]
	at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_212]
	at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
	at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:78)
	at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:88)
	at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:101)
	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45) [wildfly-ee-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:40)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
	at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:185) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:420) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:148) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
	at org.jboss.weld.module.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:72) [weld-ejb.jar:3.0.6.Final-redhat-00001]
	at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:89)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438)
	at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:619)
	at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
	at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198)
	at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185)
	at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81)
	at org.ovirt.engine.core.bll.interfaces.BackendInternal$$$view2.runInternalAction(Unknown Source) [bll.jar:]
	at sun.reflect.GeneratedMethodAccessor565.invoke(Unknown Source) [:1.8.0_212]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_212]
	at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_212]
	at org.jboss.weld.util.reflection.Reflections.invokeAndUnwrap(Reflections.java:410) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.module.ejb.EnterpriseBeanProxyMethodHandler.invoke(EnterpriseBeanProxyMethodHandler.java:134) [weld-ejb.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.bean.proxy.EnterpriseTargetBeanInstance.invoke(EnterpriseTargetBeanInstance.java:56) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.module.ejb.InjectionPointPropagatingEnterpriseTargetBeanInstance.invoke(InjectionPointPropagatingEnterpriseTargetBeanInstance.java:68) [weld-ejb.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:106) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.ovirt.engine.core.bll.BackendCommandObjectsHandler$BackendInternal$BackendLocal$2049259618$Proxy$_$$_Weld$EnterpriseProxy$.runInternalAction(Unknown Source) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.runInternalAction(CommandBase.java:2348) [bll.jar:]
	at org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand.endWithFailure(CreateSnapshotCommand.java:196) [bll.jar:]
	at org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand.endWithFailure(CreateSnapshotFromTemplateCommand.java:94) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.internalEndWithFailure(CommandBase.java:735) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:657) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1966) [bll.jar:]
	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:139) [utils.jar:]
	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105) [utils.jar:]
	at org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:519) [bll.jar:]
	at org.ovirt.engine.core.bll.Backend.endAction(Backend.java:478) [bll.jar:]
	at sun.reflect.GeneratedMethodAccessor844.invoke(Unknown Source) [:1.8.0_212]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_212]
	at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_212]
	at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
	at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:78)
	at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:88)
	at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:101)
	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
	at org.ovirt.engine.core.bll.interceptors.CorrelationIdTrackerInterceptor.aroundInvoke(CorrelationIdTrackerInterceptor.java:13) [bll.jar:]
	at sun.reflect.GeneratedMethodAccessor71.invoke(Unknown Source) [:1.8.0_212]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_212]
	at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_212]
	at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptor.java:89)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45) [wildfly-ee-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:40)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
	at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:185) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:420) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:148) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
	at org.jboss.weld.module.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:81) [weld-ejb.jar:3.0.6.Final-redhat-00001]
	at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:89)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67) [wildfly-ejb3-7.2.2.GA-redhat-00001.jar:7.2.2.GA-redhat-00001]
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438)
	at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:619)
	at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
	at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198)
	at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185)
	at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81)
	at org.ovirt.engine.core.bll.interfaces.BackendInternal$$$view2.endAction(Unknown Source) [bll.jar:]
	at sun.reflect.GeneratedMethodAccessor843.invoke(Unknown Source) [:1.8.0_212]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_212]
	at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_212]
	at org.jboss.weld.util.reflection.Reflections.invokeAndUnwrap(Reflections.java:410) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.module.ejb.EnterpriseBeanProxyMethodHandler.invoke(EnterpriseBeanProxyMethodHandler.java:134) [weld-ejb.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.bean.proxy.EnterpriseTargetBeanInstance.invoke(EnterpriseTargetBeanInstance.java:56) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.module.ejb.InjectionPointPropagatingEnterpriseTargetBeanInstance.invoke(InjectionPointPropagatingEnterpriseTargetBeanInstance.java:68) [weld-ejb.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:106) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.ovirt.engine.core.bll.BackendCommandObjectsHandler$BackendInternal$BackendLocal$2049259618$Proxy$_$$_Weld$EnterpriseProxy$.endAction(Unknown Source) [bll.jar:]
	at org.ovirt.engine.core.bll.VmCommand.endActionOnDisks(VmCommand.java:262) [bll.jar:]
	at org.ovirt.engine.core.bll.AddVmCommand.endWithFailure(AddVmCommand.java:1440) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.internalEndWithFailure(CommandBase.java:735) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:657) [bll.jar:]
	at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1966) [bll.jar:]
	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202) [utils.jar:]
	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137) [utils.jar:]
	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105) [utils.jar:]
	at org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:519) [bll.jar:]
	at org.ovirt.engine.core.bll.ChildCommandsCallbackBase.endAction(ChildCommandsCallbackBase.java:134) [bll.jar:]
	at org.ovirt.engine.core.bll.ChildCommandsCallbackBase.onFailed(ChildCommandsCallbackBase.java:174) [bll.jar:]
	at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.endCallback(CommandCallbacksPoller.java:67) [bll.jar:]
	at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:166) [bll.jar:]
	at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:109) [bll.jar:]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_212]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [rt.jar:1.8.0_212]
	at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383) [javax.enterprise.concurrent.jar:1.0.0.redhat-1]
	at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534) [javax.enterprise.concurrent.jar:1.0.0.redhat-1]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_212]
	at org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250) [javax.enterprise.concurrent.jar:1.0.0.redhat-1]
Caused by: java.lang.NullPointerException
	at org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxy.getIrsProxy(IrsProxy.java:653) [vdsbroker.jar:]
	at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand.getIrsProxy(IrsBrokerCommand.java:89) [vdsbroker.jar:]
	at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand.lambda$executeVDSCommand$0(IrsBrokerCommand.java:97) [vdsbroker.jar:]
	at org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxy.runInControlledConcurrency(IrsProxy.java:272) [vdsbroker.jar:]
	at org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand.executeVDSCommand(IrsBrokerCommand.java:95) [vdsbroker.jar:]
	at org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:65) [vdsbroker.jar:]
	at org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:31) [dal.jar:]
	at org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14) [vdsbroker.jar:]
	at org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:398) [vdsbroker.jar:]
	at org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand$$super(Unknown Source) [vdsbroker.jar:]
	at sun.reflect.GeneratedMethodAccessor65.invoke(Unknown Source) [:1.8.0_212]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_212]
	at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_212]
	at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12) [common.jar:]
	at sun.reflect.GeneratedMethodAccessor61.invoke(Unknown Source) [:1.8.0_212]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_212]
	at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_212]
	at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68) [weld-core-impl.jar:3.0.6.Final-redhat-00001]
	at org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand(Unknown Source) [vdsbroker.jar:]
	... 181 more

2019-06-13 01:16:47,631+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [vms_create_5e19f3cf-f6f1-45cb] Command 'org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand' failed: EngineException: java.lang.NullPointerException (Failed with error ENGINE and code 5001)
2019-06-13 01:16:47,671+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [] Transaction rolled-back for command 'org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand'.
2019-06-13 01:16:47,671+03 INFO  [org.ovirt.engine.core.utils.transaction.TransactionSupport] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [] transaction rolled back
2019-06-13 01:16:47,671+03 INFO  [org.ovirt.engine.core.bll.AddVmFromTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [] Lock freed to object 'EngineLock:{exclusiveLocks='[vm_TestCase18982_1301153188=VM_NAME]', sharedLocks='[09dadc7d-1edb-4b36-b9a1-451dcd4f6e9b=DISK, 4f76a951-cd20-4be4-9884-b7568f5214bf=TEMPLATE]'}'
2019-06-13 01:16:47,697+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(60), Failed to complete VM vm_TestCase18982_1301153188 creation.
2019-06-13 01:16:47,697+03 ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-28) [] Failed invoking callback end method 'onFailed' for command '92e7df94-8585-4981-b124-6048a28b3088' with exception 'CallableStatementCallback; uncategorized SQLException for SQL [{call deleteimage_storage_domain_map_by_image_id(?)}]; SQL state [null]; error code [0]; IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK; nested exception is java.sql.SQLException: IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK', the callback is marked for end method retries
2019-06-13 01:16:49,722+03 ERROR [org.ovirt.engine.core.bll.AddVmFromTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-95) [vms_create_5e19f3cf-f6f1-45cb] Ending command 'org.ovirt.engine.core.bll.AddVmFromTemplateCommand' with failure.
2019-06-13 01:16:49,725+03 ERROR [org.ovirt.engine.core.bll.CreateCloneOfTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-95) [vms_create_5e19f3cf-f6f1-45cb] Ending command 'org.ovirt.engine.core.bll.CreateCloneOfTemplateCommand' with failure.
Comment 6 Evelina Shames 2019-06-13 12:42:31 UTC 
Created attachment 1580265 [details]
Logs
Comment 14 Nir Soffer 2020-04-02 16:41:14 UTC 
This looks like a duplicate of bug 1819098.

Amit, can you confirm and explain the root cause solved by
https://gerrit.ovirt.org/c/108143/
Comment 15 Nir Soffer 2020-04-02 16:43:35 UTC 
Based on comment 13, the issue was reproduced on vdsm 4.30.17. Updating
the version field.
Comment 16 Amit Bawer 2020-04-05 07:38:49 UTC 
Task is invoked for creating a volume:

2019-06-13 01:15:58,374+0300 INFO  (jsonrpc/0) [vdsm.api] START createVolume(sdUUID=u'1a57359e-00e3-4a4d-91aa-b07411129095', spUUID=u'f7d05048-70f3-4aab-9063-1d3eedf2378f', imgUUID=u'2131ad0f-247e-4587-a807-881f0975aba8', size=u'10737418240', volFormat=4, preallocate=2, diskType=u'DATA', volUUID=u'9f41305f-3abf-4cc5-a641-515a10d528bb', desc=None, srcImgUUID=u'00000000-0000-0000-0000-000000000000', srcVolUUID=u'00000000-0000-0000-0000-000000000000', initialSize=u'9761289310') from=::ffff:10.46.16.251,48666, flow_id=vms_create_5e19f3cf-f6f1-45cb, task_id=07a52d43-1568-452b-8219-63c77512dd91 (api:48)

And writes metadata slot number 5 for the new volume:

2019-06-13 01:15:59,464+0300 DEBUG (tasks/0) [storage.StorageDomainManifest] Found free slot 5 in VG 1a57359e-00e3-4a4d-91aa-b07411129095 (blockSD:875)
2019-06-13 01:15:59,464+0300 INFO  (tasks/0) [storage.LVM] Change LV tags (vg=1a57359e-00e3-4a4d-91aa-b07411129095, lv=9f41305f-3abf-4cc5-a641-515a10d528bb, delTags=['OVIRT_VOL_INITIALIZING'], addTags=['MD_5', u'PU_00000000-0000-0000-0000-000000000000', u'IU_2131ad0f-247e-4587-a807-881f0975aba8']) (lvm:1467)
2019-06-13 01:15:59,464+0300 DEBUG (tasks/0) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/sudo -n /sbin/lvm lvchange --config 'devices {  preferred_names=["^/dev/mapper/"]  ignore_suspended_devices=1  write_cache_state=0  disable_after_error_count=3  filter=["a|^/dev/mapper/3600a09803830447a4f244c4657595050$|^/dev/mapper/3600a09803830447a4f244c4657595051$|^/dev/mapper/3600a09803830447a4f244c4657595052$|^/dev/mapper/3600a09803830447a4f244c4657595053$|^/dev/mapper/3600a09803830447a4f244c4657595054$|^/dev/mapper/3600a09803830447a4f244c4657595055$|^/dev/mapper/3600a09803830447a4f244c4657595056$|", "r|.*|"] } global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 } backup {  retain_min=50  retain_days=0 }' --autobackup n --deltag OVIRT_VOL_INITIALIZING --addtag PU_00000000-0000-0000-0000-000000000000 --addtag MD_5 --addtag IU_2131ad0f-247e-4587-a807-881f0975aba8 1a57359e-00e3-4a4d-91aa-b07411129095/9f41305f-3abf-4cc5-a641-515a10d528bb (cwd None) (commands:198)
2019-06-13 01:15:59,680+0300 DEBUG (mpathlistener) [storage.udev] Received udev event (action=change, device=Device(u'/sys/devices/virtual/block/dm-13')) (udev:218)


Vdsm is restarted:

2019-06-13 01:16:03,413+0300 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.08 seconds (__init__:312)
2019-06-13 01:16:20,533+0300 INFO  (MainThread) [vds] (PID: 90151) I am the actual vdsm 4.30.17.1.git0de043f lynx12.lab.eng.tlv2.redhat.com (3.10.0-957.21.2.el7.x86_64) (vdsmd:150)


Unifinished task is reloaded for recovery:

2019-06-13 01:16:32,223+0300 DEBUG (tasks/0) [storage.TaskManager] Loading dumped task 07a52d43-1568-452b-8219-63c77512dd91 (taskManager:212)
2019-06-13 01:16:32,224+0300 DEBUG (tasks/0) [storage.TaskManager.Task] (Task='07a52d43-1568-452b-8219-63c77512dd91') 07a52d43-1568-452b-8219-63c77512dd91: load from /rhev/data-center/f7d05048-70f3-4aab-9063-1d3eedf2378f/mastersd/master/tasks, ext '' (task:729)


Task rollback for clearing the already written metadata block for the interrupted create volume attempt fails for mismatching types on offset calc as slot number is passed as a string:

2019-06-13 01:16:32,396+0300 DEBUG (tasks/0) [storage.TaskManager.Task] (Task='07a52d43-1568-452b-8219-63c77512dd91') running recovery Create volume metadata rollback: BlockVolume->createVolumeMetadataRollback(1a57359e-00e3-4a4d-91aa-b07411129095,5) (task:812)
2019-06-13 01:16:32,396+0300 INFO  (tasks/0) [storage.Volume] Metadata rollback for sdUUID=1a57359e-00e3-4a4d-91aa-b07411129095 slot=5 (blockVolume:485)
2019-06-13 01:16:32,397+0300 ERROR (tasks/0) [storage.TaskManager.Task] (Task='07a52d43-1568-452b-8219-63c77512dd91') Unexpected error (task:875)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run
    return fn(*args, **kargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 405, in run
    return function(self.task, *argslist)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/blockVolume.py", line 487, in createVolumeMetadataRollback
    sd.clear_metadata_block(slot)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 1015, in clear_metadata_block
    self.write_metadata_block(slot, data)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 1007, in write_metadata_block
    f.seek(self.metadata_offset(slot))
  File "/usr/lib/python2.7/site-packages/vdsm/storage/blockSD.py", line 985, in metadata_offset
    return METADATA_BASE_V5 + slot * METADATA_SLOT_SIZE_V5
TypeError: unsupported operand type(s) for +: 'int' and 'str'
Comment 17 Amit Bawer 2020-04-05 07:48:36 UTC 
1819098 has same rollback issue, but trigger there was due to sanlock exception in creating lease for the new volume.
Comment 18 shani 2020-04-12 10:50:45 UTC 
*** Bug 1812564 has been marked as a duplicate of this bug. ***
Comment 19 Lukas Svaty 2020-04-16 10:30:01 UTC 
Closing low/medium severity bugs, based on QE capacity, if you would like to still verify this issue please reopen.
Comment 22 Steve Goodman 2020-07-28 09:29:48 UTC 
Hi Shani,

I agree it's best to keep them synced, but I still want to make sure that we give the right info.

From the user's point of view, it seems that the real bug here is that you can't create a VM from a template when using an Ansible script. Do I understand that correctly?
Comment 24 Steve Goodman 2020-07-28 10:54:29 UTC 
OK. So I'm going to change the text for