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:
Created attachment 1559608 [details] Logs
*** Bug 1720096 has been marked as a duplicate of this bug. ***
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.
Created attachment 1580265 [details] Logs
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/
Based on comment 13, the issue was reproduced on vdsm 4.30.17. Updating the version field.
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'
1819098 has same rollback issue, but trigger there was due to sanlock exception in creating lease for the new volume.
*** Bug 1812564 has been marked as a duplicate of this bug. ***
Closing low/medium severity bugs, based on QE capacity, if you would like to still verify this issue please reopen.
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?
OK. So I'm going to change the text for