0

I have an HTTP server and client (they are my code both, C#, HttpListener on the server, HttpWebrequest on a client).

Every client makes approx 6 HTTP requests to the server per minute (if all is OK). There can be up to 10000 clients per server. The server should respond less than 1 second. Server logic is simple (there are no CPU issues). The most code is async.

All works fine in several environments (Intranet).

But in some Intranet environment, approximately 1 of 3 POST HTTP web requests hangs.

The issue is manifested on single client computer under VMware (Win 8.1 Professional, 6.3.9600 build 9600 .net 4.7.1)

I cannot reproduce it on another computer and cannot move this VM to another network environment. So I need to get some more detailed info.

The issue is detailed below. It is very like as described at

Async TCP System.Net.Socket send (Begin/End Send) not actually sending anything several years ago.

I have got WireShark and detailed System.Net logs from client and server as recommended by Microsoft.

<source name="LowLevelDesign" switchValue="Verbose">
<source name="System.Net.Http" switchValue="Verbose">
<source name="System.Net.HttpListener" switchValue="Verbose">
<source name="System.Net" switchValue="Verbose">
<source name="System.Net.Sockets" switchValue="Verbose">

Several POST HttpWebRequests from client on the same socket work fine, i.e. log shows the same client port and socket ID between requests.

I see all TCP packets in Wireshark OK both on server and client (The only warning on the server is Checksum: 0xd28c incorrect, should be 0xb54c(maybe caused by "TCP checksum offload"?).

The server responds greatly less than 1 sec for all requests.

Then after 3 or 4 successful requests, the client tries to send the next request.

But there are no TCP packets in Wireshark (nor at server nor at the client). So there is no answer from the server due to it does not see the request.

My code detects timeout (10 seconds) without answer and aborts the HttpWebRequest.

Then the same (new) requests works well on other new sockets (i.e. new client port). But after 3-6 requests the issue repeats.

There are no messages with length > 1500. The hanged request is short message too (<100 bytes for headers and <200 bytes for POST request stream data, <400 bytes for response). I see no differences between OK and Hanged requests except OK is first and Hanged is second with 100-continue. All other requests has no request data (i.e. request content-length==0). I see that the second request with 100-continue is hanged always in that environment.

The old connection is not disposed properly due to I see that server sends [RST, ACK] to the old socket (old client port) 2 minutes later. And I do not know how to close it gracefully.

... 
System.Net.Sockets Verbose: 0 : [6420] Data from Socket#11429296::PostCompletion
DateTime=2019-06-24T06:43:08.7370581Z
...
System.Net.Sockets Verbose: 0 : [6420] 000000A0 : 35 0D 0A 45 78 70 65 63-74 3A 20 31 30 30 2D 63 : 5..Expect: 100-c
DateTime=2019-06-24T06:43:08.7410625Z
System.Net.Sockets Verbose: 0 : [6420] Socket#11429296::EndSend(OverlappedAsyncResult#13804354)
DateTime=2019-06-24T06:43:08.7420738Z
System.Net.Sockets Verbose: 0 : [6420] Exiting Socket#11429296::EndSend()   -> Int32#187
DateTime=2019-06-24T06:43:08.7420738Z
System.Net.Sockets Verbose: 0 : [6420] Socket#11429296::UnsafeBeginReceive()
DateTime=2019-06-24T06:43:08.7420738Z
System.Net.Sockets Verbose: 0 : [6420] Exiting Socket#11429296::UnsafeBeginReceive()    -> OverlappedAsyncResult#47962264
DateTime=2019-06-24T06:43:08.7431561Z
System.Net Verbose: 0 : [5896] HttpWebRequest#52253787::EndGetRequestStream()
DateTime=2019-06-24T06:43:09.1071980Z
System.Net Verbose: 0 : [5896] Exiting HttpWebRequest#52253787::EndGetRequestStream()   -> ConnectStream#17987329
DateTime=2019-06-24T06:43:09.1081881Z
System.Net Verbose: 0 : [5896] ConnectStream#17987329::BeginWrite()
DateTime=2019-06-24T06:43:09.1081881Z
System.Net Verbose: 0 : [5896] Data from ConnectStream#17987329::BeginWrite
DateTime=2019-06-24T06:43:09.1091858Z
System.Net Verbose: 0 : [5896] 00000000 : 7B 22 43 6F 6E 6E 65 63-74 69 6F 6E 73 22 3A 7B : {"Connections":{
DateTime=2019-06-24T06:43:09.1091858Z
...
System.Net.Sockets Verbose: 0 : [5896] Socket#11429296::BeginSend()
DateTime=2019-06-24T06:43:09.1140970Z
System.Net.Sockets Verbose: 0 : [5896] Exiting Socket#11429296::BeginSend()     -> OverlappedAsyncResult#60375305
DateTime=2019-06-24T06:43:09.1151910Z
System.Net Verbose: 0 : [5896] Exiting ConnectStream#17987329::BeginWrite()     -> NestedSingleAsyncResult#46228029
DateTime=2019-06-24T06:43:09.1160992Z
System.Net.Sockets Verbose: 0 : [6420] Data from Socket#11429296::PostCompletion
DateTime=2019-06-24T06:43:09.1180991Z
System.Net.Sockets Verbose: 0 : [6420] 00000000 : 7B 22 43 6F 6E 6E 65 63-74 69 6F 6E 73 22 3A 7B : {"Connections":{
DateTime=2019-06-24T06:43:09.1180991Z
...
System.Net.Sockets Verbose: 0 : [6420] Socket#11429296::EndSend(OverlappedAsyncResult#60375305)
DateTime=2019-06-24T06:43:09.1212220Z
System.Net.Sockets Verbose: 0 : [6420] Exiting Socket#11429296::EndSend()   -> Int32#125
DateTime=2019-06-24T06:43:09.1212220Z
System.Net Verbose: 0 : [6420] ConnectStream#17987329::EndWrite()
DateTime=2019-06-24T06:43:09.1212220Z
System.Net Verbose: 0 : [6420] Exiting ConnectStream#17987329::EndWrite() 
DateTime=2019-06-24T06:43:09.1222229Z
System.Net Verbose: 0 : [6420] ConnectStream#17987329::Close()
DateTime=2019-06-24T06:43:09.1222229Z
System.Net Verbose: 0 : [6420] Exiting ConnectStream#17987329::Close() 
DateTime=2019-06-24T06:43:09.1232215Z
System.Net Verbose: 0 : [7368] HttpWebRequest#52253787::BeginGetResponse()
DateTime=2019-06-24T06:43:09.1232215Z
System.Net Verbose: 0 : [7368] Exiting HttpWebRequest#52253787::BeginGetResponse()  -> ContextAwareResult#13009416
DateTime=2019-06-24T06:43:09.1241884Z
System.Net Verbose: 0 : [7368] HttpWebRequest#52253787::Abort()
DateTime=2019-06-24T06:43:18.7330583Z

Wireshark:

Protocol Length Info
TCP      66     56916 → 33444 [SYN] Seq=0 Win=8192 Len=0 MSS=1432 WS=256 SACK_PERM=1
TCP      66     33444 → 56916 [SYN, ACK] Seq=0 Ack=1 Win=8192 Len=0 MSS=1404 WS=256 SACK_PERM=1
TCP      54     56916 → 33444 [ACK] Seq=1 Ack=1 Win=65792 Len=0
HTTP     248    POST /Service_v2/GetServerInformation/ HTTP/1.1 
TCP      60     33444 → 56916 [ACK] Seq=1 Ack=195 Win=65792 Len=0
HTTP     438    HTTP/1.1 200 OK  (text/plain)
TCP      54     56916 → 33444 [ACK] Seq=195 Ack=385 Win=65536 Len=0
HTTP     220    POST /Service_v2/GetServerLicense/ HTTP/1.1 
TCP      60     33444 → 56916 [ACK] Seq=385 Ack=361 Win=65792 Len=0
HTTP     1252   HTTP/1.1 200 OK  (text/plain)
TCP      54     56916 → 33444 [ACK] Seq=361 Ack=1583 Win=65792 Len=0
HTTP     220    POST /Service_v2/GetSecondMessage/ HTTP/1.1 
TCP      60     33444 → 56916 [ACK] Seq=1583 Ack=527 Win=65536 Len=0
HTTP     858    HTTP/1.1 200 OK  (text/plain)
HTTP     265    POST /Service_v2/GetMainMessage/?messageid=10d5d406-634e-4b65-9d99-f614e8b8398b HTTP/1.1 
TCP      60     33444 → 56916 [ACK] Seq=2387 Ack=738 Win=65280 Len=0
HTTP     836    HTTP/1.1 200 OK  (text/plain)
TCP      241    56916 → 33444 [PSH, ACK] Seq=738 Ack=3169 Win=65792 Len=187 [TCP segment of a reassembled PDU]
TCP      60     33444 → 56916 [ACK] Seq=3169 Ack=925 Win=65024 Len=0
HTTP     79     HTTP/1.1 100 Continue 
HTTP     181    POST /Service_v2/ProcessMessage/ HTTP/1.1  (application/raw)
TCP      60     33444 → 56916 [ACK] Seq=3194 Ack=1052 Win=65024 Len=0
HTTP     372    HTTP/1.1 200 OK  (text/plain)
TCP      54     56916 → 33444 [ACK] Seq=1052 Ack=3512 Win=65536 Len=0
HTTP     220    POST /Service_v2/GetSecondMessage/ HTTP/1.1 
TCP      60     33444 → 56916 [ACK] Seq=3512 Ack=1218 Win=64768 Len=0
HTTP     882    HTTP/1.1 200 OK  (text/plain)
TCP      54     56916 → 33444 [ACK] Seq=1218 Ack=4340 Win=64768 Len=0
    Here I try to make new POST /Service_v2/ProcessMessage/ HTTP/1.1  (application/raw) but there are NO data in WireShark
I see only next line ([RST, ACK]) after 2 minutes, no [FIN], no [ASK], no [PSH]
TCP      60     33444 → 56916 [RST, ACK] Seq=4340 Ack=1218 Win=0 Len=0

Source code:

public ServerHttpRequest(string methodSuffix, NameValueCollection requestParams = null, string requestBody = null)
{
    if (methodSuffix == null)
        throw new AggregateException(nameof(methodSuffix));

    _methodSuffix = methodSuffix;
    _requestParams = requestParams;
    _requestBody = requestBody;
}

public async Task<string> SendRequest()
{
    var sendRequestTask = Send();

    if (await Task.WhenAny(sendRequestTask, Task.Delay(TimeSpan.FromSeconds(Configuration.ServerTimeout))) == sendRequestTask)
        return await sendRequestTask.ConfigureAwait(false);

    ThreadPool.QueueUserWorkItem(this.Abort);
    throw new TimeoutException("HttpRequest timeout exceeded. Probably having problems connecting to the server.");
}

private void Abort(object obj)
{
    try
    {
        _httpRequest?.Abort();
    }
    catch (Exception ex)
    {
        Log(ex);
    }
}

private HttpWebRequest CreateRequest(string methodSuffix, NameValueCollection requestParams = null)
{
    string url = GetUrl(methodSuffix) 

    if (requestParams != null && requestParams.Count > 0)
            serviceAdress = AddParamsToUrl(url, requestParams);

    var webRequest = WebRequest.CreateHttp(licServiceAdress);

    webRequest.Method = "POST";

    //The Timeout property indicates the length of time, in milliseconds,
    //until the request times out and throws a WebException.
    //The Timeout property affects only synchronous requests made with the GetResponse method.
    //https://docs.microsoft.com/en-us/dotnet/api/system.net.webrequest.timeout?view=netframework-4.8#remarks
    webRequest.Timeout = (int)TimeSpan.FromSeconds(Configuration.ServerTimeout).TotalMilliseconds;

    webRequest.Proxy = null;
    webRequest.AutomaticDecompression = DecompressionMethods.GZip | DecompressionMethods.Deflate;

    webRequest.Headers.Add("Accept-Encoding", "gzip");

    return webRequest;
}

private async Task<string> Send()
{
    try
    {
        _httpRequest = await Task.Run(() => CreateRequest(_methodSuffix, _requestParams)).ConfigureAwait(false);

        UTF8Encoding encoding = new UTF8Encoding();
        byte[] requestBodyBytes = null;
        if (_requestBody == null)
            requestBodyBytes = encoding.GetBytes("");
        else
            requestBodyBytes = encoding.GetBytes(_requestBody);

        _httpRequest.ContentType = "application/raw";
        _httpRequest.ContentLength = requestBodyBytes.Length;

        using (Stream newStream = await _httpRequest.GetRequestStreamAsync().ConfigureAwait(false))
        {
            await newStream.WriteAsync(requestBodyBytes, 0, requestBodyBytes.Length).ConfigureAwait(false);
        }

        using (var webResponse = (HttpWebResponse)await _httpRequest.GetResponseAsync().ConfigureAwait(false))
        {
            using (var responseStream = webResponse.GetResponseStream())
                if (responseStream != null)
                    using (var reader = new StreamReader(responseStream))
                        return await reader.ReadToEndAsync().ConfigureAwait(false);


            return "";
        }

    }
    catch (Exception ex)
    {
        Log($"Request failed. Uri: '{_httpRequest.RequestUri.AbsoluteUri}'. {ex}");

        throw;
    }
}

I need to know why socket data are not shown in Wireshark. How to diagnose this?

Anatoly Volodko
  • 1
  • 4
  • First check wireshark to make sure you do not get [FIN] which is a connection closed. [RST, ACK] is the ack to the connection closing. You need to check the mask of the interface to make sure it is in the correct subnet. From cmd.exe use >IPCONFIG/ALL. You should be listening at IP.ANY which accepts into from all ethernet interface on PC. It is possible you have more than one interface and you are listening to the wrong interface. IP.Any listens to all interface. – jdweng Jun 27 '19 at 17:24
  • I see all tcp packets from previous (succeded) requests. Do you mean that established tcp-connection can change interface on the fly? – Anatoly Volodko Jun 28 '19 at 07:14
  • I am sure that there are no [FIN] in wireshark. WireShark trace of single http-tcp stream shows 5 requests is OK. Next (6) - hangs without any data. And 2 minutes later - [RST, ASK] from server, no answer from client – Anatoly Volodko Jun 28 '19 at 08:43
  • Great set of data.Shows a lot of info.You are using http 1.1 which is chunk mode. Chunk mode requires client to send Next Chunk message when a 100 continue is returned.Normally a response has a 200 OK indicating the end of the response.Every message should have an ACK.When you do not get an ACK the message is resent.So you have to check the sequence number to make sure no messages are resent. The 5 OKs may be repeats. I would use HTTP 1.0 which is stream mode in your request : HttpWebRequest request = (HttpWebRequest)WebRequest.Create("URL");request.ProtocolVersion = HttpVersion.Version10; – jdweng Jun 28 '19 at 08:45
  • HTTP messages are composed of one or more TCP messages. A TCP has max length of ~1500 Bytes. The [FIN] would be at the TCP so you have to sniff both HTTP and TCP to see the entire story. – jdweng Jun 28 '19 at 08:56
  • I know that I can use http 1.0 but then http-tcp stream will be established on every request. So there will be a lot of reconnects which is bad in heavy load system. – Anatoly Volodko Jun 28 '19 at 09:06
  • I have never been able in Net Library to send Next Chunk Message. I always get a timeout. I believe 1.1 requires a new request for every message. The only difference between 1.0 and 1.1 is the response in 1.0 is one stream while the response in 1.1 is in chunks. – jdweng Jun 28 '19 at 09:21
  • You can see that there are no messages with length > 1500. The hanged request is short message too (<100 bytes for headers and <200 bytes for POST request stream data). I see no differences between OK and Hanged requests except OK is first and Hanged is second with 100-continue. All other request has no request data (i.e. request content length=0). I see that the second request with 100-continue is hanged always in that environment. – Anatoly Volodko Jun 28 '19 at 09:24
  • But in many other environments all works fine without any hangs. So I need to know what is the difference between environments. – Anatoly Volodko Jun 28 '19 at 09:30
  • HTTP always uses TCP as transport layer and you did not post the TCP. WHERE is the NEXT CHUNK messages after the 100 CONTINUE? – jdweng Jun 28 '19 at 09:44
  • Wireshark simply decode tcp as http. HTTP 181 POST /Service_v2/ProcessMessage/ HTTP/1.1 (application/raw) is next chunck message, it is the same for TCP 181 56916 → 33444 [PSH, ACK] Seq=925 Ack=3194 Win=65792 Len=127 – Anatoly Volodko Jun 28 '19 at 09:55
  • TCP 60 bytes 33444 → 56916 [ACK] Seq=3169 Ack=925 Win=65024 Len=0 is headers with expect 100-cointinue and HTTP is next chunk 181 bytes. – Anatoly Volodko Jun 28 '19 at 09:59
  • 100 Continue means the server has more chunks to send. The client must send a Next Chunk Message before server send the next chunk. The message you posted is the ACK not a data messages. Every message sent will have an ACK in opposite direction with the same sequence number of the data message. The ack has a length of zero. – jdweng Jun 28 '19 at 10:07
  • HTTP 79 HTTP/1.1 100 Continue is 100-continue answer from server after it receive headers only message then server wait for request data, confirm it by TCP 60 [ACK] and sends next chunk with all response data TCP 372 33444 → 56916 [PSH, ACK] = HTTP 372 HTTP/1.1 200 OK (text/plain). If server waits for NEXT CHUNK message then why it sends real response (http 200)? – Anatoly Volodko Jun 28 '19 at 10:32
  • Because that what the specifications says. See : https://www.w3.org/Protocols/rfc2616/rfc2616-sec8.html#sec8.2.3 – jdweng Jun 28 '19 at 10:50
  • I have read the spec. "100 Continue means the server has more chunks to send" - It is wrong. 100 Continue means that client want to get from server confirmation that server successfully have got headers of POST request from client and is waiting for request body. It is exactly what I see in Wireshark. After 100-continue message from server Client send request body, server confirms it by [ACK] and then send HTTP/1.1 200 OK. May be you are confused with "Chunked Encoding"? There are no Transfer-Encoding=chunked header here, nor from client, nor from server. – Anatoly Volodko Jun 28 '19 at 12:54
  • The RFP are very hard to understand and usually you have to read a lot of times. See 8.2.3. The real question is if the connection is closing and if you are seeing repeated messages. If you are net seeing a send message it is usually due to the connection closing. So first you have to find the [FIN] and then figure out why the [FIN] is occurring. A message will get resent up to 5 times and then if no ack the connection will be close. Also If the 100 continue response isn't sent. You can also from cmd.exe use : >Netstat -a which will give status of the TCP connection. – jdweng Jun 28 '19 at 13:09
  • 100 continue response is really sent by server and is confirmed by client. – Anatoly Volodko Jun 28 '19 at 13:16
  • But in new (bad, hanged) request the Client doesn't ever start a request so server never knows about 100-continue. TCP connection is not closed on the server side, due to server succsessfully send [RST] 2 minutes after the issue. TCP connection may be closed or lost by client but I do not know how to make sure of it. – Anatoly Volodko Jun 28 '19 at 13:29
  • Client always send Request and Server always sends the Response!!! The server will terminate a response with either a 200 OK or a 100 continue. The client when receiving a 100 continue should send back the 100 continue. To check if connection is closed see following : https://stackoverflow.com/questions/722240/instantly-detect-client-disconnection-from-server-socket – jdweng Jun 28 '19 at 13:47
  • "The client when receiving a 100 continue should send back the 100 continue" - it is wrong. The client when receiving a 100-continue from server should send to server the request body [PSH,ACK] or close connection. There are no such thing as "send back the 100 continue from client". Client may send "Expect:100-continue" header while initiate the request. No confirmation for 100-continue response from server are required from client except proper request body. Thank you for ref about client connection closing detection - I will try it. – Anatoly Volodko Jun 28 '19 at 14:32
  • There is a 100 Continue Request (from server) and a 100 Continue Response (from Client). – jdweng Jun 28 '19 at 14:39
  • Server cannot request client :-) There is Expect:100-Continue header in request from client to server and 100-continue response from server to client. https://httpstatusdogs.com/100-continue. – Anatoly Volodko Jun 28 '19 at 15:03
  • The server always sends 100 continue before the client sends the 100 continue. – jdweng Jun 28 '19 at 15:07

0 Answers0