HttpComponents HttpClient
  1. HttpComponents HttpClient
  2. HTTPCLIENT-1048

PostMethod very slow 'out of the box' for /j_security_check

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Not a Problem
    • Affects Version/s: 4.0.3
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None
    • Environment:
      Java 6, Tomcat 6, JBoss 5.1

      Description

      First, thanks for an awesome piece of work in HttpClient. I use it every day and it is very useful to me.

      HttpClient's default settings include adding an...

      Expect: 100-continue

      ...header to every PostMethod. This seems to interact poorly with Tomcat's (and possibly other Java EE containers) FormAuthenticator. I tested on both Tomcat 6 and JBoss 5.1.0 (which I believe uses a fork of Tomcat). Testing both with/without the 'Expect' header I see '/j_security_check' login times of:

      With Expect header: 2012ms
      Without Expect header: 8ms

      So the default is some 250x slower. This is without a database or any other complicating factors. It can make a dramatic difference if you are using HttpClient to simulate logging in and retrieving information.

      I include a test WAR. To deploy it:

      1. Copy into /webapps
      2. Edit conf/tomcat-users.xml to enable the tomcat/tomcat username/password
      3. Run Tomcat
      4. Hit http://localhost:8080/ExpectTest
      5. Log in as tomcat/tomcat
      6. Hit 'Start Test'

      The issue can be worked around by removing the RequestExpectContinue interceptor, but it takes a lot of digging through code to realise this. Otherwise you may simply conclude 'HttpClient is slow'.

      According to the HTTP spec (http://www.w3.org/Protocols/rfc2616/rfc2616-sec8.html#sec8.2.3), the 100 header "allows a client that is sending a request message with a request body to determine if the origin server is willing to accept the request (based on the request headers) before the client sends the request body. In some cases, it might either be inappropriate or highly inefficient for the client to send the body if the server will reject the message without looking at the body". So perhaps this setting should only apply for 'large' POST bodies, not for simple 'j_username=Foo&j_password=Bar' bodies?

      Regards,

      Richard

      1. wire.log
        41 kB
        Kennard Consulting
      2. ExpectTest.war
        462 kB
        Kennard Consulting

        Activity

        Hide
        Kennard Consulting added a comment -
        Show
        Kennard Consulting added a comment - Okay opened: https://issues.apache.org/bugzilla/show_bug.cgi?id=50689 Thanks, Richard.
        Hide
        Oleg Kalnichevski added a comment -

        You could certainly try.

        Oleg

        Show
        Oleg Kalnichevski added a comment - You could certainly try. Oleg
        Hide
        Kennard Consulting added a comment -

        So you think I should raise this with the Tomcat guys?

        Richard.

        Show
        Kennard Consulting added a comment - So you think I should raise this with the Tomcat guys? Richard.
        Hide
        Oleg Kalnichevski added a comment -

        >> "POST /ExpectTest/j_security_check HTTP/1.1[EOL]"

        >> "Content-Length: 35[EOL]"

        >> "Content-Type: application/x-www-form-urlencoded; charset=ISO-8859-1[EOL]"

        >> "Host: localhost:8080[EOL]"

        >> "Connection: Keep-Alive[EOL]"

        >> "User-Agent: Apache-HttpClient/4.0.3 (java 1.5)[EOL]"

        >> "Expect: 100-Continue[EOL]"

        >> "Cookie: JSESSIONID=F1A440D77108B972C472B368A7695FA5[EOL]"

        >> "Cookie2: $Version=1[EOL]"

        >> "[EOL]"

        >> "j_username=tomcat&j_password=tomcat"

        << "HTTP/1.1 302 Moved Temporarily[EOL]"

        << "Server: Apache-Coyote/1.1[EOL]"

        << "Location: http://localhost:8080/ExpectTest/[EOL]"

        << "Content-Length: 0[EOL]"

        << "Date: Sat, 29 Jan 2011 10:03:17 GMT[EOL]"

        << "[EOL]"

        As you can see from this snippet, both the agent and the origin server use HTTP/1.1 protocol versions, and therefore both are expected to comply with the requirements of section 8.2.3 'Use of the 100 (Continue) Status', RFC 2616


        Requirements for HTTP/1.1 origin servers:

        • Upon receiving a request which includes an Expect request-header
          field with the "100-continue" expectation, an origin server MUST
          either respond with 100 (Continue) status and continue to read
          from the input stream, or respond with a final status code. The
          origin server MUST NOT wait for the request body before sending
          the 100 (Continue) response.

        As far as I can tell the origin server fails to comply with this requirement.

        The delay of two seconds is caused by HttpClient waiting for the origin server to respond with a 100 status or a final response such as status 417.


        Because of the presence of older implementations, the protocol allows
        ambiguous situations in which a client may send "Expect: 100-
        continue" without receiving either a 417 (Expectation Failed) status
        or a 100 (Continue) status. Therefore, when a client sends this
        header field to an origin server (possibly via a proxy) from which it
        has never seen a 100 (Continue) status, the client SHOULD NOT wait
        for an indefinite period before sending the request body.

        Show
        Oleg Kalnichevski added a comment - >> "POST /ExpectTest/j_security_check HTTP/1.1 [EOL] " >> "Content-Length: 35 [EOL] " >> "Content-Type: application/x-www-form-urlencoded; charset=ISO-8859-1 [EOL] " >> "Host: localhost:8080 [EOL] " >> "Connection: Keep-Alive [EOL] " >> "User-Agent: Apache-HttpClient/4.0.3 (java 1.5) [EOL] " >> "Expect: 100-Continue [EOL] " >> "Cookie: JSESSIONID=F1A440D77108B972C472B368A7695FA5 [EOL] " >> "Cookie2: $Version=1 [EOL] " >> " [EOL] " >> "j_username=tomcat&j_password=tomcat" << "HTTP/1.1 302 Moved Temporarily [EOL] " << "Server: Apache-Coyote/1.1 [EOL] " << "Location: http://localhost:8080/ExpectTest/[EOL ]" << "Content-Length: 0 [EOL] " << "Date: Sat, 29 Jan 2011 10:03:17 GMT [EOL] " << " [EOL] " As you can see from this snippet, both the agent and the origin server use HTTP/1.1 protocol versions, and therefore both are expected to comply with the requirements of section 8.2.3 'Use of the 100 (Continue) Status', RFC 2616 — Requirements for HTTP/1.1 origin servers: Upon receiving a request which includes an Expect request-header field with the "100-continue" expectation, an origin server MUST either respond with 100 (Continue) status and continue to read from the input stream, or respond with a final status code. The origin server MUST NOT wait for the request body before sending the 100 (Continue) response. — As far as I can tell the origin server fails to comply with this requirement. The delay of two seconds is caused by HttpClient waiting for the origin server to respond with a 100 status or a final response such as status 417. — Because of the presence of older implementations, the protocol allows ambiguous situations in which a client may send "Expect: 100- continue" without receiving either a 417 (Expectation Failed) status or a 100 (Continue) status. Therefore, when a client sends this header field to an origin server (possibly via a proxy) from which it has never seen a 100 (Continue) status, the client SHOULD NOT wait for an indefinite period before sending the request body. —
        Hide
        Kennard Consulting added a comment -

        > The log could be used to show that the web container is not fully compliant with the HTTP spec.

        Good point. Log of EventTest.war attached. Includes wire logging of HttpClient as well as TRACE logging of Tomcat. Unfortunately there does not appear to be any further information inside the 2 second 'hole'. I have annotated the hole with four stars (****) in the log.

        Also note there is a mistake in EventTest.war: in start.jsp, I do not recreate the HttpClient before the second login attempt. This does not impact the bug (the 2 second 'hole' is there either way) but does affect the trace slightly (as the second login attempt is therefore already logged in). My apologies.

        Regards,

        Richard.

        Show
        Kennard Consulting added a comment - > The log could be used to show that the web container is not fully compliant with the HTTP spec. Good point. Log of EventTest.war attached. Includes wire logging of HttpClient as well as TRACE logging of Tomcat. Unfortunately there does not appear to be any further information inside the 2 second 'hole'. I have annotated the hole with four stars (****) in the log. Also note there is a mistake in EventTest.war: in start.jsp, I do not recreate the HttpClient before the second login attempt. This does not impact the bug (the 2 second 'hole' is there either way) but does affect the trace slightly (as the second login attempt is therefore already logged in). My apologies. Regards, Richard.
        Hide
        Kennard Consulting added a comment -

        Wire log attached. Please search for a string of four stars (****) where I have highlighted the problem both with/without the Expect header.

        Show
        Kennard Consulting added a comment - Wire log attached. Please search for a string of four stars (****) where I have highlighted the problem both with/without the Expect header.
        Hide
        Oleg Kalnichevski added a comment -

        The log could be used to show that the web container is not fully compliant with the HTTP spec.

        Oleg

        Show
        Oleg Kalnichevski added a comment - The log could be used to show that the web container is not fully compliant with the HTTP spec. Oleg
        Hide
        Kennard Consulting added a comment - - edited

        Oleg,

        Thanks for your response.

        I'm afraid the wire log isn't very helpful: it shows the presence/absence of the Expect header, and shows the body being 'pulled' either during/before the request processing - pretty much what you'd expect. But the actual cause of the 2 second slowdown is not revealed. If you try the attached WAR you may be able to discover what is taking 2 seconds?

        Anyway, if 'expect-continue' is disabled by default in 4.1, that works for me!

        Thanks,

        Richard.

        Show
        Kennard Consulting added a comment - - edited Oleg, Thanks for your response. I'm afraid the wire log isn't very helpful: it shows the presence/absence of the Expect header, and shows the body being 'pulled' either during/before the request processing - pretty much what you'd expect. But the actual cause of the 2 second slowdown is not revealed. If you try the attached WAR you may be able to discover what is taking 2 seconds? Anyway, if 'expect-continue' is disabled by default in 4.1, that works for me! Thanks, Richard.
        Hide
        Oleg Kalnichevski added a comment -

        Kennard

        Please produce a complete wire / context log of the session as described here [1] and attach the log to this issue

        Please note that one can disable the 'expect-continue' handshake using a configuration parameter. You might also want to upgrade to HttpClient 4.1 which has the 'expect-continue' disabled per default.

        Oleg

        [1] http://hc.apache.org/httpcomponents-client-ga/logging.html

        Show
        Oleg Kalnichevski added a comment - Kennard Please produce a complete wire / context log of the session as described here [1] and attach the log to this issue Please note that one can disable the 'expect-continue' handshake using a configuration parameter. You might also want to upgrade to HttpClient 4.1 which has the 'expect-continue' disabled per default. Oleg [1] http://hc.apache.org/httpcomponents-client-ga/logging.html
        Hide
        Kennard Consulting added a comment -

        WAR demonstrating the problem

        Show
        Kennard Consulting added a comment - WAR demonstrating the problem

          People

          • Assignee:
            Unassigned
            Reporter:
            Kennard Consulting
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development