Created attachment 1580136 [details] Logs Description of problem: Failed to create VM from template. Looks like the engine lost connection to the host while the VM was created. 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. Version-Release number of selected component (if applicable): ovirt-engine-4.3.4.3-0.1.el7.noarch vdsm-4.30.17-1.el7ev.x86_64 How reproducible: Once (automation) Steps to Reproduce: 1. Deactivate HSM hosts (stay with SPM only) 2. Create VM from template Actual results: Failed to create VM from template Expected results: Operation should succeed Additional info: Logs are attached.
Evelina, does this issue reproduced again with local runs of the same TC? What was this host state other than that, maybe this is a system/networking issue?
*** This bug has been marked as a duplicate of bug 1680368 ***