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.


                • 5. Re: Error processing courier
                  Ed Bowler Newbie

                  I've created a bug on JIRA for this:

                  [a]http://jira.jboss.com/jira/browse/JBESB-1748[/a]

                  • 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