search

dotnet / efcore

EF Core is a modern object-database mapper for .NET. It supports LINQ queries, change tracking, updates, and schema migrations.
https://docs.microsoft.com/ef/
MIT License
13.71k stars 3.17k forks source link

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

Open bbascarevic opened 11 months ago

bbascarevic commented 11 months ago

I noticed a very strange behavior today that I can't fully explain. In the following simplified scenario:

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.

roji commented 11 months ago

This issue is lacking enough information for us to be able to fully understand what is happening. Please attach a small, runnable project or post a small, runnable code listing that reproduces what you are seeing so that we can investigate.

bbascarevic commented 11 months ago

@roji I created a repo that demonstrates the problem.

ajcvickers commented 11 months ago

@bbascarevic I get the same output regardless of whether _disableLoggingCache is true or false:

fail: 11/15/2023 13:36:42.713 CoreEventId.SaveChangesFailed[10000] (Microsoft.EntityFrameworkCore.Update) 
      An exception occurred in the database while saving changes for context type 'EfCoreIssue32244.DbContext'.
      Microsoft.EntityFrameworkCore.DbUpdateException: An error occurred while saving the entity changes. See the inner exception for details.
       ---> Npgsql.PostgresException (0x80004005): 23505: duplicate key value violates unique constraint "PK_Foos"

      DETAIL: Key ("Id")=(1) already exists.
         at Npgsql.Internal.NpgsqlConnector.<ReadMessage>g__ReadMessageLong|234_0(NpgsqlConnector connector, Boolean async, DataRowLoadingMode dataRowLoadingMode, Boolean readingNotifications, Boolean isReadingPrependedMessage)
         at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
         at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
         at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
         at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
         at Npgsql.NpgsqlCommand.ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
        Exception data:
          Severity: ERROR
          SqlState: 23505
          MessageText: duplicate key value violates unique constraint "PK_Foos"
          Detail: Key ("Id")=(1) already exists.
          SchemaName: public
          TableName: Foos
          ConstraintName: PK_Foos
          File: nbtinsert.c
          Line: 673
          Routine: _bt_check_unique
         --- End of inner exception stack trace ---
         at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IList`1 entriesToSave, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(StateManager stateManager, Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
         at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
info: 11/15/2023 13:36:42.720 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
      Executed DbCommand (1ms) [Parameters=[@__tag_0='After'], CommandType='Text', CommandTimeout='30']
      SELECT f."Id", f."Name", @__tag_0 AS "Tag"
      FROM "Foos" AS f
info: 11/15/2023 13:36:42.804 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
      Executed DbCommand (4ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      REVOKE CONNECT ON DATABASE "ef-issue-32244" FROM PUBLIC;
      SELECT pg_terminate_backend(pg_stat_activity.pid) FROM pg_stat_activity WHERE datname = 'ef-issue-32244';
info: 11/15/2023 13:36:42.862 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
      Executed DbCommand (58ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      DROP DATABASE "ef-issue-32244";
bbascarevic commented 11 months ago

@ajcvickers If you run dotnet test --logger:"console;verbosity=detailed", can you observe the issue?

Here's the output on my machine, as you can see the second test "swallows" info log lines after logging the failure.

[boris@legion7-nb EfIssue32244]$ dotnet test --logger:"console;verbosity=detailed"
  Determining projects to restore...
  All projects are up-to-date for restore.
  EfCoreIssue32244 -> /home/boris/Projects/EfIssue32244/EfCoreIssue32244/bin/Debug/net7.0/EfCoreIssue32244.dll
Test run for /home/boris/Projects/EfIssue32244/EfCoreIssue32244/bin/Debug/net7.0/EfCoreIssue32244.dll (.NETCoreApp,Version=v7.0)
Microsoft (R) Test Execution Command Line Tool Version 17.4.1+79d56b02b69a582cd90428878a5e9411ab7538f5 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
/home/boris/Projects/EfIssue32244/EfCoreIssue32244/bin/Debug/net7.0/EfCoreIssue32244.dll
[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.4.5+1caef2f33e (64-bit .NET 7.0.13)
[xUnit.net 00:00:00.42]   Discovering: EfCoreIssue32244
[xUnit.net 00:00:00.45]   Discovered:  EfCoreIssue32244
[xUnit.net 00:00:00.45]   Starting:    EfCoreIssue32244
[xUnit.net 00:00:01.57]   Finished:    EfCoreIssue32244
  Passed EfCoreIssue32244.TestWithLoggingCacheDisabled.Test [961 ms]
  Standard Output Messages:
 warn: 11/15/2023 14:43:59.857 CoreEventId.SensitiveDataLoggingEnabledWarning[10400] (Microsoft.EntityFrameworkCore.Infrastructure) 
       Sensitive data logging is enabled. Log entries and exception messages may include sensitive application data; this mode should only be enabled during development.
 info: 11/15/2023 14:44:00.128 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
       Executed DbCommand (49ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
       CREATE DATABASE "ef-issue-32244";
 info: 11/15/2023 14:44:00.213 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
       Executed DbCommand (3ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
       CREATE TABLE "Foos" (
           "Id" integer NOT NULL,
           "Name" text NOT NULL,
           CONSTRAINT "PK_Foos" PRIMARY KEY ("Id"),
           CONSTRAINT "AK_Foos_Name" UNIQUE ("Name")
       );
 info: 11/15/2023 14:44:00.330 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
       Executed DbCommand (14ms) [Parameters=[@p0='1', @p1='Foo' (Nullable = false)], CommandType='Text', CommandTimeout='30']
       INSERT INTO "Foos" ("Id", "Name")
       VALUES (@p0, @p1);
 info: 11/15/2023 14:44:00.470 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
       Executed DbCommand (4ms) [Parameters=[@__tag_0='Before'], CommandType='Text', CommandTimeout='30']
       SELECT f."Id", f."Name", @__tag_0 AS "Tag"
       FROM "Foos" AS f
 fail: 11/15/2023 14:44:00.483 RelationalEventId.CommandError[20102] (Microsoft.EntityFrameworkCore.Database.Command) 
       Failed executing DbCommand (2ms) [Parameters=[@p0='1', @p1='Whatever' (Nullable = false)], CommandType='Text', CommandTimeout='30']
       INSERT INTO "Foos" ("Id", "Name")
       VALUES (@p0, @p1);
 fail: 11/15/2023 14:44:00.491 CoreEventId.SaveChangesFailed[10000] (Microsoft.EntityFrameworkCore.Update) 
       An exception occurred in the database while saving changes for context type 'EfCoreIssue32244.DbContext'.
       Microsoft.EntityFrameworkCore.DbUpdateException: An error occurred while saving the entity changes. See the inner exception for details.
        ---> Npgsql.PostgresException (0x80004005): 23505: duplicate key value violates unique constraint "PK_Foos"

       DETAIL: Key ("Id")=(1) already exists.
          at Npgsql.Internal.NpgsqlConnector.<ReadMessage>g__ReadMessageLong|234_0(NpgsqlConnector connector, Boolean async, DataRowLoadingMode dataRowLoadingMode, Boolean readingNotifications, Boolean isReadingPrependedMessage)
          at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
          at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
          at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
          at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
          at Npgsql.NpgsqlCommand.ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
         Exception data:
           Severity: ERROR
           SqlState: 23505
           MessageText: duplicate key value violates unique constraint "PK_Foos"
           Detail: Key ("Id")=(1) already exists.
           SchemaName: public
           TableName: Foos
           ConstraintName: PK_Foos
           File: nbtinsert.c
           Line: 664
           Routine: _bt_check_unique
          --- End of inner exception stack trace ---
          at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IList`1 entriesToSave, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(StateManager stateManager, Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
          at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
 info: 11/15/2023 14:44:00.494 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
       Executed DbCommand (1ms) [Parameters=[@__tag_0='After'], CommandType='Text', CommandTimeout='30']
       SELECT f."Id", f."Name", @__tag_0 AS "Tag"
       FROM "Foos" AS f
 info: 11/15/2023 14:44:00.511 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
       Executed DbCommand (3ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
       REVOKE CONNECT ON DATABASE "ef-issue-32244" FROM PUBLIC;
       SELECT pg_terminate_backend(pg_stat_activity.pid) FROM pg_stat_activity WHERE datname = 'ef-issue-32244';
 info: 11/15/2023 14:44:00.518 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
       Executed DbCommand (7ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
       DROP DATABASE "ef-issue-32244";

  Passed EfCoreIssue32244.TestWithLoggingCacheEnabled.Test [106 ms]
  Standard Output Messages:
 info: 11/15/2023 14:44:00.587 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
       Executed DbCommand (32ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
       CREATE DATABASE "ef-issue-32244";
 info: 11/15/2023 14:44:00.606 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
       Executed DbCommand (4ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
       CREATE TABLE "Foos" (
           "Id" integer NOT NULL,
           "Name" text NOT NULL,
           CONSTRAINT "PK_Foos" PRIMARY KEY ("Id"),
           CONSTRAINT "AK_Foos_Name" UNIQUE ("Name")
       );
 info: 11/15/2023 14:44:00.609 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
       Executed DbCommand (1ms) [Parameters=[@p0='1', @p1='Foo' (Nullable = false)], CommandType='Text', CommandTimeout='30']
       INSERT INTO "Foos" ("Id", "Name")
       VALUES (@p0, @p1);
 info: 11/15/2023 14:44:00.610 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
       Executed DbCommand (0ms) [Parameters=[@__tag_0='Before'], CommandType='Text', CommandTimeout='30']
       SELECT f."Id", f."Name", @__tag_0 AS "Tag"
       FROM "Foos" AS f
 fail: 11/15/2023 14:44:00.611 RelationalEventId.CommandError[20102] (Microsoft.EntityFrameworkCore.Database.Command) 
       Failed executing DbCommand (1ms) [Parameters=[@p0='1', @p1='Whatever' (Nullable = false)], CommandType='Text', CommandTimeout='30']
       INSERT INTO "Foos" ("Id", "Name")
       VALUES (@p0, @p1);
 fail: 11/15/2023 14:44:00.612 CoreEventId.SaveChangesFailed[10000] (Microsoft.EntityFrameworkCore.Update) 
       An exception occurred in the database while saving changes for context type 'EfCoreIssue32244.DbContext'.
       Microsoft.EntityFrameworkCore.DbUpdateException: An error occurred while saving the entity changes. See the inner exception for details.
        ---> Npgsql.PostgresException (0x80004005): 23505: duplicate key value violates unique constraint "PK_Foos"

       DETAIL: Key ("Id")=(1) already exists.
          at Npgsql.Internal.NpgsqlConnector.<ReadMessage>g__ReadMessageLong|234_0(NpgsqlConnector connector, Boolean async, DataRowLoadingMode dataRowLoadingMode, Boolean readingNotifications, Boolean isReadingPrependedMessage)
          at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
          at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
          at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
          at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
          at Npgsql.NpgsqlCommand.ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
         Exception data:
           Severity: ERROR
           SqlState: 23505
           MessageText: duplicate key value violates unique constraint "PK_Foos"
           Detail: Key ("Id")=(1) already exists.
           SchemaName: public
           TableName: Foos
           ConstraintName: PK_Foos
           File: nbtinsert.c
           Line: 664
           Routine: _bt_check_unique
          --- End of inner exception stack trace ---
          at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.Update.Internal.BatchExecutor.ExecuteAsync(IEnumerable`1 commandBatches, IRelationalConnection connection, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(IList`1 entriesToSave, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.ChangeTracking.Internal.StateManager.SaveChangesAsync(StateManager stateManager, Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
          at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
          at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)

Test Run Successful.
Total tests: 2
     Passed: 2
 Total time: 2.0539 Seconds
[boris@legion7-nb EfIssue32244]$
ajcvickers commented 11 months ago

@bbascarevic Thanks; I am able to reproduce this now.