TlsException as timeout indicator?

Question

We are using Rebex HTTPS Legacy 2019R3.3 in different Windows Embedded Handheld 6.5.3 devices. When receiving data for a longer period we get a TlsException on each request after nearly 2 minutes.

Here is the Rebex log of a sample request:

2020-01-27 21:46:23 DEBUG HttpRequest(14) HTTP: Using cached HTTP session (6) provided by Rebex.Net.HttpRequestCreator(1).
2020-01-27 21:46:23 INFO HttpRequest(14) HTTP: Sending request: GET [our query string]
2020-01-27 21:46:23 DEBUG HttpRequest(14) HTTP: PreAuthenticate: False
2020-01-27 21:46:23 DEBUG HttpRequest(14) HTTP: Request Connection: keep-alive.
2020-01-27 21:46:23 DEBUG HttpRequest(14) HTTP: Sending request (356 bytes).
2020-01-27 21:46:23 VERBOSE HttpRequest(14) TLS: Sent TLS packet: 
2020-01-27 21:46:23 VERBOSE HttpRequest(14) HTTP: Raw data:
2020-01-27 21:46:31 VERBOSE HttpRequest(14) TLS: Received TLS packet: 
2020-01-27 21:46:31 VERBOSE HttpRequest(14) HTTP: Received data:
2020-01-27 21:46:31 INFO HttpRequest(14) HTTP: Received response: 200 OK.
2020-01-27 21:46:31 DEBUG HttpRequest(14) HTTP: Received 11 headers.
2020-01-27 21:46:31 DEBUG HttpRequest(14) HTTP: Response Content-Length not specified.
2020-01-27 21:46:31 DEBUG HttpRequest(14) HTTP: Response Connection: keep-alive.
2020-01-27 21:46:31 DEBUG HttpRequest(14) HTTP: Response Content-Encoding: gzip.
2020-01-27 21:46:31 DEBUG HttpRequest(14) HTTP: Response Transfer-Encoding: chunked.
[repeating patterns of “HTTP: Received data” and “TLS: Received TLS packet”]
2020-01-27 21:48:05 DEBUG HttpRequest(14) TLS: TLS socket error, 2024 bytes of data were received.
2020-01-27 21:48:05 DEBUG HttpRequest(14) TLS: Error while processing TLS packet: System.Net.Sockets.SocketException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen
2020-01-27 21:48:05 INFO HttpRequest(14) TLS: Alert Alert:Alert was sent.
2020-01-27 21:48:05 VERBOSE HttpRequest(14) TLS: Sent TLS packet: 
2020-01-27 21:48:05 ERROR HttpRequest(14) HTTP: Error while reading response: Rebex.Net.TlsException: Connection was closed by the remote connection end. ---> System.Net.Sockets.SocketException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen
2020-01-27 21:48:05 DEBUG HttpRequest(14) HTTP: Closing response stream.
2020-01-27 21:48:05 DEBUG HttpRequest(14) TLS: Closing TLS socket.
2020-01-27 21:48:05 DEBUG HttpRequest(14) HTTP: Closing HTTP session (6).

Here is the exception stack for SocketException caught internally:

2020-01-27 21:46:05 DEBUG HttpRequest(11)[-1294189126] TLS: Error while processing TLS packet: System.Net.Sockets.SocketException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen
   at System.Net.Sockets.Socket.ReceiveNoCheck(Byte[] buffer, Int32 index, Int32 request, SocketFlags socketFlags)
   at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
   at xtwc.Receive(Byte[] buffer, Int32 offset, Int32 count, SocketFlags socketFlags)
   at Rebex.Net.ProxySocket.Receive(Byte[] buffer, Int32 offset, Int32 count, SocketFlags socketFlags)
   at xubb.krpl(Int32 atp)
   at xubb.krpm()
   at xubb.krpn()
   at Rebex.Net.TlsSocket.Poll(Int32 microSeconds, SocketSelectMode mode)
   at Rebex.Net.TlsSocket.Rebex.Net.ISimpleSocket.Poll(Int32 microSeconds)
   at qhiw.aybz(Byte[] df, Int32 dg, Int32 dh)
   at qhiw.Receive(Byte[] buffer, Int32 offset, Int32 count)
   at qhiu.rgvl(Byte[] cw, Int32 cx, Int32 cy)
   at qhiu.rgvh(Byte[] cs, Int32 ct, Int32 cu)
   at qhiu.Read(Byte[] buffer, Int32 offset, Int32 count)
   at qhjx.Read(Byte[] buffer, Int32 offset, Int32 count)
   at qhjy.noxc.fcec()
   at qhjy.vuvj[a](Func`1 qv)
   at qhjy.Read(Byte[] buffer, Int32 offset, Int32 count)
   at System.IO.StreamReader.ReadBuffer()
   at System.IO.StreamReader.Read()
   at Newtonsoft.Json.JsonTextReader.MoveNext()
   at [our code]

On the server side we see, that nginx served the request with a HTTP status 200 (OK) after 6 or 7 seconds.

As the devices are slow receiving and processing the data, could the TlsException be masking a timeout?
Should we get a different exception here?

In this sample the HttpSessionCacheTimeout was set to 5 minutes, but the excption is also thrown with HttpSessionCacheEnabled = false.

Answer 1

It looks like the TlsException occured due to a socket being closed by the server (or at least that how it appears to the client), and is not masking a timeout. It is also unlikely to have anything to do with HTTP session cache - apparently, the session has been active and able to receive an HTTP request and provide some response.

However, with the most interesting part of the log removed, it's impossible to tell what might have gone wrong after the response headers were successfully received by the client. How much data has been transferred, and has the response appeared like a proper HTTP response for the specific URL? We are unable to tell.

The error at the end of the transfer ("TLS socket error, 2024 bytes of data were received") indicates that the TLS socket has been closed in the middle of receiving a TLS packet, of which only 2024 bytes has been received.

At the moment, we do not have sufficient information to be able to tell what is going on with any degree of certainty. It might be useful to run a network protocol analyzer (such as Wireshark) between the client and the server to capture the communication and determine how the communication in fact looks like at the TCP level. If there are any delays in data transmission, they would be clearly identifiable in the log as well.

Based on the information we do have at the moment, this might be caused a server-side timeout setting. For example, if the server has been configured to close sockets that have been receiving data for too long (let's say 90 seconds), if would manifest this way.

Comments

Thanks for the information! We have sent a complete Rebex log via e-mail.

---

Thanks for the log. I have replied to your mail with a suggestion. If it is working, I will report it here as a solution for other users.

---

Thank you for analyzing our log file and for the recommendations!

Our software receives large amounts of JSON data per HTTP request (uncompressed 10 to 20 MB, GZip-compressed by the endpoint to < 1 MB) and needs to build an object structure out of it, using Newtonsoft JSON.NET for the .NET Compact Framwork 3.5 (.NET CF)

Because of the small RAM available on Windows Mobile, we deserialized incoming data directly from HttpRequest.GetResponseStream() into objects. The decompression was performed internally, as HttpRequest.AutomaticDecompression was enabled (by default). Deserializing is quite slow on our devices, so receiving further data (in the same HTTP request) was heavily delayed, which forced Rebex to hold the connection open for some minutes. Having a “patient” endpoint and a stable connection for the whole time, this would be fine. But our endpoint got impatient, and the connection is not as stable as expected, which caused the TlsException.

From now on, we cache incoming data first as-is (GZip-compressed) in a MemoryStream, allowing Rebex to close the connection after some seconds. To get the compressed data out of HttpRequest.GetResponseStream() we set HttpRequest.AutomaticDecompression to None, and HttpRequest.Headers["Accept-Encoding"] = "gzip" instead (header is created automatically, as long as AutomaticDecompression is enabled). Caching 10 to 20 MB is a problem, caching < 1 MB is not. We deserialize the data directly from then compressed MemoryStream, pulling it through a GZipStream with CompressionMode.Decompress option. (It could also be done using the Rebex Zip library, but that seems to be a little slower.)

We are handling outgoing JSON POST data the inverse way, allowing Rebex to close the connection as fast as possible: At first we serialize and compress the data into a MemoryStream, then Rebex sends the prepared data with HttpRequest.Headers["Content-Encoding"] = "gzip". (Maybe HttpRequest.AllowWriteStreamBuffering = true would do the caching, but we do not want to rely on that.)

---

Thank you for the detailed description of the problem and also for sharing the solution. It is very appreciated!

The AllowWriteStreamBuffering = true is default, and it does the opposite what you need. It would copy the compressed data into internal buffer, then it would send the buffer to the HTTP server at once.
The HttpRequest.AllowWriteStreamBuffering = false do the trick: in this mode you compress data directly to RequestStream and the data are sent directly to the HTTP server as they are written, which means you are not holding the compressed data in memory at all.

---

We have a follow-up question related to AllowWriteStreamBuffering behaviour: https://forum.rebex.net/11965/httprequest-repeats-post-request-depending-on-settings