[
https://issues.apache.org/jira/browse/HTTPCLIENT-1910?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16400319#comment-16400319
]
Daniel H. Peger edited comment on HTTPCLIENT-1910 at 3/15/18 12:51 PM:
-----------------------------------------------------------------------
Further analysing the logs I found an interesting output in the HC 4.3.6 log
that is missing in the HC 4.4 log:
{noformat}
2018-03-14 10:47:12,815 [main] DEBUG [.impl.execchain.MainClientExec] - Stale
connection check
2018-03-14 10:47:12,815 [main] DEBUG [.impl.execchain.MainClientExec] - Stale
connection detected
2018-03-14 10:47:12,815 [main] DEBUG [ingManagedHttpClientConnection] -
http-outgoing-0: Close connection
{noformat}
I debugged this and with 4.3.+ {{ReqestConfig.isStaleConnectionCheckEnabled()}}
is {{true}} by default. With 4.4.+ this was changed and by default the stale
connection check is skipped. Enabling the stale connection check in the request
config explicitly fixes the issue for me. Probably the server closes the
initial connection after redirecting to the authentication URL and with 4.4
this closed connection is reused.
Without all the boilerplate logging the following requests are executed:
{noformat}
http-outgoing-0 >> GET /qrs/about?Xrfkey=0123456789abcdef
http-outgoing-0 >> Host: qlik2018-srv001:443
http-outgoing-0 << HTTP/1.1 302 Authenticate at this location
http-outgoing-0 << Location:
https://qlik2018-srv001:4244/windows_authentication/?targetId=78af329d-ba6b-43ea-91e1-91861faeeb5e
http-outgoing-1 >> GET
/windows_authentication/?targetId=78af329d-ba6b-43ea-91e1-91861faeeb5e HTTP/1.1
http-outgoing-1 >> Host: qlik2018-srv001:4244
http-outgoing-1 << HTTP/1.1 401 Unauthorized
http-outgoing-1 << WWW-Authenticate: NTLM
http-outgoing-1 >> GET
/windows_authentication/?targetId=78af329d-ba6b-43ea-91e1-91861faeeb5e HTTP/1.1
http-outgoing-1 >> Host: qlik2018-srv001:4244
http-outgoing-1 << HTTP/1.1 401 Unauthorized
http-outgoing-1 << WWW-Authenticate: NTLM TlRMTVNTUAACAA...V0u9MBAAAAAA==
http-outgoing-1 >> GET
/windows_authentication/?targetId=78af329d-ba6b-43ea-91e1-91861faeeb5e HTTP/1.1
http-outgoing-1 >> Host: qlik2018-srv001:4244
http-outgoing-1 << HTTP/1.1 302 Found
http-outgoing-1 << Location:
https://qlik2018-srv001:443/qrs/about?Xrfkey=0123456789abcdef&qlikTicket=RSkWFWZ4ayeWlMke
http-outgoing-0: Close connection // only with 4.3.6
http-outgoing-0 >> GET
/qrs/about?Xrfkey=0123456789abcdef&qlikTicket=RSkWFWZ4ayeWlMke HTTP/1.1
http-outgoing-0 >> Host: qlik2018-srv001:443
{noformat}
As the stale connection check is deprecated with 4.4, I tried different other
config options:
* Set {{PoolingHttpClientConnectionManager.setValidateAfterInactivity}} to 1 ms
* Use {{BasicHttpClientConnectionManager}} instead of
{{PoolingHttpClientConnectionManager}}
* Use {{NoConnectionReuseStrategy}}
But none of the above changes worked.
Is there any non-deprecated replacement for the stale connection check? I'm not
worried about performance as this program is a one shot only and a few seconds
more or less don't matter.
was (Author: [email protected]):
Further analysing the logs I found an interesting output in the HC 4.3.6 log
that is missing in the HC 4.4 log:
{noformat}
2018-03-14 10:47:12,815 [main] DEBUG [.impl.execchain.MainClientExec] - Stale
connection check
2018-03-14 10:47:12,815 [main] DEBUG [.impl.execchain.MainClientExec] - Stale
connection detected
2018-03-14 10:47:12,815 [main] DEBUG [ingManagedHttpClientConnection] -
http-outgoing-0: Close connection
{noformat}
I debugged this and with 4.3.+ {{ReqestConfig.isStaleConnectionCheckEnabled()}}
is {{true}} by default. With 4.4.+ this was changed and by default the stale
connection check is skipped. Enabling the stale connection check in the request
config explicitly fixes the issue for me. Probably the server closes the
initial connection after redirecting to the authentication URL and with 4.4
this closed connection is reused.
Without all the boilerplate logging the following requests are executed:
{noformat}
http-outgoing-0 >> GET /qrs/about?Xrfkey=0123456789abcdef
http-outgoing-0 >> Host: qlik2018-srv001:443
http-outgoing-0 << HTTP/1.1 302 Authenticate at this location
http-outgoing-0 << Location:
https://qlik2018-srv001:4244/windows_authentication/?targetId=78af329d-ba6b-43ea-91e1-91861faeeb5e
http-outgoing-1 >> GET
/windows_authentication/?targetId=78af329d-ba6b-43ea-91e1-91861faeeb5e HTTP/1.1
http-outgoing-1 >> Host: qlik2018-srv001:4244
http-outgoing-1 << HTTP/1.1 401 Unauthorized
http-outgoing-1 << WWW-Authenticate: NTLM
http-outgoing-1 >> GET
/windows_authentication/?targetId=78af329d-ba6b-43ea-91e1-91861faeeb5e HTTP/1.1
http-outgoing-1 >> Host: qlik2018-srv001:4244
http-outgoing-1 << HTTP/1.1 401 Unauthorized
http-outgoing-1 << WWW-Authenticate: NTLM TlRMTVNTUAACAA...V0u9MBAAAAAA==
http-outgoing-1 >> GET
/windows_authentication/?targetId=78af329d-ba6b-43ea-91e1-91861faeeb5e HTTP/1.1
http-outgoing-1 >> Host: qlik2018-srv001:4244
http-outgoing-1 << HTTP/1.1 302 Found
http-outgoing-1 << Location:
https://qlik2018-srv001:443/qrs/about?Xrfkey=0123456789abcdef&qlikTicket=RSkWFWZ4ayeWlMke
http-outgoing-0: Close connection // only with 4.3.6
http-outgoing-0 >> GET
/qrs/about?Xrfkey=0123456789abcdef&qlikTicket=RSkWFWZ4ayeWlMke HTTP/1.1
http-outgoing-0 >> Host: qlik2018-srv001:443
{noformat}
As the stale connection check is deprecated with 4.4, I tried different other
config options:
* Set {{PoolingHttpClientConnectionManager.setValidateAfterInactivity}} to 1 ms
* Use {{BasicHttpClientConnectionManager}} instead of
{{PoolingHttpClientConnectionManager}}
* Use {{NoConnectionReuseStrategy}}
But non of the above changes worked.
Is there any non-deprecated replacement for the stale connection check? I'm not
worried about performance as this program is a one shot only and a few seconds
more or less don't matter.
> HttpClient reuses stale connection after upgrading to 4.4.+
> -----------------------------------------------------------
>
> Key: HTTPCLIENT-1910
> URL: https://issues.apache.org/jira/browse/HTTPCLIENT-1910
> Project: HttpComponents HttpClient
> Issue Type: Bug
> Components: HttpClient (classic)
> Affects Versions: 4.4.1, 4.5.5
> Reporter: Daniel H. Peger
> Priority: Major
> Attachments: httpclient-4.3.6.log, httpclient-4.4.log
>
>
> 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:
> {noformat}
> 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]
> {noformat}
> the resulting stacktrace looks like this:
> {noformat}
> 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)
> ...
> {noformat}
> I attached debug logging of the program using [4.4
> (broken)|^httpclient-4.4.log] and [4.3.6 (working)|^httpclient-4.3.6.log].
> 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.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
