12 Replies Latest reply on Jan 31, 2012 8:34 AM by pushpak1981

    Jboss7.1 CR1 transaction timeout issue

    pushpak1981

      Hi,

       

      We have migrated our application from Jboss5.1 to JBoss7.1. After we start the server around 5 mins after starting the server we start getting warning messages on Jboss7.1 console

       

      12:05:54,931 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffffc0a83e4d:57b5587b:4f1e4ff4:79 in state  RUN
      12:05:54,931 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffffc0a83e4d:57b5587b:4f1e4ff4:79 invoked while multiple threads active within it.
      12:05:54,931 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffffc0a83e4d:57b5587b:4f1e4ff4:79 aborting with 1 threads active!
      12:05:54,947 WARN  [com.arjuna.ats.jta] (Transaction Reaper Worker 0) ARJUNA016029: SynchronizationImple.afterCompletion - failed for org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization@e66ea2 with exception: java.lang.IllegalStateException
              at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionSynchronizationRegistryImple.getTransactionImple(TransactionSynchronizationRegistryImple.java:225) [jbossjts-4.16.0.Final.jar:]
              at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionSynchronizationRegistryImple.putResource(TransactionSynchronizationRegistryImple.java:103) [jbossjts-4.16.0.Final.jar:]
              at org.jboss.as.jpa.transaction.TransactionUtil.putEntityManagerInTransactionRegistry(TransactionUtil.java:196)
              at org.jboss.as.jpa.transaction.TransactionUtil.access$100(TransactionUtil.java:49)
              at org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization.afterCompletion(TransactionUtil.java:221)
              at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:117) [jbossjts-4.16.0.Final.jar:]
              at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:403) [jbossjts-4.16.0.Final.jar:]
              at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:335) [jbossjts-4.16.0.Final.jar:]
              at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:121) [jbossjts-4.16.0.Final.jar:]
              at com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:212) [jbossjts-4.16.0.Final.jar:]
              at com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:367) [jbossjts-4.16.0.Final.jar:]
              at com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:79) [jbossjts-4.16.0.Final.jar:]
      12:05:54,978 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012127: TwoPhaseCoordinator.afterCompletion - returned failure for SynchronizationImple< 0:ffffc0a83e4d:57b5587b:4f1e4ff4:7b, org.jboss.as.jpa.transaction.TransactionUtil$SessionSynchronization@e66ea2 >
      12:05:54,994 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffffc0a83e4d:57b5587b:4f1e4ff4:79
      12:05:54,978 WARN  [org.hibernate.util.JDBCExceptionReporter] (Archive DB Controller) SQL Error: 0, SQLState: null
      12:05:54,994 ERROR [org.hibernate.util.JDBCExceptionReporter] (Archive DB Controller) javax.resource.ResourceException: IJ000460: Error checking for a transaction
      12:05:54,994 ERROR [org.jboss.as.ejb3.tx.CMTTxInterceptor] (Archive DB Controller) javax.ejb.EJBTransactionRolledbackException: org.hibernate.exception.GenericJDBCException: Cannot open connection
      12:05:55,009 ERROR [org.jboss.ejb3.invocation] (Archive DB Controller) JBAS014134: EJB Invocation failed on component TransactionBean for method public abstract java.util.List ITransaction.getArchiveTransactions(): javax.ejb.EJBTransactionRolledbackException: org.hibernate.exception.GenericJDBCException: Cannot open connection
              at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleInCallerTx(CMTTxInterceptor.java:139) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]
              at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:204) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]
              at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:306) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]
              at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:190) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]
              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.0.CR1b.jar:7.1.0.CR1b]
              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.0.CR1b.jar:7.1.0.CR1b]
      

       

      We get this error while accessing the EJB's and our application crashes. We tried to increase the transaction timeout in standalone.xml file but after increasing that the application creashes after 45mins.

       

      We have not configured any transaction timeouts in our stateful EJB. As all these EJB's were working  fine on Jboss5.1.

        • 1. Re: Jboss7.1 CR1 transaction timeout issue
          smarlow

          Best if you look at all previous activity on the specified transaction.  Try to understand what is happening with the identified transaction previously.  A first attempt, might be searching backwards in the as7/standalone/log/server.log file for the identified transaction (0:ffffc0a83e4d:57b5587b:4f1e4ff4:79).

           

          Was the application still processing a request for the transaction (0:ffffc0a83e4d:57b5587b:4f1e4ff4:79)?  If yes, why?  If no, what application operation was last associated with the transaction (0:ffffc0a83e4d:57b5587b:4f1e4ff4:79).

           

          Most likely, something is going on in your application, that your just not expecting.  You probably should look at thread dumps of the AS7 instance also and figure out why some threads are executing until the transaction times out.

           

          Scott

          • 2. Re: Jboss7.1 CR1 transaction timeout issue
            pushpak1981

            Thanks for the reply. Wil try to debug the server logs.

            Below is the stack trace for the same

             

            20:16:10,407 TRACE [org.hibernate.loader.Loader] (Archive DB Controller) Total objects hydrated: 0
            20:16:10,408 DEBUG [org.hibernate.engine.internal.StatefulPersistenceContext] (Archive DB Controller) Initializing non-lazy collections
            20:16:10,408 TRACE [com.arjuna.ats.jta] (Archive DB Controller) BaseTransaction.getStatus
            20:16:10,408 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus
            20:16:10,439 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) ReaperThread.run ()
            20:16:10,439 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check ()
            20:16:10,439 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check - comparing 1327416370439
            20:16:10,439 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffffc0a83e4d:29438d48:4f1ec2e6:65 in state  RUN
            20:16:10,444 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Reaper scheduling TX for cancellation 0:ffffc0a83e4d:29438d48:4f1ec2e6:65
            20:16:10,445 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check - comparing 1327416370944
            20:16:10,445 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Thread Thread[Transaction Reaper,5,main] sleeping for 499
            20:16:10,445 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) Thread Thread[Transaction Reaper Worker 0,5,main] performing cancellations
            20:16:10,445 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) Reaper Worker Thread[Transaction Reaper Worker 0,5,main] attempting to cancel 0:ffffc0a83e4d:29438d48:4f1ec2e6:65
            20:16:10,446 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::Abort() for action-id 0:ffffc0a83e4d:29438d48:4f1ec2e6:65
            20:16:10,447 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffffc0a83e4d:29438d48:4f1ec2e6:65 invoked while multiple threads active within it.
            20:16:10,450 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffffc0a83e4d:29438d48:4f1ec2e6:65 aborting with 1 threads active!
            20:16:10,456 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::removeAllChildThreads () action 0:ffffc0a83e4d:29438d48:4f1ec2e6:65 removing Thread[Archive DB Controller,5,EJB default]
            20:16:10,456 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::removeChildThread () action 0:ffffc0a83e4d:29438d48:4f1ec2e6:65 removing TSThread:9
            20:16:10,456 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::removeChildThread () action 0:ffffc0a83e4d:29438d48:4f1ec2e6:65 removing TSThread:9 result = true
            20:16:10,457 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) InputObjectState::InputObjectState()
            20:16:10,457 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0
            InputObjectState Type  : null
            InputObjectState Size  : 0
            InputObjectState Buffer: , -1)
            20:16:10,457 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) OutputObjectState::OutputObjectState()
            20:16:10,458 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus
            20:16:10,458 DEBUG [org.hibernate.internal.SessionImpl] (Archive DB Controller) Opened session at timestamp: 13274163704
            20:16:10,458 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking
            20:16:10,458 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionSynchronizationRegistryImple.getTransactionStatus
            20:16:10,458 TRACE [com.arjuna.ats.jta] (Archive DB Controller) BaseTransaction.getStatus
            20:16:10,458 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus
            20:16:10,458 TRACE [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) registered JTA platform says we cannot currently resister synchronization; skipping
            20:16:10,458 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (Archive DB Controller) Looking for a JTA transaction to join
            20:16:10,458 TRACE [com.arjuna.ats.jta] (Archive DB Controller) BaseTransaction.getStatus
            20:16:10,458 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus
            20:16:10,458 TRACE [com.arjuna.ats.jta] (Archive DB Controller) BaseTransaction.getStatus
            20:16:10,458 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus
            20:16:10,458 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (Archive DB Controller) Unable to join JTA transaction
            20:16:10,458 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking
            20:16:10,458 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking
            20:16:10,458 TRACE [org.hibernate.internal.SessionImpl] (Archive DB Controller) Setting flush mode to: AUTO
            20:16:10,459 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking
            20:16:10,459 TRACE [org.hibernate.internal.SessionImpl] (Archive DB Controller) Setting cache mode to: NORMAL
            20:16:10,459 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking
            20:16:10,459 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking
            20:16:10,459 TRACE [org.hibernate.engine.query.spi.QueryPlanCache] (Archive DB Controller) Located HQL query plan in cache (select t from Transaction t where t.id in (select transactionId from TransactionStatus where status = 'COMPLETED' or status = 'ERROR'))
            20:16:10,459 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking
            20:16:10,459 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking
            20:16:10,459 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking
            20:16:10,459 TRACE [org.hibernate.engine.query.spi.QueryPlanCache] (Archive DB Controller) Located HQL query plan in cache (select t from Transaction t where t.id in (select transactionId from TransactionStatus where status = 'COMPLETED' or status = 'ERROR'))
            20:16:10,459 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking
            20:16:10,459 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking
            20:16:10,459 TRACE [com.arjuna.ats.jta] (Archive DB Controller) BaseTransaction.getStatus
            20:16:10,459 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus
            20:16:10,459 TRACE [org.hibernate.engine.query.spi.HQLQueryPlan] (Archive DB Controller) Find: select t from Transaction t where t.id in (select transactionId from TransactionStatus where status = 'COMPLETED' or status = 'ERROR')
            20:16:10,459 TRACE [org.hibernate.engine.spi.QueryParameters] (Archive DB Controller) Named parameters: {}
            20:16:10,459 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking
            20:16:10,459 TRACE [org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler] (Archive DB Controller) Handling invocation of connection method [prepareStatement]
            20:16:10,459 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Archive DB Controller) Obtaining JDBC connection
            20:16:10,459 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus
            20:16:10,460 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.read_committed(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME)
            20:16:10,460 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.read_state(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, StateType.OS_ORIGINAL)
            20:16:10,460 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, StateType.OS_SHADOW)
            20:16:10,460 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, 10)
            20:16:10,460 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, StateType.OS_ORIGINAL)
            20:16:10,460 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, 11)
            20:16:10,460 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.currentState(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME) - returning StateStatus.OS_COMMITTED
            20:16:10,460 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, StateType.OS_ORIGINAL)
            20:16:10,460 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, 11)
            20:16:10,462 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.openAndLock(C:\JBOSS7.1CR1\jboss-as-7.1.0.CR1b\jboss-as-7.1.0.CR1b\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83e4d_-3fcd0fc7_4f141590_e, FileLock.F_RDLCK, false)
            20:16:10,463 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) InputObjectState::InputObjectState(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME)
            20:16:10,463 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.closeAndUnlock(C:\JBOSS7.1CR1\jboss-as-7.1.0.CR1b\jboss-as-7.1.0.CR1b\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83e4d_-3fcd0fc7_4f141590_e, java.io.FileInputStream@165cf09, null)
            20:16:10,464 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.read_committed(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME)
            20:16:10,464 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.read_state(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, StateType.OS_ORIGINAL)
            20:16:10,464 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, StateType.OS_SHADOW)
            20:16:10,465 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, 10)
            20:16:10,465 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, StateType.OS_ORIGINAL)
            20:16:10,465 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, 11)
            20:16:10,465 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.currentState(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME) - returning StateStatus.OS_COMMITTED
            20:16:10,465 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, StateType.OS_ORIGINAL)
            20:16:10,465 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, 11)
            20:16:10,465 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.openAndLock(C:\JBOSS7.1CR1\jboss-as-7.1.0.CR1b\jboss-as-7.1.0.CR1b\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83e4d_133d1dbb_4f141241_46, FileLock.F_RDLCK, false)
            20:16:10,465 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) InputObjectState::InputObjectState(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME)
            20:16:10,465 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.closeAndUnlock(C:\JBOSS7.1CR1\jboss-as-7.1.0.CR1b\jboss-as-7.1.0.CR1b\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83e4d_133d1dbb_4f141241_46, java.io.FileInputStream@fb5baa, null)
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.read_committed(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME)
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.read_state(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, StateType.OS_ORIGINAL)
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, StateType.OS_SHADOW)
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, 10)
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, StateType.OS_ORIGINAL)
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, 11)
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.currentState(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME) - returning StateStatus.OS_COMMITTED
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, StateType.OS_ORIGINAL)
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, 11)
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.openAndLock(C:\JBOSS7.1CR1\jboss-as-7.1.0.CR1b\jboss-as-7.1.0.CR1b\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83e4d_29ba15a5_4f158365_e, FileLock.F_RDLCK, false)
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) InputObjectState::InputObjectState(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME)
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.closeAndUnlock(C:\JBOSS7.1CR1\jboss-as-7.1.0.CR1b\jboss-as-7.1.0.CR1b\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83e4d_29ba15a5_4f158365_e, java.io.FileInputStream@3f0cf8, null)
            20:16:10,466 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::doAbort (LastResourceRecord(XAOnePhaseResource(LocalXAResourceImpl@1715ab5[connectionListener=470422 connectionManager=fa3f90 warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a83e4d:29438d48:4f1ec2e6:65, node_name=1, branch_uid=0:ffffc0a83e4d:29438d48:4f1ec2e6:69, subordinatenodename=null, eis_name=unknown eis name >])))
            20:16:10,467 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) LastResourceRecord::topLevelAbort() for 0:0:0:0:1
            20:16:10,469 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) SynchronizationImple.afterCompletion
            20:16:10,469 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) TransactionImple.equals
            20:16:10,469 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) TransactionImple.equals
            20:16:10,469 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) SynchronizationImple.afterCompletion
            
            • 3. Re: Jboss7.1 CR1 transaction timeout issue
              smarlow

              It seems like there are two problems going on.  The first being that you are getting the transaction timeout (implying that some unit of work is taking longer than expected.)  You should be able to figure out why that is happening from the thread dumps.

               

              The other problem, that I need to understand better, is why the com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion is executing after the transaction times out.  I'll ask around about that.

               

              Scott

              • 4. Re: Jboss7.1 CR1 transaction timeout issue
                smarlow

                The SynchronizationImple.afterCompletion is expected to run, even after the tx has timed out.  The nightly as7 build has a fix for AS7-3335 (TransactionUtil.putEntityManagerInTransactionRegistry shouldn't be called after the transaction completes).

                 

                That still leaves the question for you to figure out, why the application requests are running longer than transaction timeout.

                • 5. Re: Jboss7.1 CR1 transaction timeout issue
                  pushpak1981

                  Hi Scott,

                   

                  Thanks for the reply. We will download and latest JBoss7.1 build and try to deploy our application. Also we will identify why our code is taking so much time for execution. Will update you accordingly.

                  • 6. Re: Jboss7.1 CR1 transaction timeout issue
                    pushpak1981

                    We downloaded the Latest nightly build and the error you mentioned "TransactionUtil.putEntityManagerInTransactionRegistry" no longer appears.

                     

                    We also did some thread dumps but did not find any  information. As our per our execution cycle we have a thread which runs after a particular amount of time. We have done an EJB lookup only once when the thread is initialized. It runs properly after a particular amount of time and then throws an error message that it cannot find active transaction. This error only appears after we face the warning message. After the warning message the transaction status for this EJB is "aborted".

                     

                    Can it be the case as the transaction is already aborted for that particular instance of EJB it is no longer able to perform any operation during the next thread cycle as its using the same instance of EJB?

                     

                    below is the stack trace for the same.

                     

                    20:16:16,363 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) ReaperThread.run ()

                    20:16:16,363 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check ()

                    20:16:16,363 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check - comparing 1327502776363

                    20:16:16,363 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffffc0a83e4d:2eccfb7c:4f201458:79 in state  RUN

                    20:16:16,368 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Reaper scheduling TX for cancellation 0:ffffc0a83e4d:2eccfb7c:4f201458:79

                    20:16:16,368 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check - comparing 1327502776868

                    20:16:16,368 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Thread Thread[Transaction Reaper,5,main] sleeping for 500

                    20:16:16,368 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) Thread Thread[Transaction Reaper Worker 0,5,main] performing cancellations

                    20:16:16,368 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) Reaper Worker Thread[Transaction Reaper Worker 0,5,main] attempting to cancel 0:ffffc0a83e4d:2eccfb7c:4f201458:79

                    20:16:16,368 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::Abort() for action-id 0:ffffc0a83e4d:2eccfb7c:4f201458:79

                    20:16:16,368 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffffc0a83e4d:2eccfb7c:4f201458:79 invoked while multiple threads active within it.

                    20:16:16,371 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffffc0a83e4d:2eccfb7c:4f201458:79 aborting with 1 threads active!

                    20:16:16,374 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::removeAllChildThreads () action 0:ffffc0a83e4d:2eccfb7c:4f201458:79 removing Thread[Archive DB Controller,5,EJB default]

                    20:16:16,375 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::removeChildThread () action 0:ffffc0a83e4d:2eccfb7c:4f201458:79 removing TSThread:9

                    20:16:16,375 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::removeChildThread () action 0:ffffc0a83e4d:2eccfb7c:4f201458:79 removing TSThread:9 result = true

                    20:16:16,375 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) InputObjectState::InputObjectState()

                    20:16:16,375 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0

                    InputObjectState Type  : null

                    InputObjectState Size  : 0

                    InputObjectState Buffer: , -1)

                    20:16:16,375 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) OutputObjectState::OutputObjectState()

                    20:16:16,377 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.read_committed(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME)

                    20:16:16,377 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.read_state(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, StateType.OS_ORIGINAL)

                    20:16:16,377 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, StateType.OS_SHADOW)

                    20:16:16,377 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, 10)

                    20:16:16,377 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, StateType.OS_ORIGINAL)

                    20:16:16,377 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, 11)

                    20:16:16,377 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.currentState(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME) - returning StateStatus.OS_COMMITTED

                    20:16:16,377 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, StateType.OS_ORIGINAL)

                    20:16:16,377 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME, 11)

                    20:16:16,393 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.openAndLock(C:\JBOSS7.1CR1\jboss-as-7.1.0.CR1b\jboss-as-7.1.0.CR1b\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83e4d_-3fcd0fc7_4f141590_e, FileLock.F_RDLCK, false)

                    20:16:16,394 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) InputObjectState::InputObjectState(0:ffffc0a83e4d:-3fcd0fc7:4f141590:e, EISNAME)

                    20:16:16,394 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus

                    20:16:16,394 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.closeAndUnlock(C:\JBOSS7.1CR1\jboss-as-7.1.0.CR1b\jboss-as-7.1.0.CR1b\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83e4d_-3fcd0fc7_4f141590_e, java.io.FileInputStream@1802b40, null)

                    20:16:16,394 DEBUG [org.hibernate.internal.SessionImpl] (Archive DB Controller) Opened session at timestamp: 13275027763

                    20:16:16,394 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.read_committed(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME)

                    20:16:16,394 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking

                    20:16:16,394 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.read_state(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, StateType.OS_ORIGINAL)

                    20:16:16,394 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionSynchronizationRegistryImple.getTransactionStatus

                    20:16:16,394 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, StateType.OS_SHADOW)

                    20:16:16,394 TRACE [com.arjuna.ats.jta] (Archive DB Controller) BaseTransaction.getStatus

                    20:16:16,394 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, 10)

                    20:16:16,395 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus

                    20:16:16,395 TRACE [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) registered JTA platform says we cannot currently resister synchronization; skipping

                    20:16:16,395 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (Archive DB Controller) Looking for a JTA transaction to join

                    20:16:16,395 TRACE [com.arjuna.ats.jta] (Archive DB Controller) BaseTransaction.getStatus

                    20:16:16,395 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus

                    20:16:16,395 TRACE [com.arjuna.ats.jta] (Archive DB Controller) BaseTransaction.getStatus

                    20:16:16,395 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus

                    20:16:16,395 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] (Archive DB Controller) Unable to join JTA transaction

                    20:16:16,395 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, StateType.OS_ORIGINAL)

                    20:16:16,395 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking

                    20:16:16,395 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, 11)

                    20:16:16,395 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking

                    20:16:16,395 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.currentState(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME) - returning StateStatus.OS_COMMITTED

                    20:16:16,395 TRACE [org.hibernate.internal.SessionImpl] (Archive DB Controller) Setting flush mode to: AUTO

                    20:16:16,395 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, StateType.OS_ORIGINAL)

                    20:16:16,395 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking

                    20:16:16,395 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME, 11)

                    20:16:16,395 TRACE [org.hibernate.internal.SessionImpl] (Archive DB Controller) Setting cache mode to: NORMAL

                    20:16:16,395 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.openAndLock(C:\JBOSS7.1CR1\jboss-as-7.1.0.CR1b\jboss-as-7.1.0.CR1b\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83e4d_133d1dbb_4f141241_46, FileLock.F_RDLCK, false)

                    20:16:16,395 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking

                    20:16:16,395 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking

                    20:16:16,395 TRACE [org.hibernate.engine.query.spi.QueryPlanCache] (Archive DB Controller) Located HQL query plan in cache (select t from Transaction t where t.id in (select transactionId from TransactionStatus where status = 'COMPLETED' or status = 'ERROR'))

                    20:16:16,395 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking

                    20:16:16,395 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking

                    20:16:16,395 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking

                    20:16:16,395 TRACE [org.hibernate.engine.query.spi.QueryPlanCache] (Archive DB Controller) Located HQL query plan in cache (select t from Transaction t where t.id in (select transactionId from TransactionStatus where status = 'COMPLETED' or status = 'ERROR'))

                    20:16:16,395 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking

                    20:16:16,395 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) InputObjectState::InputObjectState(0:ffffc0a83e4d:133d1dbb:4f141241:46, EISNAME)

                    20:16:16,395 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking

                    20:16:16,396 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.closeAndUnlock(C:\JBOSS7.1CR1\jboss-as-7.1.0.CR1b\jboss-as-7.1.0.CR1b\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83e4d_133d1dbb_4f141241_46, java.io.FileInputStream@197b1fd, null)

                    20:16:16,396 TRACE [com.arjuna.ats.jta] (Archive DB Controller) BaseTransaction.getStatus

                    20:16:16,396 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus

                    20:16:16,396 TRACE [org.hibernate.engine.query.spi.HQLQueryPlan] (Archive DB Controller) Find: select t from Transaction t where t.id in (select transactionId from TransactionStatus where status = 'COMPLETED' or status = 'ERROR')

                    20:16:16,396 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.read_committed(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME)

                    20:16:16,396 TRACE [org.hibernate.engine.spi.QueryParameters] (Archive DB Controller) Named parameters: {}

                    20:16:16,396 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.read_state(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, StateType.OS_ORIGINAL)

                    20:16:16,396 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, StateType.OS_SHADOW)

                    20:16:16,396 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Archive DB Controller) Skipping JTA sync registration due to auto join checking

                    20:16:16,396 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, 10)

                    20:16:16,396 TRACE [org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler] (Archive DB Controller) Handling invocation of connection method [prepareStatement]

                    20:16:16,396 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Archive DB Controller) Obtaining JDBC connection

                    20:16:16,396 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, StateType.OS_ORIGINAL)

                    20:16:16,396 TRACE [com.arjuna.ats.jta] (Archive DB Controller) TransactionImple.getStatus

                    20:16:16,396 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, 11)

                    20:16:16,396 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.currentState(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME) - returning StateStatus.OS_COMMITTED

                    20:16:16,396 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ShadowingStore.genPathName(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, StateType.OS_ORIGINAL)

                    20:16:16,396 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.genPathName(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME, 11)

                    20:16:16,396 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.openAndLock(C:\JBOSS7.1CR1\jboss-as-7.1.0.CR1b\jboss-as-7.1.0.CR1b\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83e4d_29ba15a5_4f158365_e, FileLock.F_RDLCK, false)

                    20:16:16,396 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) InputObjectState::InputObjectState(0:ffffc0a83e4d:29ba15a5:4f158365:e, EISNAME)

                    20:16:16,397 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.closeAndUnlock(C:\JBOSS7.1CR1\jboss-as-7.1.0.CR1b\jboss-as-7.1.0.CR1b\standalone\data\tx-object-store\ShadowNoFileLockStore\defaultStore\EISNAME\0_ffffc0a83e4d_29ba15a5_4f158365_e, java.io.FileInputStream@478a50, null)

                    20:16:16,397 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::doAbort (LastResourceRecord(XAOnePhaseResource(LocalXAResourceImpl@e8cc00[connectionListener=aa3e6e connectionManager=78f54 warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a83e4d:2eccfb7c:4f201458:79, node_name=1, branch_uid=0:ffffc0a83e4d:2eccfb7c:4f201458:7d, subordinatenodename=null, eis_name=unknown eis name >])))

                    20:16:16,397 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) LastResourceRecord::topLevelAbort() for 0:0:0:0:1

                    20:16:16,398 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) SynchronizationImple.afterCompletion

                    20:16:16,398 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) TransactionImple.equals

                    20:16:16,398 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) TransactionImple.equals

                    20:16:16,398 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) SynchronizationImple.afterCompletion

                    20:16:16,398 TRACE [org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization] (Transaction Reaper Worker 0) JTA sync : afterCompletion(4)

                    20:16:16,399 TRACE [org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorImpl] (Transaction Reaper Worker 0) Transaction after completion callback [status=4]

                    20:16:16,399 TRACE [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Transaction Reaper Worker 0) after transaction completion

                    20:16:16,399 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Transaction Reaper Worker 0) Aggressively releasing JDBC connection

                    20:16:16,399 TRACE [org.hibernate.internal.SessionImpl] (Transaction Reaper Worker 0) after transaction completion

                    20:16:16,399 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) SynchronizationImple.afterCompletion

                    20:16:16,399 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Transaction Reaper Worker 0) Skipping JTA sync registration due to auto join checking

                    20:16:16,399 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Transaction Reaper Worker 0) Skipping JTA sync registration due to auto join checking

                    20:16:16,399 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) BaseTransaction.getStatus

                    20:16:16,399 TRACE [org.hibernate.internal.SessionImpl] (Transaction Reaper Worker 0) Closing session

                    20:16:16,399 TRACE [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Transaction Reaper Worker 0) Closing logical connection

                    20:16:16,399 TRACE [org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler] (Transaction Reaper Worker 0) Handling invocation of connection method [close]

                    20:16:16,399 TRACE [org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler] (Transaction Reaper Worker 0) Invalidating connection handle

                    20:16:16,399 TRACE [org.hibernate.engine.jdbc.internal.JdbcResourceRegistryImpl] (Transaction Reaper Worker 0) Closing JDBC container [org.hibernate.engine.jdbc.internal.JdbcResourceRegistryImpl@c9aa21]

                    20:16:16,399 TRACE [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Transaction Reaper Worker 0) Logical connection closed

                    20:16:16,399 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) TransactionSynchronizationRegistryImple.putResource

                    20:16:16,397 DEBUG [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Archive DB Controller) Could not open connection [n/a]: java.sql.SQLException: javax.resource.ResourceException: IJ000460: Error checking for a transaction

                        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.0.Final.jar:4.0.0.Final]

                        at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:276) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:297) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:169) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.extractPhysicalConnection(ConnectionProxyHandler.java:82) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.continueInvocation(ConnectionProxyHandler.java:138) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.engine.jdbc.internal.proxy.AbstractProxyHandler.invoke(AbstractProxyHandler.java:81) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at $Proxy116.prepareStatement(Unknown Source)    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:147) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:166) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:145) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1739) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.loader.Loader.doQuery(Loader.java:828) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:289) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.loader.Loader.doList(Loader.java:2463) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.loader.Loader.doList(Loader.java:2449) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2279) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.loader.Loader.list(Loader.java:2274) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:470) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:355) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:196) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1115) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101) [hibernate-core-4.0.0.Final.jar:4.0.0.Final]

                        at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:252) [hibernate-entitymanager-4.0.0.Final.jar:4.0.0.Final]

                        at com.model.transaction.TransactionBean.getArchiveTransactions(TransactionBean.java:108) [WFM7.jar:]

                        at sun.reflect.GeneratedMethodAccessor18.invoke(Unknown Source) [:1.6.0_03]

                        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [:1.6.0_03]

                        at java.lang.reflect.Method.invoke(Method.java:597) [:1.6.0_03]

                        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]

                        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]

                        at org.jboss.seam.intercept.EJBInvocationContext.proceed(EJBInvocationContext.java:44) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:56) [jboss-seam.jar:]

                        at org.jboss.seam.transaction.RollbackInterceptor.aroundInvoke(RollbackInterceptor.java:28) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) [jboss-seam.jar:]

                        at org.jboss.seam.core.MethodContextInterceptor.aroundInvoke(MethodContextInterceptor.java:44) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) [jboss-seam.jar:]

                        at org.jboss.seam.persistence.EntityManagerProxyInterceptor.aroundInvoke(EntityManagerProxyInterceptor.java:29) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.RootInterceptor.invoke(RootInterceptor.java:107) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.SessionBeanInterceptor.aroundInvoke(SessionBeanInterceptor.java:50) [jboss-seam.jar:]

                        at sun.reflect.GeneratedMethodAccessor11.invoke(Unknown Source) [:1.6.0_03]

                        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [:1.6.0_03]

                        at java.lang.reflect.Method.invoke(Method.java:597) [:1.6.0_03]

                        at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptorFactory$ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptorFactory.java:123) [jboss-as-ee-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]

                        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]

                        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:37) [jboss-as-ee-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]

                        at org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:45) [jboss-as-jpa-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]

                        at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation-1.1.1.Final.jar:1.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.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee-7.1.0.CR1b.jar:7.1.0.CR1b]

                        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.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        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.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:202) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:306) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:190) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        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.0.CR1b.jar:7.1.0.CR1b]

                        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.0.CR1b.jar:7.1.0.CR1b]

                        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.0.CR1b.jar:7.1.0.CR1b]

                        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:57) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        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.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:173) [jboss-as-ee-7.1.0.CR1b.jar:7.1.0.CR1b]

                        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-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at com.model.transaction.TransactionLocal$$$view11.getArchiveTransactions(Unknown Source) [WFM7.jar:]

                        at com.controller.ArchiveDBController.archiveTransactions(ArchiveDBController.java:100) [WFM7.jar:]

                        at com.controller.ArchiveDBController.run(ArchiveDBController.java:77) [WFM7.jar:]

                        at com.controller.ArchiveDBController.startArchiveDBControllerThread(ArchiveDBController.java:58) [WFM7.jar:]

                        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [:1.6.0_03]

                        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [:1.6.0_03]

                        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [:1.6.0_03]

                        at java.lang.reflect.Method.invoke(Method.java:597) [:1.6.0_03]

                        at org.jboss.seam.util.Reflections.invoke(Reflections.java:22) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.RootInvocationContext.proceed(RootInvocationContext.java:32) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:56) [jboss-seam.jar:]

                        at org.jboss.seam.transaction.RollbackInterceptor.aroundInvoke(RollbackInterceptor.java:28) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) [jboss-seam.jar:]

                        at org.jboss.seam.core.BijectionInterceptor.aroundInvoke(BijectionInterceptor.java:77) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) [jboss-seam.jar:]

                        at org.jboss.seam.core.MethodContextInterceptor.aroundInvoke(MethodContextInterceptor.java:44) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) [jboss-seam.jar:]

                        at org.jboss.seam.async.AsynchronousInterceptor.aroundInvoke(AsynchronousInterceptor.java:52) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.RootInterceptor.invoke(RootInterceptor.java:107) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.JavaBeanInterceptor.interceptInvocation(JavaBeanInterceptor.java:185) [jboss-seam.jar:]

                        at org.jboss.seam.intercept.JavaBeanInterceptor.invoke(JavaBeanInterceptor.java:103) [jboss-seam.jar:]

                        at com.controller.ArchiveDBController_$$_javassist_seam_12.startArchiveDBControllerThread(ArchiveDBController_$$_javassist_seam_12.java) [WFM7.jar:]

                        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [:1.6.0_03]

                        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [:1.6.0_03]

                        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [:1.6.0_03]

                        at java.lang.reflect.Method.invoke(Method.java:597) [:1.6.0_03]

                        at org.jboss.seam.util.Reflections.invoke(Reflections.java:22) [jboss-seam.jar:]

                        at org.jboss.seam.util.Reflections.invokeAndWrap(Reflections.java:144) [jboss-seam.jar:]

                        at org.jboss.seam.async.AsynchronousInvocation$1.process(AsynchronousInvocation.java:62) [jboss-seam.jar:]

                        at org.jboss.seam.async.Asynchronous$ContextualAsynchronousRequest.run(Asynchronous.java:80) [jboss-seam.jar:]

                        at org.jboss.seam.async.AsynchronousInvocation.execute(AsynchronousInvocation.java:44) [jboss-seam.jar:]

                        at org.jboss.seam.async.TimerServiceDispatcher.dispatch(TimerServiceDispatcher.java:50) [jboss-seam.jar:]

                        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [:1.6.0_03]

                        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [:1.6.0_03]

                        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [:1.6.0_03]

                        at java.lang.reflect.Method.invoke(Method.java:597) [:1.6.0_03]

                        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]

                        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]

                        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:39) [jboss-as-ee-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]

                        at org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:45) [jboss-as-jpa-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]

                        at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation-1.1.1.Final.jar:1.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.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee-7.1.0.CR1b.jar:7.1.0.CR1b]

                        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.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        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.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:228) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:304) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:190) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        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.0.CR1b.jar:7.1.0.CR1b]

                        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.0.CR1b.jar:7.1.0.CR1b]

                        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.0.CR1b.jar:7.1.0.CR1b]

                        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.ejb3.timerservice.TimedObjectInvokerImpl.callTimeout(TimedObjectInvokerImpl.java:101) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.callTimeout(TimedObjectInvokerImpl.java:111) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.as.ejb3.timerservice.task.TimerTask.callTimeout(TimerTask.java:148) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at org.jboss.as.ejb3.timerservice.task.TimerTask.run(TimerTask.java:126) [jboss-as-ejb3-7.1.0.CR1b.jar:7.1.0.CR1b]

                        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) [:1.6.0_03]

                        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [:1.6.0_03]

                        at java.util.concurrent.FutureTask.run(FutureTask.java:138) [:1.6.0_03]

                        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885) [:1.6.0_03]

                        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) [:1.6.0_03]

                        at java.lang.Thread.run(Thread.java:619) [:1.6.0_03]

                        at org.jboss.threads.JBossThread.run(JBossThread.java:122)

                    Caused by: javax.resource.ResourceException: IJ000460: Error checking for a transaction

                        at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:361)

                        at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:444)

                        at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:129)

                        ... 149 more

                    Caused by: javax.resource.ResourceException: IJ000459: Transaction is not active: tx=TransactionImple < ac, BasicAction: 0:ffffc0a83e4d:2eccfb7c:4f201458:79 status: ActionStatus.ABORTING >

                        at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:351)

                        ... 151 more

                    • 7. Re: Jboss7.1 CR1 transaction timeout issue
                      smarlow

                      pushpak1981 wrote:

                       

                      We downloaded the Latest nightly build and the error you mentioned "TransactionUtil.putEntityManagerInTransactionRegistry" no longer appears.

                       

                      Glad to hear that. 

                       

                       

                      20:16:16,363 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffffc0a83e4d:2eccfb7c:4f201458:79 in state  RUN

                      20:16:16,368 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Reaper scheduling TX for cancellation 0:ffffc0a83e4d:2eccfb7c:4f201458:79

                       

                      I would of expected that the thread dump would of shown a thread that is not completing (since the transaction is the same one that timed out).  You should see whatever it is that is preventing the operation from completing.  The following is from the bottom that shows the same transaction.

                       

                      Caused by: javax.resource.ResourceException: IJ000460: Error checking for a transaction

                          at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:361)

                          at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:444)

                          at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:129)

                          ... 149 more

                      Caused by: javax.resource.ResourceException: IJ000459: Transaction is not active: tx=TransactionImple < ac, BasicAction: 0:ffffc0a83e4d:2eccfb7c:4f201458:79 status: ActionStatus.ABORTING >

                          at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:351)

                          ... 151 more

                       

                       

                      Previous to this error occurring, I can think of two possible causes, that you need to figure out which one is happening (or if its something else). 

                       

                      The hint is that we seem to be executing "select t from Transaction t where t.id in (select transactionId from TransactionStatus where status = 'COMPLETED' or status = 'ERROR')" from a timer. 

                       

                      Possible activity #1 is that the timer was triggered 15 minutes ago and something blocked the operation from executing (until the transaction times out). 

                       

                      Possible activity #2 is that transaction started 15 minutes ago and the timer triggered after the transaction was already timed out (or about to timeout). 

                       

                      I would look in the server.log for previous references to the 0:ffffc0a83e4d:2eccfb7c:4f201458:79 transaction and see if you can tell what operation it was associated with. 

                       

                      Scott

                      • 8. Re: Jboss7.1 CR1 transaction timeout issue
                        pushpak1981

                        Thanks for the reply. Will look into more details in server.log and try to identify why the code is blocking.

                         

                        20:16:16,398 TRACE [org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization] (Transaction Reaper Worker 0) JTA sync : afterCompletion(4)

                        20:16:16,399 TRACE [org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorImpl] (Transaction Reaper Worker 0) Transaction after completion callback [status=4]

                        20:16:16,399 TRACE [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Transaction Reaper Worker 0) after transaction completion

                        20:16:16,399 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Transaction Reaper Worker 0) Aggressively releasing JDBC connection

                        20:16:16,399 TRACE [org.hibernate.internal.SessionImpl] (Transaction Reaper Worker 0) after transaction completion

                        20:16:16,399 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) SynchronizationImple.afterCompletion

                        20:16:16,399 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Transaction Reaper Worker 0) Skipping JTA sync registration due to auto join checking

                        20:16:16,399 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Transaction Reaper Worker 0) Skipping JTA sync registration due to auto join checking

                        20:16:16,399 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) BaseTransaction.getStatus

                        20:16:16,399 TRACE [org.hibernate.internal.SessionImpl] (Transaction Reaper Worker 0) Closing session

                        20:16:16,399 TRACE [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Transaction Reaper Worker 0) Closing logical connection

                        20:16:16,399 TRACE [org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler] (Transaction Reaper Worker 0) Handling invocation of connection method [close]

                        20:16:16,399 TRACE [org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler] (Transaction Reaper Worker 0) Invalidating connection handle

                        20:16:16,399 TRACE [org.hibernate.engine.jdbc.internal.JdbcResourceRegistryImpl] (Transaction Reaper Worker 0) Closing JDBC container [org.hibernate.engine.jdbc.internal.JdbcResourceRegistryImpl@c9aa21]

                        20:16:16,399 TRACE [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Transaction Reaper Worker 0) Logical connection closed

                        In the logs mentioned above displays message as "Logical Connection closed". Is this the reason it throwing error message as cannot open connection when we try to acess the same instance of EJB.

                        • 9. Re: Jboss7.1 CR1 transaction timeout issue
                          smarlow
                          In the logs mentioned above displays message as "Logical Connection closed". Is this the reason it throwing error message as cannot open connection when we try to acess the same instance of EJB.

                           

                          No, it looks like the JTA transaction timed out before trying to get the database connection.  You have to find out why the JTA transaction timed out and go from there.

                          • 10. Re: Jboss7.1 CR1 transaction timeout issue
                            pushpak1981

                            Hi Scott,

                             

                            I think we were able to find out the issue for Transaction timeout.

                             

                            1. We were having a seam application scoped component which contained a method with @Asynchronous annotation. (Seam 2.1.2)

                            2. In the @Asynchronous method we were calling another method which contained a while(true) loop which did a lookup for the EJB and executed the method of the EJB.

                             

                            @Scope(ScopeType.APPLICATION)

                            @Name("archiveDBController")

                            Class ArchiveDBController{

                             

                                       @Asynchronous

                                      public void startArchiveDBControllerThread(){

                                     archive();

                                      }

                             

                             

                                      public void archive(){

                             

                                      while(true){

                                           ejb = lookup("ejb")

                                           ejb.getUsers();   

                                         }

                                      }

                                 }

                            As per the seam documentation the @Asynchronous starts a new transaction when it executes the method and commit the transaction when the method execution is completed.

                            As we were having a while loop inside the method which is called from @Asynchronous method the @Asynchronous method transacition never used to commit.

                             

                            Recently we migrated our application from JBoss5.1 to JBoss7.1. This code was working in JBoss5.1. What can be the reason this code is failing in Jboss7.1 ? I think this is a design issue

                             

                            We manually committed the transaction in startArchiveDBControllerThread method after which the transactiion created by seam was comitted. And it did not gave any more exceptions.

                            org.jboss.seam.transaction.Transaction.instance().commit();

                            Is there any way we can stop seam to create transactions for @Asynchronous methods ?

                             

                            thanks a lot for your help.

                            • 11. Re: Jboss7.1 CR1 transaction timeout issue
                              sfcoy

                              Did you try this?

                              pushpak1981 wrote:

                               

                                         @Asynchronous

                                         @TransactionAttribute(NOT_SUPPORTED)

                                        public void startArchiveDBControllerThread(){

                                       archive();

                                        }

                               

                               

                              • 12. Re: Jboss7.1 CR1 transaction timeout issue
                                pushpak1981

                                Yes i tried by specifying @TransactionAttribute(NOT_SUPPORTED) but we faced the same issue. @TransactionAttribute is EJB annotation i am not sure whether it will work with Seam components.