Return-Path: X-Original-To: apmail-qpid-users-archive@www.apache.org Delivered-To: apmail-qpid-users-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id E2C3CD23A for ; Tue, 10 Jul 2012 22:16:39 +0000 (UTC) Received: (qmail 83824 invoked by uid 500); 10 Jul 2012 22:16:39 -0000 Delivered-To: apmail-qpid-users-archive@qpid.apache.org Received: (qmail 83802 invoked by uid 500); 10 Jul 2012 22:16:39 -0000 Mailing-List: contact users-help@qpid.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: users@qpid.apache.org Delivered-To: mailing list users@qpid.apache.org Received: (qmail 83793 invoked by uid 99); 10 Jul 2012 22:16:39 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 10 Jul 2012 22:16:39 +0000 X-ASF-Spam-Status: No, hits=1.5 required=5.0 tests=HTML_MESSAGE,NORMAL_HTTP_TO_IP,RCVD_IN_DNSWL_LOW,SPF_PASS,WEIRD_PORT X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of robbie.gemmell@gmail.com designates 74.125.82.170 as permitted sender) Received: from [74.125.82.170] (HELO mail-we0-f170.google.com) (74.125.82.170) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 10 Jul 2012 22:16:32 +0000 Received: by weyr1 with SMTP id r1so313251wey.15 for ; Tue, 10 Jul 2012 15:16:12 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :content-type; bh=SUYJRSe0vibkY6M9l+Faw/n/ehxew6kV4B+3rWb4aH4=; b=CymN8hu0EhCJC9/c78qFMSp4Ad6euZdJwlDZu/5ZAjEPbKD7zWGCdagN4jX/awF8lI wn5afCkK2ooERnCvfTJZESOly/VJlREA80NTTTzpfKFTI2PJXvkYaEKe9Ibk1g+b7Nsu RzY2W+GiYZ0z5k7vjHpANxQmrbEglUdk52OMtYu+GeRxp8kBLpwPJSCrsYsP+8RJkJBN vqkozVbHeXxVHWNtWYcjJzizYKDURxot6gsoiaYD2AWQ7pNDbG02o5KLigdK/JemmvOR Qmw7OhC5bywzvfQDqBpuMyeqMz8prY2IjlJdG5bCdl595K7/UgukbtSQQToB33kqDXnc t/3w== MIME-Version: 1.0 Received: by 10.180.98.69 with SMTP id eg5mr41763404wib.3.1341958571768; Tue, 10 Jul 2012 15:16:11 -0700 (PDT) Received: by 10.227.93.133 with HTTP; Tue, 10 Jul 2012 15:16:11 -0700 (PDT) In-Reply-To: References: <8B96E214-86E9-45E3-A5C8-D9AFFB23C6E7@redhat.com> <39379CEA-6A20-4360-9B79-0FACE94274FB@redhat.com> Date: Tue, 10 Jul 2012 23:16:11 +0100 Message-ID: Subject: Re: XA_RBTIMEOUT From: Robbie Gemmell To: users@qpid.apache.org Content-Type: multipart/alternative; boundary=f46d04182820f93a8f04c4811328 --f46d04182820f93a8f04c4811328 Content-Type: text/plain; charset=ISO-8859-1 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 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 >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 > > > > > --f46d04182820f93a8f04c4811328--