1 2 Previous Next 25 Replies Latest reply on May 4, 2009 9:23 PM by Federico Herrera

    Error processing courier

    Ed Bowler Newbie

      Hi,

      I am seeing some serious problems with JBossESB 4.2.1 installed in
      JBoss AS 4.2.2GA, using JBoss MQ. The main symptom I see is that all
      the ESB Services fail to pick up messages from their JMS queues. This
      appears to be emerging after several hours of happy usage (processing
      around 100,000 ESB messages per day).

      I start seeing:

      2008-04-20 10:00:06,386 WARN [MessageAwareListener] Error processing courier, backing off for 1000 milliseconds
      


      (with the backing off time increasing to 32000)

      I have also discovered that this situation does not seem to occur
      nearly as often with log4j logging set to DEBUG (with the system
      lasting for days as opposed to hours).

      I have dug around and found this exception. It seems that the
      SpySession.createReceiver call is being run on a closed session. This
      must mean that getJmsSession is returning an invalid session.

      This may be related to http://jira.jboss.com/jira/browse/JBESB-1491

      So I've added some logging to the MessageAwareListener, so we output
      this stack trace on the "Error processing courier" warning:

      2008-05-14 11:00:18,034 WARN [MessageAwareListener] Error processing courier, backing off for 32000 milliseconds
      org.jboss.soa.esb.couriers.CourierException: Unable to create Message Consumer
       at org.jboss.internal.soa.esb.couriers.JmsCourier.pickupPayload(JmsCourier.java:410)
       at org.jboss.internal.soa.esb.couriers.JmsCourier.pickup(JmsCourier.java:391)
       at org.jboss.internal.soa.esb.couriers.TwoWayCourierImpl.pickup(TwoWayCourierImpl.java:223)
       at org.jboss.internal.soa.esb.couriers.TwoWayCourierImpl.pickup(TwoWayCourierImpl.java:205)
       at org.jboss.soa.esb.listeners.message.MessageAwareListener.waitForEventAndProcess(MessageAwareListener.java:270)
       at org.jboss.soa.esb.listeners.message.MessageAwareListener.doRun(MessageAwareListener.java:253)
       at org.jboss.soa.esb.listeners.lifecycle.AbstractThreadedManagedLifecycle.run(AbstractThreadedManagedLifecycle.java:115)
       at java.lang.Thread.run(Thread.java:619)
      Caused by: org.jboss.soa.esb.couriers.CourierException: javax.jms.IllegalStateException: The session is closed
       at org.jboss.internal.soa.esb.couriers.JmsCourier.createMessageConsumer(JmsCourier.java:515)
       at org.jboss.internal.soa.esb.couriers.JmsCourier.pickupPayload(JmsCourier.java:402)
       ... 7 more
      Caused by: javax.jms.IllegalStateException: The session is closed
       at org.jboss.mq.SpySession.checkClosed(SpySession.java:1149)
       at org.jboss.mq.SpySession.createReceiver(SpySession.java:652)
       at org.jboss.internal.soa.esb.couriers.JmsCourier.createMessageConsumer(JmsCourier.java:501)
       ... 8 more
      


      I suspect a concurreny problem, where the JMS session is being changed
      under the JmsCourier's nose, however, any suggestions as to where I
      should be looking?


        • 1. Re: Error processing courier
          Mark Little Master

          Can you try with a more recent version of JBossESB? There were some changes/fixes in that area as part of the SOA Platform work we did. May not address your problem, but it would be a better starting point. Plus 4.3 is about to be released in the next few days.

          • 2. Re: Error processing courier
            Kevin Conner Master

            Mark is correct, this area has undergone a major overhaul since the 4.2.1 release was made.

            Could you try the same test on the 4.3CR1 release and see if you still have an issue?

            • 3. Re: Error processing courier
              Ed Bowler Newbie

              Thanks very much for the prompt reply, I have downloaded, upgraded and deployed our application, and will wait for this to happen again.

              If the error fails to raise it's ugly head in the next week or so, I guess we can label this as fixed.

              Thanks again

              • 4. Re: Error processing courier
                Ed Bowler Newbie

                Hi,

                After the suggested JbossESB to 4.3CR1 I am still getting the "Error
                processing courier, backing off for 1000 milliseconds" error, however
                with new exceptions around it.

                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)
                ... [snip] ...
                


                which goes through my code, followed by:

                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)
                ... [snip] ...
                 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)
                ... [snip] ...
                 at java.lang.Thread.run(Thread.java:619)
                Caused by: java.net.SocketTimeoutException: Read timed out
                 at java.net.SocketInputStream.socketRead0(Native Method)
                ... [snip] ...
                 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
                


                Is it worth me posting a bug of JIRA?

                Many thanks for your help.


                • 6. Re: Error processing courier
                  Kevin Conner Master

                  It looks like there are a couple of problems here.

                  The first issue is that something in your application is causing the transaction to timeout, this is why you see the following

                  "bowlere" wrote:
                  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)
                  ... [snip] ...
                  


                  The following is a bug, we will fix this.

                  "bowlere" wrote:
                  java.lang.NullPointerException
                   at org.jboss.internal.soa.esb.couriers.JmsCourier.jmsConnectRetry(JmsCourier.java:272)
                  ... [snip] ...
                   at org.jboss.soa.esb.listeners.lifecycle.AbstractThreadedManagedLifecycle.run(AbstractThreadedManagedLifecycle.java:115)
                   at java.lang.Thread.run(Thread.java:619)
                  


                  The backing off error is normal if a processing exception has occurred and the following suggests you are using synchronous invocations. Synchronous invocations expect to receive a response within a specified time, this message is telling you that the service has been unresponsive.

                  "bowlere" wrote:
                  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 ]
                  


                  The following appear to be JBossMQ error messages, relating to stale connections.

                  "bowlere" wrote:
                  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)
                  ... [snip] ...
                   at java.lang.Thread.run(Thread.java:619)
                  Caused by: java.net.SocketTimeoutException: Read timed out
                   at java.net.SocketInputStream.socketRead0(Native Method)
                  ... [snip] ...
                   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
                  



                  • 7. Re: Error processing courier
                    Kevin Conner Master

                    The real question that needs answered is why does the transaction time out? Is there something in the stacktrace that could shed some light on this?

                    If you can send your server.log file then we may be able to see something.

                    • 8. Re: Error processing courier
                      Ed Bowler Newbie

                      One of the things that is happening in this transaction is it is
                      calling the ServiceInvoker to deliver a message to a service:

                       public void sendMessage(String xml) {
                       Message esbMessage = MessageFactory.getInstance().getMessage();
                       esbMessage.getBody().add(xml);
                       ServiceInvoker invoker;
                       try {
                       invoker = new ServiceInvoker(CATEGORY, SERVICE);
                       invoker.deliverAsync(esbMessage);
                       } catch (MessageDeliverException ex) {
                       LOGGER.warn("Could not deliver message", ex);
                       }
                       }
                      


                      This code is called from CDMEventDiscriminatorMessageProcessor.java
                      line 184 in the stack trace. But we see no "Could not deliver
                      message" warnings in the log, so I can only assume that it
                      successfully delivers the message. The code doesn't seem to be doing
                      much else that would take a significant amout of time - just updating
                      some entities from the data in the ESB message.

                      The full stack trace is here:

                      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.ar
                      junacore.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)
                      


                      I can provide a lot of logs, and would much appreciate your time and
                      help with this, how would you prefer I send them ? Email ?


                      • 9. Re: Error processing courier
                        Ed Bowler Newbie

                         


                        The backing off error is normal if a processing exception has
                        occurred and the following suggests you are using synchronous
                        invocations. Synchronous invocations expect to receive a response
                        within a specified time, this message is telling you that the service
                        has been unresponsive.


                        If I am reading this error message correctly, then it means that the
                        unresponsive EPR is the one that receives messages from the
                        cdm_inbound_event_esb JMS queue. This message is being sent by an ESB
                        service that uses the org.jboss.soa.esb.actions.MessageFilter. In the
                        4.3CR1 source, it seems to me that this is using the
                        MessageMulticaster.sendToSubset method to send messages, which seems
                        to use the ServiceInvoker.deliverAsync method.

                        (I've reformatted it cos I found it hard to read ;)

                        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:persi stent : 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:ja va.naming.factory.initial : org.jnp.interfaces.NamingContextFactory/>,
                        <wsa:ReferenceProperties jbossesb:java.naming.provider.url : jnp://jndi-server-1:1099/>,
                        <wsa:ReferenceProper ties 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:ReferenceProp erties 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 ]
                        



                        • 10. Re: Error processing courier
                          Kevin Conner Master

                           

                          "bowlere" wrote:
                          This code is called from CDMEventDiscriminatorMessageProcessor.java
                          line 184 in the stack trace. But we see no "Could not deliver
                          message" warnings in the log, so I can only assume that it
                          successfully delivers the message.

                          The deliverAsync works in a different manner as it does not expect a response.

                          The stacktrace appears to show an invocation to a stateless session bean, what is happening within this?

                          "bowlere" wrote:
                          I can provide a lot of logs, and would much appreciate your time and
                          help with this, how would you prefer I send them ? Email ?

                          Email is good.

                          • 11. Re: Error processing courier
                            Kevin Conner Master

                             

                            "bowlere" wrote:
                            If I am reading this error message correctly, then it means that the
                            unresponsive EPR is the one that receives messages from the
                            cdm_inbound_event_esb JMS queue. This message is being sent by an ESB
                            service that uses the org.jboss.soa.esb.actions.MessageFilter. In the
                            4.3CR1 source, it seems to me that this is using the
                            MessageMulticaster.sendToSubset method to send messages, which seems
                            to use the ServiceInvoker.deliverAsync method.

                            Asynchronous invocations would not cause this.

                            If you are using a synchronous invocation within a transaction, invoking a service over JMS, then this will be the cause of the problem.

                            The outgoing JMS message will never be sent until the transaction has committed and, therefore, any expected response will never arrive.



                            • 12. Re: Error processing courier
                              Ed Bowler Newbie

                               


                              Asynchronous invocations would not cause this.


                              I have failed to find any synchronous messages in the application. I
                              have grepped the whole codebase for deliverSync, and come up empty.
                              The only out of the box actions in use are:

                              - org.jboss.soa.esb.actions.MessageFilter - which uses
                              MessageMulticaster.sendToSubset

                              - org.jboss.soa.esb.actions.StaticRouter - which uses
                              MessageMulticaster.sendToSubset

                              - org.jboss.soa.esb.actions.SystemPrintln

                              and MessageMulticaster.sendToSubset calls
                              ServiceInvoker.deliverAsync. All but 2 of the actions pipelines are
                              marked as "OneWay". I think this is an oversight, and will correct
                              that, but I don't think that there are any calls to
                              ServiceInvoker.deliverSync that would wait for the response from an
                              action pipeline that isn't marked as "OneWay". Am I missing something
                              fundamental?


                              • 13. Re: Error processing courier
                                Ed Bowler Newbie


                                Firstly I saw this in the logs:-

                                ----------------
                                2008-05-21 06:44:26,299 ERROR
                                [org.jboss.soa.esb.monitoring.server.DataFilerJob]
                                org.jboss.soa.esb.couriers.CourierServiceBindException: Failed to get
                                JMS Session from pool.
                                at
                                org.jboss.internal.soa.esb.couriers.JmsCourier.getJmsSession(JmsCourier.java:162)
                                at
                                org.jboss.internal.soa.esb.couriers.JmsCourier.createMessageProducer(JmsCourier.java:323)
                                at
                                org.jboss.internal.soa.esb.couriers.JmsCourier.deliver(JmsCourier.java:186)
                                at
                                org.jboss.internal.soa.esb.couriers.TwoWayCourierImpl.deliver(TwoWayCourierImpl.java:199)
                                at
                                org.jboss.soa.esb.monitoring.server.DataFilerJob.execute(DataFilerJob.java:84)
                                at org.quartz.core.JobRunShell.run(JobRunShell.java:203)
                                at org.quartz.simpl.SimpleThreadPool
                                $WorkerThread.run(SimpleThreadPool.java:520)
                                Caused by:
                                org.jboss.internal.soa.esb.rosetta.pooling.ConnectionException:
                                Connection pool has been terminated
                                at
                                org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool.initConnection(JmsConnectionPool.java:401)
                                at
                                org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool.getSession(JmsConnectionPool.java:163)
                                at
                                org.jboss.internal.soa.esb.couriers.JmsCourier.getJmsSession(JmsCourier.java:156)
                                ... 6 more

                                ------------------

                                Looking into this, the ConnectionException is thrown in
                                JmsConnectionPool.java:401 when the pool has been marked as
                                'terminated'. The pool gets marked as terminated only at
                                JmsConnectionPool.java:439 when a JMSException triggers the call to
                                the removeSessionPool().

                                removeSessionPool() is also called by JmsConnectionPoolFactory (inner
                                class of JmsConnectionPoolContainer) in response to a call to
                                destroyLifecycleResource()...


                                Once this happens, there doesn't appear to be any attempt to recreate
                                a new pool thus rendering the ESB unable to operate.

                                Is my interpretation correct?

                                • 14. Re: Error processing courier
                                  Ed Bowler Newbie

                                  Hi,

                                  I can reliably duplicate this now, by blocking JMS at the firewall:

                                  # iptables -I INPUT -p tcp --dport 8093 -j REJECT
                                  


                                  and leaving it for 30s or so, then putting it back:

                                  # iptables -D INPUT -p tcp --dport 8093 -j REJECT
                                  


                                  I think that this simulates what's really causing the issue - load
                                  increasing to the point that MQ doesn't respond to a ping in time.
                                  This is probably caused by some bad code in my application, but I
                                  think that the ESB server shouldn't get itself into a broken state
                                  just because I've done a JNDI look up inside a loop, or something else
                                  that saps the limited resources of my box.



                                  1 2 Previous Next