dotnet / dotnet/efcore

Logging of RelationalCommands stops for up to 1000ms once a command errors

Open
#32,244 5 comments 0 reactions 0 assignees View on GitHub
area-logging customer-reported
Dominant language
C#
Stars
14.8k
Forks
3.4k
PR merge metrics
PR metrics pending

Description

I noticed a very strange behavior today that I can't fully explain. In the following simplified scenario:
```csharp
myDbContext.Foos.Add(new Foo { SomeUniqueKey = "foo" });
myDbContext.SaveChanges();
myDbContext.ChangeTracker.Clear(); // To avoid an early failure and cause an actual db constraint violation.
try
{
myDbContext.Foos.Add(new Foo { SomeUniqueKey = "foo" });
myDbContext.SaveChanges();
}
catch (Exception)
{
// Whatever here...
}

// Rest of the code
```
No RelationalCommand executions will be logged in the _Rest of the code_ section for up to 1000ms after the failure.

The issue only presents itself if the debugger is not attached; if a debugger _is_ attached, even with no breakpoints, then logging works as it should, which made this very difficult to pin down.

I noticed this in an XUnit.Net test that was testing whether our CreateOrUpdate implementation was working as it should, as it relies on asking for forgiveness after a constraint violation. The test is using ASP.Net WebApplicationFactory to assemble the app and resolve dependencies, so it should be as close to the ASP metal as possible from tests.

Other independent things that make it work as it should:
1. Setting `optionsBuilder.ConfigureLoggingCacheTime(TimeSpan.Zero)`.
2. Moving the test to a console app and running it, with or without debugger attached. (EDIT: This one is also problematic. Running from the console using `dotnet run` doesn't log properly while running from an IDE does.)
3. Lowering the log level for EF from Information to Debug. This somehow makes both Debug and Information EF command logging work again.

Thing `#1` is the reason I'm asking here instead of looking for a bug in XUnit runner or our own code.

I can't explain `#2`. I suspected XUnit.Net at first so I created a new console project that references the test project, and created a Program.cs that instantiates and runs the test with no code changes. Logging works in all cases.

`#3` is also weird, why would lowering the level to Debug make Information work? Ultimately, why does attaching the debugger change the behavior?

Using EF 7.0.13 with Npgsql on Linux.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.