FUSE ESB
  1. FUSE ESB
  2. ESB-1397

HTTP Consumer timeout handling is incorrect

    Details

    • Similar Issues:
      Show 10 results 

      Description

      I'm still getting:

      2011-02-09 04:44:15,353 [pool-flow.seda.servicemix-eip-thread-247] ERROR org.apache.servicemix.http.HttpComponent - 
      Error processing exchange InOut[id: ID:10.209.8.87-12e099f306b-6:82790
      status: Active
      role: consumer
      service: {https://webservices.mycompany.com/websvc}ConsumerStaticRoutingSlipService
      endpoint: sws
      in: (...)
      out: <?xml version="1.0" encoding="UTF-8"?><soap-env:Envelope xmlns:soap-env="http://schemas.xmlsoap.org/soap/envelope/">...
      ]
      java.lang.Exception: HTTP request has timed out for exchange: ID:10.209.8.87-12e099f306b-6:82790
      at org.apache.servicemix.http.endpoints.HttpConsumerEndpoint.process(HttpConsumerEndpoint.java:251)
      at org.apache.servicemix.common.AsyncBaseLifeCycle.doProcess(AsyncBaseLifeCycle.java:617)
      at org.apache.servicemix.common.AsyncBaseLifeCycle.processExchange(AsyncBaseLifeCycle.java:588)
      at org.apache.servicemix.common.AsyncBaseLifeCycle.onMessageExchange(AsyncBaseLifeCycle.java:525)
      at org.apache.servicemix.common.SyncLifeCycleWrapper.onMessageExchange(SyncLifeCycleWrapper.java:60)
      at org.apache.servicemix.jbi.messaging.DeliveryChannelImpl.processInBound(DeliveryChannelImpl.java:632)
      at org.apache.servicemix.jbi.nmr.flow.AbstractFlow.doRouting(AbstractFlow.java:185)
      at org.apache.servicemix.jbi.nmr.flow.seda.SedaFlow.doRouting(SedaFlow.java:168)
      at org.apache.servicemix.jbi.nmr.flow.seda.SedaQueue$1.run(SedaQueue.java:134)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:619)
      2011-02-09 04:44:15,354 [pool-flow.seda.servicemix-eip-thread-247] ERROR org.apache.servicemix.http.HttpComponent - 
      Error setting exchange status to ERROR 7-12e099f306b-6:82790
      at org.apache.servicemix.jbi.messaging.MessageExchangeImpl.setError(MessageExchangeImpl.java:264)
      at org.apache.servicemix.common.AsyncBaseLifeCycle.onMessageExchange(AsyncBaseLifeCycle.java:540)
      at org.apache.servicemix.common.SyncLifeCycleWrapper.onMessageExchange(SyncLifeCycleWrapper.java:60)
      at org.apache.servicemix.jbi.messaging.DeliveryChannelImpl.processInBound(DeliveryChannelImpl.java:632)
      at org.apache.servicemix.jbi.nmr.flow.AbstractFlow.doRouting(AbstractFlow.java:185)
      at org.apache.servicemix.jbi.nmr.flow.seda.SedaFlow.doRouting(SedaFlow.java:168)
      at org.apache.servicemix.jbi.nmr.flow.seda.SedaQueue$1.run(SedaQueue.java:134)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:619)
      Caused by: java.lang.Exception: HTTP request has timed out for exchange: ID:10.209.8.87-12e099f306b-6:82790
      at org.apache.servicemix.http.endpoints.HttpConsumerEndpoint.process(HttpConsumerEndpoint.java:251)
      at org.apache.servicemix.common.AsyncBaseLifeCycle.doProcess(AsyncBaseLifeCycle.java:617)
      at org.apache.servicemix.common.AsyncBaseLifeCycle.processExchange(AsyncBaseLifeCycle.java:588)
      at org.apache.servicemix.common.AsyncBaseLifeCycle.onMessageExchange(AsyncBaseLifeCycle.java:525)
      ... 8 more
      

      There are several issues relating to HTTP consumer timeout handling.

      In a nutshell:

      • there was no synchronization where continuation were already resumed() and process(request,respone) was invoked for the second time.
      • there exceptions thrown in process(exchange) method are misleading.
      • They really mean that we has received a late response from the JBI bus, but the response with a timeout has been already sent to the client.
      • The test ConsumerEndpointTest.xtestHttpInOutUnderLoad can be uncommented now, because it passes all the time now.

      Attached is a patch based on servicemix-http-2010.02.0-fuse-00-00.

        Activity

        Hide
        Claudio Corsi
        added a comment -

        This patch contains the fix that can be applied to the 3.3.1 stream.

        Show
        Claudio Corsi
        added a comment - This patch contains the fix that can be applied to the 3.3.1 stream.
        Hide
        Gert Vanthienen
        added a comment -

        The patch can basically be translated into two distinct issues to be fixed:

        Show
        Gert Vanthienen
        added a comment - The patch can basically be translated into two distinct issues to be fixed: clean up and refactor locking with a separate lock object (cfr. https://issues.apache.org/jira/browse/SMXCOMP-880 ) make a timeout look a bit less alarming and/or allow configuring the endpoint to just ignore those entirely (cfr. https://issues.apache.org/jira/browse/SMXCOMP-881 )
        Hide
        Gert Vanthienen
        added a comment -

        Both issues have been resolved at Apache by now - the fixes still need to get merged into the right branches at FuseSource.

        However, in the meanwhile, would it be possible to get back in touch with the customer and check if these two fixes are meeting their requirements. In particular, the proposed fix had a pluggable LateResponseListener but since the main goal there was to avoid throwing exceptions or failing exchanges for timed out HTTP requests and there's really not that much you can do inside the ESB once the request has timed out, I left the extra listener interface out and allowed for configuring the behaviour through a simple 'lateResponseStrategy' flag (cfr. https://issues.apache.org/jira/browse/SMXCOMP-881) instead.

        Show
        Gert Vanthienen
        added a comment - Both issues have been resolved at Apache by now - the fixes still need to get merged into the right branches at FuseSource. However, in the meanwhile, would it be possible to get back in touch with the customer and check if these two fixes are meeting their requirements. In particular, the proposed fix had a pluggable LateResponseListener but since the main goal there was to avoid throwing exceptions or failing exchanges for timed out HTTP requests and there's really not that much you can do inside the ESB once the request has timed out, I left the extra listener interface out and allowed for configuring the behaviour through a simple 'lateResponseStrategy' flag (cfr. https://issues.apache.org/jira/browse/SMXCOMP-881 ) instead.
        Hide
        Gert Vanthienen
        added a comment -

        Joe,

        For SMXCOMP-880, I do agree with Mateusz that the original implementation was broken, but I think the refactoring addresses the original issue as well. For the logging remarks, I'll modify those statements to reuse the existing exchange id variable. With the upgrade to SLF4J a while ago however, we removed the extraneous if (logger.isDebugEnabled()) for all the cases where we can pass the message and a single parameter. Those if-clauses will be there again when this patch gets backported to branches that are using LOG4J though.

        For SMXCOMP-881, I can see how the exceptions used for a late response can be altered to better reflect what's going on instead of using "HTTP request has timed out..." all over the place, so I'll make that change. I left out the explicit LateResponseListener but allowed for configuring both the behavior in the proposed patch (WARN en end with status DONE) as well as the original behaviour of the component (end the exchange with ERROR). I couldn't really imagine any other way to terminate the MessageExchange, but I could obviously add a callback somewhere for them to implement something else if they have a use case for that?

        Regards,

        Gert

        Show
        Gert Vanthienen
        added a comment - Joe, For SMXCOMP-880, I do agree with Mateusz that the original implementation was broken, but I think the refactoring addresses the original issue as well. For the logging remarks, I'll modify those statements to reuse the existing exchange id variable. With the upgrade to SLF4J a while ago however, we removed the extraneous if (logger.isDebugEnabled()) for all the cases where we can pass the message and a single parameter. Those if-clauses will be there again when this patch gets backported to branches that are using LOG4J though. For SMXCOMP-881, I can see how the exceptions used for a late response can be altered to better reflect what's going on instead of using "HTTP request has timed out..." all over the place, so I'll make that change. I left out the explicit LateResponseListener but allowed for configuring both the behavior in the proposed patch (WARN en end with status DONE) as well as the original behaviour of the component (end the exchange with ERROR). I couldn't really imagine any other way to terminate the MessageExchange, but I could obviously add a callback somewhere for them to implement something else if they have a use case for that? Regards, Gert
        Hide
        Gert Vanthienen
        added a comment -

        FIxed the remaining remarks by Mateusz in http://svn.apache.org/viewvc?view=revision&revision=1134568

        Backported this fix into the 2011.02-fuse and 2011.01-fuse branches

        Show
        Gert Vanthienen
        added a comment - FIxed the remaining remarks by Mateusz in http://svn.apache.org/viewvc?view=revision&revision=1134568 Backported this fix into the 2011.02-fuse and 2011.01-fuse branches

          People

          • Assignee:
            Gert Vanthienen
            Reporter:
            Joe Luo
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: