1 2 Previous Next 17 Replies Latest reply on Sep 3, 2014 10:24 AM by smarlow

    XA END / un-enlist for database connection called to early

    aliebscher

      While trying to port an EE application from JBoss5 to WF8 the following problem occurred:

      EJBs (@Required) using JPA to do some data changes.
      Some changes get already written to the database, others reside in the session cache.

      After the top EJB call returns, a Hibernate Session flush is triggered in beforeCompletion.

      Then more changes are flushed to the database, but I run in a reproduceable database locking problem.

      After some time an update of a row fails with lock wait timeout. This row has been inserted prior during the EJB call.

      There should be exactly one xa transaction active processing all data changes.
      But the database shows two active session, one is an xa transaction with sessionId -2 (orphaned), the other session is a local transaction.

      After analyzing all database communication with the help of the JDBC driver logging I found the following behaviour:

      • a connection is enlisted and xa start called
      • the same connection is used for several select / insert / update statements
      • after return of the top EJB call on the same connection xa end and connection un-enlist is called
      • the same connection is used for session flush (beforeCompletion) but with local transaction because the connection is no longer associated with the xa transaction, so locks can be expected.

      Shouldn't xa end be called AFTER beforeCompletion / session flush!?!

       

      Environment:

      Windows 7 64-bit

      JDK 1.8.0_05-b13 64-Bit

      MS SQL Server 2012 database

      Latest MS JDBC driver

      XA datasource


      See also [WFLY-3619] XA END / un-enlist for database connection called to early - JBoss Issue Tracker.


      See attached log file.


      In the transaction two persistence units are involved, so there are two Hibernate sessions. Both use the same Datasource and share the Connection. During transaction commit the session flushes are initiated, but between the two session flushes, a delistResource occurs. The second flush then uses the connection that is no longer associated with the transaction:

      2014-08-20 08:35:16,323 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) BaseTransaction.commit

      2014-08-20 08:35:16,323 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.commitAndDisassociate

      2014-08-20 08:35:16,323 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) SynchronizationImple.beforeCompletion

      2014-08-20 08:35:16,323 TRACE [org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization] (Thread-8 (HornetQ-client-global-threads-411174393)) JTA sync : beforeCompletion()

      2014-08-20 08:35:16,323 TRACE [org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorNonTrackingImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Transaction before completion callback

      2014-08-20 08:35:16,323 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

      2014-08-20 08:35:16,323 TRACE [org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorNonTrackingImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Automatically flushing session

      2014-08-20 08:35:16,323 TRACE [org.hibernate.internal.SessionImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Automatically flushing session

      2014-08-20 08:35:16,323 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Flushing session

      2014-08-20 08:35:16,323 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Processing flush-time cascades

      2014-08-20 08:35:16,323 TRACE [org.hibernate.engine.internal.Cascade] (Thread-8 (HornetQ-client-global-threads-411174393)) Processing cascade ACTION_PERSIST_ON_FLUSH for: de.mobilexag.centerware.job.entity.Job

      2014-08-20 08:35:16,323 TRACE [org.hibernate.engine.internal.Cascade] (Thread-8 (HornetQ-client-global-threads-411174393)) Done processing cascade ACTION_PERSIST_ON_FLUSH for: de.mobilexag.centerware.job.entity.Job

      2014-08-20 08:35:16,323 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Dirty checking collections

      2014-08-20 08:35:16,323 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Flushing entities and processing referenced collections

      2014-08-20 08:35:16,323 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Processing unreferenced collections

      2014-08-20 08:35:16,323 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Scheduling collection removes/(re)creates/updates

      2014-08-20 08:35:16,323 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects

      2014-08-20 08:35:16,323 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections

      2014-08-20 08:35:16,323 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-8 (HornetQ-client-global-threads-411174393)) Listing entities:

      2014-08-20 08:35:16,323 DEBUG [org.hibernate.internal.util.EntityPrinter] (Thread-8 (HornetQ-client-global-threads-411174393)) de.mobilexag.centerware.job.entity.Job{nextPlannedStart=2014-08-20 08:35:06.993, code=SAP_BACKEND_SYNC_RESOURCE, orderId=6, initiator=SAP_BACKEND_SYNC, queued=true, timeQueued=2014-08-20 08:35:07.967, errorCode=null, timeDone=Wed Aug 20 08:35:16 UTC 2014, skipped=false, businessErrorCode=null, failureDetails=null, timeStored=2014-08-20 08:24:34.1, timeUpdated=Wed Aug 20 08:35:16 UTC 2014, id=-1007, channelId=SAP_BACKEND_SYNC_CHANGED_ORDER_ID_TEN_1, cron=onetime, failures=0, format=null, started=true, timeStarted=Wed Aug 20 08:35:08 UTC 2014, priority=4, done=true, version=5, transactionId=2bc7fe94-eb37-4438-a277-972a4490d39f, timeLastFailure=null, meta=null, tenantId=1, dataGzip=null, skipReason=null}

      2014-08-20 08:35:16,323 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Executing flush

      2014-08-20 08:35:16,323 TRACE [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Starting after statement execution processing [AFTER_STATEMENT]

      2014-08-20 08:35:16,323 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Releasing JDBC connection

      2014-08-20 08:35:16,323 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Post flush

      2014-08-20 08:35:16,323 TRACE [org.hibernate.internal.SessionImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) before transaction completion

      2014-08-20 08:35:16,323 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) SynchronizationImple.beforeCompletion

      2014-08-20 08:35:16,323 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) SynchronizationImple.beforeCompletion

      2014-08-20 08:35:16,323 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

      2014-08-20 08:35:16,323 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

      2014-08-20 08:35:16,323 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (Thread-8 (HornetQ-client-global-threads-411174393)) delistResource(org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8, TMSUCCESS)

      2014-08-20 08:35:16,323 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.delistResource ( org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8, 67108864 )

      2014-08-20 08:35:16,323 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

      2014-08-20 08:35:16,325 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) SynchronizationImple.beforeCompletion

      2014-08-20 08:35:16,325 TRACE [org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization] (Thread-8 (HornetQ-client-global-threads-411174393)) JTA sync : beforeCompletion()

      2014-08-20 08:35:16,325 TRACE [org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorNonTrackingImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Transaction before completion callback

      2014-08-20 08:35:16,325 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

      2014-08-20 08:35:16,325 TRACE [org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorNonTrackingImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Automatically flushing session

      2014-08-20 08:35:16,325 TRACE [org.hibernate.internal.SessionImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Automatically flushing session

      2014-08-20 08:35:16,325 TRACE [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Flushing session

      2014-08-20 08:35:16,325 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Processing flush-time cascades

        • 1. Re: XA END / un-enlist for database connection called to early
          smarlow

          This sounds like an (Synchronization.beforeCompletion) ordering issue but I would like to understand the details from the log better (from transaction start to after the last Synchronization.beforeCompletion/afterCompletion is run). 

          • 2. Re: Re: XA END / un-enlist for database connection called to early
            smarlow

            The below log output, shows what occurs early in the JTA transaction:

             

            tx == 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4

             

            2014-08-20 08:35:08,694 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) BaseTransaction.begin^M

            2014-08-20 08:35:08,694 TRACE [com.arjuna.ats.arjuna] (Thread-8 (HornetQ-client-global-threads-411174393)) StateManager::StateManager( 2, 0 )^M

            2014-08-20 08:35:08,694 TRACE [com.arjuna.ats.arjuna] (Thread-8 (HornetQ-client-global-threads-411174393)) BasicAction::BasicAction()^M

            2014-08-20 08:35:08,694 TRACE [com.arjuna.ats.arjuna] (Thread-8 (HornetQ-client-global-threads-411174393)) BasicAction::Begin() for action-id 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4^M

            2014-08-20 08:35:08,694 TRACE [com.arjuna.ats.arjuna] (Thread-8 (HornetQ-client-global-threads-411174393)) BasicAction::actionInitialise() for action-id 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4^M

            2014-08-20 08:35:08,694 TRACE [com.arjuna.ats.arjuna] (Thread-8 (HornetQ-client-global-threads-411174393)) ActionHierarchy::ActionHierarchy(1)^M

            2014-08-20 08:35:08,694 TRACE [com.arjuna.ats.arjuna] (Thread-8 (HornetQ-client-global-threads-411174393)) ActionHierarchy::add(0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4, 1)^M

            2014-08-20 08:35:08,694 TRACE [com.arjuna.ats.arjuna] (Thread-8 (HornetQ-client-global-threads-411174393)) BasicAction::addChildThread () action 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 adding Thread[Thread-8 (HornetQ-client-global-threads-411174393),5,HornetQ-client-global-threads-411174393]^M

            2014-08-20 08:35:08,694 TRACE [com.arjuna.ats.arjuna] (Thread-8 (HornetQ-client-global-threads-411174393)) BasicAction::addChildThread () action 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 adding Thread[Thread-8 (HornetQ-client-global-threads-411174393),5,HornetQ-client-global-threads-411174393] result = true^M

            2014-08-20 08:35:08,694 TRACE [com.arjuna.ats.arjuna] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionReaper::insert ( BasicAction: 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 status: ActionStatus.RUNNING, 300 )^M

            2014-08-20 08:35:08,694 TRACE [com.arjuna.ats.arjuna] (Thread-8 (HornetQ-client-global-threads-411174393)) ReaperElement::ReaperElement ( BasicAction: 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 status: ActionStatus.RUNNING, 300 )^M

             

            Hibernate ORM Synchronization is registered:

             

            2014-08-20 08:35:08,694 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.registerInterposedSynchronization^M

             

            2014-08-20 08:35:08,695 DEBUG [org.jboss.as.jpa] (Thread-8 (HornetQ-client-global-threads-411174393)) Thread-8 (HornetQ-client-global-threads-411174393):[transaction scoped EntityManager]: created entity manager session TransactionImple < ac, BasicAction: 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 status: ActionStatus.RUNNING >^M

             

            2014-08-20 08:35:08,695 TRACE [org.hibernate.persister.entity.AbstractEntityPersister] (Thread-8 (HornetQ-client-global-threads-411174393)) Fetching entity: [de.mobilexag.centerware.job.entity.Job#-1007]^M

            2014-08-20 08:35:08,695 DEBUG [org.hibernate.loader.Loader] (Thread-8 (HornetQ-client-global-threads-411174393)) Loading entity: [de.mobilexag.centerware.job.entity.Job#-1007]^M

            2014-08-20 08:35:08,695 DEBUG [org.hibernate.SQL] (Thread-8 (HornetQ-client-global-threads-411174393)) select job0_.JOB_ID as JOB_ID1_0_0_, job0_.JOB_BUSINESS_ERROR_CODE as JOB_BUSI2_0_0_, job0_.JOB_CHANNEL_ID as JOB_CHAN3_0_0_, job0_.JOB_CODE as JOB_CODE4_0_0_, job0_.JOB_CRON as JOB_CRON5_0_0_, job0_.JOB_DATA_GZIP as JOB_DATA6_0_0_, job0_.JOB_DONE as JOB_DONE7_0_0_, job0_.JOB_ERROR_CODE as JOB_ERRO8_0_0_, job0_.JOB_FAILURE_DETAILS as JOB_FAIL9_0_0_, job0_.JOB_FAILURES as JOB_FAI10_0_0_, job0_.JOB_FORMAT as JOB_FOR11_0_0_, job0_.JOB_INITIATOR as JOB_INI12_0_0_, job0_.JOB_META as JOB_MET13_0_0_, job0_.JOB_NEXT_PLANNED_START as JOB_NEX14_0_0_, job0_.JOB_ORDER_ID as JOB_ORD15_0_0_, job0_.JOB_PRIORITY as JOB_PRI16_0_0_, job0_.JOB_QUEUED as JOB_QUE17_0_0_, job0_.JOB_SKIP_REASON as JOB_SKI18_0_0_, job0_.JOB_SKIPPED as JOB_SKI19_0_0_, job0_.JOB_STARTED as JOB_STA20_0_0_, job0_.JOB_TEN_ID as JOB_TEN21_0_0_, job0_.JOB_TIME_DONE as JOB_TIM22_0_0_, job0_.JOB_TIME_LAST_FAILURE as JOB_TIM23_0_0_, job0_.JOB_TIME_QUEUED as JOB_TIM24_0_0_, job0_.JOB_TIME_STARTED as JOB_TIM25_0_0_, job0_.JOB_TIME_STORED as JOB_TIM26_0_0_, job0_.JOB_TIME_UPDATED as JOB_TIM27_0_0_, job0_.JOB_TRANSACTION_ID as JOB_TRA28_0_0_, job0_.JOB_VERSION as JOB_VER29_0_0_ from CW_JOB job0_ where job0_.JOB_ID=?^M

            2014-08-20 08:35:08,695 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Obtaining JDBC connection^M

            2014-08-20 08:35:08,695 TRACE [org.jboss.jca.core.connectionmanager.TxConnectionManager] (Thread-8 (HornetQ-client-global-threads-411174393)) Subject: null^M

            2014-08-20 08:35:08,695 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,695 TRACE [org.jboss.jca.core.connectionmanager.TxConnectionManager] (Thread-8 (HornetQ-client-global-threads-411174393)) getManagedConnection interleaving=false , tx=TransactionImple < ac, BasicAction: 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 status: ActionStatus.RUNNING >^M

            2014-08-20 08:35:08,695 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.getTransactionKey^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.getTransactionKey^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.getResource^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.getTransactionKey^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.getResource^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.putResource^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.getResource^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,696 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (Thread-8 (HornetQ-client-global-threads-411174393)) getConnection(null, WrappedConnectionRequestInfo@3af423de[userN

            ManagedConnectionPool: 26e064d2^M

            Method: getConnection(null, WrappedConnectionRequestInfo@3af423de[userName=ROB_MIP])^M

            ManagedConnectionFactory:^M

              Class: org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$WildFlyXaMCF^M

              Object: 75e3d5c4^M

            ConnectionListenerFactory:^M

              Class: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl^M

              Object: 445ff7d1^M

            Pool:^M

              Name: centerware2^M

            PoolConfiguration:^M

              MinSize: 5^M

              InitialSize: 5^M

              MaxSize: 30^M

              BlockingTimeout: 30000^M

              IdleTimeoutMinutes: 30^M

              BackgroundValidation: false^M

              BackgroundValidationMillis: 0^M

              StrictMin: false^M

              UseFastFail: false^M

            Available (2):^M

              41dcc2ae (NORMAL) (Used: 1408523707945) (Validated: 1408523259440)^M

              498e27f7 (NORMAL) (Used: 1408523708675) (Validated: 1408523405709)^M

            InUse (2):^M

              159492ef (NORMAL) (Validated: 1408523558210)^M

              2770daf4 (NORMAL) (Validated: 1408523259428)^M

            Statistics:^M

              ActiveCount: 4^M

              AvailableCount: 28^M

              AverageBlockingTime: 1^M

              AverageCreationTime: 65^M

              AverageGetTime: 4^M

              BlockingFailureCount: 0^M

              CreatedCount: 4^M

              DestroyedCount: 0^M

              IdleCount: 2^M

              InUseCount: 2^M

              MaxCreationTime: 111^M

              MaxGetTime: 155^M

              MaxUsedCount: 4^M

              MaxWaitCount: 0^M

              MaxWaitTime: 1^M

              TimedOut: 0^M

              TotalBlockingTime: 5^M

              TotalCreationTime: 262^M

              TotalGetTime: 578^M

              WaitCount: 0^M

            2014-08-20 08:35:08,696 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (Thread-8 (HornetQ-client-global-threads-411174393)) supplying ManagedConnection from pool: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@41dcc2ae[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 connection handles=0 lastUse=1408523707945 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@70d22cae mcp=SemaphoreArrayListManagedConnectionPool@26e064d2[pool=centerware2] xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 txSync=null]^M

            2014-08-20 08:35:08,696 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (Thread-8 (HornetQ-client-global-threads-411174393)) Got connection from pool tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@41dcc2ae[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 connection handles=0 lastUse=1408523707945 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@70d22cae mcp=SemaphoreArrayListManagedConnectionPool@26e064d2[pool=centerware2] xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 txSync=null] tx=TransactionImple < ac, BasicAction: 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 status: ActionStatus.RUNNING >^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.getTransactionKey^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.getResource^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.getResource^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.putResource^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,696 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (Thread-8 (HornetQ-client-global-threads-411174393)) Using connection from pool tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@41dcc2ae[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 connection handles=0 lastUse=1408523707945 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@70d22cae mcp=SemaphoreArrayListManagedConnectionPool@26e064d2[pool=centerware2] xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 txSync=null] tx=TransactionImple < ac, BasicAction: 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 status: ActionStatus.RUNNING >^M

            2014-08-20 08:35:08,696 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,696 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Pre-enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@41dcc2ae[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 connection handles=0 lastUse=1408523707945 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@70d22cae mcp=SemaphoreArrayListManagedConnectionPool@26e064d2[pool=centerware2] xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 txSync=null] threadTx=TransactionImple < ac, BasicAction: 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 status: ActionStatus.RUNNING >^M

             

            IJ/JCA Synchronization is registered:

             

            2014-08-20 08:35:08,697 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.registerInterposedSynchronization^M

            2014-08-20 08:35:08,697 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,697 TRACE [com.arjuna.ats.arjuna] (EJB default - 9) BasicAction::End() for action-id 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ee9^M

            2014-08-20 08:35:08,697 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Get synchronizer org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@41dcc2ae[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 connection handles=0 lastUse=1408523707945 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@70d22cae mcp=SemaphoreArrayListManagedConnectionPool@26e064d2[pool=centerware2] xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 txSync=null] threadTx=TransactionImple < ac, BasicAction: 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 status: ActionStatus.RUNNING >^M

            2014-08-20 08:35:08,697 TRACE [com.arjuna.ats.arjuna] (EJB default - 9) BasicAction::onePhaseCommit() for action-id 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ee9^M

            2014-08-20 08:35:08,697 TRACE [com.arjuna.ats.jta] (EJB default - 9) XAResourceRecord.topLevelOnePhaseCommit for XAResourceRecord < resource:org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5bfa74ef, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ee9, node_name=1, branch_uid=0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef1, subordinatenodename=null, eis_name=unknown eis name >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@c407b7e >, record id=0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef2^M

            2014-08-20 08:35:08,697 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Enlisting resource org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@41dcc2ae[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 connection handles=0 lastUse=1408523707945 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@70d22cae mcp=SemaphoreArrayListManagedConnectionPool@26e064d2[pool=centerware2] xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 txSync=TransactionSynchronization@747706068{tx=TransactionImple < ac, BasicAction: 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=false cancel=false}]^M

            2014-08-20 08:35:08,697 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.enlistResource ( org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@394146c8 )^M

            2014-08-20 08:35:08,697 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,697 TRACE [com.arjuna.ats.arjuna] (Thread-8 (HornetQ-client-global-threads-411174393)) StateManager::StateManager( 1, 0 )^M

            2014-08-20 08:35:08,697 TRACE [com.arjuna.ats.arjuna] (Thread-8 (HornetQ-client-global-threads-411174393)) AbstractRecord::AbstractRecord (0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef9, 1)^M

             

             

            some log output skipped that shows Hibernate using the database connection,

            then within the same tx (0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4) , we reference another transaction scoped pc/em

            and other Hibernate session will be created:

             

            2014-08-20 08:35:08,707 TRACE [org.hibernate.internal.SessionFactoryImpl$SessionBuilderImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Opening Hibernate Session.  tenant=null, owner=org.hibernate.jpa.internal.EntityManagerImpl@656282fc^M

            2014-08-20 08:35:08,707 TRACE [org.hibernate.internal.SessionImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Opened session at timestamp: 14085237087^M

            2014-08-20 08:35:08,707 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Skipping JTA sync registration due to auto join checking^M

            2014-08-20 08:35:08,707 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,707 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.getRollbackOnly^M

            2014-08-20 08:35:08,707 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,707 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,707 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,708 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.registerInterposedSynchronization^M

            2014-08-20 08:35:08,708 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,708 DEBUG [org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) successfully registered Synchronization^M

            2014-08-20 08:35:08,708 DEBUG [org.hibernate.jpa.spi.AbstractEntityManagerImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Looking for a JTA transaction to join^M

            2014-08-20 08:35:08,708 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,708 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,708 TRACE [org.hibernate.internal.SessionImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Setting flush mode to: AUTO^M

            2014-08-20 08:35:08,708 TRACE [org.hibernate.internal.SessionImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Setting cache mode to: NORMAL^M

            2014-08-20 08:35:08,708 DEBUG [org.jboss.as.jpa] (Thread-8 (HornetQ-client-global-threads-411174393)) Thread-8 (HornetQ-client-global-threads-411174393):[transaction scoped EntityManager]: created entity manager session TransactionImple < ac, BasicAction: 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 status: ActionStatus.RUNNING >^M

            2014-08-20 08:35:08,708 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.registerInterposedSynchronization^M

            2014-08-20 08:35:08,708 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,708 TRACE [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (EJB default - 9) popped object: org.jboss.as.connector.deployers.ra.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction@5f9e72c3^M

            2014-08-20 08:35:08,708 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.putResource^M

            2014-08-20 08:35:08,708 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,708 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,708 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionSynchronizationRegistryImple.getResource^M

            2014-08-20 08:35:08,708 TRACE [com.arjuna.ats.jta] (Thread-8 (HornetQ-client-global-threads-411174393)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE^M

            2014-08-20 08:35:08,708 DEBUG [org.jboss.as.jpa] (Thread-8 (HornetQ-client-global-threads-411174393)) Thread-8 (HornetQ-client-global-threads-411174393):[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffffc0a8022e:-64f4f7ab:53f45bf2:9ef4 status: ActionStatus.RUNNING >^M

            2014-08-20 08:35:08,708 TRACE [org.hibernate.internal.SessionImpl] (Thread-8 (HornetQ-client-global-threads-411174393)) Setting cache mode to: NORMAL^M

            2014-08-20 08:35:08,708 TRACE [org.hibernate.event.internal.DefaultLoadEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Loading entity: [de.mobilexag.mip.sdm.entity.MxTenant#1]^M

            2014-08-20 08:35:08,708 TRACE [org.hibernate.event.internal.DefaultLoadEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Attempting to resolve: [de.mobilexag.mip.sdm.entity.MxTenant#1]^M

            2014-08-20 08:35:08,708 TRACE [org.hibernate.event.internal.DefaultLoadEventListener] (Thread-8 (HornetQ-client-global-threads-411174393)) Object not resolved in any cache: [de.mobilexag.mip.sdm.entity.MxTenant#1]^M

             

             

            What I am seeing above that is copied from the attached log is the following:

            1. The tx starts
            2. Three calls to TransactionSynchronizationRegistryImple.registerInterposedSynchronization are made, in order:
              1. The first transaction scoped persistence context/entity manager is created and Hibernate registers its Synchronization to be called back (for Hibernate session-1).
              2. Hibernate gets a database connection and IJ/JCA registers its Synchronization to be called back.
              3. The second transaction scoped persistence context/entity manager is created and Hibernate registers its Synchronization to be called back (for Hibernate session-1).
            3. When the transaction is committed, the Synchronization beforeCompletion callbacks are invoked in order { Hibernate session-1, IJ/JCA, Hibernate-session-2 }.

             

            The IJ/JCA Synchronization callback delists the connection from the transaction before Hibernate session-2 has done its work with it.  The Hibernate session syncs must run first, before IJ delists the resource from the transaction.

             

            Some possible solutions to this ordering bug that come to mind:

            1. https://java.net/jira/browse/JTA_SPEC-11 might be related, I'm not really sure what Synchronization ordering requirements might come out of that as it seems to be more about distributed transactions. 
            2. Solve at the Narayana level by introducing a way for the application server to specify that the IJ Synchronization callback is always called last during beforeCompletion.  This is the strongest solution as it would allow more applications to run correctly (including apps that package a persistence provider that doesn't have a change for #3 below).
            3. Change each persistence provider that runs on EE Application Servers like WildFly and change them to only ever register one Synchronization per transaction.  This wouldn't help in transactions that load the data source first.
            4. Copy the Synchronization registration logic from Narayana and have WildFly wrap the transaction manager/transaction synchronization registry, in order to enforce the correct Synchronization callbacks.

             

            Other solutions or suggestions are welcome.

             

            This is a great bug report!  Thanks for bringing it to the WildFly forum. 

             

            I'm not yet sure if we need a https://issues.jboss.org/browse/JBTM jira or a https://hibernate.onjira.com/browse/HHH (we already have a WFLY jira that could be reopened or a new one created that is related if we do #4).  Will probably start a wildfly-dev mailing list discussion of this issue.

             

            Scott

            • 3. Re: XA END / un-enlist for database connection called to early
              smarlow
              • 4. Re: XA END / un-enlist for database connection called to early
                jesper.pedersen

                I have added a system property to IronJacamar to disable the call - see JBJCA-1210 for details. Use 1.1.8-SNAPSHOT together with the WildFly 8.x branch.

                 

                Of course you are on your own, so your mileage may vary

                • 5. Re: XA END / un-enlist for database connection called to early
                  smarlow

                  Nice, will be interesting to hear feedback from users about this.  An easy way to add a system property (to WildFly configuration) is via:

                    jboss-cli.sh --connect '/system-property=ironjacamar.no_delist_resource_all:add(value=true)'

                  • 6. Re: XA END / un-enlist for database connection called to early
                    lafr

                    I'm seeing similar problem where application ends with database lock error although only one session bean is reading and modifying data, no concurrent use, only one xa-datasource in use. Second one configured but not used in this scenario.

                    As it's really a database lock, 2 connections seem to be used. I did not drill down it further. It might also be a problem of the IBM Informix Database or their JDBC driver.

                     

                    Do I have to replace all these jars

                    modules/system/layers/base/org/jboss/ironjacamar/api/main/ironjacamar-common-api-1.1.5.Final.jar 
                    modules/system/layers/base/org/jboss/ironjacamar/api/main/ironjacamar-common-spi-1.1.5.Final.jar 
                    modules/system/layers/base/org/jboss/ironjacamar/api/main/ironjacamar-core-api-1.1.5.Final.jar   
                    modules/system/layers/base/org/jboss/ironjacamar/impl/main/ironjacamar-common-impl-1.1.5.Final.jar
                    modules/system/layers/base/org/jboss/ironjacamar/impl/main/ironjacamar-core-impl-1.1.5.Final.jar 

                    modules/system/layers/base/org/jboss/ironjacamar/impl/main/ironjacamar-deployers-common-1.1.5.Final.jar

                    modules/system/layers/base/org/jboss/ironjacamar/impl/main/ironjacamar-validator-1.1.5.Final.jar 
                    modules/system/layers/base/org/jboss/ironjacamar/jdbcadapters/main/ironjacamar-jdbc-1.1.5.Final.jar

                    with 1.1.8-SNAPSHOT?

                    • 7. Re: XA END / un-enlist for database connection called to early
                      lafr

                      I anyways had created my WildFly 8.1.0.Final from sources.

                      So I changed ironjacamar version in pom.xml from 1.1.5.Final to 1.1.8-SNAPSHOT and build again. No problems.

                       

                      Set system property "no_delist_resource_all" to true.

                      And now my problem went away, no concurrent locks and lock timeout from database anymore.

                      Great.

                      • 8. Re: XA END / un-enlist for database connection called to early
                        jesper.pedersen

                        The physical connection to the database is scoped to the transaction, so this sounds unrelated - if it isn't JDBC driver problem. Better investigate via TRACE on a separate forum thread. Switching to PostgreSQL is also an option

                        • 9. Re: XA END / un-enlist for database connection called to early
                          lafr

                          But without property set, the problem is there. With property set to true, the problem is gone. So this fix solves my problem too.

                          Nothing else changed in between. Only stop / start of WF 8.1.

                          There are SLSB methods involved with Transaction attribute "REQUIRES_NEW". But only for used for reading, not for writing.

                          I'll try to create a trace output like the one above tomorrow.

                           

                          And no, changing the database is no option. The legacy part of our application loves the Informix database most, only oracle is accepted as an alternative.

                          • 10. Re: Re: XA END / un-enlist for database connection called to early
                            lafr

                            Here's my server.log extract with a lot of TRACE and DEBUG and a few comments.

                             

                            One thing I have under suspect is the usage of https://xadisk.java.net/ in this case.

                            So there is a second XA-Datasource involved, not database but filesystem.

                            • 11. Re: XA END / un-enlist for database connection called to early
                              jesper.pedersen

                              I would get to the root of that "SQLException: ISAM error: Lock Timeout Expired" first, but likely there is a similar scenario here.

                              • 12. Re: XA END / un-enlist for database connection called to early
                                lafr

                                The Lock timeout is the result of this issue with the XA-connection handling.

                                As said, if I set system property ironjacamar.no_delist_resource_all to true, this does not happen anymore.

                                Two more things I tried today:

                                - if I use a standard datasource instead of xa-datasource in combination with xadisk, also no problem anymore

                                - if I don't use xadisk here, having only the xa-datasource, also no problem anymore

                                • 13. Re: XA END / un-enlist for database connection called to early
                                  aliebscher

                                  What does this system property exactly change?

                                  When will the delist occurr?

                                  • 14. Re: XA END / un-enlist for database connection called to early
                                    aliebscher

                                    Any idea when there will be a released fix available?

                                    In what WF release version?

                                    1 2 Previous Next