UNResponsive EPR after First Timeout - Very Strange

[ash316]

My scenario is as follows:

1) ServiceInvoker -> Routing Service -> Use Drools Rules -> Go to Service A or B based on some XPATH in the request.

2) If service A or B times out (I have introduced manual delay as these services hosted on websphere).

3) serviceInvoker.deliverSync() starts giving errors even if the service A/B are made available.

Gist of the problem is once I catch the ResponseTimeoutException and render it gracefully, the subsequent invocatons from ServiceInvokers always times out until I restart the server hosting the ESB.

This is really a show stopper for me.

Experts please help.

I am using ESB 4.11

Regards

Ashish

[ash316]

Logs when Service is being invoked:

2013-11-29 21:34:21,383 INFO  [STDOUT] (pool-26-thread-1) Invoker org.jboss.soa.esb.client.ServiceInvoker@737ccf67

2013-11-29 21:34:21,383 DEBUG [org.jboss.internal.soa.esb.couriers.transport.InVMTransport] (pool-26-thread-1) Delivering message to 63726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6743617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6753657276696365

2013-11-29 21:34:21,383 DEBUG [org.jboss.internal.soa.esb.couriers.transport.InVMTransport] (pool-26-thread-1) Delivering message direct to 63726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6743617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6753657276696365 queue

2013-11-29 21:34:21,383 DEBUG [org.jboss.internal.soa.esb.couriers.transport.InVMTransport] (Thread-46) Pickup of message from 63726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6743617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6753657276696365

2013-11-29 21:34:21,384 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] (pool-27-thread-1) pipeline process for message: header: [ To: InVMEpr [ PortReference < <wsa:Address invm://63726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6743617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6753657276696365/false?false#10000/>, <wsa:ReferenceProperties jbossesb:type : urn:jboss/esb/epr/type/invm/>, <wsa:ReferenceProperties jbossesb:passByValue : false/> > ] ReplyTo: InVMEpr [ PortReference < <wsa:Address invm://thread-154-2/>, <wsa:ReferenceProperties jbossesb:type : urn:jboss/esb/epr/type/invm/>, <wsa:ReferenceProperties jbossesb:passByValue : false/>, <wsa:ReferenceProperties jbossesb:temporaryEPR : true/> > ] MessageID: fb9da61d-d47b-4503-a186-43538ae94b06 ]

2013-11-29 21:34:21,384 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] (pool-27-thread-1) executing processor 0 org.jboss.soa.esb.actions.ContentBasedRouter@2cf3820b

2013-11-29 21:34:21,384 DEBUG [org.jboss.internal.soa.esb.services.rules.DroolsRuleBaseState] (pool-27-thread-1) reusing old stateles session [1388609989]

2013-11-29 21:34:21,384 DEBUG [org.jboss.internal.soa.esb.services.rules.DroolsRuleBaseState] (pool-27-thread-1) calling execute(Iterable) on stateless session [1388609989]

2013-11-29 21:34:21,406 INFO  [STDOUT] (pool-27-thread-1) Routing to PCF BANK

2013-11-29 21:34:21,407 DEBUG [org.jboss.internal.soa.esb.services.registry.JAXRRegistryImpl] (pool-27-thread-1) Going to query the registry for name pattern [CredentialMangementPCFSOAPService]

2013-11-29 21:34:21,413 DEBUG [org.jboss.soa.esb.client.ServiceInvoker] (pool-27-thread-1) EPR=InVMEpr [ PortReference < <wsa:Address invm://43726564656e7469616c4d616e67656d656e74504346536572766963657343617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74504346534f415053657276696365/false?false#10000/>, <wsa:ReferenceProperties jbossesb:type : urn:jboss/esb/epr/type/invm/>, <wsa:ReferenceProperties jbossesb:passByValue : false/> > ] XML=<wsa:From xmlns:wsa="http://schemas.xmlsoap.org/ws/2004/08/addressing"><wsa:Address>invm://43726564656e7469616c4d616e67656d656e74504346536572766963657343617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74504346534f415053657276696365/false?false#10000</wsa:Address><wsa:ReferenceProperties><jbossesb:type xmlns:jbossesb="http://schemas.jboss.com/ws/2007/01/jbossesb">urn:jboss/esb/epr/type/invm</jbossesb:type><jbossesb:passByValue xmlns:jbossesb="http://schemas.jboss.com/ws/2007/01/jbossesb">false</jbossesb:passByValue></wsa:ReferenceProperties></wsa:From>

2013-11-29 21:34:21,413 DEBUG [org.jboss.internal.soa.esb.couriers.transport.InVMTransport] (pool-27-thread-1) Delivering message to 43726564656e7469616c4d616e67656d656e74504346536572766963657343617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74504346534f415053657276696365

2013-11-29 21:34:21,413 DEBUG [org.jboss.internal.soa.esb.couriers.transport.InVMTransport] (pool-27-thread-1) Delivering message direct to 43726564656e7469616c4d616e67656d656e74504346536572766963657343617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74504346534f415053657276696365 queue

2013-11-29 21:34:21,413 DEBUG [org.jboss.internal.soa.esb.couriers.transport.InVMTransport] (Thread-48) Pickup of message from 43726564656e7469616c4d616e67656d656e74504346536572766963657343617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74504346534f415053657276696365

2013-11-29 21:34:21,413 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] (pool-29-thread-1) pipeline process for message: header: [ To: InVMEpr [ PortReference < <wsa:Address invm://43726564656e7469616c4d616e67656d656e74504346536572766963657343617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74504346534f415053657276696365/false?false#10000/>, <wsa:ReferenceProperties jbossesb:type : urn:jboss/esb/epr/type/invm/>, <wsa:ReferenceProperties jbossesb:passByValue : false/> > ] ReplyTo: InVMEpr [ PortReference < <wsa:Address invm://thread-154-2/>, <wsa:ReferenceProperties jbossesb:type : urn:jboss/esb/epr/type/invm/>, <wsa:ReferenceProperties jbossesb:passByValue : false/>, <wsa:ReferenceProperties jbossesb:temporaryEPR : true/> > ] MessageID: fb9da61d-d47b-4503-a186-43538ae94b06 ]

2013-11-29 21:34:21,413 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] (pool-29-thread-1) executing processor 0 org.jboss.soa.esb.actions.SystemPrintln@481beb90

2013-11-29 21:34:21,413 INFO  [STDOUT] (pool-29-thread-1) BEFORE Going to PC:

2013-11-29 21:34:21,415 INFO  [STDOUT] (pool-29-thread-1) [ message: [ JBOSS_XML ]

header: [ To: InVMEpr [ PortReference < <wsa:Address invm://43726564656e7469616c4d616e67656d656e74504346536572766963657343617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74504346534f415053657276696365/false?false#10000/>, <wsa:ReferenceProperties jbossesb:type : urn:jboss/esb/epr/type/invm/>, <wsa:ReferenceProperties jbossesb:passByValue : false/> > ] ReplyTo: InVMEpr [ PortReference < <wsa:Address invm://thread-154-2/>, <wsa:ReferenceProperties jbossesb:type : urn:jboss/esb/epr/type/invm/>, <wsa:ReferenceProperties jbossesb:passByValue : false/>, <wsa:ReferenceProperties jbossesb:temporaryEPR : true/> > ] MessageID: fb9da61d-d47b-4503-a186-43538ae94b06 ]

context: {}

Logs when Service is not invoked

2013-11-29 21:35:06,523 INFO  [STDOUT] (pool-26-thread-1) Invoker org.jboss.soa.esb.client.ServiceInvoker@d340470

2013-11-29 21:35:06,523 DEBUG [org.jboss.internal.soa.esb.couriers.transport.InVMTransport] (pool-26-thread-1) Delivering message to 63726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6743617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6753657276696365

2013-11-29 21:35:06,523 DEBUG [org.jboss.internal.soa.esb.couriers.transport.InVMTransport] (pool-26-thread-1) Delivering message direct to 63726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6743617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6753657276696365 queue

2013-11-29 21:35:06,523 DEBUG [org.jboss.internal.soa.esb.couriers.transport.InVMTransport] (Thread-46) Pickup of message from 63726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6743617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6753657276696365

2013-11-29 21:35:06,523 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] (pool-27-thread-1) pipeline process for message: header: [ To: InVMEpr [ PortReference < <wsa:Address invm://63726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6743617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74436f6e74656e74526f7574696e6753657276696365/false?false#10000/>, <wsa:ReferenceProperties jbossesb:type : urn:jboss/esb/epr/type/invm/>, <wsa:ReferenceProperties jbossesb:passByValue : false/> > ] ReplyTo: InVMEpr [ PortReference < <wsa:Address invm://thread-154-3/>, <wsa:ReferenceProperties jbossesb:type : urn:jboss/esb/epr/type/invm/>, <wsa:ReferenceProperties jbossesb:passByValue : false/>, <wsa:ReferenceProperties jbossesb:temporaryEPR : true/> > ] MessageID: 8862ea4e-c648-4e86-b309-ab00f44f988f ]

2013-11-29 21:35:06,523 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] (pool-27-thread-1) executing processor 0 org.jboss.soa.esb.actions.ContentBasedRouter@2cf3820b

2013-11-29 21:35:06,523 DEBUG [org.jboss.internal.soa.esb.services.rules.DroolsRuleBaseState] (pool-27-thread-1) reusing old stateles session [1388609989]

2013-11-29 21:35:06,523 DEBUG [org.jboss.internal.soa.esb.services.rules.DroolsRuleBaseState] (pool-27-thread-1) calling execute(Iterable) on stateless session [1388609989]

2013-11-29 21:35:06,546 INFO  [STDOUT] (pool-27-thread-1) Routing to PCF BANK

2013-11-29 21:35:06,546 DEBUG [org.jboss.internal.soa.esb.couriers.transport.InVMTransport] (pool-27-thread-1) Delivering message to 43726564656e7469616c4d616e67656d656e74504346536572766963657343617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74504346534f415053657276696365

2013-11-29 21:35:06,546 DEBUG [org.jboss.internal.soa.esb.couriers.transport.InVMTransport] (pool-27-thread-1) Delivering message direct to 43726564656e7469616c4d616e67656d656e74504346536572766963657343617465676f727924242424242424242424242443726564656e7469616c4d616e67656d656e74504346534f415053657276696365 queue

2013-11-29 21:35:08,918 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-32) TransactionReaper::insert ( BasicAction: acf5fa1:cad9:5298ba12:132 status: ActionStatus.RUNNING, 300 )

2013-11-29 21:35:08,920 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-32) TransactionReaper::remove ( BasicAction: acf5fa1:cad9:5298ba12:132 status: ActionStatus.COMMITTED )

2013-11-29 21:35:09,369 WARN  [org.rhq.core.pc.event.EventManager] (EventManager.sender-1) Failure to report Events to Server.

[tcunning]

Ashish,

Take a look at Kevin Conner's posts in the following topic - I think it is similar to the issue you have.

https://community.jboss.org/thread/228373

[ash316]

Thanks Tom for the pointers.

I already looked into this but it did not helped.

I did some play around with timings mentioned in the jboss-properties.xml.

Can you please throw some light on the parameters mentioned below. If we set them to lower values, will there be any impact?

<property name="org.jboss.soa.esb.registry.interceptors"
value="org.jboss.internal.soa.esb.services.registry.InVMRegistryInterceptor, org.jboss.internal.soa.esb.services.registry.CachingRegistryInterceptor"/>

<!-- The following properties modify the cache interceptor behaviour -->
<property name="org.jboss.soa.esb.registry.cache.maxSize" value="100"/>
<!-- If the validityPeriod is not specified then it will default to the same value as org.jboss.soa.esb.registry.cache.life-->
<property name="org.jboss.soa.esb.registry.cache.validityPeriod" value="6000"/>

Thanks

Ashish