[esb-issues] [JBoss JIRA] Commented: (JBESB-1748) Error processing courier, backing off - ESBs stop processing messages
Kevin Conner (JIRA)
jira-events at lists.jboss.org
Wed Jun 11 07:40:16 EDT 2008
[ http://jira.jboss.com/jira/browse/JBESB-1748?page=comments#action_12416454 ]
Kevin Conner commented on JBESB-1748:
-------------------------------------
The current pooling codebase reacts to a JMS connection failure by closing down the connection and destroying the pool.
Unfortunately a connection to the pool is being held within the courier (and a couple of other places) and, as a consequence, this results in an exception stating that the pool has been terminated when it is next accessed.
The solution is to clean the pool on the exception, allowing the references to remain valid.
> Error processing courier, backing off - ESBs stop processing messages
> ---------------------------------------------------------------------
>
> Key: JBESB-1748
> URL: http://jira.jboss.com/jira/browse/JBESB-1748
> Project: JBoss ESB
> Issue Type: Bug
> Security Level: Public(Everyone can see)
> Components: Rosetta
> Affects Versions: 4.2.1, 4.3
> Environment: Centos(2.6.18-8.el5 #1 SMP, x86_64 GNU/Linux), Sun JDK1.6, JBoss AS 4.2.2, MySQL (5.0.22)
> Reporter: Ed Bowler
> Assigned To: Kevin Conner
> Fix For: 4.4
>
>
> Hi,
> I have asked for help on the forums about this here:
> http://www.jboss.com/index.html?module=bb&op=viewtopic&t=135536
> To summarise, after a few days of (reasonably heavy, but happy) usage,
> the ESB services I have deployed stop picking up messages from their
> JMS queues, and "Error processing courier, backing off for 32000
> milliseconds" is repeatedly written into the log files.
> I have configured a few datasources to use MySQL instead of the
> default HSQL (namely esb, jms and juddi).
> After the suggested upgrade JbossESB to 4.3CR1 I am still getting the
> "Error processing courier, backing off" error.
> I now see:
> {{{
> 2008-05-17 10:09:03,558 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id a01023a:9f00:482d5dee:eb53a invoked while multiple threads active within it.
> 2008-05-17 10:09:03,615 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action a01023a:9f00:482d5dee:eb53a aborting with 1 threads active!
> }}}
> followed by several:
> {{{
> 2008-05-17 10:09:19,067 ERROR [net.rockshore.cdm.services.cdmeventdiscriminator.CDMEventDiscriminatorInboundMessageHandler] Exception whilst processing incoming message: [com.arjuna.ats.internal.jta.transaction.arjunacore.inactive] [com.arjuna.ats.internal.jta.transaction.arjunacore.inactive] The transaction is not active!
> java.lang.IllegalStateException: [com.arjuna.ats.internal.jta.transaction.arjunacore.inactive] [com.arjuna.ats.internal.jta.transaction.arjunacore.inactive] The transaction is not active!
> at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1379)
> at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
> at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
> at org.jboss.aspects.tx.TxPolicy.endTransaction(TxPolicy.java:175)
> at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:87)
> at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:191)
> at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
> at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:95)
> at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
> at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
> at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
> at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
> at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:110)
> at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
> at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
> at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
> at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
> at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
> at org.jboss.ejb3.stateless.StatelessContainer.dynamicInvoke(StatelessContainer.java:304)
> at org.jboss.ejb3.remoting.IsLocalInterceptor.invokeLocal(IsLocalInterceptor.java:81)
> at org.jboss.ejb3.remoting.IsLocalInterceptor.invoke(IsLocalInterceptor.java:72)
> at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
> at org.jboss.ejb3.stateless.StatelessRemoteProxy.invoke(StatelessRemoteProxy.java:107)
> at $Proxy325.processEvent(Unknown Source)
> at net.rockshore.cdm.services.cdmeventdiscriminator.CDMEventDiscriminatorMessageProcessor.process(CDMEventDiscriminatorMessageProcessor.java:184)
> at net.rockshore.cdm.services.cdmeventdiscriminator.CDMEventDiscriminatorInboundMessageHandler.processMessage(CDMEventDiscriminatorInboundMessageHandler.java:34)
> at sun.reflect.GeneratedMethodAccessor131.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.jboss.soa.esb.listeners.message.ActionProcessorMethodInfo.processMethods(ActionProcessorMethodInfo.java:102)
> at org.jboss.soa.esb.listeners.message.OverriddenActionLifecycleProcessor.process(OverriddenActionLifecycleProcessor.java:74)
> at org.jboss.soa.esb.listeners.message.ActionProcessingPipeline.process(ActionProcessingPipeline.java:316)
> at org.jboss.soa.esb.listeners.message.MessageAwareListener$TransactionalRunner.run(MessageAwareListener.java:530)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
> at java.lang.Thread.run(Thread.java:619)
> }}}
> and:
> {{{
> 2008-05-17 10:44:02,412 WARN [org.jboss.soa.esb.listeners.message.MessageAwareListener] Error processing courier, backing off for 1000 milliseconds
> 2008-05-17 10:44:06,681 WARN [org.jboss.soa.esb.listeners.lifecycle.AbstractThreadedManagedLifecycle] Unexpected error from doRun()
> java.lang.NullPointerException
> at org.jboss.internal.soa.esb.couriers.JmsCourier.jmsConnectRetry(JmsCourier.java:272)
> at org.jboss.internal.soa.esb.couriers.JmsCourier.pickupPayload(JmsCourier.java:434)
> at org.jboss.internal.soa.esb.couriers.JmsCourier.pickup(JmsCourier.java:402)
> at org.jboss.internal.soa.esb.couriers.TwoWayCourierImpl.pickup(TwoWayCourierImpl.java:232)
> at org.jboss.internal.soa.esb.couriers.TwoWayCourierImpl.pickup(TwoWayCourierImpl.java:214)
> at org.jboss.soa.esb.listeners.message.MessageAwareListener.waitForEventAndProcess(MessageAwareListener.java:280)
> at org.jboss.soa.esb.listeners.message.MessageAwareListener.doRun(MessageAwareListener.java:248)
> at org.jboss.soa.esb.listeners.lifecycle.AbstractThreadedManagedLifecycle.run(AbstractThreadedManagedLifecycle.java:115)
> at java.lang.Thread.run(Thread.java:619)
> }}}
> which returns us to the backing off error. Followed by:
> {{{
> 2008-05-17 12:30:09,180 INFO [org.jboss.soa.esb.client.ServiceInvoker] Unresponsive EPR: JMSEpr [ PortReference < <wsa:Address jms://0.0.0.0:1099/queue/cdm_inbound_event_esb/>, <wsa:ReferenceProperties jbossesb:java.naming.factory.initial : org.jnp.interfaces.NamingContextFactory/>, <wsa:ReferenceProperties jbossesb:java.naming.provider.url : jnp://jndi-server-1:1099/>, <wsa:ReferenceProperties jbossesb:java.naming.factory.url.pkgs : org.jboss.naming:org.jnp.interfaces/>, <wsa:ReferenceProperties jbossesb:destination-type : queue/>,<wsa:ReferenceProperties jbossesb:specification-version : 1.1/>, <wsa:ReferenceProperties jbossesb:connection-factory : ConnectionFactory/>, <wsa:ReferenceProperties jbossesb:persistent : true/>, <wsa:ReferenceProperties jbossesb:acknowledge-mode : AUTO_ACKNOWLEDGE/>, <wsa:ReferenceProperties jbossesb:transacted : false/>, <wsa:ReferenceProperties jbossesb:type : urn:jboss/esb/epr/type/jms/> > ] for message: header: [ To: JMSEpr [ PortReference < <wsa:Address jms://0.0.0.0:1099/queue/acl_cbr_esb/>, <wsa:ReferenceProperties jbossesb:java.naming.factory.initial : org.jnp.interfaces.NamingContextFactory/>, <wsa:ReferenceProperties jbossesb:java.naming.provider.url : jnp://jndi-server-1:1099/>, <wsa:ReferenceProperties jbossesb:java.naming.factory.url.pkgs : org.jboss.naming:org.jnp.interfaces/>, <wsa:ReferenceProperties jbossesb:destination-type : queue/>, <wsa:ReferenceProperties jbossesb:specification-version : 1.1/>, <wsa:ReferenceProperties jbossesb:connection-factory : ConnectionFactory/>, <wsa:ReferenceProperties jbossesb:persistent : true/>, <wsa:ReferenceProperties jbossesb:acknowledge-mode : AUTO_ACKNOWLEDGE/>, <wsa:ReferenceProperties jbossesb:transacted : false/>, <wsa:ReferenceProperties jbossesb:type : urn:jboss/esb/epr/type/jms/>> ] MessageID: 1d18b548-9f67-44a5-8b65-b08f666dcb6f RelatesTo: jms:correlationID#1d18b548-9f67-44a5-8b65-b08f666dcb6f ]
> }}}
> Then:
> {{{
> 2008-05-17 21:24:54,610 WARN [org.jboss.mq.Connection] Connection failure, already in the exception listener
> org.jboss.mq.SpyJMSException: Exiting on IOE; - nested throwable: (java.net.SocketTimeoutException: Read timed out)
> at org.jboss.mq.SpyJMSException.getAsJMSException(SpyJMSException.java:72)
> at org.jboss.mq.Connection.asynchFailure(Connection.java:423)
> at org.jboss.mq.il.uil2.UILClientILService.asynchFailure(UILClientILService.java:174)
> at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleStop(SocketManager.java:466)
> at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:395)
> at java.lang.Thread.run(Thread.java:619)
> Caused by: java.net.SocketTimeoutException: Read timed out
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
> at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
> at org.jboss.util.stream.NotifyingBufferedInputStream.read(NotifyingBufferedInputStream.java:79)
> at java.io.ObjectInputStream$PeekInputStream.peek(ObjectInputStream.java:2249)
> at java.io.ObjectInputStream$BlockDataInputStream.readBlockHeader(ObjectInputStream.java:2429)
> at java.io.ObjectInputStream$BlockDataInputStream.refill(ObjectInputStream.java:2499)
> at java.io.ObjectInputStream$BlockDataInputStream.read(ObjectInputStream.java:2571)
> at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2720)
> at java.io.ObjectInputStream.readByte(ObjectInputStream.java:895)
> at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:340)
> ... 1 more
> }}}
> and:
> {{{
> 2008-05-17 21:24:54,624 WARN [org.jboss.mq.Connection] Connection failure, already in the exception listener
> org.jboss.mq.SpyJMSException: No pong received; - nested throwable: (java.io.IOException: ping timeout.)
> at org.jboss.mq.Connection$PingTask.run(Connection.java:1313)
> at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364)
> at java.lang.Thread.run(Thread.java:619)
> Caused by: java.io.IOException: ping timeout.
> ... 3 more
> }}}
> and no messages are taken from the JMS queues, and processed by the
> ESB services.
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the esb-issues
mailing list