Bug in HornetQ or API misuse?
_sst_ Jul 16, 2012 2:38 PMFirst of all: I am NOT sure whether it is a bug. It is quite possible that it happens to be an API misuse. I am merely asking for advices/suggestions on what might be causing it.
While running jBoss 6.1.0 (community edition) with HornetQ 2.2.5 from time to time we get a very interesting exception:
2012-04-04 11:18:49,553 ERROR [org.hornetq.core.client.impl.ClientSessionImpl] (Thread-2912 (group:HornetQ-client-global-threads-1107999515)) XA operation failed Cannot start, session is already doing work in a transaction null code:-6
2012-04-04 11:18:49,556 WARN [com.arjuna.ats.jta] (Thread-2912 (group:HornetQ-client-global-threads-1107999515)) ARJUNA-16061 TransactionImple.enlistResource - XAResource.start returned: XAException.XAER_PROTO for < formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffffac1f7e01:126a:4f7b4fce:7b68, node_name=1, branch_uid=0:ffffac1f7e01:126a:4f7b4fce:7b69, eis_name=unknown eis name >: javax.transaction.xa.XAException
at org.hornetq.core.client.impl.ClientSessionImpl.start(ClientSessionImpl.java:1552) [:6.1.0.Final]
at org.hornetq.core.client.impl.DelegatingSession.start(DelegatingSession.java:507) [:6.1.0.Final]
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:629) [:6.1.0.Final]
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:390) [:6.1.0.Final]
at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.startTransaction(MessageInflowLocalProxy.java:399) [:1.7.21]
at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.before(MessageInflowLocalProxy.java:235) [:1.7.21]
at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:135) [:1.7.21]
at $Proxy205.beforeDelivery(Unknown Source) at org.hornetq.ra.inflow.HornetQMessageHandler.onMessage(HornetQMessageHandler.java:267) [:6.1.0.Final]
at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:866) [:6.1.0.Final]
at org.hornetq.core.client.impl.ClientConsumerImpl.access$100(ClientConsumerImpl.java:44) [:6.1.0.Final]
at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:983) [:6.1.0.Final]
at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100) [:6.1.0.Final]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [:1.6.0_30]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [:1.6.0_30]
at java.lang.Thread.run(Thread.java:662) [:1.6.0_30]
ClientSessionImpl code suggests that exception happened in server-side code. Here is a relevant code fragment:
public void xaStart(final Xid xid) throws Exception
{
if (tx != null)
{
final String msg = "Cannot start, session is already doing work in a transaction " + tx.getXid();
throw new HornetQXAException(XAException.XAER_PROTO, msg);
}
else
{ ... }
}
While I was checking source code of this class I found out that this situation might be possible: constructor creates a default transaction if (boolean xa) argument is false.
At this point I see 2 possible solutions:
a) 'xa' argument should be set to true to avoid creating a default transaction
b) add check in ServerSessionImpl.xaStart() that takes this.xa in account. ( same is done for ServerSessionImpl.individualAcknowledge() and ServerSessionImpl.rollback() )
I tried googling it but couldn't find anything (i'd be glad to google it again if you hint me on proper keywords)
While running same code in my local instance of jBoss I stumbled upon another exception being thrown (might be related to https://community.jboss.org/message/566463#566463):
2012-03-22 16:32:49,830 WARN [org.hornetq.core.protocol.core.ServerSessionPacketHandler] (Thread-16 (group:HornetQ-remoting-threads1330942-21892593)) Sending unexpected exception to the client: java.lang.NullPointerException
at org.hornetq.core.server.impl.ServerSessionImpl.xaEnd(ServerSessionImpl.java:682) [:6.1.0.Final]
at org.hornetq.core.protocol.core.ServerSessionPacketHandler.handlePacket(ServerSessionPacketHandler.java:308) [:6.1.0.Final]
at org.hornetq.core.protocol.core.impl.ChannelImpl.handlePacket(ChannelImpl.java:474) [:6.1.0.Final]
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.doBufferReceived(RemotingConnectionImpl.java:496) [:6.1.0.Final]
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.bufferReceived(RemotingConnectionImpl.java:457) [:6.1.0.Final]
at org.hornetq.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:459) [:6.1.0.Final]
at org.hornetq.core.remoting.impl.invm.InVMConnection$1.run(InVMConnection.java:137) [:6.1.0.Final]
at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100) [:6.1.0.Final]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [:1.6.0_30]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [:1.6.0_30]
at java.lang.Thread.run(Thread.java:662) [:1.6.0_30]
2012-03-22 16:32:49,830 ERROR [org.hornetq.core.client.impl.ClientSessionImpl] (Thread-9 (group:HornetQ-client-global-threads-11522794)) Caught jmsexecptione : HornetQException[errorCode=0 message=null]
at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:286) [:6.1.0.Final]
at org.hornetq.core.client.impl.ClientSessionImpl.end(ClientSessionImpl.java:1275) [:6.1.0.Final]
at org.hornetq.core.client.impl.DelegatingSession.end(DelegatingSession.java:332) [:6.1.0.Final]
at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:588) [:6.1.0.Final]
at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2287) [:6.1.0.Final]
at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1452) [:6.1.0.Final]
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:99) [:6.1.0.Final]
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:159) [:6.1.0.Final]
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1158) [:6.1.0.Final]
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:119) [:6.1.0.Final]
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75) [:6.1.0.Final]
at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.endTransaction(MessageInflowLocalProxy.java:464) [:1.7.21]
at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.finish(MessageInflowLocalProxy.java:343) [:1.7.21]
at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.after(MessageInflowLocalProxy.java:259) [:1.7.21]
at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:140) [:1.7.21]
at $Proxy205.afterDelivery(Unknown Source) at org.hornetq.ra.inflow.HornetQMessageHandler.onMessage(HornetQMessageHandler.java:287) [:6.1.0.Final]
at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:866) [:6.1.0.Final]
at org.hornetq.core.client.impl.ClientConsumerImpl.access$100(ClientConsumerImpl.java:44) [:6.1.0.Final]
at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:983) [:6.1.0.Final]
at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100) [:6.1.0.Final]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [:1.6.0_30]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [:1.6.0_30]
at java.lang.Thread.run(Thread.java:662) [:1.6.0_30]
Here is the relevant code fragment:
public void xaEnd(final Xid xid) throws Exception
{
if (tx != null && tx.getXid().equals(xid))
{ ... }
....
}
I've added some crude logging capability that logs when an empty (xid=null) transaction is being created and it turns out that:
java.lang.Exception: [server] new Transaction() - hashCode(this), thread=Thread[Thread-12 (group:HornetQ-server-threads28104970-30661940),5,HornetQ-server-threads28104970-30661940]
at org.hornetq.core.transaction.impl.TransactionImpl.<init>(TransactionImpl.java:81)
at org.hornetq.core.server.impl.ServerSessionImpl.commit(ServerSessionImpl.java:614)
at org.hornetq.core.protocol.core.ServerSessionPacketHandler.handlePacket(ServerSessionPacketHandler.java:285)
at org.hornetq.core.protocol.core.impl.ChannelImpl.handlePacket(ChannelImpl.java:474)
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.doBufferReceived(RemotingConnectionImpl.java:496)
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.access$000(RemotingConnectionImpl.java:45)
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl$1.run(RemotingConnectionImpl.java:436)
at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
and right after that:
java.lang.Exception: [server] xaEnd: argXid=26169233, hashCode(tx)=32530158, hashCode(tx.xid)=0, thread=Thread[Thread-18 (group:HornetQ-remoting-threads18469713-8425294),5,HornetQ-remoting-threads18469713-8425294]
at org.hornetq.core.server.impl.ServerSessionImpl.xaEnd(ServerSessionImpl.java:690)
at org.hornetq.core.protocol.core.ServerSessionPacketHandler.handlePacket(ServerSessionPacketHandler.java:308)
at org.hornetq.core.protocol.core.impl.ChannelImpl.handlePacket(ChannelImpl.java:474)
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.doBufferReceived(RemotingConnectionImpl.java:496)
at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.bufferReceived(RemotingConnectionImpl.java:457)
at org.hornetq.core.remoting.server.impl.RemotingServiceImpl$DelegatingBufferHandler.bufferReceived(RemotingServiceImpl.java:459)
at org.hornetq.core.remoting.impl.invm.InVMConnection$1.run(InVMConnection.java:137)
at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
I have 2 guesses:
a) race condition: session object is being shared by different threads (commit() was called by Thread-12, while xaEnd() is called by Thread-18)
b) bug: commit() should create new transaction object only if '!xa' and set 'this.tx=null' otherwise ( same way like rollback() does )
I came up with a fix for (b) and attached a patch. It removes previous exception and exposes another one that I was getting before applying a patch anyway:
2012-07-16 14:26:13,423 WARN [com.arjuna.ats.jta] (Thread-7 (group:HornetQ-client-global-threads-23489525)) ARJUNA-16039 onePhaseCommit on < formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffffac1c2caa:126a:50045c1f:21, node_name=1, branch_uid=0:ffffac1c2caa:126a:50045c1f:23, eis_name=unknown eis name > (org.hornetq.core.client.impl.DelegatingSession@8dd70b) failed with exception XAException.XAER_PROTO: javax.transaction.xa.XAException
at org.hornetq.core.client.impl.ClientSessionImpl.end(ClientSessionImpl.java:1293) [:]
at org.hornetq.core.client.impl.DelegatingSession.end(DelegatingSession.java:332) [:]
at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:588) [:6.1.0.Final]
at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2287) [:6.1.0.Final]
at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1452) [:6.1.0.Final]
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:99) [:6.1.0.Final]
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:159) [:6.1.0.Final]
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1158) [:6.1.0.Final]
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:119) [:6.1.0.Final]
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75) [:6.1.0.Final]
at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.endTransaction(MessageInflowLocalProxy.java:464) [:1.7.21]
at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.finish(MessageInflowLocalProxy.java:343) [:1.7.21]
at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.after(MessageInflowLocalProxy.java:259) [:1.7.21]
at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:140) [:1.7.21]
at $Proxy154.afterDelivery(Unknown Source) at org.hornetq.ra.inflow.HornetQMessageHandler.onMessage(HornetQMessageHandler.java:287) [:6.1.0.Final]
at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:866) [:]
at org.hornetq.core.client.impl.ClientConsumerImpl.access$100(ClientConsumerImpl.java:44) [:]
at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:983) [:]
at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:100) [:]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [:1.6.0_27]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [:1.6.0_27]
at java.lang.Thread.run(Thread.java:662) [:1.6.0_27]
I'm trying to come up with some kind of reproducible test, but have no luck so far.
Any help and suggestions are greatly appreciated!
Thanks.