Hi,
I am using PostgreSQL 9.2 Beta and the postgres JDBC driver code in CVS. In 9.2 the java.sql.Statement.setQueryTimeout(int) method is implemented for the first time. The value is in seconds.
Using the postgres JDBC driver that I built from source I find my JEE application is failing to execute PreparedStatements.
My application has named queries. These work fine because I have defined timeouts (120) in the deployment descriptor.
But the PreparedStatements causing the issue are generated by Hibernate to load entities with the timeout set to 0. That causes the driver to timeout the call immediately. This is one example of the error.
Code:
06:10:42,637 ERROR [org.jboss.as.ejb3.invocation] (EJB default - 13) JBAS014134: EJB Invocation failed on component OrderAuditSession for method public abstract void org.spec.jent.ejb.orders.session.OrderAuditService.validateInitialValues(int) throws org.spec.jent.common.AuditValidationException: javax.ejb.EJBException: java.lang.RuntimeException: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: ERROR: canceling statement due to user request
at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleExceptionInOurTx(CMTTxInterceptor.java:165) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:229) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:303) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:189) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:80) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:42) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:43) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.invokeMethod(MethodInvocationMessageHandler.java:299) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$100(MethodInvocationMessageHandler.java:67) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:199) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.6.0_22]
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) [rt.jar:1.6.0_22]
at java.util.concurrent.FutureTask.run(FutureTask.java:166) [rt.jar:1.6.0_22]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [rt.jar:1.6.0_22]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) [rt.jar:1.6.0_22]
at java.lang.Thread.run(Thread.java:679) [rt.jar:1.6.0_22]
at org.jboss.threads.JBossThread.run(JBossThread.java:122)
Caused by: java.lang.RuntimeException: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: ERROR: canceling statement due to user request
at org.spec.jent.common.util.Utils.count(Utils.java:273) [specj.jar:1.0]
at org.spec.jent.ejb.orders.session.OrderAuditSession.validateInitialValues(OrderAuditSession.java:72) [specj.jar:1.0]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.6.0_22]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.6.0_22]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.6.0_22]
at java.lang.reflect.Method.invoke(Method.java:616) [rt.jar:1.6.0_22]
at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:36) [jboss-as-ee-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47) [jboss-as-jpa-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-1.jar:1.1.1.Final-redhat-1]
at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:227) [jboss-as-ejb3-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
... 29 more
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: ERROR: canceling statement due to user request
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1372) [hibernate-entitymanager-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1295) [hibernate-entitymanager-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.ejb.QueryImpl.getSingleResult(QueryImpl.java:317) [hibernate-entitymanager-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.spec.jent.common.util.Utils.count(Utils.java:271) [specj.jar:1.0]
... 51 more
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: ERROR: canceling statement due to user request
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1372) [hibernate-entitymanager-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1295) [hibernate-entitymanager-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.ejb.QueryImpl.getSingleResult(QueryImpl.java:317) [hibernate-entitymanager-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.spec.jent.common.util.Utils.count(Utils.java:271) [specj.jar:1.0]
... 51 more
Caused by: org.hibernate.exception.GenericJDBCException: ERROR: canceling statement due to user request
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.engine.jdbc.internal.proxy.AbstractStatementProxyHandler.continueInvocation(AbstractStatementProxyHandler.java:129) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.engine.jdbc.internal.proxy.AbstractProxyHandler.invoke(AbstractProxyHandler.java:81) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at $Proxy97.executeQuery(Unknown Source) at org.hibernate.loader.Loader.getResultSet(Loader.java:1953) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.loader.Loader.doQuery(Loader.java:829) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:289) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.loader.Loader.doList(Loader.java:2438) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.loader.Loader.doList(Loader.java:2424) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2254) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.loader.Loader.list(Loader.java:2249) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:470) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:355) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:195) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1248) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
at org.hibernate.ejb.QueryImpl.getSingleResult(QueryImpl.java:284) [hibernate-entitymanager-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
... 52 more
Caused by: org.postgresql.util.PSQLException: ERROR: canceling statement due to user request
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2159)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1888)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:555)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:417)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:302)
at sun.reflect.GeneratedMethodAccessor39.invoke(Unknown Source) [:1.6.0_22]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.6.0_22]
at java.lang.reflect.Method.invoke(Method.java:616) [rt.jar:1.6.0_22]
at org.postgresql.ds.jdbc23.AbstractJdbc23PooledConnection$StatementHandler.invoke(AbstractJdbc23PooledConnection.java:455)
at $Proxy96.executeQuery(Unknown Source) at org.jboss.jca.adapters.jdbc.CachedPreparedStatement.executeQuery(CachedPreparedStatement.java:107)
at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:462)
at sun.reflect.GeneratedMethodAccessor39.invoke(Unknown Source) [:1.6.0_22]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.6.0_22]
at java.lang.reflect.Method.invoke(Method.java:616) [rt.jar:1.6.0_22]
at org.hibernate.engine.jdbc.internal.proxy.AbstractStatementProxyHandler.continueInvocation(AbstractStatementProxyHandler.java:122) [hibernate-core-4.1.3.Final-redhat-1.jar:4.1.3.Final-redhat-1]
... 67 more
Is there a property I can set in persistence.xml to change the default timeout from 0 to a higher value for PreparedStatements ?
Regards,
Jeremy