Bug 1082652
| Summary: | Transaction started in MDB can't be committed when previous transaction was started on client with jboss ejb remoting | ||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | [JBoss] JBoss Enterprise Application Platform 6 | Reporter: | Ondrej Chaloupka <ochaloup> | ||||||||||
| Component: | HornetQ | Assignee: | Clebert Suconic <csuconic> | ||||||||||
| Status: | CLOSED NOTABUG | QA Contact: | Ondrej Chaloupka <ochaloup> | ||||||||||
| Severity: | high | Docs Contact: | Russell Dickenson <rdickens> | ||||||||||
| Priority: | unspecified | ||||||||||||
| Version: | 6.3.0 | CC: | csuconic, hhovsepy, mnovak, msvehla, ochaloup | ||||||||||
| Target Milestone: | --- | ||||||||||||
| Target Release: | --- | ||||||||||||
| Hardware: | Unspecified | ||||||||||||
| OS: | Unspecified | ||||||||||||
| Whiteboard: | |||||||||||||
| Fixed In Version: | Doc Type: | Bug Fix | |||||||||||
| Doc Text: | Story Points: | --- | |||||||||||
| Clone Of: | Environment: | ||||||||||||
| Last Closed: | 2014-07-08 13:24:14 UTC | Type: | Bug | ||||||||||
| Regression: | --- | Mount Type: | --- | ||||||||||
| Documentation: | --- | CRM: | |||||||||||
| Verified Versions: | Category: | --- | |||||||||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||||||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||||||||
| Embargoed: | |||||||||||||
| Attachments: |
|
||||||||||||
Created attachment 880788 [details]
jta requires_new server.log
Created attachment 880789 [details]
jts requires server.log
This issue could be already reproduced with EAP 6.2.0.GA. Created attachment 902145 [details]
server.log from 6.3.0.ER5
I'm still hitting the issue - now for 6.3.0.ER5 there is a bit different exception but the reason seems to be the same.
The exception message is here:
WARN [com.arjuna.ats.jta] (Thread-0 (HornetQ-client-global-threads-140932677)) ARJUNA016041: prepare on < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:25699049:538efd3e:27, node_name=1, branch_uid=0:ffff7f000001:25699049:538efd3e:28, subordinatenodename=null, eis_name=unknown eis name > (DelegatingSession [session=ClientSessionImpl [name=05309528-ebd8-11e3-b3ac-a3cc7d7c32ba, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=03eaf5bd-ebd8-11e3-b3ac-a3cc7d7c32ba, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=03eaf5bd-ebd8-11e3-b3ac-a3cc7d7c32ba, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], metaData=(resource-adapter=inbound,jms-session=,)]@2ae13b5e]) failed with exception -: org.hornetq.api.core.HornetQInterruptedException: java.lang.InterruptedException
at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:363)
at org.hornetq.core.client.impl.ClientSessionImpl.end(ClientSessionImpl.java:1469)
at org.hornetq.core.client.impl.DelegatingSession.end(DelegatingSession.java:331)
at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:208) [jbossjts-jacorb-4.17.20.Final-redhat-1.jar:4.17.20.Final-redhat-1]
at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2522) [jbossjts-jacorb-4.17.20.Final-redhat-1.jar:4.17.20.Final-redhat-1]
at com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2489) [jbossjts-jacorb-4.17.20.Final-redhat-1.jar:4.17.20.Final-redhat-1]
at com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2066) [jbossjts-jacorb-4.17.20.Final-redhat-1.jar:4.17.20.Final-redhat-1]
at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1481) [jbossjts-jacorb-4.17.20.Final-redhat-1.jar:4.17.20.Final-redhat-1]
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:98) [jbossjts-jacorb-4.17.20.Final-redhat-1.jar:4.17.20.Final-redhat-1]
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162) [jbossjts-jacorb-4.17.20.Final-redhat-1.jar:4.17.20.Final-redhat-1]
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1189) [jbossjts-jacorb-4.17.20.Final-redhat-1.jar:4.17.20.Final-redhat-1]
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126) [jbossjts-jacorb-4.17.20.Final-redhat-1.jar:4.17.20.Final-redhat-1]
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.afterDelivery(MessageEndpointInvocationHandler.java:72) [jboss-as-ejb3-7.4.0.Final-redhat-13.jar:7.4.0.Final-redhat-13]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_60]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_60]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_60]
at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_60]
at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.handle(AbstractInvocationHandler.java:60) [jboss-as-ejb3-7.4.0.Final-redhat-13.jar:7.4.0.Final-redhat-13]
at org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke(MessageEndpointInvocationHandler.java:136) [jboss-as-ejb3-7.4.0.Final-redhat-13.jar:7.4.0.Final-redhat-13]
at org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:73) [jboss-as-ejb3-7.4.0.Final-redhat-13.jar:7.4.0.Final-redhat-13]
at com.sun.proxy.$Proxy20.afterDelivery(Unknown Source)
at org.hornetq.ra.inflow.HornetQMessageHandler.onMessage(HornetQMessageHandler.java:337)
at org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage(ClientConsumerImpl.java:1117)
at org.hornetq.core.client.impl.ClientConsumerImpl.access$500(ClientConsumerImpl.java:57)
at org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run(ClientConsumerImpl.java:1252)
at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:105)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_60]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_60]
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_60]
Caused by: java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2164) [rt.jar:1.7.0_60]
at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:359)
... 29 more
It looks like something is shutting down the server whilst a transaction is preparing the JMS resource. Hornetq interrupts resources before shutting down. Narayana does not handle Runtime exceptions (but simply logs them and propagates the error seen in the test). Later versions of hornetq now raise proper XA exceptions which Narayana will handle correctly (as per the XA spec). The version being tested is HornetQ_2.3.19.Final-redhat-1 but the fix was only introduced in HornetQ_2_4_0_Final. Ondrej, how should we proceed with this one? Hi Mike, if it's trouble of HornetQ component then I'm moving this bug to HornetQ. As 2.4.x version is part of WildFly I think that there will be needed some backport of the fix to 2.3.x branch for EAP 6.4. Ondra It's not a bug.. if you shutdown the server we send interrupts to the resource adapter... otherwise there are scenarios where the server just freezes and never shutdown. (e.g. when waiting for certain things that will never complete since the server is shutting down). Hi Clebert, I think that the point here is what exception is used for interrupting the RA. In new version of HornetQ the XAException is used for TM correctly process the RA unavailability. Could be possible to backport the exception handling from 2.4.x branch to 2.3.x branch which will (probably) go to EAP 6.4? Ondra We've checked with Mirek the commit log and the change that Mike asked for is already backported. I've rechecked the results of the test and I found that this was rather test issue then the bug in Hornet. Closing as not a bug. Thanks for help. |
Created attachment 880787 [details] jta required server.log We found that there is problem with committing transaction started by MDB when the initial transaction - transaction started by method that sent msg to queue where the MDB is bound to - was started on client connected with jboss ejb remoting. The same scenario works when the JTS transaction and IIOP client connection is used. The same scenario works when the transaction is started at server side. Test flow: 1) client starts transaction 2) client calls server method (TransactionAttributeType.MANDATORY) which creates message producer and sends text message to input queue 3) MDB is bound to input queue and the message is received 4) MDB enlist one more XA resource (test xa resource) 5) MDB sends message to output queue 6) test checks whether message is in output queue and that 2pc was processed on the test xa resource It seems that the client transaction is suspended on the server side but then it's not correctly awaken. The message driven bean is annotated with: TransactionAttributeType.REQUIRED I've tried to change to TransactionAttributeType.REQUIRES_NEW it changed the behavior just slightly in way that there was created brand new transaction that was tried to be aborted (rolled back) which failed. But the the cause exception message is the same. The exception message is: WARN [com.arjuna.ats.jta] (Thread-2 (HornetQ-client-global-threads-39329233)) ARJUNA016041: prepare on < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:6d5ac93c:5339280e:26, node_name=1, branch_uid=0:ffff7f000001:6d5ac93c:5339280e:27, subordinatenodename=null, eis_name=unknown eis name > (DelegatingSession [session=ClientSessionImpl [name=fa71d121-b8ae-11e3-b4a8-9b998317edfe, username=null, closed=false, factory = ClientSessionFactoryImpl [serverLocator=ServerLocatorImpl [initialConnectors=[TransportConfiguration(name=f9288835-b8ae-11e3-b4a8-9b998317edfe, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0], discoveryGroupConfiguration=null], connectorConfig=TransportConfiguration(name=f9288835-b8ae-11e3-b4a8-9b998317edfe, factory=org-hornetq-core-remoting-impl-invm-InVMConnectorFactory) ?server-id=0, backupConfig=null], metaData=(resource-adapter=inbound,jms-session=,)]@36a4646e]) failed with exception -: org.hornetq.api.core.HornetQInterruptedException: java.lang.InterruptedException at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:363) As I wanted to know whether it could not be problem of HornetQ messaging I've checked the behavior on WSMQ and the error is the same. You can check the server log which is attached. For comparision I'm adding server.log when transactions are running on jts. I'm not sure whether this is issue rather of transaction manager or jboss remoting but I'm putting that as first under transaction manager.