efcore: Distinguish cancellation from failure to allow different logging strategies

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.

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”.

@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? 😃

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.

@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.

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

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.

@sommmen This issue was about modifying the logging that EF does when there’s a cancellation, not about changing the exceptions that SqlClient throws. See https://github.com/dotnet/SqlClient/issues/26, which was linked earlier in this issue.

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.

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

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

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

Thank you @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.

@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>();
    // ...
}

@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.