Fails to Handle Stacktrace From EF Core DbUpdateException

[Cooksauce]

Please mark the type framework used:

• ASP.NET MVC
• ASP.NET Web API (OWIN)
• ASP.NET Core
• WPF
• WinForms
• Xamarin
• Other:

Please mark the type of the runtime used:

• .NET Framework
• Mono
• .NET Core

• Version: 3.1.x

Please mark the NuGet packages used:

• Sentry
• Sentry.Serilog
• Sentry.NLog
• Sentry.Log4Net
• Sentry.Extensions.Logging
• Sentry.AspNetCore

• Version: 2.1.4

Details

Sentry fails to properly handle the Stacktrace in DbUpdateException thrown EF Core with Npgsql provider.
Half of the stacktrace (containing all of the application method calls) is completely dropped.

Sentry "Raw" Stacktrace (shown in Sentry web-app):

Microsoft.EntityFrameworkCore.DbUpdateException: An error occurred while updating the entries. See the inner exception for details.
  Module "Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch", in ExecuteAsync
  Module "System.Runtime.ExceptionServices.ExceptionDispatchInfo", in Throw
  Module "System.Runtime.CompilerServices.TaskAwaiter", in ThrowForNonSuccess
  Module "Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor", in ExecuteAsync
  Module "System.Runtime.ExceptionServices.ExceptionDispatchInfo", in Throw
  Module "Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor", in ExecuteAsync
  Module "System.Runtime.ExceptionServices.ExceptionDispatchInfo", in Throw
  Module "System.Runtime.CompilerServices.TaskAwaiter", in ThrowForNonSuccess
  Module "System.Runtime.CompilerServices.TaskAwaiter", in HandleNonSuccessAndDebuggerNotification
  Module "System.Runtime.CompilerServices.TaskAwaiter`1", in GetResult
  Module "Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager", in SaveChangesAsync
  Module "System.Runtime.ExceptionServices.ExceptionDispatchInfo", in Throw
  Module "System.Runtime.CompilerServices.TaskAwaiter", in ThrowForNonSuccess
  Module "System.Runtime.CompilerServices.TaskAwaiter", in HandleNonSuccessAndDebuggerNotification
  Module "Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager", in SaveChangesAsync
  Module "System.Runtime.ExceptionServices.ExceptionDispatchInfo", in Throw
  Module "System.Runtime.CompilerServices.TaskAwaiter", in ThrowForNonSuccess
  Module "System.Runtime.CompilerServices.TaskAwaiter", in HandleNonSuccessAndDebuggerNotification
  Module "System.Runtime.CompilerServices.TaskAwaiter`1", in GetResult
  Module "Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy+<ExecuteAsync>d__7`2", in MoveNext
  Module "System.Runtime.ExceptionServices.ExceptionDispatchInfo", in Throw
  Module "System.Runtime.CompilerServices.TaskAwaiter", in ThrowForNonSuccess
  Module "System.Runtime.CompilerServices.TaskAwaiter", in HandleNonSuccessAndDebuggerNotification
  Module "System.Runtime.CompilerServices.TaskAwaiter`1", in GetResult
  Module "Microsoft.EntityFrameworkCore.DbContext", in SaveChangesAsync

Actual Stacktrace (captured right before call to SentrySdk.CaptureException(..)):

   at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.<ExecuteAsync>d__29.MoveNext()
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.<ExecuteAsync>d__8.MoveNext()
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.<ExecuteAsync>d__8.MoveNext()
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.<SaveChangesAsync>d__97.MoveNext()
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.<SaveChangesAsync>d__101.MoveNext()
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.<ExecuteAsync>d__7`2.MoveNext()
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at Microsoft.EntityFrameworkCore.DbContext.<SaveChangesAsync>d__54.MoveNext()
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at MyClass.<MyMethodC>d__7.MoveNext() in /<redacted file path>/MyClass.cs:line 184
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at MyClass.<MyMethodB>d__3.MoveNext() in /<redacted file path>/MyClass.cs:line 44
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at MyClass.<MyMethodA>d__9.MoveNext() in /<redacted file path>/MyClass.cs:line 44

[bruno-garcia]

The Sentry SDK is doing it's job and logging something as it was provided to it. EF Core though is logging in the middle which doesn't include the stack trace. This issue suggest just dropping that log entry altogether (since it'll be logged once rethrown)

Could you please, for now, try to get rid of this log with this filter:

c.AddLogEntryFilter((category, level, eventId, exception)
    => eventId.Id == 10000 
       && string.Equals(eventId.Name, "Microsoft.EntityFrameworkCore.Update.SaveChangesFailed", StringComparison.Ordinal)
       && string.Equals(category,"Microsoft.EntityFrameworkCore.Database.Command", StringComparison.Ordinal));

[Cooksauce]

@bruno-garcia My issue is not with the log entry, but with capturing the exception. I need the full stacktrace from the exception to be shown in Sentry. Right now, Sentry is cutting off part of the exception stacktrace.

*Adding the log filter has no effect. (Because I'm capturing the exception with SentrySdk.CaptureException(..))

[bruno-garcia]

Sentry ir reporting the stack trace correctly, as it received. The problem here is that EF is logging the error internally. The top of the stack is itself. The issue linked suggests a fix (don't log this exception, it'll be logged when rethrown so from the top of the stack, with the complete stacktrace

[Cooksauce]

Forgive me, I'm not quite following what you're suggesting. EF throws the exception when SaveChanges() is called. It then bubbles up to my top level catch statement. In that catch statement I can see the entire stacktrace on the exception. Then, I use the Sentry sdk, calling CaptureException(), to report it to Sentry. I'm not following why that would not include the full exception stacktrace?

Note: I did try your log filter suggestion and it did not change anything (which is what I expected - because I'm talking about capturing the exception not the log message from EF).

[bruno-garcia]

Could you please share a repro so we can look into it?

[Cooksauce]

@bruno-garcia Here is a repro. After playing around with it, it appears Sentry is trying to merge the event from the error log message & the event from the error. When doing this, it keeps the stacktrace from the error log message instead of using the stack trace from the exception. IMO, this should either merge events (keeping/appending the stacktrace/s) or record two separate events. Right now, it's halfway merging in a non-intuitive way. Additionally, adding specific filters for these specific error messages seems like a maintenance nightmare. I think a more generalized configuration of how exceptions & error logs are merged would be a much better solution.

*Note: You have to specify the SENTRY_DSN environment variable in docker-compose.yml

*Note: I was able to filter the event by inverting the bool result your log entry filter.
SentryRepro.zip

[bruno-garcia]

OK, I ran your example (with an invalid connection string) which is enough to reproduce the error anyway.
It's the same problem I was trying to explain above. Let me try to reword it:

In Sentry I see 2 events. They are both triggered by the same exception.

One of them has the top of the frame SaveChangesAsync and that's because EF Core calls LogError passing the exception. @kanadaj pointed this out before on Sentry's Discord server.

You can see that because it has a tag called logger with a value Microsoft.EntityFrameworkCore.Update.

This event also has the ex.ToString() as a message. Which turns out to be a horrible event in Sentry since it's a huge Message string with the stack trace, on top of the misleading stack trace (all frames visible since no InApp frames exist. So Sentry shows everything):

The second event is actually logged once EF Core rethrows that exception and it's captured above, with the complete stacktrace (some frames not visible because App Only is selected):

So to clarify a few things: Sentry's SDK simply gets an Exception either by its public API (SentrySdk.CaptureException) or by one of the integrations, like the Sentry.Extensions.Logging through LogError(exception, ..), reads the frames that are in there and send to Sentry. There is no merging of exceptions or anything fancy or special happening.

This odd exception with "an incomplete stacktrace" is simply an internal logger.LogError that happens inside EF Core right before EF Core throws the exception. We can simply ignore it (best approach up for discussion but suggesting a filter) since the rethrown exception should be logged instead (it will contain the complete stack trace).

That said I suggest we simply filter out messages coming out from that EF Core logger like:

o.AddLogEntryFilter((category, level, eventId, exception)
    => eventId.Name == "Microsoft.EntityFrameworkCore.Update.SaveChangesFailed" 
       && level == LogLevel.Error);

[Cooksauce]

@bruno-garcia

Thanks for looking into this. Can you clarify, without any filtering, this given situation should produce two, distinct Sentry events viewable in the Sentry web-app?
In other words, there is no merging done in Sentry's servers? Though they likely share a fingerprint and get grouped together

[bruno-garcia]

There should be two events, indeed.

They will not be grouped together though. Sentry will use the stacktrace for grouping, when available. The frames that are marked inApp=true when some are there. And since the event captured by EF Core has only the frames from SaveChangesAsync to the point where the exception was thrown, and the second issue will contain frames from the catch block, including the call to EF Core SaveChangesAsync + the frames into the throw expression, the two events won't be grouped.

[bruno-garcia]

Basically the code in EF is here:

https://github.com/dotnet/efcore/blob/37f94ec3459d50dc030019c694acb99af4d53586/src/EFCore/DbContext.cs#L509-L511

            catch (Exception exception)
            {
                DbContextDependencies.UpdateLogger.SaveChangesFailed(this, exception);

                throw;
            }

So it logs and rethrows. We care about the rethrown error (the logged one isn't helpful)

[kanadaj]

@Cooksauce @bruno-garcia EF Core uses an internal logger to log the exception internally. Since Sentry subscribes to the logging system, this log reaches Sentry and gets sent as an error. Next, the error bubbles up, and Sentry catches that too; however I believe Sentry SDK might be de-duplicating the latter exception (the Sentry has an exception de-duplication filter). This means only the internal exception is sent to Sentry, which hasn't had the chance to bubble up to the user code, so the stacktrace ends up missing a part.

The filter shared by Bruno is meant to stop the internal exception from being sent, so only the exception bubbling up to the user code is caught. Just add the code to your Sentry config method.

c.AddLogEntryFilter((category, level, eventId, exception)
    => eventId.Id == 10000 
       && string.Equals(eventId.Name, "Microsoft.EntityFrameworkCore.Update.SaveChangesFailed", StringComparison.Ordinal)
       && string.Equals(category,"Microsoft.EntityFrameworkCore.Database.Command", StringComparison.Ordinal));

[bruno-garcia]

Sentry SDK doesn't de duplicate inner exceptions (by default, can opt in) for a few releases now so both events get to Sentry with the latest SDK.
Filtering out still advised to reduce noise.