Как диагностировать, почему асинхронная отправка TCP System.Net.Socket (Begin / End Send) фактически ничего не отправляет? - PullRequest
Новая
       66

Как диагностировать, почему асинхронная отправка TCP System.Net.Socket (Begin / End Send) фактически ничего не отправляет?

0 голосов
/ 27 июня 2019

У меня есть HTTP-сервер и клиент (это мой код, C #, HttpListener на сервере, HttpWebrequest на клиенте).

Каждый клиент отправляет около 6 HTTP-запросов на сервер в минуту (если все в порядке). На сервере может быть до 10000 клиентов. Сервер должен ответить менее чем за 1 секунду. Логика сервера проста (нет проблем с процессором). Большая часть кода асинхронна.

Все отлично работает в нескольких средах (Интранет).

Но в некоторых средах интрасети зависает примерно 1 из 3 веб-запросов POST HTTP.

Проблема проявляется на компьютере с одним клиентом под VMware (Win 8.1 Professional, 6.3.9600 build 9600 .net 4.7.1)

Я не могу воспроизвести его на другом компьютере и не могу переместить эту виртуальную машину в другое сетевое окружение. Поэтому мне нужно получить более подробную информацию.

Проблема подробно описана ниже. Это очень похоже на то, как описано в

Асинхронная отправка TCP System.Net.Socket (начало / конец отправки) фактически ничего не отправляла несколько лет назад.

Я получил WireShark и подробные журналы System.Net от клиента и сервера в соответствии с рекомендациями 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">

Несколько запросов POST HttpWebRequest от клиента в одном и том же сокете работают нормально, т. Е. Журнал показывает один и тот же порт клиента и идентификатор сокета между запросами.

Я вижу все TCP-пакеты в Wireshark OK как на сервере, так и на клиенте (Единственное предупреждение на сервере - контрольная сумма неверна: 0xd28c, должно быть 0xb54c (может быть вызвано «разгрузкой контрольной суммы TCP»?).

Сервер отвечает значительно меньше, чем 1 сек на все запросы.

Затем после 3 или 4 успешных запросов клиент пытается отправить следующий запрос.

Но в Wireshark нет TCP-пакетов (ни на сервере, ни на клиенте). Таким образом, нет ответа от сервера, потому что он не видит запрос.

Мой код обнаруживает тайм-аут (10 секунд) без ответа и прерывает запрос HttpWebRequest.

Тогда те же самые (новые) запросы хорошо работают на других новых сокетах (то есть на новом клиентском порту). Но после 3-6 запросов проблема повторяется.

Нет сообщений длиной> 1500. Зависший запрос также является коротким сообщением (<100 байт для заголовков и <200 байт для данных потока запросов POST, <400 байт для ответа). Я не вижу различий между запросами OK и Hanged, за исключением того, что OK - первый, а Hanged - второй со 100-продолжением. Все остальные запросы не имеют данных запроса (т.е. длина содержимого запроса == 0). Я вижу, что второй запрос с 100-continue всегда висит в этой среде. </p>

Старое соединение не установлено должным образом, поскольку я вижу, что сервер отправляет [RST, ACK] на старый сокет (старый клиентский порт) через 2 минуты. И я не знаю, как изящно закрыть его. 

... 
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

Исходный код: 

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;
    }
}

Мне нужно знать, почему данные сокетов не отображаются в Wireshark. Как это диагностировать?

Добро пожаловать на сайт PullRequest, где вы можете задавать вопросы и получать ответы от других членов сообщества.

Похожие темы

...