4 Replies Latest reply on Oct 8, 2015 12:05 AM by markathomas

    Problem with connection from XA connection pool when transaction timeouts

    skorepam

      Hello,

       

      I 've found following problem in our application running on AS 7.1.1.

       

      A Message driven bean is processing message, doing some database (Oracle) inserts, updates, sending messages to another JMS queues (HornetQ).

      All these stuff must be done in one transaction - do everything or nothing - for this purposes XA Datasources for both DB and JMS resources are defined.

      Everything works fine and the problem occurs only in case that transaction timeout defined on the Message Driven Bean is exceeded.

      It doesn't matter if the timeout is default (five minutes) or overriden by @ActivationConfigProperty(propertyName = "transactionTimeout") property.

       

      At the time when transaction timeouts the TransactionReaper correctly marks the transaction as rolled back, the transaction continues its processing (which is fine by definition)

      - there are some cleaning tasks done within the interrupted transaction (not using the XA resources of course - they are correctly marked for rollback) and in the meantime the connection is returned to the pool.

      Everything works as expected to this time. Another thread tries to use the connection returned to the pool  getting following WARNING followed by set of ERRORS.

       

       

      13:26:32,436 WARN  [com.arjuna.ats.jta] (Thread-451 (HornetQ-client-global-threads-301058000)) ARJUNA016061: TransactionImple.enlistResource - XAResource.start returned: XAException.XAER_PROTO for
      < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a21212c:fafd5c7:5200afe1:41a509, node_name=1, branch_uid=0:ffff0a21212c:fafd5c7:5200afe1:41a55d, subordinatenodename=null, eis_nam
      e=java:jboss/datasources/MNPDS >: oracle.jdbc.xa.OracleXAException
              at oracle.jdbc.xa.OracleXAResource.checkError(OracleXAResource.java:1110)
              at oracle.jdbc.xa.client.OracleXAResource.start(OracleXAResource.java:240)
              at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.start(XAManagedConnection.java:259)
              at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.start(XAResourceWrapperImpl.java:188)
              at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:636)
              at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:397)
              at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener$TransactionSynchronization.enlist(TxConnectionListener.java:587)
              at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:264)
              at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:467)
              at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:599)
              at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:467)
              at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:129)
              at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:67) [hibernate-entitymanager-4.0.1.Final.jar:4.0.1.Final]
              at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:276) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
              at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:297) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
              at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:169) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
              at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.extractPhysicalConnection(ConnectionProxyHandler.java:82) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
              at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.continueInvocation(ConnectionProxyHandler.java:138) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
              at org.hibernate.engine.jdbc.internal.proxy.AbstractProxyHandler.invoke(AbstractProxyHandler.java:81) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
              at com.sun.proxy.$Proxy94.prepareStatement(Unknown Source)
      
      13:26:32,680 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000)) oracle.jdbc.xa.OracleXAException
      13:26:32,742 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at oracle.jdbc.xa.OracleXAResource.checkError(OracleXAResource.java:1110)
      13:26:32,833 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at oracle.jdbc.xa.client.OracleXAResource.start(OracleXAResource.java:240)
      13:26:33,083 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.start(XAManagedConnection.java:259)
      13:26:33,134 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.start(XAResourceWrapperImpl.java:188)
      13:26:33,352 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:6
      36)
      13:26:33,383 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:3
      97)
      13:26:33,417 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener$TransactionSynchronization.enlist(TxCon
      nectionListener.java:587)
      13:26:33,753 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:264)
      13:26:33,771 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionM
      anagerImpl.java:467)
      13:26:33,990 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:599)
      13:26:34,021 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:467)
      13:26:34,047 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:129)
      13:26:34,065 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:67)
      13:26:34,242 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:276)
      13:26:34,255 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:297)
      13:26:34,440 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:169)
      13:26:34,449 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.extractPhysicalConnection(ConnectionProxyHandler.java:82)
      13:26:34,823 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.continueInvocation(ConnectionProxyHandler.java:138)
      13:26:34,832 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at org.hibernate.engine.jdbc.internal.proxy.AbstractProxyHandler.invoke(AbstractProxyHandler.java:81)
      13:26:34,995 ERROR [stderr] (Thread-451 (HornetQ-client-global-threads-301058000))      at com.sun.proxy.$Proxy94.prepareStatement(Unknown Source)
      
       throws org.hibernate.HibernateException: javax.ejb.EJBTransactionRolledbackException: Could not open
       connection
              at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleInCallerTx(CMTTxInterceptor.java:139) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
              at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:204) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
              at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:306) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
              at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:190) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
              at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
              at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
              at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
              at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:32) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
              at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
              at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
              at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
              at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:173) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
              at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
              at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
              at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72) [jboss-as-ee                  
      
      Caused by: java.sql.SQLException: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@fe26893[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@36d5bd43 connection handles=0 lastUse=1375790399364 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@163a3215 pool internal context=SemaphoreArrayListManagedConnectionPool@4a761bf[pool=MNPDS] xaResource=XAResourceWrapperImpl@593f930a[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@36d5bd43 pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
      With the Partitioning, OLAP, Data Mining and Real Application Testing options jndiName=java:jboss/datasources/MNPDS] txSync=null]
              at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:137)
              at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:67) [hibernate-entitymanager-4.0.1.Final.jar:4.0.1.Final]
              at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:276) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
              at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:297) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
              ... 252 more
      Caused by: javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@fe26893[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@36d5bd43 connection handles=0 lastUse=1375790399364 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@163a3215 pool internal context=SemaphoreArrayListManagedConnectionPool@4a761bf[pool=MNPDS] xaResource=XAResourceWrapperImpl@593f930a[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@36d5bd43 pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
      With the Partitioning, OLAP, Data Mining and Real Application Testing options jndiName=java:jboss/datasources/MNPDS] txSync=null]
              at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:604)
              at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:467)
              at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:129)
              ... 255 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:474)
              at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:599)
              ... 257 more
      Caused by: javax.transaction.SystemException: IJ000356: Failed to enlist: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: 0:ffff0a21212c:fafd5c7:5200afe1:4bccdf status: ActionStatus.ABORT_ONLY >
              at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener$TransactionSynchronization.checkEnlisted(TxConnectionListener.java:552)
              at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:282)
              at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:467)
              ... 258 more
      

       

       

       

      The XA datasource is defined as follows:

       

       

      <xa-datasource jta="true" jndi-name="java:jboss/datasources/MNPDS" pool-name="MNPDS" enabled="true" use-java-context="true">
      <xa-datasource-property name="URL">
                              DB_CONN
                          </xa-datasource-property>
                          <xa-datasource-property name="User">
                              USER
                          </xa-datasource-property>
                          <xa-datasource-property name="Password">
                              PASS
                          </xa-datasource-property>
                          <xa-datasource-class>oracle.jdbc.xa.client.OracleXADataSource</xa-datasource-class>
                          <driver>ojdbc</driver>
                          <xa-pool>
                              <min-pool-size>1</min-pool-size>
                              <max-pool-size>200</max-pool-size>
                              <prefill>true</prefill>
                              <use-strict-min>true</use-strict-min>
                              <flush-strategy>FailingConnectionOnly</flush-strategy>
                              <no-tx-separate-pools>true</no-tx-separate-pools>
                          </xa-pool>
                          <validation>
                              <valid-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleValidConnectionChecker"/>
                              <check-valid-connection-sql>select 1 from dual</check-valid-connection-sql>
                              <stale-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleStaleConnectionChecker"/>
                              <exception-sorter class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleExceptionSorter"/>
                          </validation>
                          <timeout>
                              <blocking-timeout-millis>60000</blocking-timeout-millis>
                          </timeout>
                      </xa-datasource>
      
      

       

       

                       

      I forgot to mention that all of the transactions are managed by container.

       

      Of course there exists a workarround to set the transaction timeout so high that it will ensure all the work will be done in the timeout specified but I'd like to find the root cause.

       

      Any help appreciated.

       

      Martin