Warnings when refreshing token

[ADringer]

Hi all,

I have a warning to do with DB concurrency when refreshing a token, but not sure what is causing it. The full logs are:

dbug: Duende.IdentityServer.EntityFramework.Stores.PersistedGrantStore[0] FF2BD137D7B3DF7374D6F43C872A4758EC0B35323A2688BE75995A07BF01188F found in database

dbug: Microsoft.EntityFrameworkCore.Update[10004] SaveChanges starting for 'PersistedGrantDbContext'. 

dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10800] DetectChanges starting for 'PersistedGrantDbContext'. 

dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10802] The unchanged property 'PersistedGrant.CreationTime' was detected as changed and will be marked as modified. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see property values. 

dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10807] An entity of type 'PersistedGrant' tracked by 'PersistedGrantDbContext' changed state from 'Unchanged' to 'Modified'. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. 

dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10802] The unchanged property 'PersistedGrant.Data' was detected as changed and will be marked as modified. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see property values. 

dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10802] The unchanged property 'PersistedGrant.Expiration' was detected as changed and will be marked as modified. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see property values. 

dbug: Microsoft.EntityFrameworkCore.ChangeTracking[10801] DetectChanges completed for 'PersistedGrantDbContext'. 

dbug: Microsoft.EntityFrameworkCore.Database.Command[20100] Executing DbCommand [Parameters=[@p3='?' (DbType = Int64), @p0='?' (DbType = DateTime), @p1='?' (Size = 4000), @p2='?' (DbType = DateTime)], CommandType='Text', CommandTimeout='30'] SET AUTOCOMMIT = 1; UPDATE `PersistedGrants` SET `CreationTime` = @p0, `Data` = @p1, `Expiration` = @p2 WHERE `Id` = @p3; SELECT ROW_COUNT(); 

info: Microsoft.EntityFrameworkCore.Database.Command[20101] Executed DbCommand (10ms) [Parameters=[@p3='?' (DbType = Int64), @p0='?' (DbType = DateTime), @p1='?' (Size = 4000), @p2='?' (DbType = DateTime)], CommandType='Text', CommandTimeout='30'] SET AUTOCOMMIT = 1; UPDATE `PersistedGrants` SET `CreationTime` = @p0, `Data` = @p1, `Expiration` = @p2 WHERE `Id` = @p3; SELECT ROW_COUNT();

dbug: Microsoft.EntityFrameworkCore.Update[10006] 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 https://go.microsoft.com/fwlink/?LinkId=527962 for information on understanding and handling optimistic concurrency exceptions. 

warn: Duende.IdentityServer.EntityFramework.Stores.PersistedGrantStore[0] exception updating FF2BD137D7B3DF7374D6F43C872A4758EC0B35323A2688BE75995A07BF01188F persisted grant in 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 https://go.microsoft.com/fwlink/?LinkId=527962 for information on understanding and handling optimistic concurrency exceptions. 

dbug: Duende.IdentityServer.Services.DefaultRefreshTokenService[0] Updated refresh token in store 

Some notes:

1. I have two tasks running load balanced
2. I'm running 7.4.8 (due to upgrade to 8 soon)
3. I can see the expiration date has been updated after the error so not sure what the actual issue is?
4. If I refresh shortly after there is no error, but after ~5 mins then it is reproduced
5. Refresh tokens are set to reusable, and sliding window.

Cleanup config is:

options.EnableTokenCleanup = true;
options.RemoveConsumedTokens = true;

[wcabus]

@ADringer, which database provider and EF Core implementation are you using? Is it MySQL and MySql.EntityFrameworkCore by any chance?

If so, check if the connection string you're using contains UseAffectedRows=true, and try setting this to false. The Pomelo EF Core provider actually disables this for you (or even throws an exception when enabled), because of how EF Core deals with concurrency exceptions based on the affected row count.
Should you use the same connection string in multiple places, for example to perform custom queries using ADO.NET, you may need to adapt the connection string if you're relying on this behavior. But for EF Core, UseAffectedRows should be disabled in a MySQL system.

[ADringer]

Also to add to it, it seems like for a new session/user the token is never persisted but is returned. So it appears to work for an hour but then when it tries to refresh it's rejected as the refresh token wasn't persisted. But if I try reauthenticating again it persists fine. Still within the ~5 minute window

[ADringer]

Ah, think I've found the issue.

We're using AWS RDS proxy and have just noticed the following limitation:

Using the ROW_COUNT() function in a multi-statement query is not supported.

And then from the logs it's running:

dbug: Microsoft.EntityFrameworkCore.Database.Command[20100] Executing DbCommand [Parameters=[@p0='?' (DbType = Int64), @p1='?' (Size = 200), @p2='?' (DbType = DateTime), @p3='?' (DbType = DateTime), @p4='?' (Size = 4000), @p5='?' (Size = 200), @p6='?' (DbType = DateTime), @p7='?' (Size = 200), @p8='?' (Size = 100), @p9='?' (Size = 200), @p10='?' (Size = 50)], CommandType='Text', CommandTimeout='30'] DELETE FROM `PersistedGrants` WHERE `Id` = @p0; SELECT ROW_COUNT(); INSERT INTO `PersistedGrants` (`ClientId`, `ConsumedTime`, `CreationTime`, `Data`, `Description`, `Expiration`, `Key`, `SessionId`, `SubjectId`, `Type`) VALUES (@p1, @p2, @p3, @p4, @p5, @p6, @p7, @p8, @p9, @p10); SELECT `Id` FROM `PersistedGrants` WHERE ROW_COUNT() = 1 AND `Id` = LAST_INSERT_ID(); 

So I assume this is the cause.

Are there any workaround for working with RDS proxy?

[wcabus]

In the Pomelo repository, I found a similar issue when using AWS RDS. Unfortunately, the issue was closed without a fix because it is caused by an external service, and not considered to be a bug in the Pomelo EF Core provider.

They did suggest a workaround, by creating a custom DbCommandInterceptor to rewrite the query when a ROW_COUNT() subquery is present.

[ADringer]

Ok, thanks for the pointer, that could be useful.

I can see that in that example it's catching any queries that end with the SELECT ROW_COUNT() and running that separately. But in the logs that I put above it's doing:

DELETE FROM PersistedGrants ...;
SELECT ROW_COUNT();
INSERT INTO PersistedGrants ...;
SELECT FROM PersistedGrants ... WHERE ROW_COUNT() = 1 ....;

I'm not sure it's possible to resolve it for this example as it's got to be a multi statement query as there should be two result sets (based on the number of selects)?

[wcabus]

You could try changing the maximum batch size to 1 when configuring MySQL in the EF Core DbContext. This will increase the number of roundtrips between IdentityServer and the database, but operations like the DELETE + INSERT will still be a single transaction.

Changing the batch size however will split up the actual statements, so that each of them will only contain a single SELECT ROW_COUNT() or similar SQL statement.

var migrationsAssembly = typeof(Program).Assembly.GetName().Name;
var connectionString = builder.Configuration.GetConnectionString("MySqlDb");
var serverVersion = new MySqlServerVersion(new Version(8, 0, 46));

builder.Services.AddIdentityServer()
    .AddConfigurationStore(options =>
    {
        options.ConfigureDbContext = db =>
            db.UseMySql(connectionString, serverVersion, mysql =>
                mysql.MigrationsAssembly(migrationsAssembly));
    })
    .AddOperationalStore(options =>
    {
        options.ConfigureDbContext = db =>
        {
            db.UseMySql(connectionString, serverVersion, mysql =>
            {
                mysql.MigrationsAssembly(migrationsAssembly);

                // One command per round trip instead of batching DELETE with INSERT together
                mysql.MaxBatchSize(1);
            });

            // Add your custom interceptor here
            // db.AddInterceptors(new RdsProxyRowCountInterceptor());
        };

        options.EnableTokenCleanup = true;
        options.RemoveConsumedTokens = true;
    });