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.