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