Aborting with 1 threads active

[f28b1edf]

Hi,
from time to time our log file ends with

WARN : [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id 7f000002:a108:48b40e06:282b06e invoked while multiple threads active within it.
WARN : [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action 7f000002:a108:48b40e06:282b06e aborting with 1 threads active!

and nothing works until JBoss restart. We tried some googling and so we found e.g.
https://jira.jboss.org/jira/browse/JBAS-4493
https://jira.jboss.org/jira/browse/JBAS-4481
http://wiki.jboss.org/wiki/TxMultipleThreads
We tried some changes, we checked our code that we do close all connections in finally blocks, but nothing helped. Could someone please suggest any way how to solve this? We use JBoss 4.2.2, EJB3
Thanks, Jana

[marklittle]

Turn on debugging (see the docs for how to do that). Then you'll see what transactions are created and when they are terminated. BTW, I assume you have ruled out timeouts as the wiki page mentions?

[f28b1edf]

Thank you for reply. I've changed Threshold value from INFO to DEBUG in jboss-log4j.xml appender tag, but it is not the right place i guess... Could you please give me link to docs?
There is nothing more about arjuna in the log file than this:

DEBUG: Periodic recovery - first pass <Tue, 16 Sep 2008 05:11:36>
DEBUG: StatusModule: first pass
DEBUG: [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass
DEBUG: [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
DEBUG: Periodic recovery - second pass <Tue, 16 Sep 2008 05:11:46>
DEBUG: AtomicActionRecoveryModule: Second pass
DEBUG: [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second pass
DEBUG: [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
DEBUG: Periodic recovery - first pass <Tue, 16 Sep 2008 05:13:46>

WARN : [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id 7f000002:ac37:48cf23c7:18810 invoked while multiple threads active within it.
WARN : [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action 7f000002:ac37:48cf23c7:18810 aborting with 1 threads active!

[f28b1edf]

so i found http://www.jboss.org/jbosstm/docs/4.2.3/manuals/html/jta/AdministrationGuide.html (is that right?)
I'll do some more research in a few days...

[marklittle]

Yes, that's right.

[f28b1edf]

With the debugging on the log file is too big...
I did grep one action id and the result is this:

03:37:50,444 arjLogger DEBUG: BasicAction::Begin() for action-id 7f000002:cfb:492a03da:548f6
03:37:50,444 arjLogger DEBUG: BasicAction::actionInitialise() for action-id 7f000002:cfb:492a03da:548f6
03:37:50,444 arjLogger DEBUG: ActionHierarchy::add(7f000002:cfb:492a03da:548f6, 1)
03:37:50,444 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss]
03:37:50,444 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss] result = true
03:37:50,444 arjLogger DEBUG: TransactionReaper::insert ( BasicAction: 7f000002:cfb:492a03da:548f6 status: ActionStatus.RUNNING, 300 )
03:37:50,444 arjLogger DEBUG: ReaperElement::ReaperElement ( BasicAction: 7f000002:cfb:492a03da:548f6 status: ActionStatus.RUNNING, 300 )
03:37:50,461 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:d7
03:37:50,461 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:d7 result = true
03:37:50,461 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss]
03:37:50,461 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss] result = true
03:37:57,162 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:d7
03:37:57,162 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:d7 result = true
03:37:57,162 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss]
03:37:57,162 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss] result = true
03:37:57,162 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:d7
03:37:57,163 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:d7 result = true
03:37:57,163 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss]
03:37:57,163 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss] result = true
03:42:50,462 arjLogger DEBUG: BasicAction::Abort() for action-id 7f000002:cfb:492a03da:548f6
03:42:50,462 arjLoggerI18N WARN : [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id 7f000002:cfb:492a03da:548f6 invoked while multiple threads active within it.
03:42:50,462 arjLoggerI18N WARN : [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action 7f000002:cfb:492a03da:548f6 aborting with 1 threads active!
03:42:50,462 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_63] - BasicAction::removeAllChildThreads () action 7f000002:cfb:492a03da:548f6 removing Thread[http-0.0.0.0-80-207,5,jboss]
03:42:50,462 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:10a
03:42:50,462 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:10a result = true
03:42:50,464 arjLogger DEBUG: TransactionReaper::remove ( BasicAction: 7f000002:cfb:492a03da:548f6 status: ActionStatus.ABORTED )
03:42:50,464 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.TransactionReaper_3] - TransactionReaper::check - rollback for 7f000002:cfb:492a03da:548f6

But now i'm lost again...

[marklittle]

Yes, this looks like a timeout as I mentioned in September. So you need to figure out why the transaction is "blocked" and being timed out.

[f28b1edf]

I know, but 300 seconds is a long time...
The problem happens only sometimes, eg. after a week or longer.

[marklittle]

"300 seconds is a long time..." is a subjective statement. For the Methuselah Tree (http://www.waymarking.com/waymarks/WMQDF) it's nothing. Whereas for the mayfly it can be an eternity.

It's obvious that you have a transaction that is "blocking" on a resource (maybe a locked db table?) You'd have to try stepping through the running system and identifying what's happening in that specific transaction though to go further.

[f28b1edf]

Ok, thank you :)

[mazz]

BTW: I wrote a CheckedAction class that will log the actual stack trace of the thread(s) that are active when a tx aborts (e.g. when it times out). This will let you know exactly what was working in that tx at the time of the time out (I've found that I would like to see this information, rather than the rather uninformative "CheckedAction::check - atomic action aborting with 1 threads active!" message). e.g. You can see exactly what part of your code was blocked.

Note: this will ONLY log stack traces of threads whose tx's timed out (you won't get flooded with information unless and until tx's time out or are aborted for some reason by the TM)

See the inner class found at the bottom of this:

http://svn.rhq-project.org/repos/rhq/trunk/modules/enterprise/server/jar/src/main/java/org/rhq/enterprise/server/common/TransactionInterruptInterceptor.java

The parent class is an EJB3 interceptor that shows you how you can install this CheckedAction class into the current thread's associated transaction (using BasicAction.Current).

This custom CheckedAction also has the ability to issue a Thread.interrupt to the threads that are active (to possibly wake them up and let them know their tx timed out). But that feature is orthogonal to the logging feature.

[marklittle]

"mazz" wrote:

This custom CheckedAction also has the ability to issue a Thread.interrupt to the threads that are active (to possibly wake them up and let them know their tx timed out). But that feature is orthogonal to the logging feature.

Yes, that's one of the advantages of being able to override this on an application specific basis, but we definitely won't do that by default since it can be dangerous ;-) Think of the TM as a dumb overlord who always does the safest thing possible. But we provide you the rope if you know what I mean ;-)

[mazz]

but we definitely won't do that by default since it can be dangerous ;-) Think of the TM as a dumb overlord who always does the safest thing possible. But we provide you the rope if you know what I mean ;-)

Absolutely, in fact, even that custom code I wrote doesn't do it by default :) I don't trust myself with the rope. But for those instances where interrupting the thread is appropriate, adding a simple annotation on the SLSB method will do the trick.

[born_free]

We are also facing the same issue, in our case we are using ejb 2.0, will this help in our case

[f28b1edf]

mazz, thank you a lot, i did use you code and i got this:

java.lang.Throwable: STACK TRACE OF ACTIVE THREAD IN TERMINATING TRANSACTION
 at java.lang.Object.wait(Native Method)
 at org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock.waitForTx(QueuedPessimisticEJBLock.java:323)
 at org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock.doSchedule(QueuedPessimisticEJBLock.java:230)
 at org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock.schedule(QueuedPessimisticEJBLock.java:194)
 at org.jboss.ejb.plugins.EntityLockInterceptor.invoke(EntityLockInterceptor.java:100)

I have found some bug report https://jira.jboss.org/jira/browse/JBAS-6348, can it be related? I'm stuck again.