Uploaded image for project: 'HttpComponents HttpClient'
  1. HttpComponents HttpClient
  2. HTTPCLIENT-1910

HttpClient reuses stale connection after upgrading to 4.4.+

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Invalid
    • Affects Version/s: 4.4.1, 4.5.5
    • Fix Version/s: None
    • Component/s: HttpClient (classic)
    • Labels:
      None

      Description

      I'm currently trying to update a project of mine that is currently using HttpClient 4.3.6 to 4.5.5. While everything is working with 4.3.6 the newer versions of HttpClient are prematurely closing connections starting with HttpClient 4.4. I read the changelogs for 4.4 and think this may be releated to the improved stale connection handling as this seems to the only thing that is related...

      My program basically tries to perform a simple GET-request to an URL that requires NTLM authentication. The authentication succeeds but when trying to access the initial resource again, the connection is discarded:

      2018-03-14 10:10:18,376 [main] DEBUG [tp.impl.auth.HttpAuthenticator] - Authentication succeeded
      2018-03-14 10:10:18,376 [main] DEBUG [client.DefaultRedirectStrategy] - Redirect requested to location 'https://qlik2018-srv001:443/qrs/about?Xrfkey=0123456789abcdef&qlikTicket=RSkWFWZ4ayeWlMke'
      2018-03-14 10:10:18,376 [main] DEBUG [tp.impl.execchain.RedirectExec] - Resetting target auth state
      2018-03-14 10:10:18,376 [main] DEBUG [tp.impl.execchain.RedirectExec] - Redirecting to 'https://qlik2018-srv001:443/qrs/about?Xrfkey=0123456789abcdef&qlikTicket=RSkWFWZ4ayeWlMke' via \{s}->https://qlik2018-srv001:443
      2018-03-14 10:10:18,376 [main] DEBUG [ingHttpClientConnectionManager] - Connection [id: 1][route: \{s}->https://qlik2018-srv001:4244][state: QLIK2018-SRV001\qlik-admin] can be kept alive indefinitely
      2018-03-14 10:10:18,376 [main] DEBUG [ingHttpClientConnectionManager] - Connection released: [id: 1][route: \{s}->https://qlik2018-srv001:4244][state: QLIK2018-SRV001\qlik-admin][total kept alive: 2; route allocated: 1 of 2; total allocated: 2 of 20]
      2018-03-14 10:10:18,376 [main] DEBUG [ent.protocol.RequestAddCookies] - CookieSpec selected: default
      2018-03-14 10:10:18,392 [main] DEBUG [ient.protocol.RequestAuthCache] - Auth cache not set in the context
      2018-03-14 10:10:18,392 [main] DEBUG [ingHttpClientConnectionManager] - Connection request: [route: \{s}->https://qlik2018-srv001:443][state: QLIK2018-SRV001\qlik-admin][total kept alive: 2; route allocated: 1 of 2; total allocated: 2 of 20]
      2018-03-14 10:10:18,392 [main] DEBUG [ingHttpClientConnectionManager] - Connection leased: [id: 0][route: \{s}->https://qlik2018-srv001:443][total kept alive: 1; route allocated: 1 of 2; total allocated: 2 of 20]
      2018-03-14 10:10:18,392 [main] DEBUG [.impl.execchain.MainClientExec] - Executing request GET /qrs/about?Xrfkey=0123456789abcdef&qlikTicket=RSkWFWZ4ayeWlMke HTTP/1.1
      2018-03-14 10:10:18,392 [main] DEBUG [.impl.execchain.MainClientExec] - Target auth state: UNCHALLENGED
      2018-03-14 10:10:18,392 [main] DEBUG [.impl.execchain.MainClientExec] - Proxy auth state: UNCHALLENGED
      2018-03-14 10:10:18,392 [main] DEBUG [ingManagedHttpClientConnection] - http-outgoing-0 >> GET /qrs/about?Xrfkey=0123456789abcdef&qlikTicket=RSkWFWZ4ayeWlMke HTTP/1.1
      2018-03-14 10:10:18,392 [main] DEBUG [ingManagedHttpClientConnection] - http-outgoing-0 >> X-Qlik-Xrfkey: 0123456789abcdef
      2018-03-14 10:10:18,392 [main] DEBUG [ingManagedHttpClientConnection] - http-outgoing-0 >> User-Agent: Windows
      2018-03-14 10:10:18,392 [main] DEBUG [ingManagedHttpClientConnection] - http-outgoing-0 >> Host: qlik2018-srv001:443
      2018-03-14 10:10:18,392 [main] DEBUG [ingManagedHttpClientConnection] - http-outgoing-0 >> Connection: Keep-Alive
      2018-03-14 10:10:18,392 [main] DEBUG [ingManagedHttpClientConnection] - http-outgoing-0 >> Accept-Encoding: gzip,deflate
      2018-03-14 10:10:18,392 [main] DEBUG [ingManagedHttpClientConnection] - http-outgoing-0: Close connection
      2018-03-14 10:10:18,392 [main] DEBUG [ingManagedHttpClientConnection] - http-outgoing-0: Shutdown connection
      2018-03-14 10:10:18,392 [main] DEBUG [mpl.execchain.ConnectionHolder] - Connection discarded
      2018-03-14 10:10:18,392 [main] DEBUG [ingManagedHttpClientConnection] - http-outgoing-0: Close connection
      2018-03-14 10:10:18,392 [main] DEBUG [ingHttpClientConnectionManager] - Connection released: [id: 0][route: \{s}->https://qlik2018-srv001:443][total kept alive: 1; route allocated: 0 of 2; total allocated: 1 of 20]
      

      the resulting stacktrace looks like this:

      java.net.SocketException: Software caused connection abort: recv failed
      	at java.net.SocketInputStream.socketRead0(Native Method)
      	at java.net.SocketInputStream.socketRead(Unknown Source)
      	at java.net.SocketInputStream.read(Unknown Source)
      	at java.net.SocketInputStream.read(Unknown Source)
      	at sun.security.ssl.InputRecord.readFully(Unknown Source)
      	at sun.security.ssl.InputRecord.read(Unknown Source)
      	at sun.security.ssl.SSLSocketImpl.readRecord(Unknown Source)
      	at sun.security.ssl.SSLSocketImpl.readDataRecord(Unknown Source)
      	at sun.security.ssl.AppInputStream.read(Unknown Source)
      	at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
      	at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
      	at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282)
      	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138)
      	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)
      	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
      	at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
      	at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165)
      	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
      	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
      	at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
      	at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
      	at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
      	at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111)
      	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
      	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
      ...
      

      I attached debug logging of the program using 4.4 (broken) and 4.3.6 (working).

      Please let me know if additional information is needed. I could try to provide an MVE for the client code, if the information from the logs is not sufficient to analyse the problem.

        Attachments

        1. httpclient-4.3.6.log
          22 kB
          Daniel H. Peger
        2. httpclient-4.4.log
          22 kB
          Daniel H. Peger

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              daniel@peger.de Daniel H. Peger
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: