What to do when there are XA Transaction Timeout?

Jerome.Jargot's picture
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:

2018-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

These 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. Simple configuration check with Tomcat

Narayana transaction manager (TM) had been integrated into Tomcat in order to enable the use of the XA transactions.

Make sure that this option below is passed to the java command used to run the Tomcat, otherwise all the defaults will apply:

-Dcom.arjuna.ats.arjuna.common.propertiesFile=/a/path/to/jbossts-properties.xml

Make sure that the jbossts-properties.xml file exists.

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

4. 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:

5. 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:

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 (standalone.bat) or as a Windows service, edit the BonitaSubscription-7.9.0-wildfly-10.1.0.Final/server/standalone/configuration/standalone.xml file.

Comments

Submitted by the.shirini on Sat, 08/10/2019 - 20:45

Thats Cool, Thank you

Notifications