qpid-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Robbie Gemmell <robbie.gemm...@gmail.com>
Subject Re: XA_RBTIMEOUT
Date Tue, 10 Jul 2012 22:16:11 GMT
Hi Joey,

I have just added some additional logging on trunk around the brokers
handling of timeouts for the transaction branches to see if we can better
observe what is going on (see
http://svn.apache.org/viewvc?rev=1359916&view=rev ) . Could you update your
broker and try running it again? The full logs would be better than just
snippets so could you please compress and email them directly to me and
Rob, along with info such as how far into the run it starts doing it
(elapsed time and number of messages).

Would it be possible for you to strip your test case down to its simplest
form and send us any code / config / download links we could then use to
reproduce the setup as directly as possible?

Robbie

On 9 July 2012 15:33, Joey Daughtery <jdaughtery@t-sciences.com> wrote:

> All
> I am unable to attach the file due to size limitation of gmail.
>
> Below are the exceptions I am seeing in jboss server.log and qpid.log.
>
> server.log:
>
> 09:09:23,776 INFO  [org.apache.qpid.transport.ClientDelegate] (IoReceiver -
> /127.0.0.1:5672) The broker does not support the configured connection
> idle
> timeout of 120 sec, using the brokers max supported value of 0 sec instead.
> 09:09:26,019 INFO  [org.apache.qpid.client.AMQConnection]
> (http--0.0.0.0-8080-1) Connection 11 now connected from /127.0.0.1:49705to
> /127.0.0.1:5672
> 09:09:28,157 WARN  [com.arjuna.ats.jta] (http--0.0.0.0-8080-1)
> ARJUNA016039: onePhaseCommit on < formatId=131077, gtrid_length=29,
> bqual_length=36, tx_uid=0:ffff7f000001:-ce4aa9e:4ffad703:1d, node_name=1,
> branch_uid=0:ffff7f000001:-ce4aa9e:4ffad703:1f, subordinatenodename=null,
> eis_name=java:/QpidJMSXA > (XAResourceWrapperImpl@222411d2
> [xaResource=org.apache.qpid.ra.QpidRAXAResource@395ad219 pad=false
> overrideRmValue=false productName=Qpid productVersion=2.0
> jndiName=java:/QpidJMSXA]) 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.rollback(XAResourceImpl.java:384)
> [qpid-client-0.17.jar:]
> at org.apache.qpid.ra.QpidRAXAResource.rollback(QpidRAXAResource.java:159)
> at
>
> org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.rollback(XAResourceWrapperImpl.java:171)
> at
>
> com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelOnePhaseCommit(XAResourceRecord.java:669)
> at
>
> com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2283)
> at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1466)
> 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.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
>
> org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:232)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
> org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:304)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
>
> org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:190)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
>
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
>
> org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:80)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
>
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
>
> org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
>
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
>
> org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
>
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
>
> org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
> [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
> at
>
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
>
> org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)
> [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
> at
>
> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at
>
> org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
> [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
> at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165)
> [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
> at
>
> org.jboss.as.ejb3.remote.LocalEjbReceiver.processInvocation(LocalEjbReceiver.java:179)
> [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
> at
>
> org.jboss.ejb.client.EJBClientInvocationContext.sendRequest(EJBClientInvocationContext.java:179)
> [jboss-ejb-client-1.0.5.Final.jar:1.0.5.Final]
> at
>
> org.jboss.ejb.client.TransactionInterceptor.handleInvocation(TransactionInterceptor.java:43)
> [jboss-ejb-client-1.0.5.Final.jar:1.0.5.Final]
> at
>
> org.jboss.ejb.client.EJBClientInvocationContext.sendRequest(EJBClientInvocationContext.java:181)
> [jboss-ejb-client-1.0.5.Final.jar:1.0.5.Final]
> at
>
> org.jboss.ejb.client.ReceiverInterceptor.handleInvocation(ReceiverInterceptor.java:128)
> [jboss-ejb-client-1.0.5.Final.jar:1.0.5.Final]
> at
>
> org.jboss.ejb.client.EJBClientInvocationContext.sendRequest(EJBClientInvocationContext.java:181)
> [jboss-ejb-client-1.0.5.Final.jar:1.0.5.Final]
> at
>
> org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:136)
> [jboss-ejb-client-1.0.5.Final.jar:1.0.5.Final]
> at
>
> org.jboss.ejb.client.EJBInvocationHandler.doInvoke(EJBInvocationHandler.java:121)
> [jboss-ejb-client-1.0.5.Final.jar:1.0.5.Final]
> at
>
> org.jboss.ejb.client.EJBInvocationHandler.invoke(EJBInvocationHandler.java:104)
> [jboss-ejb-client-1.0.5.Final.jar:1.0.5.Final]
> at $Proxy28.process(Unknown Source) at
>
> com.tst.iharvest.rest.ActivityResource.postActivity(ActivityResource.java:261)
> 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.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:155)
> [resteasy-jaxrs-2.3.2.Final.jar:]
> at
>
> org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:257)
> [resteasy-jaxrs-2.3.2.Final.jar:]
> at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:222)
> [resteasy-jaxrs-2.3.2.Final.jar:]
> at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:211)
> [resteasy-jaxrs-2.3.2.Final.jar:]
> at
>
> org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:525)
> [resteasy-jaxrs-2.3.2.Final.jar:]
> at
>
> org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:502)
> [resteasy-jaxrs-2.3.2.Final.jar:]
> at
>
> org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119)
> [resteasy-jaxrs-2.3.2.Final.jar:]
> at
>
> org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208)
> [resteasy-jaxrs-2.3.2.Final.jar:]
> at
>
> org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55)
> [resteasy-jaxrs-2.3.2.Final.jar:]
> at
>
> org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50)
> [resteasy-jaxrs-2.3.2.Final.jar:]
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
> [jboss-servlet-api_3.0_spec-1.0.0.Final.jar:1.0.0.Final]
> at
>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329)
> at
>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)
> at
>
> org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:163)
> at
>
> org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
> at
>
> org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
> at
>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280)
> at
>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)
> at
>
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275)
> at
>
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161)
> at
>
> org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153)
> at
>
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155)
> at
>
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
> at
>
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
> at
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368)
> at
>
> org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:897)
> at
>
> org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:626)
> at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:2039)
> at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_32]
>
> qpid.log:
>
> (Logger.java:54) - ID: [1] 8
> 2012-07-09 09:09:28,154 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - SEND: [conn:7d1c19e6] ch=1 id=1
> ExecutionResult(commandId=8, value=XaResult(status=XA_RBTIMEOUT))
> 2012-07-09 09:09:28,154 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - FLUSH: [conn:7d1c19e6]
> 2012-07-09 09:09:28,155 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - ssn:"75dba681-a0b5-415f-9649-f7a07c6d4cf4"
> processed([8,8]) 7 7
> 2012-07-09 09:09:28,155 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - {[0, 7]}
> 2012-07-09 09:09:28,155 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - RECV: [conn:7d1c19e6] ch=1
> DtxRollback(xid=Xid(format=131077, globalId=[B@2d388e5e,
> branchId=[B@5c0ad483))
> 2012-07-09 09:09:28,156 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - ID: [1] 9
> 2012-07-09 09:09:28,156 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - SEND: [conn:7d1c19e6] ch=1 id=2
> ExecutionResult(commandId=9, value=XaResult(status=XA_RBTIMEOUT))
> 2012-07-09 09:09:28,156 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - FLUSH: [conn:7d1c19e6]
> 2012-07-09 09:09:28,156 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - ssn:"75dba681-a0b5-415f-9649-f7a07c6d4cf4"
> processed([9,9]) 8 8
> 2012-07-09 09:09:28,157 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - {[0, 8]}
> 2012-07-09 09:09:28,966 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - RECV: [conn:7d1c19e6] ch=1
> DtxStart(xid=Xid(format=131077, globalId=[B@4b0613aa, branchId=[B@7bf52460
> ))
> 2012-07-09 09:09:28,967 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - ID: [1] 10
> 2012-07-09 09:09:28,967 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - SEND: [conn:7d1c19e6] ch=1 id=3
> ExecutionResult(commandId=10, value=XaResult(status=XA_OK))
> 2012-07-09 09:09:28,967 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - FLUSH: [conn:7d1c19e6]
> 2012-07-09 09:09:28,968 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - ssn:"75dba681-a0b5-415f-9649-f7a07c6d4cf4"
> processed([10,10]) 9 9
> 2012-07-09 09:09:28,968 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - {[0, 9]}
> 2012-07-09 09:09:28,969 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - RECV: [conn:7d1c19e6] ch=1
> DtxSetTimeout(xid=Xid(format=131077, globalId=[B@1b275a34,
> branchId=[B@349319d9), timeout=300)
> 2012-07-09 09:09:28,969 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - ID: [1] 11
> 2012-07-09 09:09:28,969 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - ssn:"75dba681-a0b5-415f-9649-f7a07c6d4cf4"
> processed([11,11]) 10 10
> 2012-07-09 09:09:28,970 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - {[0, 10]}
> 2012-07-09 09:09:28,970 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - RECV: [conn:7d1c19e6] ch=1 [S] ExecutionSync()
> 2012-07-09 09:09:28,970 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - ID: [1] 12
> 2012-07-09 09:09:28,970 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - ssn:"75dba681-a0b5-415f-9649-f7a07c6d4cf4" synced to 12
> 2012-07-09 09:09:28,971 DEBUG [IoReceiver - /127.0.0.1:49705]
> (Logger.java:54) - ssn:"75dba681-a0b5-415f-9649-f7a07c6d4cf4"
> processed([12,12]) 12 11
> 2012-07-09 09:09:28,971 DEBUG [IoReceiver - /127.0.0.1:49705] (
>
> Thanks
>
> Joe
>
>
>
> On Mon, Jul 9, 2012 at 8:51 AM, Joey Daughtery <jdaughtery@t-sciences.com
> >wrote:
>
> > All
> > Thanks for the response.  I was out on vacation last week moving.  I will
> > respond to all asap.
> >
> > FYI -- I am executing a test where I am calling a REST endpoint 5000
> times
> > synchronously.  Each call to the endpoint results in a TextMessage being
> > placed on the queue.  Note that the timeout does not occur for each
> > message.  It seems that it begins to occur about halfway through the
> > process last I remember.  I will rerun the test and try to note the
> message
> > count when the timeout first occurs.
> >
> > Note that the MDB receiving the messages simply upon receipt puts the
> > message in mongodb and returns.  I will send the logs after cleaning and
> > running a new test.
> >
> > Thanks
> >
> > Joe
> >
> >
>


<snip />

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message