Race condition causing invalid_token errors in OpenID Server

[mvarblow]

Describe the bug

Since updating to OC 2.1.7 we occasionally see this error in our application that relies on the Orchard Core OpenID Server:

2025-10-31 00:00:59.9707|Error||Microsoft.AspNetCore.Authentication.OpenIdConnect.OpenIdConnectHandler|Exception occurred while processing message. |remoteip: 10.232.0.42 |session-id: 
[OpenIdConnectProtocolException] Message contains error: 'invalid_grant', error_description: 'The specified token is invalid.', error_uri: 'https://documentation.openiddict.com/errors/ID2004'.
	error: invalid_grant
	error_description: The specified token is invalid.
	error_uri: https://documentation.openiddict.com/errors/ID2004
	at Microsoft.AspNetCore.Authentication.OpenIdConnect.OpenIdConnectHandler.RedeemAuthorizationCodeAsync(OpenIdConnectMessage tokenEndpointRequest)
	at Microsoft.AspNetCore.Authentication.OpenIdConnect.OpenIdConnectHandler.HandleRemoteAuthenticateAsync()
--- End of stack trace for exception handler ---
	at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
	at Microsoft.Extensions.Logging.LoggerMessage.<>c__DisplayClass8_0.<Define>g__Log|0(ILogger logger, Exception exception)
	at Microsoft.Extensions.Logging.LoggingExtensions.ExceptionProcessingMessage(ILogger logger, Exception ex)

After chasing this for a while via increased logging on the Orchard Core side (OpenIddict logging is tough as it's either incredibly verbose or very sparse unless you apply filters that are tricky to get right until you know what you're looking for), we've determined that the error results from the call to the /userinfo endpoint failing.

The failure looks like this in the OC logs:

2025-11-05 00:00:54.4990|6141|INFO|OpenIddict.Server.OpenIddictServerDispatcher|The response was successfully returned as a challenge response: {
  "error": "invalid_token",
  "error_description": "The specified token is invalid.",
  "error_uri": "https://documentation.openiddict.com/errors/ID2004"
}. |url: https://advantageacs.acsdomain.advantagecs.com/launchpad/connect/userinfo |action: Me|trace: 00-34884212f9cdb892aba0192f473e1d14-3fec4caf9896f05b-00|user: |ip: 10.232.2.84

It fails because the token isn't found:

However, I was able to determine the token identifier that it was looking for via the OC logs:

2025-11-05 00:00:54.4520|6001|TRACE|OpenIddict.Server.OpenIddictServerDispatcher|The token '[redacted]' was successfully validated and the following claims could be extracted: iss:... updated_at: 1715097600, oc:entyp: user, sub: 4r19qa0kcjrfw5171z4wcmnqnp, ..., oi_au_id: 129982164a6c4bdc8a8f9f0624e94d1b, client_id: advantage-ui-UI-PERF, **oi_tkn_id: 72668b8758a049e381de54ea6f829677**, oi_tkn_typ: urn:ietf:params:oauth:token-type:access_token. |url: https://advantageacs.acsdomain.advantagecs.com/launchpad/connect/userinfo |action: Me|trace: 00-34884212f9cdb892aba0192f473e1d14-3fec4caf9896f05b-00|user: |ip: 10.232.2.84|OpenIddict.Server.OpenIddictServerHandlers+Protection+ValidateIdentityModelToken.HandleAsync

And that token actually is in the database now:

It looks like this is almost certainly a timing issue as the call to the token endpoint to exchange the authorization code for a token is immediately followed by a call to the userinfo endpoint to exchange the access token for additional user information (all handled by the Microsoft.AspNetCore.Authentication.OpenIdConnect.OpenIdConnectHandler).

It appears that there is effectively a race condition that was introduced by Replace unnecesary calls to SaveChangesAsync by FlushAsync

Previously SaveChangesAsync was used in the TokenStore. This would ensure that the token was committed to the DB immediately. Now FlushAsync is used which leaves the commit to happen when the YesSQL Session is disposed. I don't think that is guaranteed to happen before the response is parsed by the OpenID client which immediately issues the follow-on /userinfo endpoint request.

Orchard Core version

Reproduced in 2.1.7, 2.2.0, 2.2.1

To Reproduce

See above. Unfortunately, I don't have simple repro steps using the orchard repo. You need to set up an OpenID client that users the authorization code flow and then hit it many times and you'll eventually see the problem. It happens rarely, but several times per day for us.

Expected behavior

An access token should be immediately usable when it is returned to the caller.

Logs and screenshots

See above.

[mvarblow]

For what it's worth, I rolled out a "custom" TokenStore yesterday that's a clone of 2.2.1 but with the FlushAsync calls changed back to SaveChangesAsync (as in 2.1.6 and earlier). We haven't seen this error since that change went live. I'm going to create a pull request.

[kevinchalet]

The reasoning is sound, tho' it doesn't seem using the userinfo is even necessary to trigger this bug: an exception thrown in OpenIdConnectHandler.RedeemAuthorizationCodeAsync() indicates the process failed at the token request phase (before the userinfo request is prepared), likely because the token entry associated with the authorization code couldn't be retrieved.

[github-actions]

We triaged this issue and set the milestone according to the priority we think is appropriate (see the docs on how we triage and prioritize issues).

This indicates when the core team may start working on it. However, if you'd like to contribute, we'd warmly welcome you to do that anytime. See our guide on contributions here.

[sebastienros]

If could be the SaveChangesAsync change, or it could be a recent change of isolation level from ReadUncommitted to ReadCommitted. Or both!

The reasoning is that SaveChangesAsync executes a commit. FlushAsync only executes the update/insert statement. Before ReadCommitted it's possible that FlushAsync was working fine because the next read would get the value even if it was not committed. Now with both changes we start seeing a problem.

If we think that the token should be read before the request is done, and the commit sent, then it's fine, even as a mitigation, to call SaveChangeAsync when the token is created.

However, I'd like to understand how the client is deciding to the invocations are invoked. Are both write and read done on the server side with the same session? Or are there two requests done?

[sebastienros]

If this is because the client sends a request before the request is actually done, and if the client doesn't do retries, we could do retries on our side, by doing another call to the store with a delay for instance.

[kevinchalet]

However, I'd like to understand how the client is deciding to the invocations are invoked. Are both write and read done on the server side with the same session? Or are there two requests done?

In this case, there are two requests: an authorization request during which an authorization code is produced (with a backing token entry) and a token request for which the client must send the authorization code returned in the authorization response. During that second request, OpenIddict retrieves that token entry from the store and validates it.

So: different requests and different YesSql sessions. Part of the problem is likely that the HTTP response is returned to the client before the session is committed server-side, so the client initiates the second request using a code whose DB entry may not be committed yet due to a race condition. As an alternative, we could probably buffer the HTTP response, commit the session and then return the response body to the HTTP client but this really seems like a bad solution 🤣

If this is because the client sends a request before the request is actually done, and if the client doesn't do retries, we could do retries on our side, by doing another call to the store with a delay for instance.

While adding something OC-specific would work, any other client would still be prone to these racing conditions (and not all client libraries have a retry mechanism built-in). Definitely not the best option IMHO.

[sebastienros]

@kevinchalet I am suggesting that the OC userinfo action does a retry internally. But it's bad.

Another option we have since we think calling SaveChangeAsync is bad in the store (we could want to call it and other stores many times in the same isolated transaction) is to invoke it from the controller before we return the response. It's assuming the controller is the one initiating the response with status code.

[sebastienros]

@mvarblow would you mind trying this instead: resolve the session and invoke SaveChangeAsync before it returns a result in /token

[kevinchalet]

It's assuming the controller is the one initiating the response with status code.

Not an easy option: the token entries and the HTTP response are generated by OpenIddict. The controller itself simply returns a SignInResult that invokes ASP.NET Core's IAuthenticationService.SignInAsync() API, which is what trigger the process as a "block":

OrchardCore/src/OrchardCore.Modules/OrchardCore.OpenId/Controllers/AccessController.cs

Line 151 in ff7c7c9

return SignIn(new ClaimsPrincipal(identity), OpenIddictServerAspNetCoreDefaults.AuthenticationScheme);

[mvarblow]

@sebastienros Yes, I can try that.

I looked into the test failure. The pull request that I submitted it more "complete" than the change that I had tested in production using an override of OpenIdTokenStore. In the pull request, I changed the FlushAsync calls in all the OpenId_X_Stores. It looks like the test failure is a result of calling SaveChangesAsync from the OpenIdAuthorizationStore.

When OC processes the final /authorize it uses the OpenIdTokenStore to look up the token. It will later update this token to mark it redeemed. Later (while still processing this same request) it uses OpenIdAuthorizationStore to create an authorization entity. With my changes, it calls SaveChangesAsync instead of FlushAsync at this point. SaveChangesAsync commits the change (good) but also clears the YesSql IdentityMap for the Session. This clears the OpenIdToken that we read earlier from the map.

Later, still processing this request, OpenIdDictTokenManager.ValidateAsync calls OpenIdTokenStore.FindByReferenceIdAsync to see if there is already a different token (different ID) with the same "reference ID". There is not. But this lookup finds the original token. That token is thrown away and not used. But it's now in the YesSql Store's IdentityMap.

Later when we try to update the token, still processing this same /authorize request, YesSql blows up because it sees that the entity being updated is not the same instance as the entity that's already in the IdentityMap.

I'm not sure why this wasn't a problem in 2.1.6 when those FlushAsync calls in the OpenId_X_Stores were all SaveChangesAsync, probably just some unrelated change in OpenIddict 7.0 triggered this. It was a bit fragile with the SaveChangesAsync down in the Store.

That said, I think the other problem (besides the HTTP request race condition) with moving SaveChangeAsync out of the Store is that the OpenIdManager performs cache management that seems to rely on the Store committing changes to the database immediately when Create/Update/Delete are called. Cache invalidation happens right after calling Create/Update/Delete. And then the OpenIdManagers rely on subsequent FindByX calls to find the updated entity in the database. If the old value is found then the cache will be stale.