dotnet / dotnet/efcore

Make SQL available in Update failures

Open
#29,543 11 comments 3 reactions 0 assignees View on GitHub
area-save-changes customer-reported
Dominant language
C#
Stars
14.8k
Forks
3.4k
PR merge metrics
PR metrics pending

Description

When using Microsoft.Extensions.Logging in EF Core 6 (per [docs](https://learn.microsoft.com/ef/core/logging-events-diagnostics/extensions-logging)), an error in the database command will be logged with the logging category `Microsoft.EntityFrameworkCore.Database.Command[20102]` which includes the query that caused the error. An aggregate exception is also logged under `Microsoft.EntityFrameworkCore.Update[10000]`, but it doesn't send the offending query to the logger. This is working fine with EF Core 6.

After upgrading to EF Core 7, `Microsoft.EntityFrameworkCore.Database.Command[20102]` failures are no longer logged. Only the `Microsoft.EntityFrameworkCore.Update[10000]` failures appear in the log output.

### Full Reproduction

- On a Windows machine, install the latest .NET 6 and .NET 7 SDKs
- Clone the repository at: https://github.com/mattjohnsonpint/ef7-logging-issue-repro
- Run `dotnet run -f net6.0` to see the log output when running on .NET 6 with EF Core 6
- Run `dotnet run -f net7.0` to see the log output when running on .NET 7 with EF Core 7

This app creates a new SQL LocalDB instance when it is run. It adds a table with an entity that has a unique index. It adds an item to the table, then violates the index by adding another item with the same name. That should be in the logs.

On the EF Core 6 version, you will see in the logs:
```
fail: Microsoft.EntityFrameworkCore.Database.Command[20102]
Failed executing DbCommand (2ms) [Parameters=[@p0='Value' (Nullable = false) (Size = 450)], CommandType='Text', CommandTimeout='30']
SET NOCOUNT ON;
INSERT INTO [TestEntities] ([Property])
VALUES (@p0);
SELECT [Id]
FROM [TestEntities]
WHERE @@ROWCOUNT = 1 AND [Id] = scope_identity();
```

That entry is missing from the EF Core 7 version.

This is super important. I believe it will affect anyone using any logging provider with EF Core 7 to log errors. Thanks in advance for your prompt attention.

Full Log Output - EF Core 6

```
warn: Microsoft.EntityFrameworkCore.Model.Validation[10400]
Sensitive data logging is enabled. Log entries and exception messages may include sensitive application data; this mode should only be enabled during development.
info: Microsoft.EntityFrameworkCore.Infrastructure[10403]
Entity Framework Core 6.0.11 initialized 'TestDbContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer:6.0.11' with options: SensitiveDataLoggingEnabled DetailedErrorsEnabled
LocalDb: Start `(LocalDb)\TestDbContext` 314ms.
info: Microsoft.EntityFrameworkCore.Infrastructure[10403]
Entity Framework Core 6.0.11 initialized 'TestDbContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer:6.0.11' with options: SensitiveDataLoggingEnabled DetailedErrorsEnabled
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (7ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT 1
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (36ms) [Parameters=[], CommandType='Text', CommandTimeout='30']

IF EXISTS
(SELECT *
FROM [sys].[objects] o
WHERE [o].[type] = 'U'
AND [o].[is_ms_shipped] = 0
AND NOT EXISTS (SELECT *
FROM [sys].[extended_properties] AS [ep]
WHERE [ep].[major_id] = [o].[object_id]
AND [ep].[minor_id] = 0
AND [ep].[class] = 1
AND [ep].[name] = N'microsoft_database_tools_support'
)
)
SELECT 1 ELSE SELECT 0
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (1ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
CREATE TABLE [TestEntities] (
[Id] int NOT NULL IDENTITY,
[Property] nvarchar(450) NOT NULL,
CONSTRAINT [PK_TestEntities] PRIMARY KEY ([Id])
);
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (1ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
CREATE UNIQUE INDEX [IX_TestEntities_Property] ON [TestEntities] ([Property]);
info: Microsoft.EntityFrameworkCore.Infrastructure[10403]
Entity Framework Core 6.0.11 initialized 'TestDbContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer:6.0.11' with options: SensitiveDataLoggingEnabled DetailedErrorsEnabled
info: Microsoft.EntityFrameworkCore.Infrastructure[10403]
Entity Framework Core 6.0.11 initialized 'TestDbContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer:6.0.11' with options: SensitiveDataLoggingEnabled DetailedErrorsEnabled
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (40ms) [Parameters=[@p0='Value' (Nullable = false) (Size = 450)], CommandType='Text', CommandTimeout='30']
SET NOCOUNT ON;
INSERT INTO [TestEntities] ([Property])
VALUES (@p0);
SELECT [Id]
FROM [TestEntities]
WHERE @@ROWCOUNT = 1 AND [Id] = scope_identity();
fail: Microsoft.EntityFrameworkCore.Database.Command[20102]
Failed executing DbCommand (2ms) [Parameters=[@p0='Value' (Nullable = false) (Size = 450)], CommandType='Text', CommandTimeout='30']
SET NOCOUNT ON;
INSERT INTO [TestEntities] ([Property])
VALUES (@p0);
SELECT [Id]
FROM [TestEntities]
WHERE @@ROWCOUNT = 1 AND [Id] = scope_identity();
fail: Microsoft.EntityFrameworkCore.Update[10000]
An exception occurred in the database while saving changes for context type 'EFCoreBugDemo.TestDbContext'.
Microsoft.EntityFrameworkCore.DbUpdateException: An error occurred while saving the entity changes. See the inner exception for details.
---> Microsoft.Data.SqlClient.SqlException (0x80131904): Cannot insert duplicate key row in object 'dbo.TestEntities' with unique index 'IX_TestEntities_Property'. The duplicate key value is (Value).
The statement has been terminated.
at Microsoft.Data.SqlClient.SqlCommand.<>c.b__208_0(Task`1 result)
at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
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)
ClientConnectionId:42695bd1-979c-4e65-8fb4-f68213c4c266
Error Number:2601,State:1,Class:14
--- 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 Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
Microsoft.EntityFrameworkCore.DbUpdateException: An error occurred while saving the entity changes. See the inner exception for details.
---> Microsoft.Data.SqlClient.SqlException (0x80131904): Cannot insert duplicate key row in object 'dbo.TestEntities' with unique index 'IX_TestEntities_Property'. The duplicate key value is (Value).
The statement has been terminated.
at Microsoft.Data.SqlClient.SqlCommand.<>c.b__208_0(Task`1 result)
at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
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)
ClientConnectionId:42695bd1-979c-4e65-8fb4-f68213c4c266
Error Number:2601,State:1,Class:14
--- 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 Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)

Process finished with exit code 0.
```

Full Log Output - EF Core 7

```
warn: Microsoft.EntityFrameworkCore.Model.Validation[10400]
Sensitive data logging is enabled. Log entries and exception messages may include sensitive application data; this mode should only be enabled during development.
LocalDb: Start `(LocalDb)\TestDbContext` 322ms.
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (6ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT 1
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (35ms) [Parameters=[], CommandType='Text', CommandTimeout='30']

IF EXISTS
(SELECT *
FROM [sys].[objects] o
WHERE [o].[type] = 'U'
AND [o].[is_ms_shipped] = 0
AND NOT EXISTS (SELECT *
FROM [sys].[extended_properties] AS [ep]
WHERE [ep].[major_id] = [o].[object_id]
AND [ep].[minor_id] = 0
AND [ep].[class] = 1
AND [ep].[name] = N'microsoft_database_tools_support'
)
)
SELECT 1 ELSE SELECT 0
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (1ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
CREATE TABLE [TestEntities] (
[Id] int NOT NULL IDENTITY,
[Property] nvarchar(450) NOT NULL,
CONSTRAINT [PK_TestEntities] PRIMARY KEY ([Id])
);
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (1ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
CREATE UNIQUE INDEX [IX_TestEntities_Property] ON [TestEntities] ([Property]);
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (50ms) [Parameters=[@p0='Value' (Nullable = false) (Size = 450)], CommandType='Text', CommandTimeout='30']
SET IMPLICIT_TRANSACTIONS OFF;
SET NOCOUNT ON;
INSERT INTO [TestEntities] ([Property])
OUTPUT INSERTED.[Id]
VALUES (@p0);
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
Executed DbCommand (1ms) [Parameters=[@p0='Value' (Nullable = false) (Size = 450)], CommandType='Text', CommandTimeout='30']
SET IMPLICIT_TRANSACTIONS OFF;
SET NOCOUNT ON;
INSERT INTO [TestEntities] ([Property])
OUTPUT INSERTED.[Id]
VALUES (@p0);
fail: Microsoft.EntityFrameworkCore.Update[10000]
An exception occurred in the database while saving changes for context type 'EFCoreBugDemo.TestDbContext'.
Microsoft.EntityFrameworkCore.DbUpdateException: An error occurred while saving the entity changes. See the inner exception for details.
---> Microsoft.Data.SqlClient.SqlException (0x80131904): Cannot insert duplicate key row in object 'dbo.TestEntities' with unique index 'IX_TestEntities_Property'. The duplicate key value is (Value).
at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
at Microsoft.Data.SqlClient.SqlDataReader.TryHasMoreRows(Boolean& moreRows)
at Microsoft.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)
at Microsoft.Data.SqlClient.SqlDataReader.ReadAsyncExecute(Task task, Object state)
at Microsoft.Data.SqlClient.SqlDataReader.InvokeAsyncCall[T](SqlDataReaderAsyncCallContext`1 context)
--- End of stack trace from previous location ---
at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeResultSetAsync(Int32 startCommandIndex, RelationalDataReader reader, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeAsync(RelationalDataReader reader, CancellationToken cancellationToken)
ClientConnectionId:eb16f019-db75-47c3-9f1b-1bbdf0bfae68
Error Number:2601,State:1,Class:14
--- End of inner exception stack trace ---
at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeAsync(RelationalDataReader reader, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.SqlServer.Update.Internal.SqlServerModificationCommandBatch.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 Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)
Microsoft.EntityFrameworkCore.DbUpdateException: An error occurred while saving the entity changes. See the inner exception for details.
---> Microsoft.Data.SqlClient.SqlException (0x80131904): Cannot insert duplicate key row in object 'dbo.TestEntities' with unique index 'IX_TestEntities_Property'. The duplicate key value is (Value).
at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
at Microsoft.Data.SqlClient.SqlDataReader.TryHasMoreRows(Boolean& moreRows)
at Microsoft.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)
at Microsoft.Data.SqlClient.SqlDataReader.ReadAsyncExecute(Task task, Object state)
at Microsoft.Data.SqlClient.SqlDataReader.InvokeAsyncCall[T](SqlDataReaderAsyncCallContext`1 context)
--- End of stack trace from previous location ---
at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeResultSetAsync(Int32 startCommandIndex, RelationalDataReader reader, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeAsync(RelationalDataReader reader, CancellationToken cancellationToken)
ClientConnectionId:eb16f019-db75-47c3-9f1b-1bbdf0bfae68
Error Number:2601,State:1,Class:14
--- End of inner exception stack trace ---
at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeAsync(RelationalDataReader reader, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Update.ReaderModificationCommandBatch.ExecuteAsync(IRelationalConnection connection, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.SqlServer.Update.Internal.SqlServerModificationCommandBatch.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 Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.DbContext.SaveChangesAsync(Boolean acceptAllChangesOnSuccess, CancellationToken cancellationToken)

Process finished with exit code 0.
```

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.