Weird transaction error

[theoverlord]

I'm getting these strange transaction related errors from an MDB consuming messages from queue:

2008-08-07 18:22:42,414 [JMS SessionPool Worker-5] WARN com.arjuna.ats.jta.logging.loggerI18N - [com.arjuna.ats.internal.jta.resources.arjunacore.preparefailed] [com.arjuna.ats.internal.jta.resources.arjunacore.preparefailed] XAResourceRecord.prepare - prepare failed with exception java.lang.IllegalMonitorStateException
2008-08-07 18:22:42,414 [JMS SessionPool Worker-5] WARN com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.BasicAction_36] - BasicAction.End() - prepare phase of action-id -53eef977:b8fd:489b9f66:dea failed.
2008-08-07 18:22:42,414 [JMS SessionPool Worker-5] WARN com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.BasicAction_38] - Action Aborting
2008-08-07 18:22:42,419 [JMS SessionPool Worker-5] ERROR org.jboss.jms.asf.StdServerSession - failed to commit/rollback
javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] Can't commit because the transaction is in aborted state
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1394)
 at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
 at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
 at org.jboss.jms.asf.StdServerSession.onMessage(StdServerSession.java:351)
 at org.jboss.jms.client.container.ClientConsumer.callOnMessage(ClientConsumer.java:160)
 at org.jboss.jms.client.container.SessionAspect.handleRun(SessionAspect.java:831)
 at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect14.invoke(SessionAspect14.java)
 at org.jboss.jms.client.delegate.ClientSessionDelegate$run_N8003352271541955702.invokeNext(ClientSessionDelegate$run_N8003352271541955702.java)
 at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
 at org.jboss.jms.client.delegate.ClientSessionDelegate$run_N8003352271541955702.invokeNext(ClientSessionDelegate$run_N8003352271541955702.java)
 at org.jboss.jms.client.delegate.ClientSessionDelegate.run(ClientSessionDelegate.java)
 at org.jboss.jms.client.JBossSession.run(JBossSession.java:199)
 at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:194)

I've already opened a support ticket on this but I just wanted to know what you think about this.

[clebert.suconic]

Can't commit because the transaction is in aborted state

This is a symptom.

You need to find another exception on your log that shows the cause.

[theoverlord]

I'm not seeing else in the logs that would be related to this exception.

What are some of the things that would cause this exception to be thrown?

[clebert.suconic]

It's a common practice to do:

try
{
}
catch (Exception e)
{
 log.warn (e.getMessage(), e);
 transaction.setRollbackOnly();
}

Maybe some other exception happened, and set the transaction in abort mode.


Maybe you have a case where you are setting the transaction to rollback and not logging the exception.

(Well.. maybe something on AS code is doing the similar behavior (not logging the exception). I don't think that's the case but it's not impossible).

If you have how to reproduce this, maybe you should look for more exceptions, debug it, add more logs.. don't know.

[clebert.suconic]

I remember a case where security was throwing exceptions causing that.

It was not directly related to this issue here, but I remember something like that.

Are your security configuration (Datasource... etc) properly configured?


Anyway.. this is just a guess... but worth verifying it.

[theoverlord]

I have the JmsXARealm configuration set as specified in the JBM installation guide:

 <application-policy name = "JmsXARealm">
 <authentication>
 <login-module code = "org.jboss.resource.security.ConfiguredIdentityLoginModule"
 flag = "required">
 <module-option name = "principal">guest</module-option>
 <module-option name = "userName">guest</module-option>
 <module-option name = "password">guest</module-option>
 <module-option name = "managedConnectionFactoryName">jboss.jca:service=TxCM,name=JmsXA</module-option>
 </login-module>
 </authentication>
 </application-policy>

The reported exception message does not always happen. If there were credential issues here or in the jmsdb-ds.xml file, it would fail every time I would think. I doubt it would even startup properly in that case.

[clebert.suconic]

I doubt it would even startup properly in that case.

Ok.. I was just guessing.. as I remember some other case I dealt with some time ago.

On that case, Messaging configuration on login-config was messed up, but I don't remember the exact problems I was seeing that time:

 <application-policy name="messaging">
 <authentication>
 <login-module code = "org.jboss.security.auth.spi.DatabaseServerLoginModule"
 flag = "required">
 <module-option name = "unauthenticatedIdentity">guest</module-option>
 <module-option name = "dsJndiName">java:/DefaultDS</module-option>
 <module-option name = "principalsQuery">SELECT PASSWD FROM JBM_USER WHERE USER_ID=?</module-option>
 <module-option name = "rolesQuery">SELECT ROLE_ID, 'Roles' FROM JBM_ROLE WHERE USER_ID=?</module-option>
 </login-module>
 </authentication>
 </application-policy>

But you should still look for what set the transaction into abort mode.
From your code side, look for places where you don't log exception and set the transaction as rollback/abort mode.

Or try to find a similar pattern where you could reproduce the case. If you provide us some testcase we will take a look.

[theoverlord]

I did notice this exception just before the first exception I mentioned. I don't see it all the time.

WARN com.arjuna.ats.jta.logging.loggerI18N - [com.arjuna.ats.internal.jta.resources.arjunacore.preparefailed] [com.arjuna.ats.internal.jta.resources.arjunacore.preparefailed] XAResourceRecord.prepare - prepare failed with exception java.lang.IllegalMonitorStateException
WARN com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.BasicAction_36] - BasicAction.End() - prepare phase of action-id -53eef977:b3fb:489cbb19:800 failed.
WARN com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.BasicAction_38] - Action Aborting
ERROR STDERR - java.lang.IllegalMonitorStateException
ERROR STDERR - at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:125)
ERROR STDERR - at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1102)
ERROR STDERR - at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:431)
ERROR STDERR - at org.jboss.resource.adapter.jms.JmsManagedConnection.unlock(JmsManagedConnection.java:401)
ERROR STDERR - at org.jboss.resource.adapter.jms.JmsXAResource.rollback(JmsXAResource.java:115)
ERROR STDERR - at org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper.rollback(JcaXAResourceWrapper.java:103)
ERROR STDERR - at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:391)
ERROR STDERR - at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3222)
ERROR STDERR - at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3200)
ERROR STDERR - at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:2211)
ERROR STDERR - at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1809)
ERROR STDERR - at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:88)
ERROR STDERR - at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
ERROR STDERR - at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1382)
ERROR STDERR - at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
ERROR STDERR - at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
ERROR STDERR - at org.jboss.jms.asf.StdServerSession.onMessage(StdServerSession.java:351)
ERROR STDERR - at org.jboss.jms.client.container.ClientConsumer.callOnMessage(ClientConsumer.java:160)
ERROR STDERR - at org.jboss.jms.client.container.SessionAspect.handleRun(SessionAspect.java:831)
ERROR STDERR - at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect14.invoke(SessionAspect14.java)
ERROR STDERR - at org.jboss.jms.client.delegate.ClientSessionDelegate$run_N8003352271541955702.invokeNext(ClientSessionDelegate$run_N8003352271541955702.java)
ERROR STDERR - at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
ERROR STDERR - at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
ERROR STDERR - at org.jboss.jms.client.delegate.ClientSessionDelegate$run_N8003352271541955702.invokeNext(ClientSessionDelegate$run_N8003352271541955702.java)
ERROR STDERR - at org.jboss.jms.client.delegate.ClientSessionDelegate.run(ClientSessionDelegate.java)
ERROR STDERR - at org.jboss.jms.client.JBossSession.run(JBossSession.java:199)
ERROR STDERR - at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:194)
ERROR STDERR - at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:761)
ERROR STDERR - at java.lang.Thread.run(Thread.java:595)
WARN com.arjuna.ats.arjuna.logging.arjLoggerI18N - [com.arjuna.ats.arjuna.coordinator.BasicAction_54] - Top-level abort of action -53eef977:b3fb:489cbb19:800 received TwoPhaseOutcome.FINISH_ERROR from <ClassName:RecordType.JTA_RECORD>

[clebert.suconic]

Maybe another symptom...


This exception is a bug IMO, as org.jboss.resource.adapter.jms.JmsXAResource.rollback is probably failing on the transaction event call,

But still a symptom as The TransactionManager decided to rollback.

You don't know yet why your code is calling rollback, right?

[theoverlord]

No, I don't know why this is happening.

But it happens most often on an initial startup of the server. Over time the frequency of this error diminishes.

This error seems to result in undelivered messages.

My solution is to resend messages that are undelivered and that works just fine.

[clebert.suconic]

Have you looked for this pattern in your code?

try
{

}
catch (Exception e)
{
 transaction.rolllback();
 // no logs?
}

If you want to find the root cause of that exception, you should get some help from someone on JCA.

[theoverlord]

Have you looked for this pattern in your code?

try
{

}
catch (Exception e)
{
 transaction.rolllback();
 // no logs?
}

If you want to find the root cause of that exception, you should get some help from someone on JCA.

I don't actually use that type of pattern.

In fact I don't do any explicit transaction management myself. For the MDB, it's container managed (set to REQUIRED).

[clebert.suconic]

Well... We can't do anything without a testcase.

Do you think you could provide one?


It looks something around JCA anyway.. but even them will need a testcase.

[theoverlord]

I'll try to get a testcase together.

[jhalliday]

https://jira.jboss.org/jira/browse/JBAS-5801