Rebex HTTPS Not working on server which forces TLS 1.2

Question

I am using the 2018 R4 (build number 6930) to make post calls to a server that only allows TLS 1.2, but the request fails with an error code 408.

However the same request seems to be working on an identical server, the only difference is that server allows TLS 1.0

INFO HttpRequest(1)[1] TLS: Connection secured using cipher: TLS 1.2.
DEBUG HttpRequest(1)[1] TLS: Session ID: 
 0000 |31-84-3B-50-43-4C-0F-3E 46-14-4C-5B-62-86-FE-D6| 1.;PCL.>F.L[b...
 0010 |52-95-A7-1F-6E-52-9E-73 D3-3B-26-A9-68-B1-4B-5C| R...nR.s.;&.h.K\
INFO HttpRequest(1)[1] HTTP: Sending request: POST /<internalAddress>/<internalLink0>
DEBUG HttpRequest(1)[1] HTTP: Request Connection: keep-alive.
DEBUG HttpRequest(1)[1] HTTP: Sending request (211 bytes).
DEBUG HttpRequest(1)[1] HTTP: Sending 57 bytes of data.
INFO HttpRequest(1)[1] HTTP: Received response: 200 200.
DEBUG HttpRequest(1)[1] HTTP: Received 5 headers.
DEBUG HttpRequest(1)[1] HTTP: Response Content-Length: 0 bytes.
DEBUG HttpRequest(1)[1] HTTP: Response Connection: close.
DEBUG HttpRequest(1)[1] HTTP: Response Content-Encoding not specified.
DEBUG HttpRequest(1)[1] HTTP: Response Transfer-Encoding not specified.
DEBUG HttpRequest(2)[1] HTTP: Using new HTTP session (2) provided by Rebex.Net.HttpRequestCreator(2).
INFO HttpRequest(2)[1] HTTP: Connecting to 'https://<internalIP>:443'...
DEBUG HttpRequest(2)[1] Info: Assembly: Rebex.Networking 2018 R4 for .NET 4.0-4.7
DEBUG HttpRequest(2)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
DEBUG HttpRequest(2)[1] Info: Culture: en; Windows-1252
DEBUG HttpRequest(2)[1] Proxy: Connecting to <internalIP>:443 (no proxy).
DEBUG HttpRequest(2)[1] TLS: Enabled cipher suites: 0x000FFDF7FFE0E640.
DEBUG HttpRequest(2)[1] TLS: Applicable cipher suites: 0x000FFDF7FFE0E640.
INFO HttpRequest(2)[1] TLS: State StateChange:Negotiating
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ClientHello was sent.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ServerHello was received.
INFO HttpRequest(2)[1] TLS: Negotiating TLS 1.2.
DEBUG HttpRequest(2)[1] TLS: The server supports secure renegotiation.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:Certificate was received.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ServerKeyExchange was received.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ServerHelloDone was received.
DEBUG HttpRequest(2)[1] TLS: Verifying server certificate ('<certificateInfo>').
DEBUG HttpRequest(2)[1] TLS: Certificate verification result: Accept
DEBUG HttpRequest(2)[1] TLS: Verifying server key exchange signature.
DEBUG HttpRequest(2)[1] TLS: Using ephemeral ECDH public key exchange with NIST P-256 curve.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ClientKeyExchange was sent.
DEBUG HttpRequest(2)[1] TLS: CipherSpec:ChangeCipherSpec was sent.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:Finished was sent.
DEBUG HttpRequest(2)[1] TLS: CipherSpec:ChangeCipherSpec was received.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:Finished was received.
INFO HttpRequest(2)[1] TLS: State StateChange:Secured
INFO HttpRequest(2)[1] TLS: Connection secured using cipher: TLS 1.2.
DEBUG HttpRequest(2)[1] TLS: Session ID: 
 0000 |B4-F1-86-A8-56-FC-6D-AB 71-11-FA-99-46-42-DE-37| ....V.m.q...FB.7
 0010 |B4-97-76-A6-AC-E2-79-1B 77-7D-D5-E0-59-F4-5A-6D| ..v...y.w}..Y.Zm
INFO HttpRequest(2)[1] HTTP: Sending request: POST /<internalAddress>/<internalLink1>
DEBUG HttpRequest(2)[1] HTTP: Request Connection: keep-alive.
DEBUG HttpRequest(2)[1] HTTP: Sending request (311 bytes).
DEBUG HttpRequest(2)[1] HTTP: Sending 342 bytes of data.
INFO HttpRequest(2)[1] HTTP: Received response: 302 302.
DEBUG HttpRequest(2)[1] HTTP: Received 7 headers.
DEBUG HttpRequest(2)[1] HTTP: Response Content-Length: 0 bytes.
DEBUG HttpRequest(2)[1] HTTP: Response Connection: close.
DEBUG HttpRequest(2)[1] HTTP: Response Content-Encoding not specified.
DEBUG HttpRequest(2)[1] HTTP: Response Transfer-Encoding not specified.
DEBUG HttpRequest(2)[1] HTTP: Discarding pending response data...
DEBUG HttpRequest(2)[1] HTTP: Received content (0 bytes).
INFO HttpRequest(2)[1] TLS: Alert Alert:Alert was received.
INFO HttpRequest(2)[1] TLS: Alert Alert:Alert was sent.
INFO HttpRequest(2)[1] TLS: State StateChange:Closed
DEBUG HttpRequest(2)[1] TLS: Closing TLS socket.
DEBUG HttpRequest(2)[1] HTTP: Closing response stream.
INFO HttpRequest(2)[1] HTTP: Reconnecting to 'https://<internalIP>:443'...
DEBUG HttpRequest(2)[1] Info: Assembly: Rebex.Networking 2018 R4 for .NET 4.0-4.7
DEBUG HttpRequest(2)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
DEBUG HttpRequest(2)[1] Info: Culture: en; Windows-1252
DEBUG HttpRequest(2)[1] Proxy: Connecting to <internalIP>:443 (no proxy).
DEBUG HttpRequest(2)[1] TLS: Enabled cipher suites: 0x000FFDF7FFE0E640.
DEBUG HttpRequest(2)[1] TLS: Applicable cipher suites: 0x000FFDF7FFE0E640.
INFO HttpRequest(2)[1] TLS: State StateChange:Negotiating
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ClientHello was sent.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ServerHello was received.
INFO HttpRequest(2)[1] TLS: Negotiating TLS 1.2.
DEBUG HttpRequest(2)[1] TLS: The server supports secure renegotiation.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:Certificate was received.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ServerKeyExchange was received.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ServerHelloDone was received.
DEBUG HttpRequest(2)[1] TLS: Verifying server certificate ('<certificateInfo>').
DEBUG HttpRequest(2)[1] TLS: Certificate verification result: Accept
DEBUG HttpRequest(2)[1] TLS: Verifying server key exchange signature.
DEBUG HttpRequest(2)[1] TLS: Using ephemeral ECDH public key exchange with NIST P-256 curve.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ClientKeyExchange was sent.
DEBUG HttpRequest(2)[1] TLS: CipherSpec:ChangeCipherSpec was sent.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:Finished was sent.
DEBUG HttpRequest(2)[1] TLS: CipherSpec:ChangeCipherSpec was received.
DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:Finished was received.
INFO HttpRequest(2)[1] TLS: State StateChange:Secured
INFO HttpRequest(2)[1] TLS: Connection secured using cipher: TLS 1.2.
DEBUG HttpRequest(2)[1] TLS: Session ID: 
 0000 |D2-A4-FC-82-9A-03-EE-D7 97-A7-42-3C-69-51-7F-56| ..........B<iQ.V
 0010 |A0-1F-B4-DA-AE-CC-F0-2D C7-51-8A-14-40-4F-D3-BF| .......-.Q..@O..
INFO HttpRequest(2)[1] HTTP: Sending request: GET /<internalAddress>/<internalLink2>
DEBUG HttpRequest(2)[1] HTTP: Request Connection: keep-alive.
DEBUG HttpRequest(2)[1] HTTP: Sending request (336 bytes).
INFO HttpRequest(2)[1] HTTP: Received response: 408 408.

Answer 1

This looks like a TLS 1.2 session has been successfully negotiated, and that a HTTP request has been successfully sent and a response received. The response was a "302" response indicating that the client should retrieve the resource from another URL, which it then tried as well. It negotiated a TLS 1.2 session without issues again and sent the request, but received a response with "408" status codes that indicates "Request Timeout".

The "408" response is used by HTTP servers to indicate that "the server did not receive a complete request message within the time that it was prepared to wait". Is it possible this is the case because TLS 1.2 negotiation took too long? The log you posted is missing all timestamps, which makes it impossible to tell.

Comments

The response comes back with in a second ( i had to remove the timestamp as the log was more then 8000 characters), here is that section of the log, I am also sending cookies in the request header

    16:37:37.747 INFO HttpRequest(2)[1] HTTP: Received response: 302 302.
    16:37:37.747 DEBUG HttpRequest(2)[1] HTTP: Received 7 headers.
    16:37:37.747 DEBUG HttpRequest(2)[1] HTTP: Response Content-Length: 0 bytes.
    16:37:37.747 DEBUG HttpRequest(2)[1] HTTP: Response Connection: close.
    16:37:37.747 DEBUG HttpRequest(2)[1] HTTP: Response Content-Encoding not specified.
    16:37:37.747 DEBUG HttpRequest(2)[1] HTTP: Response Transfer-Encoding not specified.
    16:37:37.748 DEBUG HttpRequest(2)[1] HTTP: Discarding pending response data...
    16:37:37.753 DEBUG HttpRequest(2)[1] HTTP: Received content (0 bytes).
    16:37:37.754 INFO HttpRequest(2)[1] TLS: Alert Alert:Alert was received.
    16:37:37.755 INFO HttpRequest(2)[1] TLS: Alert Alert:Alert was sent.
    16:37:37.755 INFO HttpRequest(2)[1] TLS: State StateChange:Closed
    16:37:37.758 DEBUG HttpRequest(2)[1] TLS: Closing TLS socket.
    16:37:37.759 DEBUG HttpRequest(2)[1] HTTP: Closing response stream.
    16:37:37.759 INFO HttpRequest(2)[1] HTTP: Reconnecting to 'https://<internalIP>:443'...
    16:37:37.759 DEBUG HttpRequest(2)[1] Info: Assembly: Rebex.Networking 2018 R4 for .NET 4.0-4.7
    16:37:37.759 DEBUG HttpRequest(2)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
    16:37:37.759 DEBUG HttpRequest(2)[1] Info: Culture: en; Windows-1252
    16:37:37.759 DEBUG HttpRequest(2)[1] Proxy: Connecting to <internalIP>:443 (no proxy).
    16:37:37.797 DEBUG HttpRequest(2)[1] TLS: Enabled cipher suites: 0x000FFDF7FFE0E640.
    16:37:37.797 DEBUG HttpRequest(2)[1] TLS: Applicable cipher suites: 0x000FFDF7FFE0E640.
    16:37:37.797 INFO HttpRequest(2)[1] TLS: State StateChange:Negotiating
    16:37:37.797 DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ClientHello was sent.
    16:37:37.837 DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ServerHello was received.
    16:37:37.837 INFO HttpRequest(2)[1] TLS: Negotiating TLS 1.2.
    16:37:37.837 DEBUG HttpRequest(2)[1] TLS: The server supports secure renegotiation.
    16:37:37.839 DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:Certificate was received.
    16:37:37.839 DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ServerKeyExchange was received.
    16:37:37.839 DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ServerHelloDone was received.
    16:37:37.839 DEBUG HttpRequest(2)[1] TLS: Verifying server certificate ('<certificateInfo>').
    16:37:37.839 DEBUG HttpRequest(2)[1] TLS: Certificate verification result: Accept
    16:37:37.839 DEBUG HttpRequest(2)[1] TLS: Verifying server key exchange signature.
    16:37:37.840 DEBUG HttpRequest(2)[1] TLS: Using ephemeral ECDH public key exchange with NIST P-256 curve.
    16:37:37.842 DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:ClientKeyExchange was sent.
    16:37:37.844 DEBUG HttpRequest(2)[1] TLS: CipherSpec:ChangeCipherSpec was sent.
    16:37:37.844 DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:Finished was sent.
    16:37:37.881 DEBUG HttpRequest(2)[1] TLS: CipherSpec:ChangeCipherSpec was received.
    16:37:37.882 DEBUG HttpRequest(2)[1] TLS: HandshakeMessage:Finished was received.
    16:37:37.882 INFO HttpRequest(2)[1] TLS: State StateChange:Secured
    16:37:37.882 INFO HttpRequest(2)[1] TLS: Connection secured using cipher: TLS 1.2.
    16:37:37.882 DEBUG HttpRequest(2)[1] TLS: Session ID:
     0000 |D2-A4-FC-82-9A-03-EE-D7 97-A7-42-3C-69-51-7F-56| ..........B<iQ.V
     0010 |A0-1F-B4-DA-AE-CC-F0-2D C7-51-8A-14-40-4F-D3-BF| .......-.Q..@O..
    16:37:37.882 INFO HttpRequest(2)[1] HTTP: Sending request: GET /<internalAddress>/<internalLink2>
    16:37:37.882 DEBUG HttpRequest(2)[1] HTTP: Request Connection: keep-alive.
    16:37:37.882 DEBUG HttpRequest(2)[1] HTTP: Sending request (336 bytes).
    16:37:37.963 INFO HttpRequest(2)[1] HTTP: Received response: 408 408.

---

Thanks for the additional information. According to this log, it took less than 200 miliseconds to connect to the server, negotiate a TLS 1.2 session, send the request and receive a response. Despite this, the server sent back a "408" response, indicating that the connection has timed out and is about to be closed. So this really looks like a server-side configuration issue. Does the server log contain any information related to this?

At this point, it would be useful to try accessing the same URL using a simple command-line HTTPS client such us "wget" or "curl" to see whether they get "408" as well.

---

Thanks Lukas,

We are using the same server with .net 4.5.2 HttpClient and it works fine, but we need to support .net 4.0 and rebex seems like the perfect choice for that.

I will check the server logs too.

---

Are you actually using TLS 1.2 with .NET 4.5.2's HttpClient? In .NET 4.5.x, TLS 1.2 is not yet enabled by default and has to be configured by setting "ServicePointManager.SecurityProtocol = SecurityProtocolType.Tls12".

---

We are using TLS 1.2 with .NET 4.5.2's HttpWebRequest and setting the security protocol as you mentioned and its working fine with the same server.

But we need to support TLS1.2 on .NET4.0

---

Thanks for the clarification. Unfortunately, we are unable to reproduce this problem  and none of our clients reported anything like this before, so we are a bit in the dark here. So to be able to do something about this, we need to gather some additional information first.

Let's start by analyzing the log. This is what seems to be going on:

1. You issue a POST request to /<internalAddress>/<internalLink0>. The server accepts this and returns "200" success result.

2. You issue another POST request to /<internalAddress>/<internalLink1>. The server responds with "302" response, indicating to the client that it should fetch another URL. At this point, the POST data has already been submitted and is not going to be sent again when fetching the other URL. (.NET's HttpClient and HttpWebRequest behave like this as well.)

3. The client issues a POST request to /<internalAddress>/<internalLink2>. The server responds with "408", indicating that the connection established less than 200 miliseconds ago has already timed out. Which is somewhat strange.

Interestingly, according to the log, it seems that the POST request has actually been successful and that the server received the posted data. Would it be possible to determine whether this is really the case?

But then there is the "408" response. This was indeed sent by the server, so whoever created the server-side application or configured the server should be able to tell what is going on. If we encountered the issue ourselves, we would investigate this first. However, it's quite possible that .NET 4.5.2's HttpWebRequest received the "408" response as well, but reconnected to resend the request. This is allowed by the specification (see https://tools.ietf.org/html/rfc7231#section-6.5.7), but it's not mandatory. We'll look into HttpClient's behavior in this scenario and let you know if we discover anything.

---

Well, it looks like .NET's HttpClient actually ignores "408" responses and behaves as if a success response has been received (in doesn't even reconnect). In other words, HttpClient DOES NOT FAIL when it receives a 408 erro, as demonstrated by the following sample code:

    var content = new StringContent("test");
    var http = new HttpClient();
    var response = http.PostAsync("http://httpbin.test.rebex.cz/redirect-to?url=/status/408", content, CancellationToken.None).Result;
    Console.WriteLine("Status code: {0}", response.StatusCode);

I'm not sure whether this is an intended behavior or whether it's bug, but it suggests that Rebex HTTPS might actually be working and that you just have to ignore the "408" error (which is what HttpClient does silently as well).

---

Thanks lucas for the indepth anaylsis

I found something interesting about cookies, when the server responds with a 302 redirect, it also updates the cookie value.

Is there anyway i can catch that event and get the cookie value ?

---

Or can i handle the redirect myself ?

---

Yes, you can handle the redirect yourself if you use the HttpRequest/HttpResponse API. Just set HttpRequest's AllowAutoRedirect property to 'false'.

You can read the cookies as well from the Headers property of HttpResponse (we plan to support .NET-like CookieContainer soon as well).

---

Thanks Lukas

its working after handling all the redirects manually :)

---

Thanks for letting us know! I'm sure this could be useful to other users as well.