Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Invalid
-
4.4.1, 4.5.5
-
None
-
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.