Observing sticky TLS versions in ClientHello messages between requests to same host

[Jason Parraga]

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.

[Oleg Kalnichevski]

Post by Jason Parraga
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.
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
{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
{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
[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
{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: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
[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
Close connection
2017-10-25T03:53:30.250+00:00 floodlight: DEBUG
[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
TLSv1.2
2017-10-25T03:53:30.273+00:00 floodlight: DEBUG
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
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
{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-***@hc.apache.org
For additional commands, e-mail: httpclient-users-***@hc.apache.org