What to do when there are XA Transaction Timeout?

Jerome.Jargot
Blog Categories: 

Component: Bonita | Version: 7.9

What's wrong?

These messages can be found in the server.log file:

2018-10-08 15:23:41,114 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0afe21b2:4672bcb6:5bbb73ed:6930 in state  RUN
2018-10-08 15:23:41,117 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff0afe21b2:4672bcb6:5bbb73ed:6930 invoked while multiple threads active within it.
2018-10-08 15:23:41,137 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffff0afe21b2:4672bcb6:5bbb73ed:6930 completed with multiple threads - thread default task-23 was in progress with java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
java.net.SocketInputStream.read(SocketInputStream.java:171)
java.net.SocketInputStream.read(SocketInputStream.java:141)
...

2018-10-08 15:23:41,138 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff0afe21b2:4672bcb6:5bbb73ed:6930 aborting with 1 threads active!
2018-10-08 15:23:41,615 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0afe21b2:4672bcb6:5bbb73ed:6930 in state  CANCEL
2018-10-08 15:23:41,616 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012378: ReaperElement appears to be wedged: sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
...

2018-10-08 15:23:42,116 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0afe21b2:4672bcb6:5bbb73ed:6930 in state  CANCEL_INTERRUPTED
2018-10-08 15:23:42,117 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012120: TransactionReaper::check worker Thread[Transaction Reaper Worker 0,5,main] not responding to interrupt when cancelling TX 0:ffff0afe21b2:4672bcb6:5bbb73ed:6930 -- worker marked as zombie and TX scheduled for mark-as-rollback
2018-10-08 15:23:42,117 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012110: TransactionReaper::check successfuly marked TX 0:ffff0afe21b2:4672bcb6:5bbb73ed:6930 as rollback only

2018-11-29 17:18:17,459 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000101:-201592e0:5c000d43:e772 in state  RUN
2018-11-29 17:18:17,478 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Obtained JDBC connection
2018-11-29 17:18:17,508 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Releasing JDBC connection
2018-11-29 17:18:17,508 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Released JDBC connection
2018-11-29 17:18:17,513 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Obtaining JDBC connection
2018-11-29 17:18:17,516 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff7f000101:-201592e0:5c000d43:e772 invoked while multiple threads active within it.
2018-11-29 17:18:17,517 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffff7f000101:-201592e0:5c000d43:e772 completed with multiple threads - thread default task-36 was in progress with java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
...

2018-11-29 17:18:17,517 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff7f000101:-201592e0:5c000d43:e772 aborting with 1 threads active!
2018-11-29 17:18:17,558 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff7f000101:-201592e0:5c000d43:e772
2018-11-29 17:18:17,571 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-36) SQL Error: 0, SQLState: null
2018-11-29 17:18:17,571 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-36) javax.resource.ResourceException: IJ000457: Unchecked throwable in managedConnectionReconnected() cl=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@63fbf68b[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@78744f3f connection handles=0 lastReturned=1543508297571 lastValidated=1543508198248 lastCheckedOut=1543508297513 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@3ee3e0ef mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@31f31673[pool=BusinessDataDS] xaResource=XAResourceWrapperImpl@1f3212c3[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@78744f3f pad=false overrideRmValue=null productName=Microsoft SQL Server productVersion=13.00.4001 jndiName=java:jboss/datasources/BusinessDataDS] txSync=null]
2018-11-29 17:18:17,571 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Aggressively releasing JDBC connection
2018-11-29 17:18:17,571 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Aggressively releasing JDBC connection
2018-11-29 17:18:17,571 WARN  [com.arjuna.ats.arjuna] (default task-36) ARJUNA012077: Abort called on already aborted atomic action 0:ffff7f000101:-201592e0:5c000d43:e772
2018-11-29 17:18:17,571 DEBUG [com.bonitasoft.engine.api.impl.ServerAPIExt] (default task-36) THREAD_ID=233 | HOSTNAME=Tetrapharmakon | TENANT_ID=1 | javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:-201592e0:5c000d43:e772: org.bonitasoft.engine.transaction.STransactionCommitException: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:-201592e0:5c000d43:e772
...
Caused by: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:-201592e0:5c000d43:e772
...

2018-11-29 17:18:17,571 TRACE [com.bonitasoft.engine.api.impl.ServerAPIExt] (default task-36) THREAD_ID=233 | HOSTNAME=Tetrapharmakon | TENANT_ID=1 | End Server API call org.bonitasoft.engine.api.CommandAPI execute
2018-11-29 17:18:17,572 SEVERE [org.restlet.Component.BonitaSPRestletApplication] (default task-36) Exception or error caught in server resource: org.bonitasoft.engine.exception.BonitaRuntimeException: USERNAME=walter.bates | org.bonitasoft.engine.transaction.STransactionCommitException: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:-201592e0:5c000d43:e772
...
Caused by: org.bonitasoft.engine.transaction.STransactionCommitException: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:-201592e0:5c000d43:e772
...
Caused by: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:-201592e0:5c000d43:e772
...

2018-11-29 17:18:17,572 SEVERE [org.bonitasoft.web.rest.server.api.resource.CommonResource] (default task-36) USERNAME=walter.bates | org.bonitasoft.engine.transaction.STransactionCommitException: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:-201592e0:5c000d43:e772: org.bonitasoft.engine.exception.BonitaRuntimeException: USERNAME=walter.bates | org.bonitasoft.engine.transaction.STransactionCommitException: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:-201592e0:5c000d43:e772
...
Caused by: org.bonitasoft.engine.transaction.STransactionCommitException: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:-201592e0:5c000d43:e772
...
Caused by: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:-201592e0:5c000d43:e772
...

2018-11-29 17:18:18,129 INFO  [org.hibernate.event.internal.DefaultLoadEventListener] (default task-36) HHH000327: Error performing load command : org.hibernate.HibernateException: Logical connection is closed
2018-11-29 17:18:18,131 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Aggressively releasing JDBC connection
2018-11-29 17:18:18,131 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Aggressively releasing JDBC connection
2018-11-29 17:18:18,131 TRACE [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Closing logical connection
2018-11-29 17:18:18,131 TRACE [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Logical connection closed
2018-11-29 17:18:18,131 DEBUG [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Aggressively releasing JDBC connection
2018-11-29 17:18:18,131 TRACE [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Closing logical connection
2018-11-29 17:18:18,131 TRACE [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (default task-36) Logical connection closed
2018-11-29 17:18:18,131 DEBUG [com.bonitasoft.engine.api.impl.ServerAPIExt] (default task-36) THREAD_ID=233 | HOSTNAME=Tetrapharmakon | TENANT_ID=1 | javax.persistence.PersistenceException: org.hibernate.HibernateException: Logical connection is closed: org.bonitasoft.engine.persistence.SRetryableException: javax.persistence.PersistenceException: org.hibernate.HibernateException: Logical connection is closed
    at org.bonitasoft.engine.business.data.impl.JPABusinessDataRepositoryImpl.findById(JPABusinessDataRepositoryImpl.java:193)
...
Caused by: javax.persistence.PersistenceException: org.hibernate.HibernateException: Logical connection is closed
...

There are below other examples from the server/logs/bonita*log file:

2017-08-17 16:05:37.780 +0200 SEVERE: org.bonitasoft.web.toolkit.server.servlet.ToolkitHttpServlet org.bonitasoft.web.toolkit.server.servlet.ToolkitHttpServlet catchAllExceptions 
SEVERE: org.bonitasoft.engine.exception.SearchException: USERNAME=ocatoul | org.bonitasoft.engine.persistence.SBonitaReadException: org.bonitasoft.engine.services.SPersistenceException: org.hibernate.HibernateException: Current transaction is not in progress
org.bonitasoft.web.toolkit.client.common.exception.api.APIException: org.bonitasoft.engine.exception.SearchException: USERNAME=ocatoul | org.bonitasoft.engine.persistence.SBonitaReadException: org.bonitasoft.engine.services.SPersistenceException: org.hibernate.HibernateException: Current transaction is not in progress
...
Caused by: org.bonitasoft.engine.services.SPersistenceException: org.hibernate.HibernateException: Current transaction is not in progress
...
Caused by: org.hibernate.HibernateException: Current transaction is not in progress
...

2018-09-10 07:40:22,470 SEVERE [org.restlet.Component.BonitaSPRestletApplication] (default task-29) Exception or error caught in server resource: org.bonitasoft.engine.exception.BonitaRuntimeException: USERNAME=aponcer | org.bonitasoft.engine.persistence.SRetryableException: javax.persistence.PersistenceException: org.hibernate.HibernateException: Logical connection is closed
    at org.bonitasoft.engine.api.impl.ServerAPIImpl.wrapThrowable(ServerAPIImpl.java:148)
...
Caused by: javax.persistence.PersistenceException: org.hibernate.HibernateException: Logical connection is closed
...
    at org.bonitasoft.engine.business.data.impl.JPABusinessDataRepositoryImpl.findList(JPABusinessDataRepositoryImpl.java:318)
    at org.bonitasoft.engine.business.data.impl.JPABusinessDataRepositoryImpl.findListByNamedQuery(JPABusinessDataRepositoryImpl.java:295)
    ... 149 more
Caused by: org.hibernate.HibernateException: Logical connection is closed
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:164)
...
2018-09-10 10:01:20,153 SEVERE [org.restlet.Component.BonitaSPRestletApplication] (default task-4) Exception or error caught in server resource: org.bonitasoft.engine.exception.BonitaRuntimeException: USERNAME=gflores | org.bonitasoft.engine.persistence.SRetryableException: javax.persistence.PersistenceException: org.hibernate.HibernateException: Logical connection is closed
...
Caused by: org.bonitasoft.engine.persistence.SRetryableException: javax.persistence.PersistenceException: org.hibernate.HibernateException: Logical connection is closed
    at org.bonitasoft.engine.business.data.impl.JPABusinessDataRepositoryImpl.findById(JPABusinessDataRepositoryImpl.java:193)
...
Caused by: javax.persistence.PersistenceException: org.hibernate.HibernateException: Logical connection is closed
...
Caused by: org.hibernate.HibernateException: Logical connection is closed
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:164)
...

Answer

You are right, the messages in the log files show that there are XA transactions which time out.

Explanation

A XA transaction can time out when:

  • Transactions are waiting for locks, when there are deadlocks...
  • There are shortage of connection in the pools associated to datasources.
  • There are long transactions:
    • The tables are becoming huge.
    • A client application calls the Engine API or the REST API which triggers searches which need a long time to execute.
    • The users are using the portal so that it triggers searches (via the REST API) which need a long time to execute.

1. Database server

Bonita requires specific database server settings. If not implemented, there could be deadlocks, especially when MS Sql server is used.

Check that the settings listed in the Database creation and settings to work with Bonita documentation page have been implemented.

2. Sizing

Analyze the configuration and better configure the connections' pools and threads' pools ; see the Sizing of the engine with examples .
Make sure that there will never be shortage of connections in the pools.

3. Tables' size

Analyze the tables' sizes used with the engine and plan to delete the oldest data, using the API: better do that with 7.7.5 version or greater.

In particular, you may want to delete archived process instances with the API call below:

4. Raise up the XA default transaction timeout

At production sites, values from 300 to 1200 seconds are used.

Narayana is the transaction manager (TM) used with Bonita. It enables the use of XA transactions.

Tomcat

Edit the BonitaSubscription-7.9-Tomcat-8.5.34/server/conf/jbossts-properties.xml.
Raise up the value, in seconds, of the xml element listed below:

<entry key="com.arjuna.ats.arjuna.coordinator.defaultTimeout">600</entry>

Restart the Tomcat to activate the changes.

Wildfly

Edit the standalone.xml file

Add the coordinator-environment element in the subsystem section, as shown below:

<subsystem xmlns="urn:jboss:domain:transactions:3.0">
    <core-environment node-identifier="bonita">
        <process-id>
            <uuid />
        </process-id>
    </core-environment>
    <recovery-environment socket-binding="txn-recovery-environment" status-socket-binding="txn-status-manager" />
    <coordinator-environment default-timeout="600" />
</subsystem>

Restart the Wildfly to activate the changes.

standalone.xml file location

start-bonita script
When the BonitaSubscription-7.9.0-wildfly-10.1.0.Final/start-bonita.sh (start-bonita.bat) script is used to start the application server, then edit the BonitaSubscription-7.9.0-wildfly-10.1.0.Final/setup/wildfly-templates/standalone.xml file.

Other situations
When Wildfly is started with the standard BonitaSubscription-7.9.0-wildfly-10.1.0.Final/server/bin/standalone.sh (start-bonita.bat) or as a Windows service, edit the BonitaSubscription-7.9.0-wildfly-10.1.0.Final/server/standalone/configuration/standalone.xml file.

Notifications