Bug 1613461
| Summary: | CreateSnapshotFromTemplateCommand (VM creation as thin) fails with internal engine error | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [oVirt] ovirt-engine | Reporter: | Evelina Shames <eshames> | ||||
| Component: | BLL.Storage | Assignee: | shani <sleviim> | ||||
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Evelina Shames <eshames> | ||||
| Severity: | medium | Docs Contact: | |||||
| Priority: | unspecified | ||||||
| Version: | 4.2.5 | CC: | aefrat, bugs, ebenahar, tnisan | ||||
| Target Milestone: | ovirt-4.3.4 | Keywords: | Automation | ||||
| Target Release: | 4.3.4.1 | Flags: | rule-engine:
ovirt-4.3+
|
||||
| Hardware: | Unspecified | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | ovirt-engine-4.3.4.1 | Doc Type: | If docs needed, set a value | ||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2019-06-11 06:24:10 UTC | Type: | Bug | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | Storage | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Embargoed: | |||||||
| Attachments: |
|
||||||
Additional info:
We noticed that the vm creation started before the status of the SD's was updated from active to unknown, and just before the update the engine sent a SpmStopVDSCommand:
Engine log:
2018-07-26 18:10:39,321+03 INFO [org.ovirt.engine.core.bll.AddVmCommand] (default task-7) [vms_create_c86e877e-e541-4791] Lock Acquired to object 'EngineLock:{exclusiveLocks='[vm_TestCase6024_2618103812=VM_NAME]', sharedLocks='[5f9a6271-a8db-4953-864d-0d2b88ea81ed=TEMPLATE, 2016cbab-234d-4bd4-a166-37d038db758a=DISK]'}'
2018-07-26 18:10:39,439+03 INFO [org.ovirt.engine.core.bll.AddVmCommand] (default task-7) [vms_create_c86e877e-e541-4791] Running command: AddVmCommand internal: false. Entities affected : ID:
2018-07-26 18:13:40,099+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (default task-7) [vms_create_c86e877e-e541-4791] START, SpmStopVDSCommand(HostName = host_mixed_2, SpmStopVDSCommandParameters:{hostId='95afd8d0-74a4-4f6f-8726-c0686161c792', storagePoolId='7a54dd4e-8fdb-11e8-b401-001a4a168bf8'}), log id: 399c34cc
2018-07-26 18:13:40,166+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (default task-7) [
] SpmStopVDSCommand::Stopping SPM on vds 'host_mixed_2', pool id '7a54dd4e-8fdb-11e8-b401-001a4a168bf8'
2018-07-26 18:13:40,177+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (default task-7) [vms_create_c86e877e-e541-4791] FINISH, SpmStopVDSCommand, log id: 399c34cc
2018-07-26 18:13:40,177+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxy] (default task-7) [vms_create_c86e877e-e541-4791] Irs placed on server '95afd8d0-74a4-4f6f-8726-c0686161c792' failed. Proceed Failover
2018-07-26 18:13:40,214+03 INFO [org.ovirt.engine.core.bll.storage.pool.SetStoragePoolStatusCommand] (default task-7) [448805e9] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: 7a54dd4e-8fdb-11e8-b401-001a4a168bf8 Type: StoragePool
.
.
.
2018-07-26 18:13:40,216+03 INFO [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] (default task-7) [448805e9] Storage Pool '7a54dd4e-8fdb-11e8-b401-001a4a168bf8' - Updating Storage Domain '01aff1bd-68ad-43ab-8f4a-d6b047446d2d' status from 'Active' to 'Unknown', reason: null
2018-07-26 18:13:40,217+03 INFO [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] (default task-7) [448805e9] Storage Pool '7a54dd4e-8fdb-11e8-b401-001a4a168bf8' - Updating Storage Domain '388b4264-29d7-44d8-9d33-e8ed34f14857' status from 'Active' to 'Unknown', reason: null
2018-07-26 18:13:40,217+03 INFO [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] (default task-7) [448805e9] Storage Pool '7a54dd4e-8fdb-11e8-b401-001a4a168bf8' - Updating Storage Domain 'e7f657db-a81a-4a84-98de-201d86c00e50' status from 'Active' to 'Unknown', reason: null
2018-07-26 18:13:40,218+03 INFO [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] (default task-7) [448805e9] Storage Pool '7a54dd4e-8fdb-11e8-b401-001a4a168bf8' - Updating Storage Domain 'f878d3c9-0a1a-4c70-9b88-d70cda36e7ba' status from 'Active' to 'Unknown', reason: null
2018-07-26 18:13:40,218+03 INFO [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] (default task-7) [448805e9] Storage Pool '7a54dd4e-8fdb-11e8-b401-001a4a168bf8' - Updating Storage Domain '361aa12e-ab3a-45c1-b487-ff6ee0101513' status from 'Active' to 'Unknown', reason: null
2018-07-26 18:13:40,219+03 INFO [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] (default task-7) [448805e9] Storage Pool '7a54dd4e-8fdb-11e8-b401-001a4a168bf8' - Updating Storage Domain '1e8755e6-cda1-465c-95f0-556da5d7c329' status from 'Active' to 'Unknown', reason: null
2018-07-26 18:13:40,219+03 INFO [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] (default task-7) [448805e9] Storage Pool '7a54dd4e-8fdb-11e8-b401-001a4a168bf8' - Updating Storage Domain '1a2bbb32-0525-4742-9423-4ab080da345a' status from 'Active' to 'Unknown', reason: null
2018-07-26 18:13:40,219+03 INFO [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] (default task-7) [448805e9] Storage Pool '7a54dd4e-8fdb-11e8-b401-001a4a168bf8' - Updating Storage Domain '8d896349-f15b-4535-a10f-c1226b02acef' status from 'Active' to 'Unknown', reason: null
2018-07-26 18:13:40,220+03 INFO [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] (default task-7) [448805e9] Storage Pool '7a54dd4e-8fdb-11e8-b401-001a4a168bf8' - Updating Storage Domain '6e3cd099-7abc-4bcf-912c-21e38ba685ba' status from 'Active' to 'Unknown', reason: null
2018-07-26 18:13:40,220+03 INFO [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] (default task-7) [448805e9] Storage Pool '7a54dd4e-8fdb-11e8-b401-001a4a168bf8' - Updating Storage Domain '2a6e47d3-d32b-46f8-9260-1cf89ed89a0f' status from 'Active' to 'Unknown', reason: null
2018-07-26 18:13:40,220+03 INFO [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] (default task-7) [448805e9] Storage Pool '7a54dd4e-8fdb-11e8-b401-001a4a168bf8' - Updating Storage Domain 'e43b9134-cd62-4bfb-8bec-c620b158aa34' status from
Reducing severity as it seems that the issue here is the wrong handling engine does in case of VM creation that falls between issues with the storage pool and domains status refresh. It seems like there was an ovirt-engine restart before the operation and the DC status was affected by this bug - https://bugzilla.redhat.com/show_bug.cgi?id=1609565 So are we fixing the test to allow the DC to change its status after a restart? (In reply to Tal Nisan from comment #4) > So are we fixing the test to allow the DC to change its status after a > restart? Elad, can you confirm the engine restart is actually part of the test? No, engine restart isn't part of the test. This bug has not been marked as blocker for oVirt 4.3.0. Since we are releasing it tomorrow, January 29th, this bug has been re-targeted to 4.3.1. Verified on engine 4.3.4.1-0.1.el7 This bugzilla is included in oVirt 4.3.4 release, published on June 11th 2019. Since the problem described in this bug report should be resolved in oVirt 4.3.4 release, it has been closed with a resolution of CURRENT RELEASE. If the solution does not work for you, please open a new bug report. |
Created attachment 1474030 [details] Logs Description of problem: CreateSnapshotFromTemplateCommand failed with the following exception while running automation tests (HE environment). Engine: 2018-07-26 18:16:40,545+03 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (default task-7) [448805e9] IrsBroker::Failed::CreateVolumeVDS: IRSGenericException: IRSErrorException: IRSNonOperationalException: Could not connect host to Data Center(Storage issue) 2018-07-26 18:16:40,626+03 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default task-7) [448805e9] Command 'CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='7a54dd4e-8fdb-11e8-b401-001a4a168bf8', ignoreFailoverLimit='false', storageDomainId='361aa12e-ab3a-45c1-b487-ff6ee0101513', imageGroupId='91b65b0a-b39c-46e4-b728-6120ae6cc5a6', imageSizeInBytes='10737418240', volumeFormat='COW', newImageId='7de6c574-afdf-4923-afeb-e12bb15dd2fa', imageType='Sparse', newImageDescription='', imageInitialSizeInBytes='0', imageId='3b023166-c186-45b8-ac23-4648c86437da', sourceImageGroupId='2016cbab-234d-4bd4-a166-37d038db758a'})' execution failed: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@13ae9629[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@73b8200b connection handles=0 lastReturned=1532618200577 lastValidated=1532617823091 lastCheckedOut=1532618200177 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@54b23178 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@1e0975f6[pool=ENGINEDataSource] xaResource=LocalXAResourceImpl@5e82f3a0[connectionListener=13ae9629 connectionManager=15d14db3 warned=false currentXid=null productName=PostgreSQL productVersion=9.5.9 jndiName=java:/ENGINEDataSource] txSync=null] 2018-07-26 18:16:40,626+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default task-7) [448805e9] FINISH, CreateVolumeVDSCommand, log id: 4238bb44 2018-07-26 18:16:40,626+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (default task-7) [448805e9] Failed creating snapshot from image id '3b023166-c186-45b8-ac23-4648c86437da' 2018-07-26 18:16:40,628+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (default task-7) [448805e9] Command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand' failed: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@13ae9629[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@73b8200b connection handles=1 lastReturned=1532618200577 lastValidated=1532617823091 lastCheckedOut=1532618200626 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@54b23178 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@1e0975f6[pool=ENGINEDataSource] xaResource=LocalXAResourceImpl@5e82f3a0[connectionListener=13ae9629 connectionManager=15d14db3 warned=false currentXid=null productName=PostgreSQL productVersion=9.5.9 jndiName=java:/ENGINEDataSource] txSync=null] 2018-07-26 18:16:40,628+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (default task-7) [448805e9] Exception: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@13ae9629[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@73b8200b connection handles=1 lastReturned=1532618200577 lastValidated=1532617823091 lastCheckedOut=1532618200626 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@54b23178 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@1e0975f6[pool=ENGINEDataSource] xaResource=LocalXAResourceImpl@5e82f3a0[connectionListener=13ae9629 connectionManager=15d14db3 warned=false currentXid=null productName=PostgreSQL productVersion=9.5.9 jndiName=java:/ENGINEDataSource] txSync=null] at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:80) [spring-jdbc.jar:4.3.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:619) [spring-jdbc.jar:4.3.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:684) [spring-jdbc.jar:4.3.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:716) [spring-jdbc.jar:4.3.9.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:766) [spring-jdbc.jar:4.3.9.RELEASE] at org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall.executeCallInternal(PostgresDbEngineDialect.java:152) [dal.jar:] at org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall.doExecute(PostgresDbEngineDialect.java:118) [dal.jar:] at org.springframework.jdbc.core.simple.SimpleJdbcCall.execute(SimpleJdbcCall.java:198) [spring-jdbc.jar:4.3.9.RELEASE] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeImpl(SimpleJdbcCallsHandler.java:135) [dal.jar:] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeReadList(SimpleJdbcCallsHandler.java:105) [dal.jar:] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeRead(SimpleJdbcCallsHandler.java:97) [dal.jar:] at org.ovirt.engine.core.dao.AsyncTaskDaoImpl.get(AsyncTaskDaoImpl.java:88) [dal.jar:] at org.ovirt.engine.core.bll.tasks.CoCoAsyncTaskHelper.getAsyncTaskFromDb(CoCoAsyncTaskHelper.java:188) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CommandCoordinatorImpl.getAsyncTaskFromDb(CommandCoordinatorImpl.java:214) [bll.jar:] at org.ovirt.engine.core.bll.tasks.AsyncTaskManager.logAndFailTaskOfCommandWithEmptyVdsmId(AsyncTaskManager.java:282) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CommandCoordinatorUtil.logAndFailTaskOfCommandWithEmptyVdsmId(CommandCoordinatorUtil.java:191) [bll.jar:] at org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand.performImageVdsmOperation(CreateSnapshotCommand.java:145) [bll.jar:] at org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand.executeCommand(CreateSnapshotCommand.java:73) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1133) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1285) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1934) [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.execute(CommandBase.java:1345) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:400) [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:468) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:450) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runInternalAction(Backend.java:656) [bll.jar:] at sun.reflect.GeneratedMethodAccessor300.invoke(Unknown Source) [:1.8.0_181] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181] 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.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45) [wildfly-ee-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] 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.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:264) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:379) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:244) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509) at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:64) [weld-core-impl.jar:2.4.7.Final-redhat-1] 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.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] 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.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] 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:609) 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.GeneratedMethodAccessor299.invoke(Unknown Source) [:1.8.0_181] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181] at org.jboss.weld.util.reflection.Reflections.invokeAndUnwrap(Reflections.java:433) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.bean.proxy.EnterpriseBeanProxyMethodHandler.invoke(EnterpriseBeanProxyMethodHandler.java:133) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.bean.proxy.EnterpriseTargetBeanInstance.invoke(EnterpriseTargetBeanInstance.java:56) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.bean.proxy.InjectionPointPropagatingEnterpriseTargetBeanInstance.invoke(InjectionPointPropagatingEnterpriseTargetBeanInstance.java:67) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:100) [weld-core-impl.jar:2.4.7.Final-redhat-1] 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:2324) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.runInternalActionWithTasksContext(CommandBase.java:2349) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.runInternalActionWithTasksContext(CommandBase.java:2344) [bll.jar:] at org.ovirt.engine.core.bll.AddVmCommand.addVmImages(AddVmCommand.java:1294) [bll.jar:] at org.ovirt.engine.core.bll.AddVmCommand.executeVmCommand(AddVmCommand.java:1012) [bll.jar:] at org.ovirt.engine.core.bll.VmCommand.executeCommand(VmCommand.java:161) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1133) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1285) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1934) [bll.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:164) [utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:103) [utils.jar:] at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1345) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:400) [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:468) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:450) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:403) [bll.jar:] at sun.reflect.GeneratedMethodAccessor306.invoke(Unknown Source) [:1.8.0_181] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181] 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.ejb.DelegatingInterceptorInvocationContext.proceed(DelegatingInterceptorInvocationContext.java:92) [wildfly-weld-ejb-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.weld.interceptor.proxy.WeldInvocationContextImpl.interceptorChainCompleted(WeldInvocationContextImpl.java:124) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.interceptor.proxy.WeldInvocationContextImpl.proceed(WeldInvocationContextImpl.java:143) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12) [common.jar:] at sun.reflect.GeneratedMethodAccessor64.invoke(Unknown Source) [:1.8.0_181] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181] at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.interceptor.proxy.WeldInvocationContextImpl.invokeNext(WeldInvocationContextImpl.java:109) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.interceptor.proxy.WeldInvocationContextImpl.proceed(WeldInvocationContextImpl.java:141) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.bean.InterceptorImpl.intercept(InterceptorImpl.java:113) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.as.weld.ejb.DelegatingInterceptorInvocationContext.proceed(DelegatingInterceptorInvocationContext.java:82) [wildfly-weld-ejb-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.as.weld.interceptors.EjbComponentInterceptorSupport.delegateInterception(EjbComponentInterceptorSupport.java:60) at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:76) 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.GeneratedMethodAccessor65.invoke(Unknown Source) [:1.8.0_181] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181] 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.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45) [wildfly-ee-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] 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.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:264) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:379) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:244) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509) at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73) [weld-core-impl.jar:2.4.7.Final-redhat-1] 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.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] 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.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2] 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:609) 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.common.interfaces.BackendLocal$$$view3.runAction(Unknown Source) [common.jar:] at org.ovirt.engine.api.restapi.resource.BackendResource.doAction(BackendResource.java:250) at org.ovirt.engine.api.restapi.resource.AbstractBackendCollectionResource.doCreateEntity(AbstractBackendCollectionResource.java:234) at org.ovirt.engine.api.restapi.resource.AbstractBackendCollectionResource.performCreate(AbstractBackendCollectionResource.java:145) at org.ovirt.engine.api.restapi.resource.AbstractBackendCollectionResource.performCreate(AbstractBackendCollectionResource.java:135) at org.ovirt.engine.api.restapi.resource.AbstractBackendCollectionResource.performCreate(AbstractBackendCollectionResource.java:154) at org.ovirt.engine.api.restapi.resource.BackendVmsResource.addVm(BackendVmsResource.java:576) at org.ovirt.engine.api.restapi.resource.BackendVmsResource.add(BackendVmsResource.java:240) at sun.reflect.GeneratedMethodAccessor1460.invoke(Unknown Source) [:1.8.0_181] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181] at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:140) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceLocatorInvoker.invokeOnTargetObject(ResourceLocatorInvoker.java:138) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.ResourceLocatorInvoker.invoke(ResourceLocatorInvoker.java:101) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:406) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:213) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:228) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) [resteasy-jaxrs.jar:3.0.25.Final-redhat-1] at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [jboss-servlet-api_3.1_spec.jar:1.0.0.Final-redhat-1] at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74) at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:81) at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62) at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:64) at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:274) at io.undertow.servlet.handlers.ServletInitialHandler.dispatchToPath(ServletInitialHandler.java:209) at io.undertow.servlet.spec.RequestDispatcherImpl.forwardImpl(RequestDispatcherImpl.java:221) at io.undertow.servlet.spec.RequestDispatcherImpl.forwardImplSetup(RequestDispatcherImpl.java:147) at io.undertow.servlet.spec.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:111) at org.ovirt.engine.api.restapi.invocation.VersionFilter.doFilter(VersionFilter.java:180) at org.ovirt.engine.api.restapi.invocation.VersionFilter.doFilter(VersionFilter.java:98) at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.api.restapi.invocation.CurrentFilter.doFilter(CurrentFilter.java:117) at org.ovirt.engine.api.restapi.invocation.CurrentFilter.doFilter(CurrentFilter.java:72) at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.aaa.filters.RestApiSessionMgmtFilter.doFilter(RestApiSessionMgmtFilter.java:78) [aaa.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.aaa.filters.EnforceAuthFilter.doFilter(EnforceAuthFilter.java:42) [aaa.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.aaa.filters.SsoRestApiNegotiationFilter.doFilter(SsoRestApiNegotiationFilter.java:84) [aaa.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.aaa.filters.SsoRestApiAuthFilter.doFilter(SsoRestApiAuthFilter.java:47) [aaa.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.aaa.filters.SessionValidationFilter.doFilter(SessionValidationFilter.java:59) [aaa.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.aaa.filters.RestApiSessionValidationFilter.doFilter(RestApiSessionValidationFilter.java:35) [aaa.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.api.restapi.security.CSRFProtectionFilter.doFilter(CSRFProtectionFilter.java:111) at org.ovirt.engine.api.restapi.security.CSRFProtectionFilter.doFilter(CSRFProtectionFilter.java:102) at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at org.ovirt.engine.core.utils.servlet.CORSSupportFilter.doFilter(CORSSupportFilter.java:284) [utils.jar:] at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84) at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62) at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:64) at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131) at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.security.handlers.AuthenticationConstraintHandler.handleRequest(AuthenticationConstraintHandler.java:53) at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46) at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64) at io.undertow.servlet.handlers.security.ServletSecurityConstraintHandler.handleRequest(ServletSecurityConstraintHandler.java:59) at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60) at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77) at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50) at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292) at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81) at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138) at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135) at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48) at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43) at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105) at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1501) at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1501) at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1501) at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272) at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81) at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104) at io.undertow.server.Connectors.executeRootHandler(Connectors.java:330) at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:812) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_181] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_181] at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_181] Caused by: java.sql.SQLException: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@13ae9629[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@73b8200b connection handles=1 lastReturned=1532618200577 lastValidated=1532617823091 lastCheckedOut=1532618200626 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@54b23178 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@1e0975f6[pool=ENGINEDataSource] xaResource=LocalXAResourceImpl@5e82f3a0[connectionListener=13ae9629 connectionManager=15d14db3 warned=false currentXid=null productName=PostgreSQL productVersion=9.5.9 jndiName=java:/ENGINEDataSource] txSync=null] at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:146) at org.jboss.as.connector.subsystems.datasources.WildFlyDataSource.getConnection(WildFlyDataSource.java:64) at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111) [spring-jdbc.jar:4.3.9.RELEASE] at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77) [spring-jdbc.jar:4.3.9.RELEASE] ... 291 more Caused by: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@13ae9629[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@73b8200b connection handles=1 lastReturned=1532618200577 lastValidated=1532617823091 lastCheckedOut=1532618200626 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@54b23178 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@1e0975f6[pool=ENGINEDataSource] xaResource=LocalXAResourceImpl@5e82f3a0[connectionListener=13ae9629 connectionManager=15d14db3 warned=false currentXid=null productName=PostgreSQL productVersion=9.5.9 jndiName=java:/ENGINEDataSource] txSync=null] at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:975) at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:792) at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:138) ... 294 more Caused by: javax.resource.ResourceException: IJ000461: Could not enlist in transaction on entering meta-aware object at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:561) at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:970) ... 296 more Caused by: java.lang.IllegalStateException: Transaction Local transaction (delegate=TransactionImple < ac, BasicAction: 0:ffff0a2e10f8:47b86f17:5b5880ad:5b240 status: ActionStatus.ABORTED >, owner=Local transaction context for provider JBoss JTA transaction provider) is not active STATUS_ROLLEDBACK at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:296) at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:554) ... 297 more 2018-07-26 18:16:40,669+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-11) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_3 command HSMGetAllTasksStatusesVDS failed: Not SPM 2018-07-26 18:16:40,669+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-11) [] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand' return value ' TaskStatusListReturn:{status='Status [code=654, message=Not SPM]'} ' 2018-07-26 18:16:40,669+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-11) [] HostName = host_mixed_3 2018-07-26 18:16:40,669+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-11) [] Command 'HSMGetAllTasksStatusesVDSCommand(HostName = host_mixed_3, VdsIdVDSCommandParametersBase:{hostId='6fbf48e6-dbf1-4b5c-b04d-37e4a29a93e7'})' execution failed: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM 2018-07-26 18:16:40,687+03 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (default task-7) [vms_create_c86e877e-e541-4791] Removed task 'adf3ceed-88dd-4989-96c0-aa1c45deff21' from DataBase 2018-07-26 18:16:40,689+03 ERROR [org.ovirt.engine.core.bll.AddVmCommand] (default task-7) [vms_create_c86e877e-e541-4791] Command 'org.ovirt.engine.core.bll.AddVmCommand' failed: EngineException: ENGINE (Failed with error ENGINE and code 5001) 2018-07-26 18:16:40,693+03 INFO [org.ovirt.engine.core.bll.CommandCompensator] (default task-7) [vms_create_c86e877e-e541-4791] Command [id=cb6c1f5e-1942-4c7d-8bc1-9274d6488bc4]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.Snapshot; snapshot: 8b56f37f-4fad-4de2-b348-31ff30ec328d. 2018-07-26 18:16:40,732+03 INFO [org.ovirt.engine.core.bll.CommandCompensator] (default task-7) [vms_create_c86e877e-e541-4791] Command [id=cb6c1f5e-1942-4c7d-8bc1-9274d6488bc4]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.VmStatistics; snapshot: 4a82b01d-a004-4c86-adcb-e16e8c96a373. 2018-07-26 18:16:40,736+03 INFO [org.ovirt.engine.core.bll.CommandCompensator] (default task-7) [vms_create_c86e877e-e541-4791] Command [id=cb6c1f5e-1942-4c7d-8bc1-9274d6488bc4]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.network.VmNetworkStatistics; snapshot: 4160462a-2735-4d46-938f-0c3dc97b5f0e. 2018-07-26 18:16:40,737+03 INFO [org.ovirt.engine.core.bll.CommandCompensator] (default task-7) [vms_create_c86e877e-e541-4791] Command [id=cb6c1f5e-1942-4c7d-8bc1-9274d6488bc4]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.network.VmNic; snapshot: 4160462a-2735-4d46-938f-0c3dc97b5f0e. 2018-07-26 18:16:40,743+03 INFO [org.ovirt.engine.core.bll.CommandCompensator] (default task-7) [vms_create_c86e877e-e541-4791] Command [id=cb6c1f5e-1942-4c7d-8bc1-9274d6488bc4]: Compensating TRANSIENT_ENTITY of org.ovirt.engine.core.common.businessentities.ReleaseMacsTransientCompensation; snapshot: org.ovirt.engine.core.common.businessentities.ReleaseMacsTransientCompensation@330847a7. 2018-07-26 18:16:40,748+03 INFO [org.ovirt.engine.core.bll.CommandCompensator] (default task-7) [vms_create_c86e877e-e541-4791] Command [id=cb6c1f5e-1942-4c7d-8bc1-9274d6488bc4]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.VmDynamic; snapshot: 4a82b01d-a004-4c86-adcb-e16e8c96a373. 2018-07-26 18:16:40,752+03 INFO [org.ovirt.engine.core.bll.CommandCompensator] (default task-7) [vms_create_c86e877e-e541-4791] Command [id=cb6c1f5e-1942-4c7d-8bc1-9274d6488bc4]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.VmStatic; snapshot: 4a82b01d-a004-4c86-adcb-e16e8c96a373. 2018-07-26 18:16:40,790+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-7) [vms_create_c86e877e-e541-4791] EVENT_ID: USER_FAILED_ADD_VM(57), Failed to create VM vm_TestCase6024_2618103812 (User: admin@internal-authz). 2018-07-26 18:16:40,791+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-11) [] START, ConnectStoragePoolVDSCommand(HostName = host_mixed_2, ConnectStoragePoolVDSCommandParameters:{hostId='95afd8d0-74a4-4f6f-8726-c0686161c792', vdsId='95afd8d0-74a4-4f6f-8726-c0686161c792', storagePoolId='7a54dd4e-8fdb-11e8-b401-001a4a168bf8', masterVersion='1'}), log id: 401cf4a4 2018-07-26 18:16:40,791+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-11) [] Executing with domain map: {01aff1bd-68ad-43ab-8f4a-d6b047446d2d=active, 8d896349-f15b-4535-a10f-c1226b02acef=active, 1a2bbb32-0525-4742-9423-4ab080da345a=active, 388b4264-29d7-44d8-9d33-e8ed34f14857=active, 6e3cd099-7abc-4bcf-912c-21e38ba685ba=active, e43b9134-cd62-4bfb-8bec-c620b158aa34=active, f878d3c9-0a1a-4c70-9b88-d70cda36e7ba=active, 2a6e47d3-d32b-46f8-9260-1cf89ed89a0f=active, 361aa12e-ab3a-45c1-b487-ff6ee0101513=active, e7f657db-a81a-4a84-98de-201d86c00e50=active, 1e8755e6-cda1-465c-95f0-556da5d7c329=active} 2018-07-26 18:16:40,797+03 INFO [org.ovirt.engine.core.bll.AddVmCommand] (default task-7) [vms_create_c86e877e-e541-4791] Lock freed to object 'EngineLock:{exclusiveLocks='[vm_TestCase6024_2618103812=VM_NAME]', sharedLocks='[5f9a6271-a8db-4953-864d-0d2b88ea81ed=TEMPLATE, 2016cbab-234d-4bd4-a166-37d038db758a=DISK]'}' 2018-07-26 18:16:40,797+03 INFO [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-2) [1426f4b1] Failed to acquire lock and wait lock 'HostEngineLock:{exclusiveLocks='[1e25a70b-b488-4976-8439-69d7db4d87df=VDS_INIT]', sharedLocks=''}' 2018-07-26 18:16:40,798+03 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-7) [] Operation Failed: [Internal Engine Error] Seems like the engine couldn't handle this (Internal Engine Error). Plus, I saw the following warnings few time in vdsm, not sure if it is relevant: 2018-07-26 18:16:39,623+0300 WARN (vdsm.Scheduler) [Executor] Worker blocked: <Worker name=jsonrpc/0 running <Task <JsonRpcTask {'params': {'preallocate': 2, 'volFormat': 4, 'srcImgUUID': '2016cbab-234d-4bd4-a166-37d038db758a', 'volumeID': '7de6c574-afdf-4923-afeb-e12bb15dd2fa', 'imageID': '91b65b0a-b39c-46e4-b728-6120ae6cc5a6', 'storagepoolID': '7a54dd4e-8fdb-11e8-b401-001a4a168bf8', 'storagedomainID': '361aa12e-ab3a-45c1-b487-ff6ee0101513', 'desc': u'', 'diskType': 'DATA', 'srcVolUUID': '3b023166-c186-45b8-ac23-4648c86437da', 'size': '10737418240'}, 'jsonrpc': '2.0', 'method': 'Volume.create', 'id': '91acc637-3eab-4047-8ba7-8b8d45fd9ae0'} at 0x7f78ac778a90> timeout=60, duration=360 at 0x7f78ac778ed0> task#=19687 at 0x7f78c4319e90>, traceback: File: "/usr/lib64/python2.7/threading.py", line 785, in __bootstrap self.__bootstrap_inner() File: "/usr/lib64/python2.7/threading.py", line 812, in __bootstrap_inner self.run() File: "/usr/lib64/python2.7/threading.py", line 765, in run self.__target(*self.__args, **self.__kwargs) File: "/usr/lib/python2.7/site-packages/vdsm/common/concurrent.py", line 194, in run ret = func(*args, **kwargs) File: "/usr/lib/python2.7/site-packages/vdsm/executor.py", line 301, in _run self._execute_task() File: "/usr/lib/python2.7/site-packages/vdsm/executor.py", line 315, in _execute_task task() File: "/usr/lib/python2.7/site-packages/vdsm/executor.py", line 391, in __call__ self._callable() File: "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 523, in __call__ self._handler(self._ctx, self._req) File: "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 566, in _serveRequest response = self._handle_request(req, ctx) File: "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 606, in _handle_request res = method(**params) File: "/usr/lib/python2.7/site-packages/vdsm/rpc/Bridge.py", line 201, in _dynamicMethod result = fn(*methodArgs) File: "/usr/lib/python2.7/site-packages/vdsm/API.py", line 795, in create initialSize=initialSize) File: "/usr/lib/python2.7/site-packages/vdsm/storage/dispatcher.py", line 73, 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 1179, in prepare result = self._run(func, *args, **kwargs) File: "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File: "<string>", line 2, in createVolume File: "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs) File: "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 1442, in createVolume dom = sdCache.produce(sdUUID=sdUUID) File: "/usr/lib/python2.7/site-packages/vdsm/storage/sdc.py", line 110, in produce domain.getRealDomain() File: "/usr/lib/python2.7/site-packages/vdsm/storage/sdc.py", line 51, in getRealDomain return self._cache._realProduce(self._sdUUID) File: "/usr/lib/python2.7/site-packages/vdsm/storage/sdc.py", line 125, in _realProduce self._syncroot.wait() File: "/usr/lib/python2.7/site-packages/pthreading.py", line 127, in wait return self.__cond.wait() File: "/usr/lib/python2.7/site-packages/pthread.py", line 131, in wait return _libpthread.pthread_cond_wait(self._cond, m.mutex()) (executor:363) 2018-07-26 18:16:40,288+0300 WARN (vdsm.Scheduler) [Executor] Worker blocked: <Worker name=jsonrpc/4 running <Task <JsonRpcTask {'params': {'masterVersion': 1, 'domainDict': {'2a6e47d3-d32b-46f8-9260-1cf89ed89a0f': 'active', 'f878d3c9-0a1a-4c70-9b88-d70cda36e7ba': 'active', '388b4264-29d7-44d8-9d33-e8ed34f14857': 'active', '6e3cd099-7abc-4bcf-912c-21e38ba685ba': 'active', '1e8755e6-cda1-465c-95f0-556da5d7c329': 'active', 'e43b9134-cd62-4bfb-8bec-c620b158aa34': 'active', '1a2bbb32-0525-4742-9423-4ab080da345a': 'active', '361aa12e-ab3a-45c1-b487-ff6ee0101513': 'active', '01aff1bd-68ad-43ab-8f4a-d6b047446d2d': 'active', 'e7f657db-a81a-4a84-98de-201d86c00e50': 'active', '8d896349-f15b-4535-a10f-c1226b02acef': 'active'}, 'storagepoolID': '7a54dd4e-8fdb-11e8-b401-001a4a168bf8', 'scsiKey': '7a54dd4e-8fdb-11e8-b401-001a4a168bf8', 'masterSdUUID': '01aff1bd-68ad-43ab-8f4a-d6b047446d2d', 'hostID': 3}, 'jsonrpc': '2.0', 'method': 'StoragePool.connect', 'id': '42fa26f0-140b-4d21-810f-d1ba4f63f767'} at 0x7f23e3568810> timeout=60, duration=180 at 0x7f23e32e4750> task#=17763 at 0x7f2418371210>, traceback: File: "/usr/lib64/python2.7/threading.py", line 785, in __bootstrap self.__bootstrap_inner() File: "/usr/lib64/python2.7/threading.py", line 812, in __bootstrap_inner self.run() File: "/usr/lib64/python2.7/threading.py", line 765, in run self.__target(*self.__args, **self.__kwargs) File: "/usr/lib/python2.7/site-packages/vdsm/common/concurrent.py", line 194, in run ret = func(*args, **kwargs) File: "/usr/lib/python2.7/site-packages/vdsm/executor.py", line 301, in _run self._execute_task() File: "/usr/lib/python2.7/site-packages/vdsm/executor.py", line 315, in _execute_task task() File: "/usr/lib/python2.7/site-packages/vdsm/executor.py", line 391, in __call__ self._callable() File: "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 523, in __call__ self._handler(self._ctx, self._req) File: "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 566, in _serveRequest response = self._handle_request(req, ctx) File: "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 606, in _handle_request res = method(**params) File: "/usr/lib/python2.7/site-packages/vdsm/rpc/Bridge.py", line 201, in _dynamicMethod result = fn(*methodArgs) File: "/usr/lib/python2.7/site-packages/vdsm/API.py", line 1068, in connect self._UUID, hostID, masterSdUUID, masterVersion, domainDict) File: "/usr/lib/python2.7/site-packages/vdsm/storage/dispatcher.py", line 73, 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 1179, in prepare result = self._run(func, *args, **kwargs) File: "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File: "<string>", line 2, in connectStoragePool File: "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs) File: "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 1035, in connectStoragePool spUUID, hostID, msdUUID, masterVersion, domainsMap) File: "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 1075, in _connectStoragePool masterVersion, domainsMap) File: "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 1055, in _updateStoragePool pool.refresh(msdUUID, masterVersion) File: "/usr/lib/python2.7/site-packages/vdsm/storage/sp.py", line 1353, in refresh self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion) File: "/usr/lib/python2.7/site-packages/vdsm/storage/sp.py", line 1299, in __rebuild blockDomUUIDs = [vg.name for vg in blockSD.lvm.getVGs(domUUIDs)] File: "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 935, in getVGs return _lvminfo.getVgs(vgNames) # returns list File: "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 591, in getVgs return [vg for vgName, vg in self._reloadvgs(vgNames).iteritems() File: "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 370, in _reloadvgs rc, out, err = self.cmd(cmd, self._getVGDevs(vgNames)) File: "/usr/lib/python2.7/site-packages/vdsm/storage/lvm.py", line 287, in cmd rc, out, err = misc.execCmd(finalCmd, sudo=True) File: "/usr/lib/python2.7/site-packages/vdsm/common/commands.py", line 80, in execCmd (out, err) = p.communicate(data) File: "/usr/lib64/python2.7/site-packages/subprocess32.py", line 924, in communicate stdout, stderr = self._communicate(input, endtime, timeout) File: "/usr/lib64/python2.7/site-packages/subprocess32.py", line 1706, in _communicate orig_timeout) File: "/usr/lib64/python2.7/site-packages/subprocess32.py", line 1779, in _communicate_with_poll ready = poller.poll(self._remaining_time(endtime)) (executor:363) Version-Release number of selected component (if applicable): engine: ovirt-engine-4.2.5.2-0.1.el7ev.noarch vdsm: vdsm-4.20.35-1.el7ev.x86_64 How reproducible: Once (automation test). Steps to Reproduce: 1. Create vm. Actual results: Should succeed. Expected results: Failed. Additional info: Relevant logs are attached.