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?