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

Error processing courier

bowlere May 14, 2008 7:51 AM

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

marklittle May 14, 2008 8:33 AM (in response to bowlere)

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.
Actions
2. Re: Error processing courier

kconner May 14, 2008 8:42 AM (in response to bowlere)

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?
Actions
3. Re: Error processing courier

bowlere May 14, 2008 11:51 AM (in response to bowlere)

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
Actions

4. Re: Error processing courier

bowlere May 19, 2008 6:34 AM (in response to bowlere)

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

bowlere May 19, 2008 7:07 AM (in response to bowlere)

I've created a bug on JIRA for this:

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

6. Re: Error processing courier

kconner May 19, 2008 8:07 AM (in response to bowlere)

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

kconner May 19, 2008 8:09 AM (in response to bowlere)

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.
Actions

8. Re: Error processing courier

bowlere May 19, 2008 11:34 AM (in response to bowlere)

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

bowlere May 19, 2008 12:38 PM (in response to bowlere)

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

kconner May 20, 2008 6:41 AM (in response to bowlere)

"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.
Actions
11. Re: Error processing courier

kconner May 20, 2008 6:46 AM (in response to bowlere)

"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.
Actions
12. Re: Error processing courier

bowlere May 21, 2008 5:37 AM (in response to bowlere)

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?
Actions
13. Re: Error processing courier

bowlere May 21, 2008 6:30 AM (in response to bowlere)

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?
Actions
14. Re: Error processing courier

bowlere May 22, 2008 11:54 AM (in response to bowlere)
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.
Actions

1 2 Previous Next

Go to original post