Created attachment 775296 [details] ## Logs rhevm, vdsm, thread dump Description of problem: Failed power-on VM’s in amount power-on VM’s scenario. Command RunVmOnceCommand throw exception: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000460: Error checking for a transaction Version-Release number of selected component (if applicable): RHEVM 3.3 - IS6 environment: RHEVM: rhevm-3.3.0-0.9.master.el6ev.noarch VDSM: vdsm-4.12.0-rc1.12.git8ee6885.el6.x86_64 LIBVIRT: libvirt-0.10.2-18.el6_4.9.x86_64 QEMU & KVM: qemu-kvm-rhev-0.12.1.2-2.355.el6_4.5.x86_64 SANLOCK: sanlock-2.6-2.el6.x86_64 How reproducible: 100% Steps to Reproduce: Power on 150 VM’s via PythonSDK. A script simulate 25 user connection, when each connection run Power-On vm. Actual results: Failed Power-On all VM’s Expected results: Succeed power on all VM’s Impact on user: Workaround: Power on VM’s via UI. Additional info: /var/log/ovirt-engine/engine.log 2013-07-18 14:00:01,322 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-5-thread-31) [478513f4] Running command: RunVmCommand internal: false. Entities affected : ID: e40474f2-5943-4fec-b55d-b802373fb487 Type: VM 2013-07-18 14:02:18,672 INFO [org.ovirt.engine.core.bll.RunVmCommand] (ajp-/127.0.0.1:8702-27) [789524e5] Failed to Acquire Lock to object EngineLock [exclusiveLocks= key: e40474f2-5943-4fec-b55d-b802373fb487 value: VM , sharedLocks= ] 2013-07-18 14:02:18,678 WARN [org.ovirt.engine.core.bll.RunVmCommand] (ajp-/127.0.0.1:8702-27) [789524e5] CanDoAction of action RunVm failed. Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,ACTION_TYPE_FAILED_OBJECT_LOCKED 2013-07-18 14:03:23,751 ERROR [org.ovirt.engine.core.bll.RunVmOnceCommand] (Transaction Reaper Worker 0) Transaction rolled-back for command: org.ovirt.engine.core.bll.RunVmOnceCommand. 2013-07-18 14:03:23,779 ERROR [org.ovirt.engine.core.bll.RunVmOnceCommand] (Transaction Reaper Worker 0) Transaction rolled-back for command: org.ovirt.engine.core.bll.RunVmOnceCommand. 2013-07-18 14:03:23,826 ERROR [org.ovirt.engine.core.bll.RunVmOnceCommand] (Transaction Reaper Worker 0) Transaction rolled-back for command: org.ovirt.engine.core.bll.RunVmOnceCommand. 2013-07-18 14:03:24,031 ERROR [org.ovirt.engine.core.bll.RunVmOnceCommand] (Transaction Reaper Worker 0) Transaction rolled-back for command: org.ovirt.engine.core.bll.RunVmOnceCommand. 2013-07-18 14:03:24,041 ERROR [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp-/127.0.0.1:8702-13) Command org.ovirt.engine.core.bll.RunVmOnceCommand throw exception: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: javax.resource.ResourceException: IJ000460: Error checking for a transaction at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:80) [spring-jdbc.jar:3.1.3.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:573) [spring-jdbc.jar:3.1.3.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:637) [spring-jdbc.jar:3.1.3.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:666) [spring-jdbc.jar:3.1.3.RELEASE] at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:706) [spring-jdbc.jar:3.1.3.RELEASE] at org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall.executeCallInternal(PostgresDbEngineDialect.java:154) [dal.jar:] at org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall.doExecute(PostgresDbEngineDialect.java:120) [dal.jar:] at org.springframework.jdbc.core.simple.SimpleJdbcCall.execute(SimpleJdbcCall.java:181) [spring-jdbc.jar:3.1.3.RELEASE] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeImpl(SimpleJdbcCallsHandler.java:147) [dal.jar:] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeReadAndReturnMap(SimpleJdbcCallsHandler.java:112) [dal.jar:] at org.ovirt.engine.core.dal.dbbroker.SimpleJdbcCallsHandler.executeReadList(SimpleJdbcCallsHandler.java:103) [dal.jar:] at org.ovirt.engine.core.dao.VdsDAODbFacadeImpl.getAllOfType(VdsDAODbFacadeImpl.java:88) [dal.jar:] at org.ovirt.engine.core.dao.VdsDAODbFacadeImpl.getAllOfTypes(VdsDAODbFacadeImpl.java:81) [dal.jar:] at org.ovirt.engine.core.bll.scheduling.SchedulingManager.schedule(SchedulingManager.java:150) [bll.jar:] at org.ovirt.engine.core.bll.RunVmCommand.getVdsToRunOn(RunVmCommand.java:643) [bll.jar:] at org.ovirt.engine.core.bll.RunVmCommand.runVm(RunVmCommand.java:230) [bll.jar:] at org.ovirt.engine.core.bll.RunVmCommand.executeVmCommand(RunVmCommand.java:306) [bll.jar:] at org.ovirt.engine.core.bll.VmCommand.executeCommand(VmCommand.java:85) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1127) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1212) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1853) [bll.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:210) [utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:149) [utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:118) [utils.jar:] at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1230) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:365) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runAction(Backend.java:404) [bll.jar:] at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:387) [bll.jar:] at org.ovirt.engine.core.bll.Backend.RunAction(Backend.java:345) [bll.jar:] at sun.reflect.GeneratedMethodAccessor193.invoke(Unknown Source) [:1.7.0_25] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25] at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee.jar:7.2.0.Final-redhat-8] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2] at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation.jar:1.1.1.Final-redhat-2] at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:58) [jboss-as-ee.jar:7.2.0.Final-redhat-8] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-2] at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation.jar:1.1.1.Final-redhat-2] at org.ovirt.engine.core.bll.interceptors.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:13) [bll.jar:] at sun.reflect.GeneratedMethodAccessor35.invoke(Unknown Source) [:1.7.0_25] /var/log/vdsm/vdsm.log
It should be solved now by the fix for bz 989916. Can you please check if it is still reproducible with the latest version? I also believe that it is not a regression, do we know of any version in which it worked?
Tested on RHEVM 3.3 - IS10 environment: RHEVM: rhevm-3.3.0-0.15.master.el6ev.noarch PythonSDK: rhevm-sdk-python-3.3.0.10-1.el6ev.noarch VDSM: vdsm-4.12.0-61.git8178ec2.el6ev.x86_64 LIBVIRT: libvirt-0.10.2-18.el6_4.9.x86_64 QEMU & KVM: qemu-kvm-rhev-0.12.1.2-2.355.el6_4.5.x86_64 SANLOCK: sanlock-2.8-1.el6.x86_64 And it works OK.