Error processing courier, backing off - ESBs stop processing messages --------------------------------------------------------------------- Key: JBESB-1806 URL: http://jira.jboss.com/jira/browse/JBESB-1806 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