Arjuna Exception

[mohitanchlia]

We are seeing below exception and not sure why that should be occuring. We use last resource gambit in that Oracle is one phase commit and JMS is 2 phase commit. We see that this leaves our transaction in some inconsistent state where some of the updates occur in database. It looks like some problem with last resouse gambit.

2009-04-13 08:13:47,239 WARN [arjuna.logging.arjLoggerI18N:JMS SessionPool Worker-86] - [com.arjuna.ats.arjuna.coordinator.BasicAction_35] - End called illegally on atomic action a040242:e1c3:49d475b4:15cdb66
2009-04-13 08:13:47,470 ERROR [agency.core.AckProcessorBean:JMS SessionPool Worker-86] - Failed to process
javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] Could not commit transaction.
 at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1402)
 at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
 at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
 at org.jboss.ejb.EnterpriseContext$UserTransactionImpl.commit(EnterpriseContext.java:693)
 at com.intuit.engine.efp.efe.agency.core.AckProcessorBean.onMessage(AckProcessorBean.java:61)
 at sun.reflect.GeneratedMethodAccessor261.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.invocation.Invocation.performCall(Invocation.java:359)
 at org.jboss.ejb.MessageDrivenContainer$ContainerInterceptor.invoke(MessageDrivenContainer.java:495)
 at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:158)
 at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:63)
 at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:121)
 at org.jboss.ejb.plugins.AbstractTxInterceptorBMT.invokeNext(AbstractTxInterceptorBMT.java:173)
 at org.jboss.ejb.plugins.MessageDrivenTxInterceptorBMT.invoke(MessageDrivenTxInterceptorBMT.java:47)
 at org.jboss.ejb.plugins.MessageDrivenInstanceInterceptor.invoke(MessageDrivenInstanceInterceptor.java:116)
 at org.jboss.ejb.plugins.RunAsSecurityInterceptor.invoke(RunAsSecurityInterceptor.java:109)
 at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205)
 at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)
 at org.jboss.ejb.MessageDrivenContainer.internalInvoke(MessageDrivenContainer.java:402)
 at org.jboss.ejb.Container.invoke(Container.java:960)
 at org.jboss.ejb.plugins.jms.JMSContainerInvoker.invoke(JMSContainerInvoker.java:1014)
@

[adinn]

Ok,

There is a big clue in the output you provided:

2009-04-13 08:13:47,239 WARN [arjuna.logging.arjLoggerI18N:JMS SessionPool Worker-86] - [com.arjuna.ats.arjuna.coordinator.BasicAction_35] - End called illegally on atomic action a040242:e1c3:49d475b4:15cdb66
2009-04-13 08:13:47,470 ERROR [agency.core.AckProcessorBean:JMS SessionPool Worker-86] - Failed to process javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] Could not commit transaction.
. . .
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
at org.jboss.ejb.EnterpriseContext$UserTransactionImpl.commit(EnterpriseContext.java:693)
at com.intuit.engine.efp.efe.agency.core.AckProcessorBean.onMessage(AckProcessorBean.java:61

So, your transaction had already been aborted when your program called commit. This may be because of a timeout or may be for some other reason. Check your logs and your code to see if you can find more info.

[mohitanchlia]

Irrespective of what the reason was shouldn't Jboss TS rollback the transaction and not leave a transaction in inconsistent state. I am more worried about Jboss TS leaving transaction in inconsistent state. Why would that occur? What's the clue in the given output? I looked at the code of BasicAction and it looks like it failed while trying to commit. But still I don't understand why it left transaction in such a inconsistent state. Probably a bug in Jboss TS?

[adinn]

Irrespective of what the reason was shouldn't Jboss TS rollback the transaction and not leave a transaction in inconsistent state. I am more worried about Jboss TS leaving transaction in inconsistent state. Why would that occur? What's the clue in the given output? I looked at the code of BasicAction and it looks like it failed while trying to commit. But still I don't understand why it left transaction in such a inconsistent state. Probably a bug in Jboss TS?

I'm not certain what is going wrong but this is very unlikely to be to do with last resource optimizaton. The transaction was already aborted before your call to commit so the TS wil not have directed any of the resources to commit their changes.

Much more likely is a bug in the EJB code, or rather in HIbernate which underlies EJB. In older versions of the AS there have been cases where a transaction is rolled back because of a timeout yet the EJB code has failed to detect the rollback. Coinsequently, it has gone on to write changes to the DB outside of the failed transaction. See for example

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

This should have fixed in the JBossAS 4.2.3.GA release (although I think there may still be outstanding issues in cases where connections are released and then reobtained by Hibernate). Which version of AS are you using and which of JBossTS?

[mohitanchlia]

I agree that probably it is Hibernate. But I also question some more things. Jira issue "https://jira.jboss.org/jira/browse/JBAS-5189" points to the transaction manager. Isn't transaction manager part of JbossTS? In one transaction JbossTS coordinates with resource manager and everythings needs to be listed and coordincated with JbossTS, so if there was a timeout wouldn't it get coordinated with Oracle's resource manager? How can hibernate start it's own transaction within another transaction and still commit the code?Isn't that disallowed?

Below issue may have been because of the timeout but I think there is more to it because generally when we get timeout we see "multiple threads active within it" message. But in this case we saw "End Called illegally". So if JbossTS is coordinating everything then why such inconsistency? Any ideas, suggestions?

[adinn]

The JIRA may refer to the Transaction Manager but that does not mean the problem is there. It refers is a known issue in Hibernate. Hibernate is not part of the Transaction Manager. If you need more convincing then you have a lot of code to read.

Ok, ok, . . . I'll save you a lot of reading. Hibernate does not start its own transactions. It performs flushes to a database using a connection obtained when the transaction started by the Transaction Manager is still valid. After the Transaction Manager detects the timeout and rolls back the transaction Hibernate tries to flush more data. The error happens because Hibernate does not check the connection to see if it is still associated with a transaction. A disassociated connection reverts to autocommit mode i.e. each database operation is commited immediately by the DBMS without the need for the caller to be inside a transaction. So, the flushes made after the timeout occur outside the aborted transaction but still get written to the DB. This is a problem between the AS, which manages connections, and Hibernate which drives connections directly.

The 'End called illegally' error occurs because your program tries to call commit after the transaction has been aborted. This is not inconsistent. You should receive an error when you try to commit an aborted transaction. It is the behaviour of Hibernate which is inconsistent. Hibernate should have thrown an error the first time it tried to flush data to the DBMS after the timeout but it didn't because of the bug.

[mohitanchlia]

Thanks. So if hibernate continues to flush data then when does it leave the transaction in half committed state. What I saw was that it committed only some rows.

Thanks for the explanation.

[adinn]

So if hibernate continues to flush data then when does it leave the transaction in half committed state. What I saw was that it committed only some rows.

This is what you would expect. The changes made inside the TX before it was rolled back will not be committed to the database because of the rollback. However, the changes made by Hibernate after the rollback using autocommit will be visible. So you should get a half-baked outcome.