Search code examples
loggingcancellation-tokenexceptionhandlerasp.net-core-7.0

.NET 7 Avoid logging exception thrown by cancellation token in database query


I'm developing an ASP.NET 7.0 application. This app makes requests to a database with a cancellation token passed to it.

public async Task OnGetAsync(CancellationToken cancellationToken)
{
    var ls = await _db.MyTable
        .ToListAsync(cancellationToken: cancellationToken);
}

With this code the following exception is logged (text shown is truncated) when the cancellation token is thrown:

fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
   => SpanId:222e09bb9f77d813, TraceId:fe07899d8a16234fe2ea9c4d5f987e7f, ParentId:0000000000000000 => ConnectionId:0HMOV3KNV8H7R => RequestPath:/ RequestId:0HMOV3KNV8H7R:00000047
   An unhandled exception has occurred while executing the request.
   System.Threading.Tasks.TaskCanceledException: A task was canceled.
      at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()
      at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync[TSource](IQueryable`1 source, CancellationToken cancellationToken)
      at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync[TSource](IQueryable`1 source, CancellationToken cancellationToken)
      at myApp.Areas.UsersAccess.Pages.SummaryModel.OnGetAsync(CancellationToken cancellationToken) in C:\Users\me\source\repos\me\myApp\myApp\Areas\UsersAccess\Pages\Summary\Summary.cshtml.cs:line 100
      at Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.ExecutorFactory.NonGenericTaskHandlerMethod.Execute(Object receiver, Object[] arguments)
      at Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker.InvokeHandlerMethodAsync()
      at Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker.InvokeNextPageFilterAsync()
      at Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker.Rethrow(PageHandlerExecutedContext context)
      at Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
      at Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure.PageActionInvoker.InvokeInnerFilterAsync()
      at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|25_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
      at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
      at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
      at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|20_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
      at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
      at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
      at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
      at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
      at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
      at Program.<>c.<<<Main>$>b__0_8>d.MoveNext() in C:\Users\me\source\repos\me\myApp\myApp\Program.cs:line 117
   --- End of stack trace from previous location ---
      at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.<Invoke>g__Awaited|8_0(ExceptionHandlerMiddlewareImpl middleware, HttpContext context, Task task)

This pollutes my logs and I want to avoid this being logged. As I have multiple queries like this, I want to avoid using a try catch block each time for more clarity in the code.

Is there a way to filter out this specific log message without using a try/catch block?

I have tried adding this to the appsettings.json file in the LogLevel section: "System.Threading.Tasks.TaskCanceledException": "None" But it didn't work (I think you have to set the log level to None for the ExceptionHandlerMiddleware instead, but then it is not specific to task cancellation exceptions anymore).

I have also tried adding a custom exception handler:

app.UseExceptionHandler(errorApp =>
{
    errorApp.Run(async context =>
    {
        var exception = context.Features.Get<IExceptionHandlerFeature>()?.Error;

        if (exception?.Message == "A task was canceled.")
        {
            await context.Response.WriteAsync("Task cancelled.");
            // How do I ignore this error afterwards?

        }
        else
        {
            // redirect to the error page
            context.Response.Redirect("/Error");
        }
    });
});

The error still gets logged after going through the middleware. Maybe there's a way to modify the context variable to avoid it? context.Features.Get<IExceptionHandlerFeature>().Error is readonly so I can't just set it to null.

Update

Looking at the source code of the default exception handler of .NET, more specifically at the function HandleException, I notice that the case of a cancelled operations is managed (code from the link):

private async Task HandleException(HttpContext context, ExceptionDispatchInfo edi)
{
    if ((edi.SourceException is OperationCanceledException || edi.SourceException is IOException) && context.RequestAborted.IsCancellationRequested)
    {
        _logger.RequestAbortedException();

        if (!context.Response.HasStarted)
        {
            context.Response.StatusCode = StatusCodes.Status499ClientClosedRequest;
        }

        return;
    }

    _logger.UnhandledException(edi.SourceException);
    ...
}

So in my case, the code execution does not enter into the "if" condition. It is skipped and the UnhandledException function of the logger is called. If instead the inner part of the "if" condition was executed, the RequestAbortedException function would be called. This would log a level 1 message (a "debug" log) which would be good enough for me. What I don't understand is why the code execution is not entering the "if" condition. Am I doing something wrong, is there something wrong in my reasoning or is there a problem with the .NET code?


Solution

  • Before .NET 8, you'll need to write your own custom handler with UseExceptionHandler or write your own middleware/filter to ignore these types of errors.

    After .NET 8, however, a very barebones implementation looks like this for a Web API.

    // Program.cs
    
    // other service registrations.
    // `builder` is part of a minimal program setup.
    
    builder.Services.AddProblemDetails();
    
    var app = builder.Build();
    
    app.UseExceptionHandler();
    
    // other middleware registrations.
    

    For a web application, this may simply be something like

    // Program.cs
    var app = builder.Build();
    
    app.UseExceptionHandler("/Error");