HTTPS session resumption sometimes partially working
I'm having an issue with ssl session caching. To test if server configuration is OK, I use the following command:
echo | openssl s_client -connect <server.com>:443 -reconnect 2>/dev/null| egrep -iw "New|Reused|Session-ID:"
It outputs "New" for the first request, and then "Reused". So server config seems ok.
When I look at apache2 access.log I can see that for some clients, it is working as expected. The best way I found so far to diagnose ssl session resumption is to look at the sent byte count (%O).
Example of a working client log :
IP - - [D:10:36:59] "GET /rest/instant_message/TEST HTTP/1.1" 200 13 5142 "-" "Dalvik/2.1.0 (Linux; U; Android 8.1.0; iot800n Build/OPM6.171019.030.K1)"
IP - - [D:10:37:00] "GET /rest/instant_message/TEST HTTP/1.1" 200 13 482 "-" "Dalvik/2.1.0 (Linux; U; Android 8.1.0; iot800n Build/OPM6.171019.030.K1)"
IP - - [D:10:37:03] "GET /rest/instant_message/TEST HTTP/1.1" 200 13 635 "-" "Dalvik/2.1.0 (Linux; U; Android 8.1.0; iot800n Build/OPM6.171019.030.K1)"
IP - - [D:10:37:04] "GET /rest/instant_message/TEST HTTP/1.1" 200 13 482 "-" "Dalvik/2.1.0 (Linux; U; Android 8.1.0; iot800n Build/OPM6.171019.030.K1)"
IP - - [D:10:37:06] "GET /rest/instant_message/TEST HTTP/1.1" 200 13 482 "-" "Dalvik/2.1.0 (Linux; U; Android 8.1.0; iot800n Build/OPM6.171019.030.K1)"
IP - - [D:10:37:09] "GET /rest/instant_message/TEST HTTP/1.1" 200 13 635 "-" "Dalvik/2.1.0 (Linux; U; Android 8.1.0; iot800n Build/OPM6.171019.030.K1)"
IP - - [D:10:37:11] "GET /rest/instant_message/TEST HTTP/1.1" 200 13 482 "-" "Dalvik/2.1.0 (Linux; U; Android 8.1.0; iot800n Build/OPM6.171019.030.K1)"
IP - - [D:10:37:13] "GET /rest/instant_message/TEST HTTP/1.1" 200 13 635 "-" "Dalvik/2.1.0 (Linux; U; Android 8.1.0; iot800n Build/OPM6.171019.030.K1)"
IP - - [D:10:37:15] "GET /rest/instant_message/TEST HTTP/1.1" 200 13 482 "-" "Dalvik/2.1.0 (Linux; U; Android 8.1.0; iot800n Build/OPM6.171019.030.K1)"
IP - - [D:10:37:17] "GET /rest/instant_message/TEST HTTP/1.1" 200 13 482 "-" "Dalvik/2.1.0 (Linux; U; Android 8.1.0; iot800n Build/OPM6.171019.030.K1)"
IP - - [D:10:37:19] "GET /rest/instant_message/TEST HTTP/1.1" 200 13 635 "-" "Dalvik/2.1.0 (Linux; U; Android 8.1.0; iot800n Build/OPM6.171019.030.K1)"
In the log above, you can see that the first request response is 5142 bytes (13 content length). And all subsequent requests responses are 482 or 635 bytes (same content length).
However for some clients, all requests responses are ~5kb. As shown in the example log bellow:
IP - - [D:10:30:45] "GET /rest/instant_message/BOM1 HTTP/1.1" 200 419 5549 "-" "Dalvik/2.1.0 (Linux; U; Android 9; SM-T395 Build/PPR1.180610.011)"
IP - - [D:10:31:00] "GET /rest/instant_message/BOM1 HTTP/1.1" 200 419 5549 "-" "Dalvik/2.1.0 (Linux; U; Android 9; SM-T395 Build/PPR1.180610.011)"
IP - - [D:10:31:15] "GET /rest/instant_message/BOM1 HTTP/1.1" 200 419 5549 "-" "Dalvik/2.1.0 (Linux; U; Android 9; SM-T395 Build/PPR1.180610.011)"
IP - - [D:10:31:30] "GET /rest/instant_message/BOM1 HTTP/1.1" 200 419 5549 "-" "Dalvik/2.1.0 (Linux; U; Android 9; SM-T395 Build/PPR1.180610.011)"
IP - - [D:10:31:45] "GET /rest/instant_message/BOM1 HTTP/1.1" 200 419 5549 "-" "Dalvik/2.1.0 (Linux; U; Android 9; SM-T395 Build/PPR1.180610.011)"
IP - - [D:10:32:00] "GET /rest/instant_message/BOM1 HTTP/1.1" 200 419 5549 "-" "Dalvik/2.1.0 (Linux; U; Android 9; SM-T395 Build/PPR1.180610.011)"
IP - - [D:10:32:15] "GET /rest/instant_message/BOM1 HTTP/1.1" 200 419 5549 "-" "Dalvik/2.1.0 (Linux; U; Android 9; SM-T395 Build/PPR1.180610.011)"
IP - - [D:10:32:30] "GET /rest/instant_message/BOM1 HTTP/1.1" 200 419 5549 "-" "Dalvik/2.1.0 (Linux; U; Android 9; SM-T395 Build/PPR1.180610.011)"
IP - - [D:10:32:45] "GET /rest/instant_message/BOM1 HTTP/1.1" 200 419 5549 "-" "Dalvik/2.1.0 (Linux; U; Android 9; SM-T395 Build/PPR1.180610.011)"
Sometimes, the same client (same ip) will sometimes use session resumption, then stop using it, then reuse it, etc.
All clients are the same android tablets (SMT395) running the same application using the Volley library for http requests. They are connected to internet with a SIM Card.
Server conf is :
SSLSessionCache shmcb:${APACHE_RUN_DIR}/ssl_scache(512000)
SSLSessionCacheTimeout 300
What could be the cause of the non-resumption of the https session ? What tools can I use to debug the https session ?
The best way I found so far to diagnose ssl session resumption is to look at the sent byte count
First, enable mod_status and set ExtendedStatus to On. Make sure this status page is non-public accessible, probably with ACL or basic authentication with strong password.
You should be able to see session cache usage from your httpd status page, something like
SSL/TLS Session Cache Status:
cache type: SHMCB, shared memory: 512000 bytes, current sessions: 1
sub-caches: 32, indexes per sub-cache: 133
time left on oldest entries' SSL sessions: avg: 297 seconds, (range: 297...297)
index usage: 0%, cache usage: 0%
total sessions stored since starting: 1
total sessions expired since starting: 0
total (pre-expiry) sessions scrolled out of the cache: 0
total retrieves since starting: 1 hit, 1 miss
total removes since starting: 0 hit, 0 miss
Thus giving you a general overview about your TLS/SSL cache usage. This will verify if your cache is full (high index and/or cache usage), thus requiring you to increase your cache size; or if your number of clients is small, a bad behaving client.
Also check cache hits and misses to verify if your server and your client is using session resumption.
Then, enable debug logging for mod_ssl, something like
<IfModule mod_ssl.c>
ErrorLog /var/log/apache2/ssl_engine.log
LogLevel ssl:debug
</IfModule>
should suffice.
This will output huge detailed logs about SSL module in your httpd instance, including session generation, resumption, and expiration. Test with your OK and faulty clients to see the difference.
Sometimes, the same client (same ip) will sometimes use session resumption, then stop using it, then reuse it, etc.
How many clients are connecting to the server? How much RAM the server has? shmcb is a shared memory cache, and 512kB should be adequate for a low traffic server, but I suspect 512kB is not enough for your implementation.
What could be the cause of the non-resumption of the https session ?
A lot. It depends on your TLS version (< 1.3, >= 1.3? SSL session resumption is already in TLS since at least v1.1, but revamped in v1.3), your client application, your client SSL library, etc.