Skip to content

Conversation

@jvgutierrez
Copy link
Member

@jvgutierrez jvgutierrez commented Sep 13, 2019

Debugging the SSL session cache I've found the following behaviour:

vgutierrez@cp5001:~$ openssl s_client -connect 127.0.0.1:443 -reconnect < /dev/null 2>1 |egrep -i "reconnect|reused"
drop connection and then reconnect
drop connection and then reconnect
drop connection and then reconnect
drop connection and then reconnect
drop connection and then reconnect

The expected output should be something like:

vgutierrez@cp5001:~$ openssl s_client -connect 127.0.0.1:4443 -reconnect < /dev/null 2>1 |egrep -i "reconnect|reused"
drop connection and then reconnect
Reused, TLSv1.2, Cipher is ECDHE-ECDSA-CHACHA20-POLY1305
drop connection and then reconnect
Reused, TLSv1.2, Cipher is ECDHE-ECDSA-CHACHA20-POLY1305
drop connection and then reconnect
Reused, TLSv1.2, Cipher is ECDHE-ECDSA-CHACHA20-POLY1305
drop connection and then reconnect
Reused, TLSv1.2, Cipher is ECDHE-ECDSA-CHACHA20-POLY1305
drop connection and then reconnect
Reused, TLSv1.2, Cipher is ECDHE-ECDSA-CHACHA20-POLY1305

Enabling the debug log for the session cache shows the following output:

[Sep 12 10:01:39.577] [ET_NET 0] DEBUG: <SSLUtils.cc:238 (ssl_new_cached_session)> (ssl.session_cache.insert) ssl_new_cached_session session '2C0460F5FA8B58E3B4E1146597A44F4AC3CB7FD5E602851FC27AC93D567ADEEB' and context 0x2940aa0
[Sep 12 10:01:39.577] [ET_NET 0] DEBUG: <SSLSessionCache.cc:110 (insertSession)> (ssl.session_cache.insert) SessionCache using bucket 194 (0x293b9d8): Inserting session '2C0460F5FA8B58E3B4E1146597A44F4AC3CB7FD5E602851FC27AC93D567ADEEB' (hash: EBDE7A563DC97AC2).
[Sep 12 10:01:39.577] [ET_NET 0] DEBUG: <SSLSessionCache.cc:129 (insertSession)> (ssl.session_cache) Inserting session '2C0460F5FA8B58E3B4E1146597A44F4AC3CB7FD5E602851FC27AC93D567ADEEB' to bucket 0x293b9d8.
[Sep 12 10:01:39.580] [ET_NET 0] DEBUG: <SSLUtils.cc:271 (ssl_rm_cached_session)> (ssl.session_cache.remove) ssl_rm_cached_session cached session '2C0460F5FA8B58E3B4E1146597A44F4AC3CB7FD5E602851FC27AC93D567ADEEB'
[Sep 12 10:01:39.580] [ET_NET 0] DEBUG: <SSLSessionCache.cc:90 (removeSession)> (ssl.session_cache.remove) SessionCache using bucket 194 (0x293b9d8): Removing session '2C0460F5FA8B58E3B4E1146597A44F4AC3CB7FD5E602851FC27AC93D567ADEEB' (hash: EBDE7A563DC97AC2).

As it can be observed from the logs, 2C0460F5FA8B58E3B4E1146597A44F4AC3CB7FD5E602851FC27AC93D567ADEEB gets saved into the session cache at 10:01:39.577 and gets evicted at 10:01:39.580

Tracking this behaviour with gdb we can see how ssl_rm_cached_session is triggered:

#0  ssl_rm_cached_session (ctx=0x188db10, sess=0x2ad5e802a910) at SSLUtils.cc:304
#1  0x00002ad5d30030f9 in remove_session_lock (ctx=0x188db10, c=0x2ad5e802a910, lck=<optimized out>) at ../ssl/ssl_sess.c:738
#2  0x00002ad5d3003eff in ssl_clear_bad_session (s=s@entry=0x2ad5e8028870) at ../ssl/ssl_sess.c:1032
#3  0x00002ad5d2ffefe6 in SSL_free (s=0x2ad5e8028870) at ../ssl/ssl_lib.c:1145
#4  0x0000000000669128 in SSLNetVConnection::clear (this=0x2ad618020bf0) at SSLNetVConnection.cc:920
#5  0x00000000006692e4 in SSLNetVConnection::free (this=0x2ad618020bf0, t=0x2ad5d8d6c010) at SSLNetVConnection.cc:954
#6  0x000000000068b4d3 in read_signal_and_update (event=104, vc=0x2ad618020bf0) at UnixNetVConnection.cc:102
#7  0x000000000068b2be in read_signal_done (event=25746192, nh=0x2ad5d8d6fcf0, vc=0x2ad618020bf0) at UnixNetVConnection.cc:144
#8  UnixNetVConnection::readSignalDone (this=0x2ad618020bf0, event=25746192, nh=0x2ad5d8d6fcf0) at UnixNetVConnection.cc:1041
#9  0x000000000066729a in SSLNetVConnection::net_read_io (this=0x2ad618020bf0, nh=0x2ad5d8d6fcf0, lthread=<optimized out>) at SSLNetVConnection.cc:696
#10 0x000000000067f6ef in NetHandler::process_ready_list (this=0x2ad5d8d6fcf0) at UnixNet.cc:395
#11 0x000000000067ff8c in NetHandler::waitForActivity (this=<optimized out>, timeout=<optimized out>) at UnixNet.cc:528
#12 0x000000000068006a in non-virtual thunk to NetHandler::waitForActivity(long) ()
#13 0x00000000006ae762 in EThread::execute_regular (this=0x2ad5d8d6c010) at UnixEThread.cc:272
#14 0x00000000006ad369 in spawn_thread_internal (a=0x17f0aa0) at Thread.cc:85
#15 0x00002ad5d39dd4a4 in start_thread (arg=0x2ad5d917d700) at pthread_create.c:456
#16 0x00002ad5d465bd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

ssl_rm_cached_session gets called after being triggered by SSL_free() --> ssl_clear_bad_session().

SSL quiet shutdown got removed from ATS as part of 03734d0 because it prevents close-notify from being set. This PR re-introduces SSL quiet shutdown iff close-notify is not sent and the SSL handshake has been completed.
With the patch applied, openssl s_client -reconnect behaves as expected:

openssl s_client -connect 127.0.0.1:443 -reconnect </dev/null 2>&1 |egrep -i "reconnect|reused"
drop connection and then reconnect
Reused, TLSv1/SSLv3, Cipher is ECDHE-ECDSA-AES256-GCM-SHA384
drop connection and then reconnect
Reused, TLSv1/SSLv3, Cipher is ECDHE-ECDSA-AES256-GCM-SHA384
drop connection and then reconnect
Reused, TLSv1/SSLv3, Cipher is ECDHE-ECDSA-AES256-GCM-SHA384
drop connection and then reconnect
Reused, TLSv1/SSLv3, Cipher is ECDHE-ECDSA-AES256-GCM-SHA384
drop connection and then reconnect
Reused, TLSv1/SSLv3, Cipher is ECDHE-ECDSA-AES256-GCM-SHA384

@zwoop zwoop mentioned this pull request Sep 13, 2019
44 tasks
@jvgutierrez jvgutierrez force-pushed the quiet-shutdown branch 2 times, most recently from 8441cd8 to c7df148 Compare September 15, 2019 09:41
@shinrich shinrich added the TLS label Sep 16, 2019
@shinrich shinrich added this to the 10.0.0 milestone Sep 16, 2019
@bryancall bryancall merged commit acf2fb7 into apache:master Sep 19, 2019
@zwoop
Copy link
Contributor

zwoop commented Oct 1, 2019

Cherry-picked to v9.0.x branch.

@zwoop zwoop modified the milestones: 10.0.0, 9.0.0 Oct 1, 2019
@zwoop
Copy link
Contributor

zwoop commented Oct 1, 2019

If this goes into 8.0.6, and released before v9.0.0, then change the Milestone accordingly.

@bryancall bryancall modified the milestones: 9.0.0, 8.0.6 Oct 30, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants