[
https://issues.apache.org/jira/browse/HTTPCLIENT-2364?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Fabien Arrault updated HTTPCLIENT-2364:
---------------------------------------
Description:
We are using Apache HTTPClient 5.4.3 to connect in HTTPS to different remote
servers through a corporate proxy (connecting in HTTP to the proxy)
Our application currently need to recreate the httpclient in some cases and
before that : it closes the previous
{{org.apache.hc.client5.http.impl.classic.CloseableHttpClient}} using the
IMMEDIATE mode : {{{}httpClient.close(CloseMode.IMMEDIATE{}}}) :
however for some remote servers : the close is not immediate at all and take 2
minutes.
I don't know which aspect of the remote servers configuration triggers that,
but it occurs consistently on specific target servers.
It happens only when there is +recently used+ http connection in the connection
pool (less than 2 minutes apparently)
Trying to figure out the problem :
* When I enable TLS debug log : I can see that our app is blocked waiting for
the response to a TLS close (see trace below)
* However, from the code of
{{{}org.apache.hc.core5.http.impl.io.BHttpConnectionBase#close(org.apache.hc.core5.io.CloseMode){}}},
its seems that in IMMEDIATE mode, the SSL socket should be bypassed and that
the physical socket should be directly close instead.
Debugging even further it appears that in my use case, the SocketHolder object
on the connection does not hold two different sockets but only the ssl one :
* socketHolder.getSSLSocket() is null
* socketHolder.getBaseSocket() returns the SSL Socket
=> which explains why the Socket.close() is called on a SSLSocket and not the
underlying physical one
It appears that this situation is linked to the use a proxy :
* the initial connection toward the proxy is plain HTTP => so initially the
socketHolder has only a baseSocket pointing to the physical socket
* then after the CONNECT operation to the remote server through the proxy :
the connection is upgraded to TLS in this method :
{{org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOperator#upgrade}}
This method seems to fail to attach both sockets to the connection retaining
only the TLS one :
{code:java}
SSLSocket upgradedSocket = tlsSocketStrategy.upgrade(socket,
tlsName.getHostName(), tlsName.getPort(), attachment, context);
conn.bind(upgradedSocket);{code}
I would have expect this instead +(at least for my specific use case)+ :
{code:java}
SSLSocket upgradedSocket = tlsSocketStrategy.upgrade(socket,
tlsName.getHostName(), tlsName.getPort(), attachment, context);
conn.bind(upgradedSocket, socket);{code}
----
Here the TLS log on close (with only one connection in the pool) :
{noformat}
18:11:23.498 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager -
Shutdown connection pool IMMEDIATE
18:11:23.498 [main] DEBUG
org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnection -
http-outgoing-0 close connection IMMEDIATE
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.498
CET|SSLSocketImpl.java:577|duplex close of SSLSocket
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.500
CET|SSLSocketOutputRecord.java:71|WRITE: TLSv1.2 alert(close_notify), length =
10
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.500
CET|SSLCipher.java:1773|Plaintext before ENCRYPTION (
0000: 01 00 ..
)
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.501
CET|SSLSocketOutputRecord.java:85|Raw write (
0000: 15 03 03 00 1A 00 00 00 00 00 00 00 02 7B C3 9A ................
0010: 10 31 40 75 4D C5 AA 32 A9 C3 4A 3F 77 F1 80 .1@uM..2..J?w..
)
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.501
CET|SSLSocketImpl.java:1759|close the underlying socket
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.502
CET|SSLSocketImpl.java:1785|close the SSL connection (initiative)
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.502
CET|SSLSocketImpl.java:1837|wait for close_notify or alert
javax.net.ssl|DEBUG|10|main|2025-03-28 18:13:23.530
CET|SSLSocketInputRecord.java:487|Raw read: EOF
javax.net.ssl|DEBUG|10|main|2025-03-28 18:13:23.531
CET|SSLSocketImpl.java:837|close inbound of SSLSocket
javax.net.ssl|ALL|10|main|2025-03-28 18:13:23.532
CET|SSLSocketImpl.java:1847|discard plaintext while waiting for close (
contentType: 0/majorVersion: 0/minorVersion: 0/recordEpoch: -1/recordSN:
0xffffffffffffffff/fragment: null
)
18:13:23.532 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager -
Connection pool shut down{noformat}
Those traces has been captured on Windows.
But the issue also occurs in linux-based production server.
was:
We are using Apache HTTPClient 5.4.3 to connect in HTTPS to different remote
servers through a corporate proxy (connecting in HTTP to the proxy)
Our application currently need to recreate the httpclient in some cases and
before that : it closes the previous
{{org.apache.hc.client5.http.impl.classic.CloseableHttpClient}} using the
IMMEDIATE mode : {{{}httpClient.close(CloseMode.IMMEDIATE{}}}) :
however for some remote servers : the close is not immediate at all and take 2
minutes.
I don't know which aspect of the remote servers configuration triggers that,
but it occurs consistently on specific target servers.
It happens only when there is +recently used+ http connection in the connection
pool (less than 2 minutes apparently)
Trying to figure out the problem :
When I enable TLS debug log : I can see that our app is blocked waiting for the
response to a TLS close record (see trace below)
However, from the code of
{{{}org.apache.hc.core5.http.impl.io.BHttpConnectionBase#close(org.apache.hc.core5.io.CloseMode){}}},
its seems that in IMMEDIATE mode, the SSL socket should be bypassed and that
the physical socket should be directly close instead.
Debuging even further it appears that in my use case, the SocketHolder object
on the connection does not hold two different sockets but only the ssl one :
* socketHolder.getSSLSocket() is null
* socketHolder.getBaseSocket() returns the SSL Socket
=> which explains why the Socket.close() is called on a SSLSocket and not the
underlying physical one
It appears that this situation is linked to the use a proxy :
* the initial connection toward the proxy is plain HTTP => so initially the
socketHolder has only a baseSocket pointing to the physical socket
* then after the CONNECT operation to the remote server through the proxy :
the connection is upgraded to TLS in this method :
{{org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOperator#upgrade}}
This method seems to fail to attach both sockets to the connection retaining
only the TLS one :
{code:java}
SSLSocket upgradedSocket = tlsSocketStrategy.upgrade(socket,
tlsName.getHostName(), tlsName.getPort(), attachment, context);
conn.bind(upgradedSocket);{code}
I would have expect this instead +(at least for my specific use case)+ :
{code:java}
SSLSocket upgradedSocket = tlsSocketStrategy.upgrade(socket,
tlsName.getHostName(), tlsName.getPort(), attachment, context);
conn.bind(upgradedSocket, socket);{code}
----
Here the TLS log on close (with only one connection in the pool) :
{noformat}
18:11:23.498 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager -
Shutdown connection pool IMMEDIATE
18:11:23.498 [main] DEBUG
org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnection -
http-outgoing-0 close connection IMMEDIATE
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.498
CET|SSLSocketImpl.java:577|duplex close of SSLSocket
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.500
CET|SSLSocketOutputRecord.java:71|WRITE: TLSv1.2 alert(close_notify), length =
10
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.500
CET|SSLCipher.java:1773|Plaintext before ENCRYPTION (
0000: 01 00 ..
)
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.501
CET|SSLSocketOutputRecord.java:85|Raw write (
0000: 15 03 03 00 1A 00 00 00 00 00 00 00 02 7B C3 9A ................
0010: 10 31 40 75 4D C5 AA 32 A9 C3 4A 3F 77 F1 80 .1@uM..2..J?w..
)
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.501
CET|SSLSocketImpl.java:1759|close the underlying socket
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.502
CET|SSLSocketImpl.java:1785|close the SSL connection (initiative)
javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.502
CET|SSLSocketImpl.java:1837|wait for close_notify or alert
javax.net.ssl|DEBUG|10|main|2025-03-28 18:13:23.530
CET|SSLSocketInputRecord.java:487|Raw read: EOF
javax.net.ssl|DEBUG|10|main|2025-03-28 18:13:23.531
CET|SSLSocketImpl.java:837|close inbound of SSLSocket
javax.net.ssl|ALL|10|main|2025-03-28 18:13:23.532
CET|SSLSocketImpl.java:1847|discard plaintext while waiting for close (
contentType: 0/majorVersion: 0/minorVersion: 0/recordEpoch: -1/recordSN:
0xffffffffffffffff/fragment: null
)
18:13:23.532 [main] DEBUG
org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager -
Connection pool shut down{noformat}
Those traces has been captured on Windows.
But the issue also occurs in linux-based production server.
> Close IMMEDIATE does not work properly on HTTPS-upgraded connection through
> proxy
> ---------------------------------------------------------------------------------
>
> Key: HTTPCLIENT-2364
> URL: https://issues.apache.org/jira/browse/HTTPCLIENT-2364
> Project: HttpComponents HttpClient
> Issue Type: Bug
> Components: HttpClient (classic)
> Affects Versions: 5.4.3
> Reporter: Fabien Arrault
> Priority: Minor
>
> We are using Apache HTTPClient 5.4.3 to connect in HTTPS to different remote
> servers through a corporate proxy (connecting in HTTP to the proxy)
> Our application currently need to recreate the httpclient in some cases and
> before that : it closes the previous
> {{org.apache.hc.client5.http.impl.classic.CloseableHttpClient}} using the
> IMMEDIATE mode : {{{}httpClient.close(CloseMode.IMMEDIATE{}}}) :
> however for some remote servers : the close is not immediate at all and take
> 2 minutes.
> I don't know which aspect of the remote servers configuration triggers that,
> but it occurs consistently on specific target servers.
> It happens only when there is +recently used+ http connection in the
> connection pool (less than 2 minutes apparently)
>
> Trying to figure out the problem :
> * When I enable TLS debug log : I can see that our app is blocked waiting
> for the response to a TLS close (see trace below)
> * However, from the code of
> {{{}org.apache.hc.core5.http.impl.io.BHttpConnectionBase#close(org.apache.hc.core5.io.CloseMode){}}},
> its seems that in IMMEDIATE mode, the SSL socket should be bypassed and that
> the physical socket should be directly close instead.
>
> Debugging even further it appears that in my use case, the SocketHolder
> object on the connection does not hold two different sockets but only the ssl
> one :
> * socketHolder.getSSLSocket() is null
> * socketHolder.getBaseSocket() returns the SSL Socket
> => which explains why the Socket.close() is called on a SSLSocket and not the
> underlying physical one
>
> It appears that this situation is linked to the use a proxy :
> * the initial connection toward the proxy is plain HTTP => so initially the
> socketHolder has only a baseSocket pointing to the physical socket
> * then after the CONNECT operation to the remote server through the proxy :
> the connection is upgraded to TLS in this method :
> {{org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOperator#upgrade}}
> This method seems to fail to attach both sockets to the connection retaining
> only the TLS one :
> {code:java}
> SSLSocket upgradedSocket = tlsSocketStrategy.upgrade(socket,
> tlsName.getHostName(), tlsName.getPort(), attachment, context);
> conn.bind(upgradedSocket);{code}
> I would have expect this instead +(at least for my specific use case)+ :
> {code:java}
> SSLSocket upgradedSocket = tlsSocketStrategy.upgrade(socket,
> tlsName.getHostName(), tlsName.getPort(), attachment, context);
> conn.bind(upgradedSocket, socket);{code}
>
>
> ----
> Here the TLS log on close (with only one connection in the pool) :
>
> {noformat}
> 18:11:23.498 [main] DEBUG
> org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager -
> Shutdown connection pool IMMEDIATE
> 18:11:23.498 [main] DEBUG
> org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnection -
> http-outgoing-0 close connection IMMEDIATE
> javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.498
> CET|SSLSocketImpl.java:577|duplex close of SSLSocket
> javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.500
> CET|SSLSocketOutputRecord.java:71|WRITE: TLSv1.2 alert(close_notify), length
> = 10
> javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.500
> CET|SSLCipher.java:1773|Plaintext before ENCRYPTION (
> 0000: 01 00 ..
> )
> javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.501
> CET|SSLSocketOutputRecord.java:85|Raw write (
> 0000: 15 03 03 00 1A 00 00 00 00 00 00 00 02 7B C3 9A ................
> 0010: 10 31 40 75 4D C5 AA 32 A9 C3 4A 3F 77 F1 80 .1@uM..2..J?w..
> )
> javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.501
> CET|SSLSocketImpl.java:1759|close the underlying socket
> javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.502
> CET|SSLSocketImpl.java:1785|close the SSL connection (initiative)
> javax.net.ssl|DEBUG|10|main|2025-03-28 18:11:23.502
> CET|SSLSocketImpl.java:1837|wait for close_notify or alert
> javax.net.ssl|DEBUG|10|main|2025-03-28 18:13:23.530
> CET|SSLSocketInputRecord.java:487|Raw read: EOF
> javax.net.ssl|DEBUG|10|main|2025-03-28 18:13:23.531
> CET|SSLSocketImpl.java:837|close inbound of SSLSocket
> javax.net.ssl|ALL|10|main|2025-03-28 18:13:23.532
> CET|SSLSocketImpl.java:1847|discard plaintext while waiting for close (
> contentType: 0/majorVersion: 0/minorVersion: 0/recordEpoch: -1/recordSN:
> 0xffffffffffffffff/fragment: null
> )
> 18:13:23.532 [main] DEBUG
> org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager -
> Connection pool shut down{noformat}
> Those traces has been captured on Windows.
> But the issue also occurs in linux-based production server.
>
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@hc.apache.org
For additional commands, e-mail: dev-h...@hc.apache.org
