1

We get an occasional TaskCanceledException on a call that, according to our logs, completes well inside the timeout we configure for the request. The first log entry is from the server. This is the last thing the method logs out before returning a JsonResult (MVC 4 Controller).

{
    "TimeGenerated": "2021-03-19T12:08:48.882Z",
    "CorrelationId": "b1568096-fdbd-46a7-8b69-58d0b33f458c",
    "date_s": "2021-03-19",
    "time_s": "07:08:37.9582",
    "callsite_s": "...ImportDatasets",
    "stacktrace_s": "",
    "Level": "INFO",
    "class_s": "...ReportConfigController",
    "Message": "Some uninteresting message",
    "exception_s": ""
}

In this case, the request took about 5 minutes to complete. Then 30 minutes later, our caller throws the task canceled exception from HttpClient.SendAsync:

{
    "TimeGenerated": "2021-03-19T12:48:27.783Z",
    "CorrelationId": "b1568096-fdbd-46a7-8b69-58d0b33f458c",
    "date_s": "2021-03-19",
    "time_s": "12:48:17.5354",
    "callsite_s": "...AuthorizedApiAccessor+<CallApi>d__29.MoveNext",
    "stacktrace_s": "TaskCanceledException    
        at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)\r\n   
        at System.Net.Http.HttpConnectionPool.SendWithNtConnectionAuthAsync(HttpConnection connection, HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)\r\n   
        at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)\r\n   
        at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)\r\n   
        at System.Net.Http.DecompressionHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)\r\n   
        at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)\r\n   
        at ...AuthorizedApiAccessor.CallApi(String url, Object content, HttpMethod httpMethod, AuthenticationType authType, Boolean isCompressed)\r\nIOException    
        at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)\r\n   
        at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)\r\n   
        at System.Net.Security.SslStream.<FillBufferAsync>g__InternalFillBufferAsync|215_0[TReadAdapter](TReadAdapter adap, ValueTask`1 task, Int32 min, Int32 initial)\r\n   
        at System.Net.Security.SslStream.ReadAsyncInternal[TReadAdapter](TReadAdapter adapter, Memory`1 buffer)\r\n   
        at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)\r\nSocketException",
    "Level": "ERROR",
    "class_s": "...AuthorizedApiAccessor",
    "Message": "Nothing good",
    "exception_s": "The operation was canceled."
}

Given that within the process that makes the request we block an async call (.Result -- hitting a brownfield caching implementation that doesn't support async), my first guess was that we had a deadlock as described by Stephen Cleary. But the caller is a dotnetcore 3.1 application, so that kind of deadlock is not possible.

Our usage of HttpClient is pretty standard, I think. This is the method that ultimately makes the call:

private async Task<string> CallApi(string url, object content, HttpMethod httpMethod, AuthenticationType authType, bool isCompressed)
{
    try
    {
        var request = new HttpRequestMessage()
        {
            RequestUri = new Uri(url),
            Method = httpMethod,
            Content = GetContent(content, isCompressed)
        };

        AddRequestHeaders(request);

        var httpClient = _httpClientFactory.CreateClient(HTTPCLIENT_NAME);
        httpClient.Timeout = Timeout;

        AddAuthenticationHeaders(httpClient, authType);

        var resp = await httpClient.SendAsync(request);
        var responseString = await (resp.Content?.ReadAsStringAsync() ?? Task.FromResult<string>(string.Empty));

        if (!resp.IsSuccessStatusCode)
        {
            var message = $"{url}: {httpMethod}: {authType}: {isCompressed}: {responseString}";
            if (resp.StatusCode == HttpStatusCode.Forbidden || resp.StatusCode == HttpStatusCode.Unauthorized)
            {
                throw new CustomException(message, ErrorType.AccessViolation);
            }

            if (resp.StatusCode == HttpStatusCode.NotFound)
            {
                throw new CustomException(message, ErrorType.NotFound);
            }

            throw new CustomException(message);
        }

        return responseString;
    }
    catch (CustomException) { throw; }
    catch (Exception ex)
    {
        var message = "{Url}: {HttpVerb}: {AuthType}: {IsCompressed}: {Message}";
        _logger.ErrorFormat(message, ex, url, httpMethod, authType, isCompressed, ex.Message);
        throw;
    }
}

We are at a loss for theories on this behavior. We've seen the task cancelation between 3-5 times a month within a few hundred successful requests, so it's intermittent, but far from rare.

Where else should we be looking for the source of what behaves like a deadlock?

update

Might be relevant to note that we are using the standard HttpClientHandler. The retry policies have been added recently, but we don't retry on a long-running POST, which is the scenario above.

builder.Services.AddHttpClient(AuthorizedApiAccessor.HTTPCLIENT_NAME)
    .ConfigurePrimaryHttpMessageHandler(_ => new HttpClientHandler()
    {
        AutomaticDecompression = System.Net.DecompressionMethods.Deflate | System.Net.DecompressionMethods.GZip
    })
    .AddRetryPolicies(retryOptions);
Stuart
  • 1,572
  • 4
  • 21
  • 39
  • 1
    It's not a deadlock because the call completes (and later, the exception is logged). Interestingly, I have also observed this behavior just last night for the first time within a .NET Core Azure Function that uses HttpClient. The call completed and then some time later the HttpClient threw a cancellation exception with the same invocation id. I'm not entirely sure how this is possible. – Stephen Cleary Mar 24 '21 at 01:57
  • Yeah, I didn't know a better work to describe the behavior. Maybe "hangs" is better -- implies (correctly) that we have no idea what's going on. – Stuart Mar 24 '21 at 13:21

0 Answers0