Optimistic concurrency exception from stored procedure logs error

[ajcvickers]

Test with https://github.com/dotnet/EntityFramework.Docs/blob/274255cff5c7d38045ad0d15a6454e199e072f2c/samples/core/Miscellaneous/NewInEFCore7/DocumentsContext.cs#L74

Normally, a DbUpdateConcurrencyException does not result in an error being logged.

Optimistic concurrency test 1...

info: 9/18/2022 22:27:03.209 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (2ms) [Parameters=[@p1='4', @p0=NULL (Size = 4000), @p2='0x00000000000007D9' (Size = 8)], CommandType='Text', CommandTimeout='30']
      SET IMPLICIT_TRANSACTIONS OFF;
      SET NOCOUNT ON;
      UPDATE [Documents] SET [Isbn] = @p0
      OUTPUT INSERTED.[RetrievedOn], INSERTED.[RowVersion]
      WHERE [Id] = @p1 AND [RowVersion] = @p2;
Caught expected: The database operation was expected to affect 1 row(s), but actually affected 0 row(s); data may have been modified or deleted since entities were loaded. See http://go.microsoft.com/fwlink/?LinkId=527962 for information on understanding and handling optimistic concurrency exceptions.

But when using stored procedures, a "fail" message is logged:

Optimistic concurrency test 1...

info: 9/18/2022 22:30:57.117 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (0ms) [Parameters=[@p0='4', @p1='0x00000000000007D4' (Size = 8), @p2='Test-Driven Development By Example (New Edition!)' (Nullable = false) (Size = 4000), @p3='220', @p4='2003-01-01T00:00:00.0000000', @p5=NULL (Size = 8000) (DbType = Binary), @p6=NULL (Size = 4000), @p7=NULL (Precision = 18) (Scale = 2) (DbType = Decimal), @p8=NULL (DbType = Int32), @p9=NULL (DbType = Int32), @p10='2022-09-18T21:30:56.6400000', @p11=NULL (Nullable = false) (Direction = Output) (DbType = DateTime2), @p12=NULL (Size = 8) (Direction = Output) (DbType = Binary)], CommandType='Text', CommandTimeout='30']
      SET NOCOUNT ON;
      EXEC [Documents_Update] @p0, @p1, @p2, @p3, @p4, @p5, @p6, @p7, @p8, @p9, @p10, @p11 OUTPUT, @p12 OUTPUT;
fail: 9/18/2022 22:30:57.133 CoreEventId.SaveChangesFailed[10000] (Microsoft.EntityFrameworkCore.Update)
      An exception occurred in the database while saving changes for context type 'NewInEfCore7.TphDocumentsContext'.
      Microsoft.EntityFrameworkCore.DbUpdateConcurrencyException: The database operation was expected to affect 1 row(s), but actually affected 0 row(s); data may have been modified or deleted since entities were loaded. See http://go.microsoft.com/fwlink/?LinkId=527962 for information on understanding and handling optimistic concurrency exceptions.
         at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ThrowAggregateUpdateConcurrencyExceptionAsync(RelationalDataReader reader, Int32 commandIndex, Int32 expectedRowsAffected, Int32 rowsAffected, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Update.AffectedCountModificationCommandBatch.ConsumeResultSetWithRowsAffectedOnlyAsync(Int32 commandIndex, RelationalDataReader reader, CancellationToken cancellationToken)
         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)
Caught expected: The database operation was expected to affect 1 row(s), but actually affected 0 row(s); data may have been modified or deleted since entities were loaded. See http://go.microsoft.com/fwlink/?LinkId=527962 for information on understanding and handling optimistic concurrency exceptions.

[roji]

This wasn't a logging issue... It turns out that the technique we were using to return the concurrency token from the sproc was returning the original value (before the modification):

BEGIN
    UPDATE [Documents] SET
        [Title] = @Title,
        -- ...
        [IssueNumber] = @IssueNumber,
        [EditorId] = @EditorId,
        @RetrievedOn = [RetrievedOn],
        @RowVersion = [RowVersion]
    WHERE [Id] = @Id AND [RowVersion] = @RowVersion_Original
    SELECT @@ROWCOUNT;
END");

This was causing the previous update to return an out-of-date concurrency token, and for the 1st SaveChanges to fail with a concurrency exception, instead of the 2nd. That 1st SaveChanges is simply on context, where LoggingEnabled is true, whereas the 2nd SaveChanges is on context2, where Loggingenabled is false.

(Note that this means we do log SaveChangesFailed for concurrency exceptions (here).

As a fix, I'm changing the sproc definition to extract the new value of the concurrency token into a temp table (via OUTPUT INTO), and then set the output parameter to that. #29138 does this for the tests for 7.0, dotnet/EntityFramework.Docs#4038 does this for the sample fixes in the docs.

Note that after this, the TPT scenario fails during seeding with the following error (regardless of whether sprocs are enabled or not). Let me know if you want me to take a look.

The instance of entity type 'Magazine' cannot be tracked because another instance with the key value '{Id: -2147482647}' is already being tracked. When attaching existing entities, ensure that only one entity instance with a given key value is attached.

[ajcvickers]

This was causing the previous update to return an out-of-date concurrency token, and for the 1st SaveChanges to fail with a concurrency exception, instead of the 2nd. That 1st SaveChanges is simply on context, where LoggingEnabled is true, whereas the 2nd SaveChanges is on context2, where Loggingenabled is false.

I just figured out this wasn't working at all and was going to ask you how to fix it. :-)

Note that after this, the TPT scenario fails during seeding with the following error (regardless of whether sprocs are enabled or not). Let me know if you want me to take a look.

This is #29134 that I want you to review. As a workaround in the sample you can use AddRange instead of AddRangeAsync.

[roji]

This is #29134 that I want you to review. As a workaround in the sample you can use AddRange instead of AddRangeAsync.

Ah great, that's merged in now so all should be good.