3 Replies Latest reply on Dec 2, 2013 10:51 PM by Ashish Nayyar

    UNResponsive EPR after First Timeout - Very Strange

    Ashish Nayyar Newbie

      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

        • 1. Re: UNResponsive EPR after First Timeout - Very Strange
          Ashish Nayyar Newbie

          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.

          • 2. Re: UNResponsive EPR after First Timeout - Very Strange
            Tom Cunningham Master

            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

            • 3. Re: UNResponsive EPR after First Timeout - Very Strange
              Ashish Nayyar Newbie

              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