FYI: Rob has beaten me to it and raised a JIRA already (https://issues.apache.org/jira/browse/QPID-4091) so I suspect a fix will be forthcoming shortly ;)
Robbie On 27 June 2012 20:30, Robbie Gemmell <[email protected]> wrote: > Thanks Joe, > > This bit stuck out when I read it, causing me to go have a quick look > about the brokers handling of the DtxSetTimeout command and have a > quick read of the AMQP 0-10 specification: > > (Logger.java:54) - RECV: [conn:19a9bea3] ch=1 > DtxSetTimeout(xid=Xid(format=131077, globalId=[B@480c72ef, > branchId=[B@294dcddd), timeout=300) > > I think the problem is that the broker is using the incorrect units > (ms instead of the seconds specified in the 0-10 spec) for the timout > value and is prematurely timing out the branch as a result. Can you > try setting the timeout value to 0 (no timeout) or increasing it a > lot, and see how that goes? I'll raise a JIRA tomorrow to correct the > handling of the timeout value. > > Robbie > > On 27 June 2012 18:06, Joey Daughtery <[email protected]> wrote: >> Robbie >> I got the qpid log from the qpid server. It is very large, so here is a >> snippet from it. I don't see any stacktraces, but when I search the log >> for exception I see: >> >> >> 2012-06-27 12:31:44,509 DEBUG [IoReceiver - /127.0.0.1:59677] >> (Logger.java:54) - SEND: [conn:5043153c] ch=1 id=2243 >> ExecutionException(errorCode=ILLEGAL_STATE, commandId=2700, description=Xid >> Xid(format=131077, globalId=[B@5786ed37, branchId=[B@5b3fe2c5) not >> associated with the current session) >> 2012-06-27 12:31:44,509 DEBUG [IoReceiver - /127.0.0.1:59677] >> (Logger.java:54) - FLUSH: [conn:5043153c] >> >> >> >> ///other logging statements >> >> 2012-06-27 12:10:08,150 DEBUG [IoReceiver - /127.0.0.1:59668] >> (Logger.java:54) - RECV: [conn:76705d28] ch=1 DtxEnd(xid=Xid(format=131077, >> globalId=[B@34ee124f, branchId=[B@79f41bae)) >> 2012-06-27 12:10:08,151 DEBUG [IoReceiver - /127.0.0.1:59668] >> (Logger.java:54) - ID: [1] 1477 >> 2012-06-27 12:10:08,151 DEBUG [IoReceiver - /127.0.0.1:59668] >> (Logger.java:54) - SEND: [conn:76705d28] ch=1 id=1223 >> ExecutionResult(commandId=1477, value=XaResult(status=XA_RBTIMEOUT)) >> 2012-06-27 12:10:08,151 DEBUG [IoReceiver - /127.0.0.1:59668] >> (Logger.java:54) - FLUSH: [conn:76705d28] >> 2012-06-27 12:10:08,152 DEBUG [IoReceiver - /127.0.0.1:59668] >> (Logger.java:54) - ssn:"f3922eac-468a-4914-bb06-479618b2f71f" >> processed([1477,1477]) 1476 1476 >> 2012-06-27 12:10:08,152 DEBUG [IoReceiver - /127.0.0.1:59668] >> (Logger.java:54) - {[1280, 1476]} >> 2012-06-27 12:10:08,183 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - RECV: [conn:19a9bea3] ch=1 >> DtxStart(xid=Xid(format=131077, globalId=[B@9457b0f, branchId=[B@30921a8a)) >> 2012-06-27 12:10:08,183 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - ID: [1] 24410 >> 2012-06-27 12:10:08,183 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - SEND: [conn:19a9bea3] ch=1 id=7323 >> ExecutionResult(commandId=24410, value=XaResult(status=XA_OK)) >> 2012-06-27 12:10:08,183 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - FLUSH: [conn:19a9bea3] >> 2012-06-27 12:10:08,184 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - ssn:"b907fe3e-068a-4b9c-8cdb-d1c6fb947832" >> processed([24410,24410]) 24409 24409 >> 2012-06-27 12:10:08,184 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - {[24320, 24409]} >> 2012-06-27 12:10:08,184 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - RECV: [conn:19a9bea3] ch=1 >> DtxSetTimeout(xid=Xid(format=131077, globalId=[B@480c72ef, >> branchId=[B@294dcddd), timeout=300) >> 2012-06-27 12:10:08,184 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - ID: [1] 24411 >> 2012-06-27 12:10:08,185 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - ssn:"b907fe3e-068a-4b9c-8cdb-d1c6fb947832" >> processed([24411,24411]) 24410 24410 >> 2012-06-27 12:10:08,185 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - {[24320, 24410]} >> 2012-06-27 12:10:08,185 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - RECV: [conn:19a9bea3] ch=1 [S] ExecutionSync() >> 2012-06-27 12:10:08,185 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - ID: [1] 24412 >> 2012-06-27 12:10:08,185 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - ssn:"b907fe3e-068a-4b9c-8cdb-d1c6fb947832" synced to >> 24412 >> 2012-06-27 12:10:08,185 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - ssn:"b907fe3e-068a-4b9c-8cdb-d1c6fb947832" >> processed([24412,24412]) 24412 24411 >> 2012-06-27 12:10:08,185 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - {[24320, 24411]} >> 2012-06-27 12:10:08,186 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - SEND: [conn:19a9bea3] ch=1 >> SessionCompleted(commands={[24320, 24412]}) >> 2012-06-27 12:10:08,186 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - FLUSH: [conn:19a9bea3] >> 2012-06-27 12:10:08,186 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - SEND: [conn:19a9bea3] ch=1 >> SessionCompleted(commands={[24320, 24412]}) >> 2012-06-27 12:10:08,186 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - FLUSH: [conn:19a9bea3] >> 2012-06-27 12:10:08,187 DEBUG [IoReceiver - /127.0.0.1:59679] >> (Logger.java:54) - RECV: [conn:19a9bea3] ch=1 MessageTransfer(destination=, >> acceptMode=NONE, acquireMode=PRE_ACQUIRED) >> >> Joe >> >> >> >> Thanks >> >> Joe >> >> On Tue, Jun 26, 2012 at 4:52 PM, Joey Daughtery >> <[email protected]>wrote: >> >>> Robbie >>> I will look into the logging configuration. Here is an example of the >>> 404. I provided the exceptions that are occurring before and after it. >>> >>> 13:40:28,368 WARN [com.arjuna.ats.jta] (Dispatcher-0-Conn-298) >>> ARJUNA016036: commit on < formatId=131077, gtrid_length=29, >>> bqual_length=36, tx_uid=0:ffff7f000001:-1c492603:4fe9ed1a:76f1, >>> node_name=1, branch_uid=0:ffff7f000001:-1c492603:4fe9ed1a:76f2, >>> subordinatenodename=null, eis_name=unknown eis name > >>> (org.apache.qpid.client.XAResourceImpl@19917517) failed with exception >>> $XAException.XA_RBTIMEOUT: javax.transaction.xa.XAException >>> at >>> org.apache.qpid.client.XAResourceImpl.checkStatus(XAResourceImpl.java:507) >>> [qpid-client-0.17.jar:] >>> at org.apache.qpid.client.XAResourceImpl.commit(XAResourceImpl.java:112) >>> [qpid-client-0.17.jar:] >>> at >>> com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit(XAResourceRecord.java:451) >>> at >>> com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2753) >>> at >>> com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2669) >>> at >>> com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit(BasicAction.java:1804) >>> at >>> com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1495) >>> at >>> com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:98) >>> at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:164) >>> at >>> com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165) >>> at >>> com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:117) >>> 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.1.1.Final.jar:7.1.1.Final] >>> at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source) >>> [:1.6.0_32] >>> at >>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) >>> [rt.jar:1.6.0_32] >>> at java.lang.reflect.Method.invoke(Method.java:597) [rt.jar:1.6.0_32] >>> at >>> org.jboss.as.ejb3.inflow.AbstractInvocationHandler.handle(AbstractInvocationHandler.java:60) >>> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] >>> at >>> org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke(MessageEndpointInvocationHandler.java:136) >>> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] >>> at >>> org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:73) >>> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] >>> at $Proxy15.afterDelivery(Unknown Source) at >>> org.apache.qpid.ra.inflow.QpidMessageHandler.onMessage(QpidMessageHandler.java:217) >>> at >>> org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:751) >>> [qpid-client-0.17.jar:] >>> at >>> org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:141) >>> [qpid-client-0.17.jar:] >>> at >>> org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:725) >>> [qpid-client-0.17.jar:] >>> at >>> org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:186) >>> [qpid-client-0.17.jar:] >>> at >>> org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:54) >>> [qpid-client-0.17.jar:] >>> at >>> org.apache.qpid.client.AMQSession$Dispatcher.notifyConsumer(AMQSession.java:3475) >>> [qpid-client-0.17.jar:] >>> at >>> org.apache.qpid.client.AMQSession$Dispatcher.dispatchMessage(AMQSession.java:3414) >>> [qpid-client-0.17.jar:] >>> at >>> org.apache.qpid.client.AMQSession$Dispatcher.access$1000(AMQSession.java:3201) >>> [qpid-client-0.17.jar:] >>> at org.apache.qpid.client.AMQSession.dispatch(AMQSession.java:3194) >>> [qpid-client-0.17.jar:] >>> at >>> org.apache.qpid.client.message.UnprocessedMessage.dispatch(UnprocessedMessage.java:54) >>> [qpid-client-0.17.jar:] >>> at >>> org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:3337) >>> [qpid-client-0.17.jar:] >>> at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_32] >>> >>> 13:40:28,396 INFO [org.apache.qpid.client.AMQConnection] (IoReceiver - / >>> 127.0.0.1:5672) Closing AMQConnection due to >>> :org.apache.qpid.AMQException: ch=1 id=6 >>> ExecutionException(errorCode=NOT_FOUND, commandId=14, description=Unknown >>> xid Xid(format=131077, globalId=[B@48c612c3, branchId=[B@43f9e588)) >>> [error code 404: not found] >>> 13:40:28,397 WARN [org.apache.qpid.ra.inflow.QpidExceptionHandler] >>> (IoReceiver - /127.0.0.1:5672) Failure in Qpid activation >>> org.apache.qpid.ra.inflow.QpidActivationSpec(ra=org.apache.qpid.ra.QpidResourceAdapter@b847db1destination=java:jboss/exported/iHarvestQueue >>> destinationType=javax.jms.Queue ack=Auto-acknowledge durable=false >>> clientID=null user=null maxSession=10 connectionPerHandler=true): >>> javax.jms.JMSException: Exception thrown against AMQConnection: >>> Host: 127.0.0.1 >>> Port: 5672 >>> Virtual Host: test >>> Client ID: client_id >>> Active session count: 1: org.apache.qpid.AMQException: ch=1 id=6 >>> ExecutionException(errorCode=NOT_FOUND, commandId=14, description=Unknown >>> xid Xid(format=131077, globalId=[B@48c612c3, branchId=[B@43f9e588)) >>> [error code 404: not found] >>> at >>> org.apache.qpid.client.AMQConnection.exceptionReceived(AMQConnection.java:1226) >>> at >>> org.apache.qpid.client.AMQSession_0_10.setCurrentException(AMQSession_0_10.java:1057) >>> at >>> org.apache.qpid.client.AMQSession_0_10.exception(AMQSession_0_10.java:907) >>> at >>> org.apache.qpid.transport.SessionDelegate.executionException(SessionDelegate.java:182) >>> at >>> org.apache.qpid.transport.SessionDelegate.executionException(SessionDelegate.java:32) >>> at >>> org.apache.qpid.transport.ExecutionException.dispatch(ExecutionException.java:103) >>> at >>> org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:55) >>> at >>> org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:50) >>> at >>> org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:32) >>> at org.apache.qpid.transport.Method.delegate(Method.java:159) >>> at org.apache.qpid.transport.Session.received(Session.java:584) >>> at org.apache.qpid.transport.Connection.dispatch(Connection.java:421) >>> at >>> org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:64) >>> at >>> org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:40) >>> at >>> org.apache.qpid.transport.MethodDelegate.executionException(MethodDelegate.java:110) >>> at >>> org.apache.qpid.transport.ExecutionException.dispatch(ExecutionException.java:103) >>> at >>> org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:54) >>> at >>> org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:40) >>> at org.apache.qpid.transport.Method.delegate(Method.java:159) >>> at org.apache.qpid.transport.Connection.received(Connection.java:376) >>> at org.apache.qpid.transport.Connection.received(Connection.java:67) >>> at org.apache.qpid.transport.network.Assembler.emit(Assembler.java:97) >>> at >>> org.apache.qpid.transport.network.Assembler.assemble(Assembler.java:198) >>> at org.apache.qpid.transport.network.Assembler.frame(Assembler.java:131) >>> at org.apache.qpid.transport.network.Frame.delegate(Frame.java:128) >>> at org.apache.qpid.transport.network.Assembler.received(Assembler.java:102) >>> at >>> org.apache.qpid.transport.network.Assembler.received(Assembler.java:44) >>> at >>> org.apache.qpid.transport.network.InputHandler.next(InputHandler.java:189) >>> at >>> org.apache.qpid.transport.network.InputHandler.received(InputHandler.java:105) >>> at >>> org.apache.qpid.transport.network.InputHandler.received(InputHandler.java:44) >>> at >>> org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:152) >>> at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_32] >>> Caused by: org.apache.qpid.AMQException: ch=1 id=6 >>> ExecutionException(errorCode=NOT_FOUND, commandId=14, description=Unknown >>> xid Xid(format=131077, globalId=[B@48c612c3, branchId=[B@43f9e588)) >>> [error code 404: not found] >>> at >>> org.apache.qpid.client.AMQSession_0_10.setCurrentException(AMQSession_0_10.java:1054) >>> ... 30 more >>> >>> Thanks >>> >>> Joe >>> >>> On Tue, Jun 26, 2012 at 4:03 PM, Robbie Gemmell >>> <[email protected]>wrote: >>> >>>> Hi Joey, >>>> >>>> I just tried the change myself to confim it works as expected, causing >>>> a suitably overwhelming amount of debug logging during use. To be >>>> clear, it is broker side logging the change turns on which by default >>>> goes to the file $QPID_WORK/log/qpid.log (where QPID_WORK defaults to >>>> your homedir if you dont set it). >>>> >>>> You could also turn on client logging to get a matching set, by >>>> ensuring a suitable SLF4J binding and associated logging >>>> implementation is available and again setting the org.apache.qpid >>>> logger to debug. >>>> >>>> Can you post an example of the particular 404 exceptions you are seeing? >>>> >>>> Robbie >>>> >>>> On 26 June 2012 18:04, Joey Daughtery <[email protected]> wrote: >>>> > All >>>> > After making the modification to log4j.xml, I really did not see any >>>> DEBUG >>>> > statements. Also, there is an exception below the RBTIMEOUT that has an >>>> > error code of 409. Note that I also see some exceptions on occasion >>>> that >>>> > has an error code of 404 associated with qpid. >>>> > >>>> > 12:13:53,368 WARN [com.arjuna.ats.jta] (Dispatcher-0-Conn-1) >>>> ARJUNA016041: >>>> > prepare on < formatId=131077, gtrid_length=29, bqual_length=36, >>>> > tx_uid=0:ffff7f000001:-796e14cd:4fe9dbc6:43cc, node_name=1, >>>> > branch_uid=0:ffff7f000001:-796e14cd:4fe9dbc6:43cd, >>>> > subordinatenodename=null, eis_name=unknown eis name > >>>> > (org.apache.qpid.client.XAResourceImpl@1d25d8a0) failed with exception >>>> > XAException.XA_RBTIMEOUT: javax.transaction.xa.XAException >>>> > at >>>> > >>>> org.apache.qpid.client.XAResourceImpl.checkStatus(XAResourceImpl.java:507) >>>> > [qpid-client-0.17.jar:] >>>> > at org.apache.qpid.client.XAResourceImpl.end(XAResourceImpl.java:166) >>>> > [qpid-client-0.17.jar:] >>>> > at >>>> > >>>> com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelPrepare(XAResourceRecord.java:208) >>>> > at >>>> > >>>> com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2535) >>>> > at >>>> > >>>> com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2502) >>>> > at >>>> > >>>> com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2079) >>>> > at >>>> com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1472) >>>> > at >>>> > >>>> com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:98) >>>> > at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:164) >>>> > at >>>> > >>>> com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165) >>>> > at >>>> > >>>> com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:117) >>>> > 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.1.1.Final.jar:7.1.1.Final] >>>> > at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source) >>>> [:1.6.0_32] >>>> > at >>>> > >>>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) >>>> > [rt.jar:1.6.0_32] >>>> > at java.lang.reflect.Method.invoke(Method.java:597) [rt.jar:1.6.0_32] >>>> > at >>>> > >>>> org.jboss.as.ejb3.inflow.AbstractInvocationHandler.handle(AbstractInvocationHandler.java:60) >>>> > [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] >>>> > at >>>> > >>>> org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke(MessageEndpointInvocationHandler.java:136) >>>> > [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] >>>> > at >>>> > >>>> org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:73) >>>> > [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] >>>> > at $Proxy15.afterDelivery(Unknown Source) at >>>> > >>>> org.apache.qpid.ra.inflow.QpidMessageHandler.onMessage(QpidMessageHandler.java:217) >>>> > at >>>> > >>>> org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:751) >>>> > [qpid-client-0.17.jar:] >>>> > at >>>> > >>>> org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:141) >>>> > [qpid-client-0.17.jar:] >>>> > at >>>> > >>>> org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:725) >>>> > [qpid-client-0.17.jar:] >>>> > at >>>> > >>>> org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:186) >>>> > [qpid-client-0.17.jar:] >>>> > at >>>> > >>>> org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:54) >>>> > [qpid-client-0.17.jar:] >>>> > at >>>> > >>>> org.apache.qpid.client.AMQSession$Dispatcher.notifyConsumer(AMQSession.java:3475) >>>> > [qpid-client-0.17.jar:] >>>> > at >>>> > >>>> org.apache.qpid.client.AMQSession$Dispatcher.dispatchMessage(AMQSession.java:3414) >>>> > [qpid-client-0.17.jar:] >>>> > at >>>> > >>>> org.apache.qpid.client.AMQSession$Dispatcher.access$1000(AMQSession.java:3201) >>>> > [qpid-client-0.17.jar:] >>>> > at org.apache.qpid.client.AMQSession.dispatch(AMQSession.java:3194) >>>> > [qpid-client-0.17.jar:] >>>> > at >>>> > >>>> org.apache.qpid.client.message.UnprocessedMessage.dispatch(UnprocessedMessage.java:54) >>>> > [qpid-client-0.17.jar:] >>>> > at >>>> org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:3337) >>>> > [qpid-client-0.17.jar:] >>>> > at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_32] >>>> > >>>> > 12:13:53,387 WARN [com.arjuna.ats.arjuna] (Dispatcher-0-Conn-1) >>>> > ARJUNA012073: BasicAction.End() - prepare phase of action-id >>>> > 0:ffff7f000001:-796e14cd:4fe9dbc6:43cc failed. >>>> > 12:13:53,387 WARN [com.arjuna.ats.arjuna] (Dispatcher-0-Conn-1) >>>> > ARJUNA012075: Action Aborting >>>> > 12:13:53,393 INFO [org.apache.qpid.client.AMQConnection] (IoReceiver - >>>> / >>>> > 127.0.0.1:5672) Closing AMQConnection due to >>>> :org.apache.qpid.AMQException: >>>> > ch=1 id=724 ExecutionException(errorCode=ILLEGAL_STATE, commandId=878, >>>> > description=Xid Xid(format=131077, globalId=[B@4738fec2, >>>> > branchId=[B@6edd9715) not associated with the current session) [error >>>> code >>>> > 409: argument invalid] >>>> > 12:13:53,394 WARN [org.apache.qpid.ra.inflow.QpidExceptionHandler] >>>> > (IoReceiver - /127.0.0.1:5672) Failure in Qpid activation >>>> > >>>> org.apache.qpid.ra.inflow.QpidActivationSpec(ra=org.apache.qpid.ra.QpidResourceAdapter@1398a09edestination >>>> =java:jboss/exported/iHarvestQueue >>>> > destinationType=javax.jms.Queue ack=Auto-acknowledge durable=false >>>> > clientID=null user=null maxSession=10 connectionPerHandler=true): >>>> > javax.jms.JMSException: Exception thrown against AMQConnection: >>>> > Host: 127.0.0.1 >>>> > Port: 5672 >>>> > Virtual Host: test >>>> > Client ID: client_id >>>> > Active session count: 1: org.apache.qpid.AMQException: ch=1 id=724 >>>> > ExecutionException(errorCode=ILLEGAL_STATE, commandId=878, >>>> description=Xid >>>> > Xid(format=131077, globalId=[B@4738fec2, branchId=[B@6edd9715) not >>>> > associated with the current session) [error code 409: argument invalid] >>>> > at >>>> > >>>> org.apache.qpid.client.AMQConnection.exceptionReceived(AMQConnection.java:1226) >>>> > at >>>> > >>>> org.apache.qpid.client.AMQSession_0_10.setCurrentException(AMQSession_0_10.java:1057) >>>> > at >>>> > >>>> org.apache.qpid.client.AMQSession_0_10.exception(AMQSession_0_10.java:907) >>>> > at >>>> > >>>> org.apache.qpid.transport.SessionDelegate.executionException(SessionDelegate.java:182) >>>> > at >>>> > >>>> org.apache.qpid.transport.SessionDelegate.executionException(SessionDelegate.java:32) >>>> > at >>>> > >>>> org.apache.qpid.transport.ExecutionException.dispatch(ExecutionException.java:103) >>>> > at >>>> > >>>> org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:55) >>>> > at >>>> > >>>> org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:50) >>>> > at >>>> > >>>> org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:32) >>>> > at org.apache.qpid.transport.Method.delegate(Method.java:159) >>>> > at org.apache.qpid.transport.Session.received(Session.java:584) >>>> > at org.apache.qpid.transport.Connection.dispatch(Connection.java:421) >>>> > at >>>> > >>>> org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:64) >>>> > at >>>> > >>>> org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:40) >>>> > at >>>> > >>>> org.apache.qpid.transport.MethodDelegate.executionException(MethodDelegate.java:110) >>>> > at >>>> > >>>> org.apache.qpid.transport.ExecutionException.dispatch(ExecutionException.java:103) >>>> > at >>>> > >>>> org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:54) >>>> > at >>>> > >>>> org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:40) >>>> > at org.apache.qpid.transport.Method.delegate(Method.java:159) >>>> > at org.apache.qpid.transport.Connection.received(Connection.java:376) >>>> > at org.apache.qpid.transport.Connection.received(Connection.java:67) >>>> > at org.apache.qpid.transport.network.Assembler.emit(Assembler.java:97) >>>> > at >>>> org.apache.qpid.transport.network.Assembler.assemble(Assembler.java:198) >>>> > at org.apache.qpid.transport.network.Assembler.frame(Assembler.java:131) >>>> > at org.apache.qpid.transport.network.Frame.delegate(Frame.java:128) >>>> > at >>>> org.apache.qpid.transport.network.Assembler.received(Assembler.java:102) >>>> > at >>>> org.apache.qpid.transport.network.Assembler.received(Assembler.java:44) >>>> > at >>>> > >>>> org.apache.qpid.transport.network.InputHandler.next(InputHandler.java:189) >>>> > at >>>> > >>>> org.apache.qpid.transport.network.InputHandler.received(InputHandler.java:105) >>>> > at >>>> > >>>> org.apache.qpid.transport.network.InputHandler.received(InputHandler.java:44) >>>> > at >>>> org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:152) >>>> > at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_32] >>>> > Caused by: org.apache.qpid.AMQException: ch=1 id=724 >>>> > ExecutionException(errorCode=ILLEGAL_STATE, commandId=878, >>>> description=Xid >>>> > Xid(format=131077, globalId=[B@4738fec2, branchId=[B@6edd9715) not >>>> > associated with the current session) [error code 409: argument invalid] >>>> > at >>>> > >>>> org.apache.qpid.client.AMQSession_0_10.setCurrentException(AMQSession_0_10.java:1054) >>>> > ... 30 more >>>> > >>>> > Thanks >>>> > >>>> > Joe >>>> > >>>> > On Tue, Jun 26, 2012 at 11:42 AM, Robbie Gemmell >>>> > <[email protected]>wrote: >>>> > >>>> >> If you open the <broker.install.path>/etc/log4j.xml file and edit the >>>> >> value of the org.apache.qpid category as follows it should provide a >>>> >> lot of additional logging, which might help shed some light: >>>> >> >>>> >> From: >>>> >> <category additivity="true" name="org.apache.qpid"> >>>> >> <priority value="warn"/> >>>> >> </category> >>>> >> >>>> >> To: >>>> >> <category additivity="true" name="org.apache.qpid"> >>>> >> <priority value="debug"/> >>>> >> </category> >>>> >> >>>> >> (Alternatively, all the loggers can be manipulated while the broker is >>>> >> running by attaching JConsole or similar to it and using the >>>> >> LoggingManagement MBean) >>>> >> >>>> >> Robbie >>>> >> >>>> >> On 26 June 2012 16:07, Weston M. Price <[email protected]> wrote: >>>> >> > Note, while JCA is being used, the underly ResourceManager is timing >>>> >> out. Joe is using the Java Broker and I know XA support is fairly new. >>>> Is >>>> >> there any tracing mechanism we can use to isolate the problem? >>>> >> > >>>> >> > Regards, >>>> >> > >>>> >> > Weston >>>> >> > On Jun 26, 2012, at 10:55 AM, Joey Daughtery wrote: >>>> >> > >>>> >> >> All >>>> >> >> I am starting to see the following exception quite often. All the >>>> data >>>> >> >> that is sent to the queue is received by the mdb and stored. The >>>> test >>>> >> >> client that I have sending TextMessages to the queue sends one per >>>> 500ms >>>> >> >> and I am sending a total of 5000. When the MDB receives the >>>> >> TextMessage, >>>> >> >> it basically does an update on a record in mongodb. >>>> >> >> >>>> >> >> >>>> >> >> >>>> >> >> >>>> >> >> 08:44:19,524 WARN [com.arjuna.ats.jta] (Dispatcher-0-Conn-1) >>>> >> ARJUNA016036: >>>> >> >> commit on < formatId=131077, gtrid_length=29, bqual_length=36, >>>> >> >> tx_uid=0:ffff7f000001:61f68a5e:4fe9ae65:13, node_name=1, >>>> >> >> branch_uid=0:ffff7f000001:61f68a5e:4fe9ae65:14, >>>> >> subordinatenodename=null, >>>> >> >> eis_name=unknown eis name > >>>> >> (org.apache.qpid.client.XAResourceImpl@6fe03f3b) >>>> >> >> failed with exception $XAException.XA_RBTIMEOUT: >>>> >> >> javax.transaction.xa.XAException >>>> >> >> at >>>> >> >> >>>> >> >>>> org.apache.qpid.client.XAResourceImpl.checkStatus(XAResourceImpl.java:507) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at >>>> org.apache.qpid.client.XAResourceImpl.commit(XAResourceImpl.java:112) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at >>>> >> >> >>>> >> >>>> com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit(XAResourceRecord.java:451) >>>> >> >> at >>>> >> >> >>>> >> >>>> com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2753) >>>> >> >> at >>>> >> >> >>>> >> >>>> com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2669) >>>> >> >> at >>>> >> >> >>>> >> >>>> com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit(BasicAction.java:1804) >>>> >> >> at >>>> >> >>>> com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1495) >>>> >> >> at >>>> >> >> >>>> >> >>>> com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:98) >>>> >> >> at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:164) >>>> >> >> at >>>> >> >> >>>> >> >>>> com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165) >>>> >> >> at >>>> >> >> >>>> >> >>>> com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:117) >>>> >> >> 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.1.1.Final.jar:7.1.1.Final] >>>> >> >> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) >>>> >> >> [rt.jar:1.6.0_32] >>>> >> >> at >>>> >> >> >>>> >> >>>> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) >>>> >> >> [rt.jar:1.6.0_32] >>>> >> >> at >>>> >> >> >>>> >> >>>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) >>>> >> >> [rt.jar:1.6.0_32] >>>> >> >> at java.lang.reflect.Method.invoke(Method.java:597) >>>> [rt.jar:1.6.0_32] >>>> >> >> at >>>> >> >> >>>> >> >>>> org.jboss.as.ejb3.inflow.AbstractInvocationHandler.handle(AbstractInvocationHandler.java:60) >>>> >> >> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] >>>> >> >> at >>>> >> >> >>>> >> >>>> org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke(MessageEndpointInvocationHandler.java:136) >>>> >> >> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] >>>> >> >> at >>>> >> >> >>>> >> >>>> org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:73) >>>> >> >> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] >>>> >> >> at $Proxy15.afterDelivery(Unknown Source) at >>>> >> >> >>>> >> >>>> org.apache.qpid.ra.inflow.QpidMessageHandler.onMessage(QpidMessageHandler.java:217) >>>> >> >> at >>>> >> >> >>>> >> >>>> org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:751) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at >>>> >> >> >>>> >> >>>> org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:141) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at >>>> >> >> >>>> >> >>>> org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:725) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at >>>> >> >> >>>> >> >>>> org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:186) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at >>>> >> >> >>>> >> >>>> org.apache.qpid.client.BasicMessageConsumer_0_10.notifyMessage(BasicMessageConsumer_0_10.java:54) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at >>>> >> >> >>>> >> >>>> org.apache.qpid.client.AMQSession$Dispatcher.notifyConsumer(AMQSession.java:3475) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at >>>> >> >> >>>> >> >>>> org.apache.qpid.client.AMQSession$Dispatcher.dispatchMessage(AMQSession.java:3414) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at >>>> >> >> >>>> >> >>>> org.apache.qpid.client.AMQSession$Dispatcher.access$1000(AMQSession.java:3201) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at org.apache.qpid.client.AMQSession.dispatch(AMQSession.java:3194) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at >>>> >> >> >>>> >> >>>> org.apache.qpid.client.message.UnprocessedMessage.dispatch(UnprocessedMessage.java:54) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at >>>> >> org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:3337) >>>> >> >> [qpid-client-0.17.jar:] >>>> >> >> at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_32] >>>> >> >> >>>> >> >> Thanks >>>> >> >> >>>> >> >> Joe >>>> >> > >>>> >> > >>>> >> > --------------------------------------------------------------------- >>>> >> > To unsubscribe, e-mail: [email protected] >>>> >> > For additional commands, e-mail: [email protected] >>>> >> > >>>> >> >>>> >> --------------------------------------------------------------------- >>>> >> To unsubscribe, e-mail: [email protected] >>>> >> For additional commands, e-mail: [email protected] >>>> >> >>>> >> >>>> >>>> --------------------------------------------------------------------- >>>> To unsubscribe, e-mail: [email protected] >>>> For additional commands, e-mail: [email protected] >>>> >>>> >>> --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
