Why is the HTTP session not re-used?

Question

Our .NET CF 3.5 application connects to two different endpoints/URLs, https://api.reservix.de/1/system/time and https://test.acm.reservix.io/graphql, using Rebex HTTPS in the latest version 2019R3.

Sending two consecutive GET requests to the same URL within some seconds, we expect the HTTP session from the first request to be re-used in the second request.

Connecting to the first endpoint api.reservix.de, this works as expected, as we can see in the Rebex debug log:

2019-09-13 18:39:02 DEBUG HttpRequest(1)[-190209506] HTTP: Using new HTTP session (1) provided by Rebex.Net.HttpRequestCreator(1).
…
2019-09-13 18:39:17 DEBUG HttpRequest(2)[-190209506] HTTP: Using
cached HTTP session (1) provided by Rebex.Net.HttpRequestCreator(1).

Connecting to the second endpoint test.acm.reservix.io, the HTTP session is not re-used, as we can see in the Rebex debug log:

2019-09-13 18:34:52 DEBUG HttpRequest(1)[303891110] HTTP: Using new HTTP session (1) provided by Rebex.Net.HttpRequestCreator(1).
…
2019-09-13 18:34:59 DEBUG HttpRequest(1)[303891110] HTTP: Closing HTTP session (1).
2019-09-13 18:35:06 DEBUG HttpRequest(2)[303891110] HTTP: Using new HTTP session (2) provided by Rebex.Net.HttpRequestCreator(1).

A difference we spotted between first and the second endpoint in the logs: There seems to be no TLS Session ID emitted by the server.

2019-09-13 18:39:08 DEBUG HttpRequest(1)[-190209506] TLS: Session ID:
0000 |6B-A3-02-D6-DD-0B-C2-38 A6-D0-CD-CC-A3-CA-7C-C8| k......8......|.
0010 |1E-A7-FD-DC-A3-14-78-0A B4-8D-CA-05-49-37-C5-5E| ......x.....I7.^
2019-09-13 18:39:08 INFO HttpRequest(1)[-190209506] HTTP: Sending request: GET /1/system/time

versus

2019-09-13 18:34:58 DEBUG HttpRequest(1)[303891110] TLS: Session ID:
2019-09-13 18:34:58 INFO HttpRequest(1)[303891110] HTTP: Sending request: GET /graphql

The application is the same for both endpoints, running on the same Windows Embedded Handheld 6.5 device via the same internet connection.

The Rebex HttpRequestCreator initialization code looks like this:

HttpRequestCreator creator = new HttpRequestCreator();
creator.Settings.AutoConnectToInternet = AutoConnectType.Enabled;
creator.Settings.HttpSessionCacheEnabled = true;
creator.LogWriter = new Rebex.FileLogWriter(path, Rebex.LogLevel.Debug);
creator.Register();
AsymmetricKeyAlgorithm.Register(EllipticCurveAlgorithm.Create);
AsymmetricKeyAlgorithm.Register(Curve25519.Create);

The code starting requests looks like this:

HttpRequest request = (HttpRequest)WebRequest.Create(url);
try {
    using (var response = (HttpResponse)request.GetResponse()) {
        try {
            …
        } finally {
            if (response != null) {
                response.Close();
            }
        }
    }
} finally {
    if (request != null) {
        request.Abort();
    }
    request = null;
}

Basically, the connection can be re-used for the second request on both endpoints, as we observed using curl [url] [url] -v --tlsv1.2 with the following output:

Connected to api.reservix.de (46.243.94.27) port 443 (#0)
…
Connection #0 to host api.reservix.de left intact
Found bundle for host api.reservix.de: 0x207948b34d0 [can pipeline]
Re-using existing connection! (#0) with host api.reservix.de

… and also:

Connected to test.acm.reservix.io (143.204.214.14) port 443 (#0)
…
Connection #0 to host test.acm.reservix.io left intact
Found bundle for host test.acm.reservix.io: 0x26a4d462610 [can pipeline]
Re-using existing connection! (#0) with host test.acm.reservix.io

From our point of view, Rebex HTTPS should re-use the HTTP session on both endpoints as well.

Without reusing HTTP sessions, consecutive requests to the same endpoint consume much more time and data, though the handshake has to be done before every new request again. Therefore we classify the reason for this behavior as a serious bug.

Comments

We were unable to match your forum account to any license purchase in our database. Please contact support@rebex.net and provide an order number so we can fix this. We are unable to provide continued support to you otherwise. Sorry for the inconvenience!

---

I have sent the license information via e-mail.

---

Thanks! We have updated our database.

Answer 1

1. Please note that the "TLS: Session ID" is not related to HTTP session caching at all. It is instead related to TLS sessions, a feature of TLS protocol that makes it possible to speed-up TLS negotiations when reconnecting to the same server by using an abbreviated variant of TLS handshake. The lack of Session ID in one of your logs indicates that TLS sessions are not enabled on one of your servers. This does not affect HTTP sessions, but it means that TLS negotiation on subsequent connections will be substantially slower.

2. To be able to determine why Rebex HTTPS reused the HTTP session with one server and not with the other server, we have to first analyze the whole log showing both the requests and their context. Could you please provide a more complete version of the log? Either post it here or mail it to support@rebex.net .

3. Which version of Curl did you use? It is possible that the observed difference in behavior was due to Curl's usage of HTTP pipelining. Although this is a nice feature, it turned out to be so problematic that Curl recently disabled it. However, your log entry contains "[can pipeline]", which suggests that pipelining might have been used, and this might have affected server's behavior.

Comments

I have sent the complete log files via e-mail to support@rebex.net.

Two files show the debug level Rebex HTTPS log file, showing subsequent connections to api.reservix.de respectively test.acm.reservix.io (with some seconds break between two requests).

Two files show the verbose cURL output, showing subsequent connections to api.reservix.de respectively test.acm.reservix.io (within one cURL call, though no break between requests). The cURL version number is in the logs. Even with the latest cURL version 7.66 (with pipelining disabled), the connection is held.

The last file is a Wireshark recording of the Chrome browser when calling test.acm.reservix.io and a page refresh after 7 seconds, showing that the TCP connection is held up to the seconds request (and HTTP keep-alive is working later).

Thanks for explaining the TLS Session ID! Does Rebex HTTPS for .NET CF makes use of it (after the TCP connection has been closed)?

---

Thanks for the logs!

According to the Rebex log of test.acm.reservix.io, I would assume that the session would get cached - we cannot see any apparent reason for not reusing that session.
One possible cause might be a custom code that does not read the whole response of the first request closing its stream, which would cause Rebex HTTPS to discard the session instead of caching it. Otherwise, this might be a bug in Rebex HTTPS.

To aid us in the search for a cause of the issue, we added more logging into Rebex HTTPS, which should hopefully make it possible to determine actual reason for not caching the connection. Please download it (I sent a link to your e-mail) and give it a try. It will behave like your current version, but the log will contain additional information.

Rebex HTTPS for .NET CF does make use of the TLS Session ID if presented by the server. There are actually two different caches inside - one for TLS sessions, and another one for HTTP sessions.

---

We have created new log Rebex HTTPS log files with the hotfix build 7200 and sent to support@rebex.net.

There are three consecutive requests inside (for each endpoint), with a break of 7 seconds between the first and the second request (where the HTTP session should be re-used) and a break of 60 seconds between the second and the third request (where the TLS session should be re-used).

The connection to the endpoint api.reservix.de does support re-using the HTTP session, but not the TLS session. Right?
The connection to the endpoint test.acm.reservix.io does support re-using neither HTTP session nor TLS session.

---

Thanks for the logs! Additional logging was indeed helpful as it confirmed that although the whole response has been read, our receiving class still treated it as unfinished due to a bug (which only manifests when reading from the stream in a certain way, possibly without waiting for the final Read method to return 0 when all data has been received). I sent a link to a hotfix to your e-mail that should resolve the issue - if it doesn't, please create a log (endpoint test.acm.reservix.io would be sufficient) and mail it to as once more.

Both endpoints support re-using of HTTP sessions, but a bug in Rebex HTTPS prevented this from working properly with test.acm.reservix.io.

Endpoint api.reservix.de provides TLS session ID, which indicates that it might support reusing TLS sessions. However, when the client later (at 2019-09-17 15:05:18 in the log) tries to actually resume a session, the server instead proceeds to negotiate a new one (rejecting client's renegotiation attempt). But it is quite possible that the server removed that session ID from its cache by that time (the client attempted resuming the TLS session 70 seconds after it obtained the session ID, and 19 seconds after the HTTP session based on that TLS session was closed).

Endpoint test.acm.reservix.io does not provide any TLS session IDs, which implies that it does not support this TLS feature.

Answer 2

This has been caused by a bug in detection of cachable HTTP session that prevented sessions from being cached in some scenarios. We have fixed this in 2019 R3.2 release.