Distinguish cancellation from failure to allow different logging strategies

[ascott18]

What problem are you trying to solve?
Right now, logs for exceptions thrown due to CancellationToken cancellation are categorized as Microsoft.EntityFrameworkCore.Query[10100]. I want to be able to keep logging all other kinds of query errors, but not ones for intentional cancellations. In my application, I'm passing aspnetcore's HttpContext.RequestedAborted token to my async EF query evaluations. If the client hangs up, there's no reason to keep querying the database working to evaluate what are in some cases quite complex search queries in an intranet application (e.g. if the client changed their search criteria, or just left the page).

We'd like to not pollute our logs with these exceptions that are fully expected. We have an ActionFilter where we handle the exception as far as aspnetcore is concerned, but EF itself still logs the error.

For example:

fail: Microsoft.EntityFrameworkCore.Query[10100]
      An exception occurred while iterating over the results of a query for context type 'My.App.AppDbContext'.
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
         at Microsoft.EntityFrameworkCore.Query.Internal.AsyncQueryingEnumerable`1.AsyncEnumerator.BufferlessMoveNext(DbContext _, Boolean buffer, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Query.Internal.AsyncQueryingEnumerable`1.AsyncEnumerator.MoveNext(CancellationToken cancellationToken)
         at System.Linq.AsyncEnumerable.SelectEnumerableAsyncIterator`2.MoveNextCore(CancellationToken cancellationToken) in D:\a\1\s\Ix.NET\Source\System.Interactive.Async\Select.cs:line 106
         at System.Linq.AsyncEnumerable.AsyncIterator`1.MoveNext(CancellationToken cancellationToken) in D:\a\1\s\Ix.NET\Source\System.Interactive.Async\AsyncIterator.cs:line 98
         at Microsoft.EntityFrameworkCore.Query.Internal.AsyncLinqOperatorProvider.ExceptionInterceptor`1.EnumeratorExceptionInterceptor.MoveNext(CancellationToken cancellationToken)
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Microsoft.EntityFrameworkCore.Query.Internal.AsyncQueryingEnumerable`1.AsyncEnumerator.BufferlessMoveNext(DbContext _, Boolean buffer, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.AsyncQueryingEnumerable`1.AsyncEnumerator.MoveNext(CancellationToken cancellationToken)
   at System.Linq.AsyncEnumerable.SelectEnumerableAsyncIterator`2.MoveNextCore(CancellationToken cancellationToken) in D:\a\1\s\Ix.NET\Source\System.Interactive.Async\Select.cs:line 106
   at System.Linq.AsyncEnumerable.AsyncIterator`1.MoveNext(CancellationToken cancellationToken) in D:\a\1\s\Ix.NET\Source\System.Interactive.Async\AsyncIterator.cs:line 98
   at Microsoft.EntityFrameworkCore.Query.Internal.AsyncLinqOperatorProvider.ExceptionInterceptor`1.EnumeratorExceptionInterceptor.MoveNext(CancellationToken cancellationToken)

Describe the solution you'd like

Create a dedicated log category for OperationCanceledExceptions that are caused by userspace-provided CancellationTokens that I can then setup a regular logging filter against.

Alternatively, just do not log OperationCanceledException at all if the CancellationToken has been triggered, since this is generally always an intentional outcome if the user has passed a CancellationToken to their query evaulations. This would be a much simpler path, but may have unintended consequences.

[ajcvickers]

Note from team discussion: putting this on the backlog to consider generating a different logging event when the exception is "TaskCanceledException".

[MattJacobi-ESO]

I'm having this problem as well. I would like to provide some additional context. Sometimes cancellation can actually generate multiple errors, some of which cannot be identified as being caused by cancellation.

For example, if you trigger the cancellation token before the database connection is made, you'll actually get two errors logged:

Error 1

Microsoft.EntityFrameworkCore.Database.Connection: An error occurred using the connection to database '<mydb>' on server '<myserver>'.

Error 2

Microsoft.EntityFrameworkCore.Query: An exception occurred while iterating over the results of a query for context type '<mydbcontext>'.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
<callstack>

Error 2 is noise -- and I'd love to be able to suppress it -- but it is at least possible to conclude that the error is likely due to a cancellation token. You can use the presence of "TaskCanceledException" to filter it out.

However, if you look at Error 1, there is no indication that this was actually caused by cancellation. This can lead to unnecessary investigation. And there is also no way to filter it out as "noise".

[4lexKislitsyn]

You can use the presence of "TaskCanceledException" to filter it out

OperationCanceledException can be filter out too. It can be thrown from ThrowIfCancellationRequested method, e.g. here

[plachor]

Similar in my case, when request is aborted I see 2 log entries with Error severity level:

"MessageTemplate: "Failed executing DbCommand ({elapsed}ms) [Parameters=[{parameters}], CommandType='{commandType}', CommandTimeout='{commandTimeout}']{newLine}{commandText}",
"SourceContext": "Microsoft.EntityFrameworkCore.Database.Command"

and

"MessageTemplate": "An exception occurred while iterating over the results of a query for context type '{contextType}'.{newline}{error}",
"SourceContext": "Microsoft.EntityFrameworkCore.Query"

Second one contains information regarding cause which was OperationCanceledException, but first one has no such indicator. Still I'm far away from parsing some string property to check if it is operation cancelled - I would need than to recheck this with my request cancellation token to be 100% sure this something I can suppress or not.

Best solution for my scenario would be a setting on DbContext allowing to lower severity of all logs from Error to Debug that are outcome of a cancellation token being cancelled but only for the one that was passed to the root invocation.

[KrzysztofBranicki]

@ajcvickers Hi, is there any timeline where we can expect a fix for this bug? The way it is working currently basically renders all APIs that use CancellationToken useless. Unless someone doesn't mind polluting his logs with flood of errors that aren't really errors (highly unlikely for any production application). My scenario is the same as others in this issue - passing ASP.CORE HTTP request related CancellationToken to handle scenarios like browser closed, F5, frontend auto complete searches etc.

[jxlarrea]

Same here. My ASP.NET Core application is unnecessarily logging thousands of TaskCanceledException errors every day due to CancellationToken being passed to EF Core queries. It is insane that this hasn't been resolved yet.

[adomass]

I think this should have a label urgent-fix not consider-for-next-release. Logging system is spammed with those errors and we are waiting for this issue to be solved for a year.

[michael-jenkinson]

Agreed, it is very annoying, and drowning out real errors.

[KrzysztofBranicki]

@ajcvickers can we expect this to be fixed in 6.0?

[ajcvickers]

@KrzysztofBranicki No, this is in the backlog milestone, which means it is not planned to be fixed for 6.0. See release-planning for information about how we plan which features go into a release. While this is an important, there are currently 53 feature requests that have more votes than this one, so it didn't make it into 6.0.

[KrzysztofBranicki]

@ajcvickers since this is not a feature request but a bug report, I think that prioritizing it by putting it on the list containing feature requests ordered by the number of "thumbs up" is probably not a good approach. Can we start by correctly labeling it as a bug? Unless there is someone who doesn't think this is a bug? :)

[brockallen]

Just came across this ourselves. Here's what shows in the customer log:

[13:29:48 Error] Microsoft.EntityFrameworkCore.Database.Connection
An error occurred using the connection to database 'Duende.EntityFramework-6.0.0' on server '(localdb)\mssqllocaldb'.

[13:29:48 Error] Microsoft.EntityFrameworkCore.Query
An exception occurred while iterating over the results of a query for context type 'Duende.IdentityServer.EntityFramework.DbContexts.ConfigurationDbContext'.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenAsync(CancellationToken cancellationToken, Boolean errorsExpected)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenAsync(CancellationToken cancellationToken, Boolean errorsExpected)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()

Which of course, looks scary for a false positive "error" condition. I'd think a flag to suppress this might be a way forward?

[roji]

@brockallen we plan to address this in EF Core 7.0.

[Liero]

Please, reconsider fixing this sooner than v7.0. There is no workaround and it is causing serious troubles under heavy workload

[roji]

@Liero I do intend to do this relatively early in the 7.0 work cycle, and at that point you'll be able to use 7.0.0 previews (which are generally very stable). However, there will not be a minor release before 7.0 with this change.

You may be able to work around this by implementing filtering outside of EF Core, i.e. by searching for TaskCanceledException in the log message text etc.

[BryceBarbara]

Here's a helper function I use in my log filter to determine if it's an exception that I can suppress.

private static bool IsCancellationException(Exception ex)
{
    if (ex == null) return false;
    if (ex is OperationCanceledException)
        return true;
    if (ex is IOException && ex.Message == "The client reset the request stream.")
        return true;
    if (ex is Microsoft.AspNetCore.Connections.ConnectionResetException)
        return true;
    // .NET SQL has a number of different exceptions thrown when operations are cancelled
    if (ex.Source == "Microsoft.Data.SqlClient" && ex.Message == "Operation cancelled by user.")
        return true;
    if ((ex is Microsoft.Data.SqlClient.SqlException || ex is System.Data.SqlClient.SqlException) &&
        ex.Message.Contains("Operation cancelled by user"))
        return true;
    return false;
}

[Liero]

@BryceBarbara: How do you apply this filter?

I was only able to filter application insights using ITelemeryProcessor, but the .NET Logging only allows filtering based on category and severity as far as I know

BTW, here is how I catch the exception:

try
{
   products = dbContext.Products.ToArray(cancellationToken)
}
catch when (cancellationToken.IsCancellationRequested) {}

[BryceBarbara]

@Liero

The project I'm working on uses a custom middleware class to suppress the unneeded exceptions. Although everyone's use case will be different, I'll share my approach here in case it's useful for anyone else.

The middleware class:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Net;
using System.Text.Json;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Http;
using Microsoft.AspNetCore.Mvc.Formatters;
using Microsoft.AspNetCore.Routing;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Primitives;
using Microsoft.Net.Http.Headers;

public class StandardizedExceptionMiddleware
{
    private static readonly HashSet<MediaType> JsonContentTypes = new HashSet<MediaType>
    {
        new MediaType("text/json"),
        new MediaType("application/json"),
    };

    private readonly RequestDelegate _next;
    private readonly ILogger<StandardizedExceptionMiddleware> _logger;

    public StandardizedExceptionMiddleware(RequestDelegate next, ILogger<StandardizedExceptionMiddleware> logger)
    {
        _next = next;
        _logger = logger;
    }

    public async Task Invoke(HttpContext context)
    {
        try
        {
            await _next(context).ConfigureAwait(false);
        }
        catch (Exception ex)
        {
            if (IsCancellationException(ex))
            {
                if (context.RequestAborted.IsCancellationRequested)
                {
                    // Try to ensure cancelled requests don't get reported as 5xx errors
                    context.Response.StatusCode = (int)HttpStatusCode.BadRequest;
                }
                return;
            }
            LogException(context, ex);
            if (!context.Response.HasStarted && await HandleExceptionAsync(context, ex).ConfigureAwait(false))
            {
                return;
            }
            // This exception wasn't handled so let it bubble up
            throw;
        }
    }

    private void LogException(HttpContext context, Exception exception)
    {
        var routeData = context.GetRouteData();
        var controller = routeData?.Values["controller"]?.ToString();
        var action = routeData?.Values["action"]?.ToString();
        if (!string.IsNullOrEmpty(controller) && !string.IsNullOrWhiteSpace(action))
        {
            _logger.LogError(exception, "Unhandled exception in {Controller}/{Action}", controller, action);
        }
        else
        {
            _logger.LogError(exception, "Unhandled exception");
        }
    }

    private static bool IsCancellationException(Exception ex)
    {
        if (ex == null) return false;
        if (ex is OperationCanceledException)
            return true;
        if (ex is System.IO.IOException && ex.Message == "The client reset the request stream.")
            return true;
        if (ex is Microsoft.AspNetCore.Connections.ConnectionResetException)
            return true;
        // .NET SQL has a number of different exceptions thrown when operations are cancelled
        if (ex.Source == "Microsoft.Data.SqlClient" && ex.Message == "Operation cancelled by user.")
            return true;
        if ((ex is Microsoft.Data.SqlClient.SqlException || ex is System.Data.SqlClient.SqlException) &&
            ex.Message.Contains("Operation cancelled by user"))
            return true;
        return false;
    }

    /// <summary>
    /// Attempts to handle sending the error response for provided context.
    /// </summary>
    /// <param name="context">The context needing a response.</param>
    /// <param name="exception">The exception that was thrown.</param>
    /// <returns>Returns true if the exception was handled and a response has been sent.</returns>
    private static async Task<bool> HandleExceptionAsync(HttpContext context, Exception exception)
    {
        if (!IsAcceptingJson(context) || exception == null) return false;

        context.Response.ContentType = "application/json";
        // this is a custom class we use, replace this with your own error response type
        var error = new StandardErrorResult(FrontEndExceptionHelpers.GetFriendlyExceptionMessage(exception));
        await JsonSerializer.SerializeAsync(context.Response.Body, error).ConfigureAwait(false);
        return true;
    }

    /// <summary>
    /// Determines if the HTTP request for the context is expecting a JSON response.
    /// </summary>
    /// <param name="context">The context containing the request.</param>
    private static bool IsAcceptingJson(HttpContext context)
    {
        var requestAccept = context.Request.Headers[HeaderNames.Accept];
        // Only consider it accepting JSON if it's explicitly stated in the request headers
        return !StringValues.IsNullOrEmpty(requestAccept) && IsSubsetOfAnyJsonContentType(requestAccept);
    }

    /// <summary>
    /// Determines if the media type provided is a subset of one of the media types in <see cref="JsonContentTypes"/>.
    /// </summary>
    /// <param name="requestMediaType">The media type to inspect.</param>
    private static bool IsSubsetOfAnyJsonContentType(string requestMediaType)
    {
        var requestedType = new MediaType(requestMediaType);
        return JsonContentTypes.Any(acceptedType => requestedType.IsSubsetOf(acceptedType));
    }
}

And we add the middleware to the Startup.cs's Configure method as so:

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
    // ...
    if (env.IsDevelopment())
    {
        app.UseDeveloperExceptionPage();
        app.UseDatabaseErrorPage();
    }
    else
    {
        app.UseExceptionHandler("/Error");
        app.UseHsts();
    }
    app.UseMiddleware<StandardizedExceptionMiddleware>();
    // ...
}

[roji]

Ran into a wall when trying to identify SqlExceptions representing cancellations - see dotnet/SqlClient#26 (comment).

If there really is no way to reliably identify cancellation with SqlClient, we could also check whether the user cancellation token has been triggered. However:

• Because of a race condition, there could be a non-cancellation SqlException bubbling up just as the user triggered their token, and we'd log incorrectly.
• At least in theory, the command could be canceled not via the cancellation token.

[roji]

This is now merged - cancellations are now logged via log new cancellation events (which are debug by default) rather than failure.

The default behavior is to identify OperationCanceledException as cancellation events. Providers can create their own IExecutionDetector and add specific logic for identifying cancellation exceptions as necessary. For SqlClient, since there's apparently no way to identify cancellation from the exception, the cancellation token is checked instead, which isn't ideal. We can fix this if SqlClient correct the problem on their side.

[brockallen]

Sorry to rekindle this thread, but is it documented or can you provide any insight into when an OperationCanceledException is thrown vs when a TaskCanceledException is thrown? We're trying to tune the filter and don't want to use OperationCanceledException is that's too broad and suppresses other meaningful exceptions/conditions. TIA!

// @josephdecock

[roji]

EF itself considers any OperationCanceledException as meaning that the operation was canceled, e.g. for the purposes of logging an error vs. a cancellation; I'd suggest you do the same. In the general case you shouldn't be catching TaskCanceledException, but rather OperationCanceledException.

[brockallen]

Thank you @roji!

[sayowayah]

Just wondering if this is still partially an issue? I'm still seeing some Microsoft.EntityFrameworkCore.Database.Connection.ConnectionError error logs when a task is cancelled. My OperationCanceledException handler is properly triggering for the same request, so it seems the new OperationCanceledException is throwing, but EF still logs that Database.Connection.ConnectionError somewhere along the way. It seems that @roji had some back and forth with someone here about the same/similar issue, but I don't see a resolution.

I was thinking about configuring EF to drop RelationalEventId.ConnectionError logs to warning, but that doesn't seem great if there's actually some other non-cancellation-related error.

More details in case my specific settings are related:

• Microsoft.EntityFrameworkCore.SqlServer 7.0.3
• Azure SQL Managed Instance
• Details for this particular query
  • Wrapped in a TransactionScope with IsolationLevel.ReadUncommitted
  • Database.SetCommandTimeout(60)
  • AsNoTracking()

[roji]

@sayowayah as far as I know the issue isolved... If you're seeing otherwise, we're going to need to see some sort of runnable repro to investigate. The SO issue linked to above was unable to do so.