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

[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). 

[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

[smarlow]

Some related back post links for Narayana and WildFly dev mailing list.

[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

[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)'

[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?

[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.

[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

[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.

[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.

[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.

[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

[aliebscher]

What does this system property exactly change?

When will the delist occurr?

[aliebscher]

Any idea when there will be a released fix available?

In what WF release version?