Is this a fix in the broker or the rar deployable? Thanks
Joe On Wed, Jun 27, 2012 at 5:09 PM, Rob Godfrey <[email protected]>wrote: > Applied a change to trunk that will hopefully fix this issue, > > Cheers, > Rob > > On 27 June 2012 22:30, Robbie Gemmell <[email protected]> wrote: > > 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] > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > >
