HttpClient usage in a web apphosted service facing time out

Viewed 39

This is a web application.

I am queuing httpclient requests like so:

                _queue.EnqueueTask(async (serviceScopeFactory, cancellationToken) =>
                {
                    using (var scope = serviceScopeFactory.CreateScope())
                    {
                        // Get services
                        var auditHelper = scope.ServiceProvider.GetRequiredService<IAuditHelper>();
                        // Do something expensive
                        var sendAudit = await auditHelper.AddAudit(auditItem);

                    }
                });

the task is dequeued in a background service

        public async Task<Func<IServiceScopeFactory, CancellationToken, Task>> DequeueAsync(CancellationToken cancellationToken)
        {
            // Wait for task to become available
            await _signal.WaitAsync(cancellationToken);

            _items.TryDequeue(out var task);
            return task;
        }

Background service

        protected override async Task ExecuteAsync(CancellationToken stoppingToken)
        {
            // Dequeue and execute tasks until the application is stopped
            while (!stoppingToken.IsCancellationRequested)
            {
                // Get next task
                // This blocks until a task becomes available
                var task = await _taskQueue.DequeueAsync(stoppingToken);

                try
                {
                    // Run task
                    await task(_serviceScopeFactory, stoppingToken);
                }
                catch (Exception ex)
                {
                    _logger.LogError(ex, "An error occured during execution of a background task");
                }
            }
        }

And finally in the AddAudit method, I am sending the request to the API using a httpclient created from the httpclient factory:

                var response = await _clientFactory
                    .CreateClient(nameof(AuditHelper))
                    .PostAsync(string.Format($"{auditService}/audit/AddAudit"), content);

However some call will fail with a TaskCanceledException.

TaskCanceledException { Task: null, CancellationToken: CancellationToken { IsCancellationRequested: True, CanBeCanceled: True, WaitHandle: "The property accessor threw an exception: ObjectDisposedException" }, TargetSite: Void Throw(), StackTrace: "   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean allowHttp2, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.GetHttpConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Polly.Retry.AsyncRetryEngine.ImplementationAsync[TResult](Func`3 action, Context context, CancellationToken cancellationToken, ExceptionPredicates shouldRetryExceptionPredicates, ResultPredicates`1 shouldRetryResultPredicates, Func`5 onRetryAsync, Int32 permittedRetryCount, IEnumerable`1 sleepDurationsEnumerable, Func`4 sleepDurationProvider, Boolean continueOnCapturedContext)
   at Polly.AsyncPolicy`1.ExecuteAsync(Func`3 action, Context context, CancellationToken cancellationToken, Boolean continueOnCapturedContext)
   at Microsoft.Extensions.Http.PolicyHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at WS.Common.Utilities.AuditHelper.AddAudit(String auditService, String userName, String actionType, String module, String description, String combinedKey, Object value, String source, String ipAddress, String status, String duration, Object previousValue) in /src/WS.Common/Utilities/AuditHelper.cs:line 120", Message: "The operation was canceled.", Data: [], InnerException: null, HelpLink: null, Source: "System.Private.CoreLib", HResult: -2146233029 }
System.Threading.Tasks.TaskCanceledException: The operation was canceled.
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean allowHttp2, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.GetHttpConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Polly.Retry.AsyncRetryEngine.ImplementationAsync[TResult](Func`3 action, Context context, CancellationToken cancellationToken, ExceptionPredicates shouldRetryExceptionPredicates, ResultPredicates`1 shouldRetryResultPredicates, Func`5 onRetryAsync, Int32 permittedRetryCount, IEnumerable`1 sleepDurationsEnumerable, Func`4 sleepDurationProvider, Boolean continueOnCapturedContext)
   at Polly.AsyncPolicy`1.ExecuteAsync(Func`3 action, Context context, CancellationToken cancellationToken, Boolean continueOnCapturedContext)
   at Microsoft.Extensions.Http.PolicyHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at WS.Common.Utilities.AuditHelper.AddAudit(String auditService, String userName, String actionType, String module, String description, String combinedKey, Object value, String source, String ipAddress, String status, String duration, Object previousValue) in /src/WS.Common/Utilities/AuditHelper.cs:line 120

The main issue I’m facing is that this error can’t be reproduced in my staging or uat environment. Based on my research, it seems to be the httpclient request timing out, but why is it doing so? And why intermittently? What else can I do to track down the root of the problem?

Endpoint that the httpclient is posting to

       public async Task<IActionResult> AddAudit([FromBody] AuditSaveRequest request)
        {
            try
            {
                var response = new AuditSaveResponse();
                var canWrite = _queue.QueueItem(new LogItem(request));

                if (!canWrite)
                {
                    response.Messages.Add(new Messages.InternalServerError("Unable to write to queue"));
                    var errorObjectResult = new ObjectResult(response);
                    errorObjectResult.StatusCode = StatusCodes.Status500InternalServerError;

                    return errorObjectResult;
                }
                return new OkObjectResult(response);
            }
            catch (Exception ex)
            {

                _logger.LogError(ex, "Error when handling audit request");
                var errorObjectResult = new ObjectResult(ex);
                errorObjectResult.StatusCode = StatusCodes.Status500InternalServerError;
                return errorObjectResult; 
            }


        }

The queue is a bounded channel:

        _queue = Channel.CreateBounded<ILogItem>(options);

And the queue method

        public bool QueueItem(
            ILogItem workItem)
        {
            if (workItem == null)
            {
                throw new ArgumentNullException(nameof(workItem));
            }
           
            return _queue.Writer.TryWrite(workItem);
        }

Edit: the object disposed exception is due to the destructing of the cancellation token. It’s not the cause.

1 Answers

The call stack indicates the exception occurred inside AuditHelper.AddAudit() which does not get the chance to complete before the task is disposed. Are you running this inside a console application? If so then you'll need to keep it running for example with a while(true) loop so the tasks get the chance to complete.

In an async await scenario, the main thread is likely to complete before the async calls, causing the whole application to shut down. See also: https://docs.microsoft.com/en-us/answers/questions/505438/c-console-program-end-before-async-function-finish.html

Related