Full table scan when deleting a PersistedGrant

[johnbaker]

Which version of Duende IdentityServer are you using?
6.1.0

Which version of .NET are you using?
6.0

Describe the bug

When calling introspection with an expired PersistedGrant, IDS occasionally runs a full table scan (SELECT p."Id", p."ClientId", p."ConsumedTime", p."CreationTime", p."Data", p."Description", p."Expiration", p."Key", p."SessionId", p."SubjectId", p."Type" FROM "PersistedGrants" AS p) on the PersistedGrants after attempting to delete the record. After which an exception is logged The database operation was expected to affect 1 row(s), but actually affected 0 row(s); .

To Reproduce

I cannot reproduce it at will, but it does occur regularly in our environment. We are running 10 instances of IDS behind a round robin load balancer. My best guess is several introspection requests come in simultaneously and two servers are attempting to delete the same record.

This behavior did not appear occur prior to upgrading from 6.1.0 to 6.0.4

Expected behavior

A full table scan should not be performed.

Log output/exception with stacktrace

{ "date": "2022/07/27 19:47:03.122", "level": "DEBUG", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "Starting introspection request.",  "logger": "Duende.IdentityServer.Endpoints.IntrospectionEndpoint", "callsite": "Duende.IdentityServer.Endpoints.IntrospectionEndpoint.ProcessIntrospectionRequestAsync(/_/src/IdentityServer/Endpoints/IntrospectionEndpoint.cs:82)", "traceId": "00-24010b896d4e60b12ae4ef151e8edb32-a191f7894529e56f-00", "RequestId": "80013bdc-0800-1800-b63f-84710c7967bb", "RequestPath": "/connect/introspect" }

{ "date": "2022/07/27 19:47:03.122", "level": "TRACE", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "Start access token validation",  "logger": "Duende.IdentityServer.Validation.TokenValidator", "callsite": "Duende.IdentityServer.Validation.TokenValidator.ValidateAccessTokenAsync(/_/src/IdentityServer/Validation/Default/TokenValidator.cs:132)", "traceId": "00-24010b896d4e60b12ae4ef151e8edb32-a191f7894529e56f-00", "RequestId": "80013bdc-0800-1800-b63f-84710c7967bb", "RequestPath": "/connect/introspect" }

{ "date": "2022/07/27 19:47:03.134", "level": "INFO", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "Executed DbCommand (1ms) [Parameters=[@__key_0='?'], CommandType='Text', CommandTimeout='30']\r
SELECT p.\"Id\", p.\"ClientId\", p.\"ConsumedTime\", p.\"CreationTime\", p.\"Data\", p.\"Description\", p.\"Expiration\", p.\"Key\", p.\"SessionId\", p.\"SubjectId\", p.\"Type\"\r
FROM \"PersistedGrants\" AS p\r
WHERE p.\"Key\" = @__key_0",  "logger": "Microsoft.EntityFrameworkCore.Database.Command", "callsite": "Microsoft.EntityFrameworkCore.Diagnostics.Internal.RelationalCommandDiagnosticsLogger.CommandReaderExecutedAsync", "traceId": "00-24010b896d4e60b12ae4ef151e8edb32-a191f7894529e56f-00", "RequestId": "80013bdc-0800-1800-b63f-84710c7967bb", "RequestPath": "/connect/introspect", "elapsed": "1", "parameters": "@__key_0='?'", "commandType": "Text", "commandTimeout": 30, "newLine": "\r
", "commandText": "SELECT p.\"Id\", p.\"ClientId\", p.\"ConsumedTime\", p.\"CreationTime\", p.\"Data\", p.\"Description\", p.\"Expiration\", p.\"Key\", p.\"SessionId\", p.\"SubjectId\", p.\"Type\"\r
FROM \"PersistedGrants\" AS p\r
WHERE p.\"Key\" = @__key_0", "EventId": 20101, "EventName": "Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted" }

{ "date": "2022/07/27 19:47:03.134", "level": "DEBUG", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "D2E5A178F066480BEB706975797FEE47E6780E80C972C349AF03C326015A9549 found in database: True",  "logger": "Duende.IdentityServer.EntityFramework.Stores.PersistedGrantStore", "callsite": "Duende.IdentityServer.EntityFramework.Stores.PersistedGrantStore.GetAsync(/_/src/EntityFramework.Storage/Stores/PersistedGrantStore.cs:96)", "traceId": "00-24010b896d4e60b12ae4ef151e8edb32-a191f7894529e56f-00", "RequestId": "80013bdc-0800-1800-b63f-84710c7967bb", "RequestPath": "/connect/introspect", "persistedGrantKey": "D2E5A178F066480BEB706975797FEE47E6780E80C972C349AF03C326015A9549", "persistedGrantKeyFound": true }

{ "date": "2022/07/27 19:47:03.134", "level": "ERROR", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "Token expired." }

{ "date": "2022/07/27 19:47:03.134", "level": "INFO", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "Executed DbCommand (1ms) [Parameters=[@__key_0='?'], CommandType='Text', CommandTimeout='30']\r
SELECT p.\"Id\", p.\"ClientId\", p.\"ConsumedTime\", p.\"CreationTime\", p.\"Data\", p.\"Description\", p.\"Expiration\", p.\"Key\", p.\"SessionId\", p.\"SubjectId\", p.\"Type\"\r
FROM \"PersistedGrants\" AS p\r
WHERE p.\"Key\" = @__key_0",  "logger": "Microsoft.EntityFrameworkCore.Database.Command", "callsite": "Microsoft.EntityFrameworkCore.Diagnostics.Internal.RelationalCommandDiagnosticsLogger.CommandReaderExecutedAsync", "traceId": "00-24010b896d4e60b12ae4ef151e8edb32-a191f7894529e56f-00", "RequestId": "80013bdc-0800-1800-b63f-84710c7967bb", "RequestPath": "/connect/introspect", "elapsed": "1", "parameters": "@__key_0='?'", "commandType": "Text", "commandTimeout": 30, "newLine": "\r
", "commandText": "SELECT p.\"Id\", p.\"ClientId\", p.\"ConsumedTime\", p.\"CreationTime\", p.\"Data\", p.\"Description\", p.\"Expiration\", p.\"Key\", p.\"SessionId\", p.\"SubjectId\", p.\"Type\"\r
FROM \"PersistedGrants\" AS p\r
WHERE p.\"Key\" = @__key_0", "EventId": 20101, "EventName": "Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted" }

{ "date": "2022/07/27 19:47:03.134", "level": "DEBUG", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "removing D2E5A178F066480BEB706975797FEE47E6780E80C972C349AF03C326015A9549 persisted grant from database",  "logger": "Duende.IdentityServer.EntityFramework.Stores.PersistedGrantStore", "callsite": "Duende.IdentityServer.EntityFramework.Stores.PersistedGrantStore.RemoveAsync(/_/src/EntityFramework.Storage/Stores/PersistedGrantStore.cs:129)", "traceId": "00-24010b896d4e60b12ae4ef151e8edb32-a191f7894529e56f-00", "RequestId": "80013bdc-0800-1800-b63f-84710c7967bb", "RequestPath": "/connect/introspect", "persistedGrantKey": "D2E5A178F066480BEB706975797FEE47E6780E80C972C349AF03C326015A9549" }

{ "date": "2022/07/27 19:47:03.150", "level": "INFO", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "Executed DbCommand (3ms) [Parameters=[@p0='?' (DbType = Int64)], CommandType='Text', CommandTimeout='30']\r
DELETE FROM \"PersistedGrants\"\r
WHERE \"Id\" = @p0;",  "logger": "Microsoft.EntityFrameworkCore.Database.Command", "callsite": "Microsoft.EntityFrameworkCore.Diagnostics.Internal.RelationalCommandDiagnosticsLogger.CommandReaderExecutedAsync", "traceId": "00-24010b896d4e60b12ae4ef151e8edb32-a191f7894529e56f-00", "RequestId": "80013bdc-0800-1800-b63f-84710c7967bb", "RequestPath": "/connect/introspect", "elapsed": "3", "parameters": "@p0='?' (DbType = Int64)", "commandType": "Text", "commandTimeout": 30, "newLine": "\r
", "commandText": "DELETE FROM \"PersistedGrants\"\r
WHERE \"Id\" = @p0;", "EventId": 20101, "EventName": "Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted" }

{ "date": "2022/07/27 19:47:03.150", "level": "INFO", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "Executed DbCommand (1ms) [Parameters=[], CommandType='Text', CommandTimeout='30']\r
SELECT p.\"Id\", p.\"ClientId\", p.\"ConsumedTime\", p.\"CreationTime\", p.\"Data\", p.\"Description\", p.\"Expiration\", p.\"Key\", p.\"SessionId\", p.\"SubjectId\", p.\"Type\"\r
FROM \"PersistedGrants\" AS p",  "logger": "Microsoft.EntityFrameworkCore.Database.Command", "callsite": "Microsoft.EntityFrameworkCore.Diagnostics.Internal.RelationalCommandDiagnosticsLogger.CommandReaderExecuted", "traceId": "00-24010b896d4e60b12ae4ef151e8edb32-a191f7894529e56f-00", "RequestId": "80013bdc-0800-1800-b63f-84710c7967bb", "RequestPath": "/connect/introspect", "elapsed": "1", "parameters": "", "commandType": "Text", "commandTimeout": 30, "newLine": "\r
", "commandText": "SELECT p.\"Id\", p.\"ClientId\", p.\"ConsumedTime\", p.\"CreationTime\", p.\"Data\", p.\"Description\", p.\"Expiration\", p.\"Key\", p.\"SessionId\", p.\"SubjectId\", p.\"Type\"\r
FROM \"PersistedGrants\" AS p", "EventId": 20101, "EventName": "Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted" }

{ "date": "2022/07/27 19:47:03.150", "level": "DEBUG", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "Context 'PersistedGrantDbContext' started tracking 'PersistedGrant' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.",  "logger": "Microsoft.EntityFrameworkCore.ChangeTracking", "callsite": "Microsoft.EntityFrameworkCore.Diagnostics.CoreLoggerExtensions.StartedTracking", "traceId": "00-24010b896d4e60b12ae4ef151e8edb32-a191f7894529e56f-00", "RequestId": "80013bdc-0800-1800-b63f-84710c7967bb", "RequestPath": "/connect/introspect", "contextType": "PersistedGrantDbContext", "entityType": "PersistedGrant", "EventId": 10806, "EventName": "Microsoft.EntityFrameworkCore.ChangeTracking.StartedTracking" }
...(repeated many times)...

{ "date": "2022/07/27 19:47:08.829", "level": "INFO", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "exception removing D2E5A178F066480BEB706975797FEE47E6780E80C972C349AF03C326015A9549 persisted grant from database: 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.",  "logger": "Duende.IdentityServer.EntityFramework.Stores.PersistedGrantStore", "callsite": "Duende.IdentityServer.EntityFramework.Stores.PersistedGrantStore.RemoveAsync(/_/src/EntityFramework.Storage/Stores/PersistedGrantStore.cs:135)", "traceId": "00-24010b896d4e60b12ae4ef151e8edb32-a191f7894529e56f-00", "RequestId": "80013bdc-0800-1800-b63f-84710c7967bb", "RequestPath": "/connect/introspect", "persistedGrantKey": "D2E5A178F066480BEB706975797FEE47E6780E80C972C349AF03C326015A9549", "error": "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." }


{ "date": "2022/07/27 19:47:08.829", "level": "INFO", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "Success token introspection. Token active: False, for API name: api",  "logger": "Duende.IdentityServer.Endpoints.IntrospectionEndpoint", "callsite": "Duende.IdentityServer.Endpoints.IntrospectionEndpoint.ProcessIntrospectionRequestAsync(/_/src/IdentityServer/Endpoints/IntrospectionEndpoint.cs:114)", "traceId": "00-24010b896d4e60b12ae4ef151e8edb32-a191f7894529e56f-00", "RequestId": "80013bdc-0800-1800-b63f-84710c7967bb", "RequestPath": "/connect/introspect", "tokenActive": false, "apiName": "api" }

{ "date": "2022/07/27 19:47:08.829", "level": "TRACE", "application": "IdentityServer, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null", "machineName": "EC2AMAZ", "message": "Invoking result: Duende.IdentityServer.Endpoints.Results.IntrospectionResult",  "logger": "Duende.IdentityServer.Hosting.IdentityServerMiddleware", "callsite": "Duende.IdentityServer.Hosting.IdentityServerMiddleware.Invoke(/_/src/IdentityServer/Hosting/IdentityServerMiddleware.cs:102)", "traceId": "00-24010b896d4e60b12ae4ef151e8edb32-a191f7894529e56f-00", "RequestId": "80013bdc-0800-1800-b63f-84710c7967bb", "RequestPath": "/connect/introspect", "type": "Duende.IdentityServer.Endpoints.Results.IntrospectionResult" }

Additional context

Add any other context about the problem here.

[johnbaker]

This has turned out to be a logging issue with the DbConcurrencyException thrown when EF tried to delete the PersistedGrant that was already deleted.

We found some issues gitlab for Serilog that implied logging serialization of some DbExceptions cause a DbSet property to be referenced and thus queried. We're using NLog, but it appears to be a similar issue.

[brockallen]

This is bizarre -- how are you planning to resolve this? Or is there some fix in Serilog/NLog?

[johnbaker]

The root Serilog issue appears to be resolved, at least if you use Serilog.Exceptions. I couldn't find a similar issue for NLog, so I plan on raising an issue with NLog if it is repeatable in a sample app. We're also evaluating if we can use the Serilog fix as a guide to resolve this in NLog.

[brockallen]

We're quite happy with Serilog, FWIW.