You are viewing a plain text version of this content. The canonical link for it is here.
Posted to httpclient-users@hc.apache.org by Jason Parraga <so...@gmail.com> on 2017/10/27 02:02:53 UTC
Observing sticky TLS versions in ClientHello messages between
requests to same host
To whom it may concern:
Issue: I encountered a protocol_version SSLException when a remote
server rebooted and transitioned from only supporting TLS 1.0 to only
supporting TLS 1.2. From my understanding the exception means that a
common TLS version could not be negotiated.
I investigated the ClientHello messages using Wireshark and indeed
noticed that a TLS 1.0 ClientHello was being sent. What I found
strange was that upon restarting the JVM a TLS 1.2 ClientHello was
sent to the remote server and the SSL handshake completed
successfully.
I spent a few hours looking into the source code to understand what
might be going on but was unable to find anything conclusive. I did
however find some DEBUG level log messages that I think are relevant.
Here is the output during the failure:
2017-10-25T03:50:39.437+00:00 floodlight: DEBUG
[RequestAddCookies:Slrest-http-285] CookieSpec selected: default
2017-10-25T03:50:39.439+00:00 floodlight: DEBUG
[RequestAuthCache:Slrest-http-285] Re-using cached 'basic' auth scheme
for https://[fe80::5054:ff:fe32:d659%ens4]:443
2017-10-25T03:50:39.439+00:00 floodlight: DEBUG
[PoolingHttpClientConnectionManager:Slrest-http-285] Connection
request: [route:
{s}->https://[fe80::5054:ff:fe32:d659%ens4]:443][total kept alive: 0;
route allocated: 0 of 5; total allocated: 0 of 50]
2017-10-25T03:50:39.439+00:00 floodlight: DEBUG
[PoolingHttpClientConnectionManager:Slrest-http-285] Connection
leased: [id: 278][route:
{s}->https://[fe80::5054:ff:fe32:d659%ens4]:443][total kept alive: 0;
route allocated: 1 of 5; total allocated: 1 of 50]
2017-10-25T03:50:39.439+00:00 floodlight: DEBUG
[MainClientExec:Slrest-http-285] Opening connection
{s}->https://[fe80::5054:ff:fe32:d659%ens4]:443
2017-10-25T03:50:39.439+00:00 floodlight: DEBUG
[DefaultHttpClientConnectionOperator:Slrest-http-285] Connecting to
/fe80:0:0:0:5054:ff:fe32:d659%ens4:443
2017-10-25T03:50:39.440+00:00 floodlight: DEBUG
[SSLConnectionSocketFactory:Slrest-http-285] Connecting socket to
/fe80:0:0:0:5054:ff:fe32:d659%ens4:443 with timeout 2000
2017-10-25T03:50:39.441+00:00 floodlight: DEBUG
[SSLConnectionSocketFactory:Slrest-http-285] Enabled protocols:
[TLSv1, TLSv1.1, TLSv1.2]
2017-10-25T03:50:39.441+00:00 floodlight: DEBUG
[SSLConnectionSocketFactory:Slrest-http-285] Enabled cipher
suites:[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, ... (redacted for
brevity)]
2017-10-25T03:50:39.441+00:00 floodlight: DEBUG
[SSLConnectionSocketFactory:Slrest-http-285] Starting handshake
2017-10-25T03:50:39.444+00:00 floodlight: DEBUG
[DefaultManagedHttpClientConnection:Slrest-http-285]
http-outgoing-278: Shutdown connection
2017-10-25T03:50:39.444+00:00 floodlight: DEBUG
[MainClientExec:Slrest-http-285] Connection discarded
2017-10-25T03:50:39.444+00:00 floodlight: DEBUG
[PoolingHttpClientConnectionManager:Slrest-http-285] Connection
released: [id: 278][route:
{s}->https://[fe80::5054:ff:fe32:d659%ens4]:443][total kept alive: 0;
route allocated: 0 of 5; total allocated: 0 of 50]
Here is the successful output after restarting the JVM:
2017-10-25T03:53:30.245+00:00 floodlight: DEBUG
[RequestAddCookies:Slrest-http-3] CookieSpec selected: default
2017-10-25T03:53:30.247+00:00 floodlight: DEBUG
[RequestAuthCache:Slrest-http-3] Re-using cached 'basic' auth scheme
for https://[fe80::5054:ff:fe32:d659%ens4]:443
2017-10-25T03:53:30.247+00:00 floodlight: DEBUG
[PoolingHttpClientConnectionManager:Slrest-http-3] Connection request:
[route: {s}->https://[fe80::5054:ff:fe32:d659%ens4]:443][total kept
alive: 1; route allocated: 1 of 5; total allocated: 1 of 50]
2017-10-25T03:53:30.250+00:00 floodlight: DEBUG
[DefaultManagedHttpClientConnection:Slrest-http-3] http-outgoing-2:
Close connection
2017-10-25T03:53:30.250+00:00 floodlight: DEBUG
[PoolingHttpClientConnectionManager:Slrest-http-3] Connection leased:
[id: 3][route: {s}->https://[fe80::5054:ff:fe32:d659%ens4]:443][total
kept alive: 0; route allocated: 1 of 5; total allocated: 1 of 50]
2017-10-25T03:53:30.250+00:00 floodlight: DEBUG
[MainClientExec:Slrest-http-3] Opening connection
{s}->https://[fe80::5054:ff:fe32:d659%ens4]:443
2017-10-25T03:53:30.251+00:00 floodlight: DEBUG
[DefaultHttpClientConnectionOperator:Slrest-http-3] Connecting to
/fe80:0:0:0:5054:ff:fe32:d659%ens4:443
2017-10-25T03:53:30.251+00:00 floodlight: DEBUG
[SSLConnectionSocketFactory:Slrest-http-3] Connecting socket to
/fe80:0:0:0:5054:ff:fe32:d659%ens4:443 with timeout 2000
2017-10-25T03:53:30.252+00:00 floodlight: DEBUG
[SSLConnectionSocketFactory:Slrest-http-3] Enabled protocols: [TLSv1,
TLSv1.1, TLSv1.2]
2017-10-25T03:53:30.252+00:00 floodlight: DEBUG
[SSLConnectionSocketFactory:Slrest-http-3] Enabled cipher
suites:[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, .. (redacted for
brevity)]
2017-10-25T03:53:30.252+00:00 floodlight: DEBUG
[SSLConnectionSocketFactory:Slrest-http-3] Starting handshake
2017-10-25T03:53:30.273+00:00 floodlight: DEBUG
[SSLConnectionSocketFactory:Slrest-http-3] Secure session established
2017-10-25T03:53:30.273+00:00 floodlight: DEBUG
[SSLConnectionSocketFactory:Slrest-http-3] negotiated protocol:
TLSv1.2
2017-10-25T03:53:30.273+00:00 floodlight: DEBUG
[SSLConnectionSocketFactory:Slrest-http-3] negotiated cipher suite:
TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
2017-10-25T03:53:31.117+00:00 floodlight: DEBUG
[MainClientExec:Slrest-http-3] Connection can be kept alive
indefinitely
2017-10-25T03:53:31.117+00:00 floodlight: DEBUG
[HttpAuthenticator:Slrest-http-3] Authentication succeeded
2017-10-25T03:53:31.117+00:00 floodlight: DEBUG
[TargetAuthenticationStrategy:Slrest-http-3] Caching 'basic' auth
scheme for https://[fe80::5054:ff:fe32:d659%ens4]:443
2017-10-25T03:53:31.119+00:00 floodlight: DEBUG
[PoolingHttpClientConnectionManager:Slrest-http-3] Connection [id:
3][route: {s}->https://[fe80::5054:ff:fe32:d659%ens4]:443] can be kept
alive indefinitely
2017-10-25T03:53:31.119+00:00 floodlight: DEBUG
[PoolingHttpClientConnectionManager:Slrest-http-3] Connection
released: [id: 3][route:
{s}->https://[fe80::5054:ff:fe32:d659%ens4]:443][total kept alive: 1;
route allocated: 1 of 5; total allocated: 1 of 50]
From the log messages it looks like TLS 1.0, 1.1, and 1.2 are
available but still, a ClientHello with version TLS 1.0 is sent.
Question: Does HttpClient perform any caching that would explain this
behavior?
Libraries: HttpCore v4.4.6 + HttpClient v4.5.3
Thanks for your time.
--
Jason Parraga
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Observing sticky TLS versions in ClientHello messages between
requests to same host
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Thu, 2017-10-26 at 19:02 -0700, Jason Parraga wrote:
> To whom it may concern:
>
> Issue: I encountered a protocol_version SSLException when a remote
> server rebooted and transitioned from only supporting TLS 1.0 to only
> supporting TLS 1.2. From my understanding the exception means that a
> common TLS version could not be negotiated.
>
> I investigated the ClientHello messages using Wireshark and indeed
> noticed that a TLS 1.0 ClientHello was being sent. What I found
> strange was that upon restarting the JVM a TLS 1.2 ClientHello was
> sent to the remote server and the SSL handshake completed
> successfully.
>
> I spent a few hours looking into the source code to understand what
> might be going on but was unable to find anything conclusive. I did
> however find some DEBUG level log messages that I think are relevant.
>
> Here is the output during the failure:
>
> 2017-10-25T03:50:39.437+00:00 floodlight: DEBUG
> [RequestAddCookies:Slrest-http-285] CookieSpec selected: default
> 2017-10-25T03:50:39.439+00:00 floodlight: DEBUG
> [RequestAuthCache:Slrest-http-285] Re-using cached 'basic' auth
> scheme
> for https://[fe80::5054:ff:fe32:d659%ens4]:443
> 2017-10-25T03:50:39.439+00:00 floodlight: DEBUG
> [PoolingHttpClientConnectionManager:Slrest-http-285] Connection
> request: [route:
> {s}->https://[fe80::5054:ff:fe32:d659%ens4]:443][total kept alive: 0;
> route allocated: 0 of 5; total allocated: 0 of 50]
> 2017-10-25T03:50:39.439+00:00 floodlight: DEBUG
> [PoolingHttpClientConnectionManager:Slrest-http-285] Connection
> leased: [id: 278][route:
> {s}->https://[fe80::5054:ff:fe32:d659%ens4]:443][total kept alive: 0;
> route allocated: 1 of 5; total allocated: 1 of 50]
> 2017-10-25T03:50:39.439+00:00 floodlight: DEBUG
> [MainClientExec:Slrest-http-285] Opening connection
> {s}->https://[fe80::5054:ff:fe32:d659%ens4]:443
> 2017-10-25T03:50:39.439+00:00 floodlight: DEBUG
> [DefaultHttpClientConnectionOperator:Slrest-http-285] Connecting to
> /fe80:0:0:0:5054:ff:fe32:d659%ens4:443
> 2017-10-25T03:50:39.440+00:00 floodlight: DEBUG
> [SSLConnectionSocketFactory:Slrest-http-285] Connecting socket to
> /fe80:0:0:0:5054:ff:fe32:d659%ens4:443 with timeout 2000
> 2017-10-25T03:50:39.441+00:00 floodlight: DEBUG
> [SSLConnectionSocketFactory:Slrest-http-285] Enabled protocols:
> [TLSv1, TLSv1.1, TLSv1.2]
> 2017-10-25T03:50:39.441+00:00 floodlight: DEBUG
> [SSLConnectionSocketFactory:Slrest-http-285] Enabled cipher
> suites:[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, ... (redacted for
> brevity)]
> 2017-10-25T03:50:39.441+00:00 floodlight: DEBUG
> [SSLConnectionSocketFactory:Slrest-http-285] Starting handshake
> 2017-10-25T03:50:39.444+00:00 floodlight: DEBUG
> [DefaultManagedHttpClientConnection:Slrest-http-285]
> http-outgoing-278: Shutdown connection
> 2017-10-25T03:50:39.444+00:00 floodlight: DEBUG
> [MainClientExec:Slrest-http-285] Connection discarded
> 2017-10-25T03:50:39.444+00:00 floodlight: DEBUG
> [PoolingHttpClientConnectionManager:Slrest-http-285] Connection
> released: [id: 278][route:
> {s}->https://[fe80::5054:ff:fe32:d659%ens4]:443][total kept alive: 0;
> route allocated: 0 of 5; total allocated: 0 of 50]
>
> Here is the successful output after restarting the JVM:
>
> 2017-10-25T03:53:30.245+00:00 floodlight: DEBUG
> [RequestAddCookies:Slrest-http-3] CookieSpec selected: default
> 2017-10-25T03:53:30.247+00:00 floodlight: DEBUG
> [RequestAuthCache:Slrest-http-3] Re-using cached 'basic' auth scheme
> for https://[fe80::5054:ff:fe32:d659%ens4]:443
> 2017-10-25T03:53:30.247+00:00 floodlight: DEBUG
> [PoolingHttpClientConnectionManager:Slrest-http-3] Connection
> request:
> [route: {s}->https://[fe80::5054:ff:fe32:d659%ens4]:443][total kept
> alive: 1; route allocated: 1 of 5; total allocated: 1 of 50]
> 2017-10-25T03:53:30.250+00:00 floodlight: DEBUG
> [DefaultManagedHttpClientConnection:Slrest-http-3] http-outgoing-2:
> Close connection
> 2017-10-25T03:53:30.250+00:00 floodlight: DEBUG
> [PoolingHttpClientConnectionManager:Slrest-http-3] Connection leased:
> [id: 3][route: {s}->https://[fe80::5054:ff:fe32:d659%ens4]:443][total
> kept alive: 0; route allocated: 1 of 5; total allocated: 1 of 50]
> 2017-10-25T03:53:30.250+00:00 floodlight: DEBUG
> [MainClientExec:Slrest-http-3] Opening connection
> {s}->https://[fe80::5054:ff:fe32:d659%ens4]:443
> 2017-10-25T03:53:30.251+00:00 floodlight: DEBUG
> [DefaultHttpClientConnectionOperator:Slrest-http-3] Connecting to
> /fe80:0:0:0:5054:ff:fe32:d659%ens4:443
> 2017-10-25T03:53:30.251+00:00 floodlight: DEBUG
> [SSLConnectionSocketFactory:Slrest-http-3] Connecting socket to
> /fe80:0:0:0:5054:ff:fe32:d659%ens4:443 with timeout 2000
> 2017-10-25T03:53:30.252+00:00 floodlight: DEBUG
> [SSLConnectionSocketFactory:Slrest-http-3] Enabled protocols: [TLSv1,
> TLSv1.1, TLSv1.2]
> 2017-10-25T03:53:30.252+00:00 floodlight: DEBUG
> [SSLConnectionSocketFactory:Slrest-http-3] Enabled cipher
> suites:[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, .. (redacted for
> brevity)]
> 2017-10-25T03:53:30.252+00:00 floodlight: DEBUG
> [SSLConnectionSocketFactory:Slrest-http-3] Starting handshake
> 2017-10-25T03:53:30.273+00:00 floodlight: DEBUG
> [SSLConnectionSocketFactory:Slrest-http-3] Secure session established
> 2017-10-25T03:53:30.273+00:00 floodlight: DEBUG
> [SSLConnectionSocketFactory:Slrest-http-3] negotiated protocol:
> TLSv1.2
> 2017-10-25T03:53:30.273+00:00 floodlight: DEBUG
> [SSLConnectionSocketFactory:Slrest-http-3] negotiated cipher suite:
> TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
> 2017-10-25T03:53:31.117+00:00 floodlight: DEBUG
> [MainClientExec:Slrest-http-3] Connection can be kept alive
> indefinitely
> 2017-10-25T03:53:31.117+00:00 floodlight: DEBUG
> [HttpAuthenticator:Slrest-http-3] Authentication succeeded
> 2017-10-25T03:53:31.117+00:00 floodlight: DEBUG
> [TargetAuthenticationStrategy:Slrest-http-3] Caching 'basic' auth
> scheme for https://[fe80::5054:ff:fe32:d659%ens4]:443
> 2017-10-25T03:53:31.119+00:00 floodlight: DEBUG
> [PoolingHttpClientConnectionManager:Slrest-http-3] Connection [id:
> 3][route: {s}->https://[fe80::5054:ff:fe32:d659%ens4]:443] can be
> kept
> alive indefinitely
> 2017-10-25T03:53:31.119+00:00 floodlight: DEBUG
> [PoolingHttpClientConnectionManager:Slrest-http-3] Connection
> released: [id: 3][route:
> {s}->https://[fe80::5054:ff:fe32:d659%ens4]:443][total kept alive: 1;
> route allocated: 1 of 5; total allocated: 1 of 50]
>
> From the log messages it looks like TLS 1.0, 1.1, and 1.2 are
> available but still, a ClientHello with version TLS 1.0 is sent.
>
> Question: Does HttpClient perform any caching that would explain this
> behavior?
>
> Libraries: HttpCore v4.4.6 + HttpClient v4.5.3
>
> Thanks for your time.
>
Jason
HttpComponents do not implement any SSL/TLS specific aspects and fully
rely on JSSE APIs and JSSE providers for matters of transport security.
HttpClient does not perform SSL session caching but as far as I know
JSSE providers might.
Hope this helps somehow.
Oleg
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org