Multiple calls made to OpenIdConnectEvents handlers when using dotnet 7

[petedishman]

Microsoft.Identity.Web Library

Microsoft.Identity.Web

Microsoft.Identity.Web version

1.25.10

Web app

Sign-in users and call web APIs

Web API

Not Applicable

Token cache serialization

Not Applicable

Description

Since upgrading to dotnet 7, configured event handlers on OpenIdConnectEvents can be called multiple times depending on how many concurrent requests hit the web app when it's just started.

If a single request hits the app after startup, then the callback handler will be called once on all subsequent requests.
If multiple concurrent requests hit the app immediately after startup then this can trigger multiple calls to any configured handlers.
This is a change of behaviour from dotnet 6.

Given an application setup like below:

builder.Services.AddAuthentication(OpenIdConnectDefaults.AuthenticationScheme)
  .AddMicrosoftIdentityWebApp(
    msIdentityOptions => {
      builder.Configuration.GetSection("AzureAd").Bind(msIdentityOptions);

      msIdentityOptions.Events.OnRedirectToIdentityProvider = context => { 
        return Task.CompletedTask; 
      };
    })
    .EnableTokenAcquisitionToCallDownstreamApi(clientAppOptions => {

    })
    .AddInMemoryTokenCaches();

If the app is started and immediately hit with 10 concurrent requests, then future requests will each trigger multiple calls to the OnRedirectToIdentityProvider handler. The same applies to all of the other handlers in OpenIdConnectEvents too.

The msIdentityOptions callback above is also being called multiple times in this situation which it wasn't before (although see note below). It doesn't matter how this callback configures the event handlers they'll still be called multiple times too.

A secondary problem, but one that also exists in dotnet 6, so nothing has actually changed, is that in the above example the msIdentityOptions callback is always called at least twice regardless of how many concurrent requests hit the app after startup.

This appears to be due to both the AddMicrosoftIdentityWebApp() and the EnableTokenAcquisitionToCallDownstreamApi(0 calling builder.Services.Configure(opendIdConnectScheme, configureMicrosoftIdentityOptions); so that the configuration callback ends up being registered twice and therefore run twice.

Reproduction steps

The project in https://github.com/petedishman/ms-identity-web-bug reproduces this problem.

It includes a web app that sets up authentication and then a test project that fires up the app and pushes concurrent requests to it and checks how many times the various callbacks were called.

Dotnet 7 gives these test results in VS:

But, if both the projects are changed to use dotnet 6, then you get these results:

The failing tests in the dotnet 6 version are due to the msIdentityOptions configuration callback always being called twice when I'd expect it to only ever get called once.

Error message

No particular error messages are thrown, or rather it depends on what you do in the handlers/callback methods that are called multiple times.

With firing concurrent requests in on startup of the app I am still sometimes getting the Collection was modified; enumeration operation may not execute error raised in #1957 despite running on 1.25.10

Id Web logs

No response

Relevant code snippets

as above

Regression

No response

Expected behavior

Configuration callbacks should only be called once regardless of the number of concurrent requests that first hit the app.

Configured OpenIdConnectEvents handlers should also only ever be called once per request

[jmprieur]

Thanks for the clear repro steps @petedishman
I believe we have addressed the msIdentityOptions configuration callback always being called twice in the rel/v2 branch.

For the change of behavior between net6.0 and net7.0, @Tratcher, would you have an idea of what is going on?

[jmprieur]

@jennyf19 FYI ...

[Tratcher]

@jmprieur could this be related to the IOptions concurrency issues you were having, modifying options instances after resolving them from DI?

[jmprieur]

no, @Tratcher : we fixed those. We are using a concurrent dictionary (they were not developer facing options,.

[Tratcher]

I'm suspicious of this code path:

microsoft-identity-web/src/Microsoft.Identity.Web/WebAppExtensions/MicrosoftIdentityWebAppAuthenticationBuilderExtensions.cs

Lines 414 to 419 in 37b0d33

	if (subscribeToOpenIdConnectMiddlewareDiagnosticsEvents)
	{
	var diagnostics = serviceProvider.GetRequiredService<IOpenIdConnectMiddlewareDiagnostics>();
	diagnostics.Subscribe(options.Events);
	}

microsoft-identity-web/src/Microsoft.Identity.Web/Resource/OpenIdConnectMiddlewareDiagnostics.cs

Lines 92 to 97 in 37b0d33

	public void Subscribe(OpenIdConnectEvents events)
	{
	events ??= new OpenIdConnectEvents();
	_onRedirectToIdentityProvider = events.OnRedirectToIdentityProvider;
	events.OnRedirectToIdentityProvider = OnRedirectToIdentityProviderAsync;

Or:

microsoft-identity-web/src/Microsoft.Identity.Web/MergedOptions.cs

Lines 113 to 125 in 37b0d33

	mergedOptions.Events.OnAccessDenied += microsoftIdentityOptions.Events.OnAccessDenied;
	mergedOptions.Events.OnAuthenticationFailed += microsoftIdentityOptions.Events.OnAuthenticationFailed;
	mergedOptions.Events.OnAuthorizationCodeReceived += microsoftIdentityOptions.Events.OnAuthorizationCodeReceived;
	mergedOptions.Events.OnMessageReceived += microsoftIdentityOptions.Events.OnMessageReceived;
	mergedOptions.Events.OnRedirectToIdentityProvider += microsoftIdentityOptions.Events.OnRedirectToIdentityProvider;
	mergedOptions.Events.OnRedirectToIdentityProviderForSignOut += microsoftIdentityOptions.Events.OnRedirectToIdentityProviderForSignOut;
	mergedOptions.Events.OnRemoteFailure += microsoftIdentityOptions.Events.OnRemoteFailure;
	mergedOptions.Events.OnRemoteSignOut += microsoftIdentityOptions.Events.OnRemoteSignOut;
	mergedOptions.Events.OnSignedOutCallbackRedirect += microsoftIdentityOptions.Events.OnSignedOutCallbackRedirect;
	mergedOptions.Events.OnTicketReceived += microsoftIdentityOptions.Events.OnTicketReceived;
	mergedOptions.Events.OnTokenResponseReceived += microsoftIdentityOptions.Events.OnTokenResponseReceived;
	mergedOptions.Events.OnTokenValidated += microsoftIdentityOptions.Events.OnTokenValidated;
	mergedOptions.Events.OnUserInformationReceived += microsoftIdentityOptions.Events.OnUserInformationReceived;

[petedishman]

The MiddlewareDiagnostics stuff wasn't turned on in my tests, so those paths weren't being hit.
I was seeing multiple calls to the section in MergedOptions.cs

That's led me to look at how that method is called and in particular the IOptions/Configuration setup.

I created another test project https://github.com/petedishman/OptionsTest
This has two projects with identical code in both, both are dotnet 6 but one is using Microsoft.Extensions.Configuration & Microsoft.Extensions.Options v6, while the other is using v7.

They set up DI with options like this:

                services.AddOptions<TestOptions>("testing")
                    .Configure<DummyService>((options, dummyService) =>
                    {
                        Console.WriteLine("Configuring TestOptions instance");
                    });

and then concurrently create multiple instances of IOptionsMonitor<TestOptions>
I think this is effectively what Microsoft.Identity.Web is doing with OpenIdConnectOptions

When I run the test program using the v6 libraries, I get this output:

C:\build\examples\OptionsTest\OptionsTest6> dotnet run
Building...
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: C:\build\examples\OptionsTest\OptionsTest6
Creating TestOptions instance
Creating TestOptions instance
Creating TestOptions instance
Creating TestOptions instance
Creating TestOptions instance
Configuring TestOptions instance

When I run the program with the v7 libraries, I get this:

C:\build\examples\OptionsTest\OptionsTest7> dotnet run
Building...
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: C:\build\examples\OptionsTest\OptionsTest7
Creating TestOptions instance
Creating TestOptions instance
Creating TestOptions instance
Creating TestOptions instance
Creating TestOptions instance
Configuring TestOptions instance
Configuring TestOptions instance
Configuring TestOptions instance
Configuring TestOptions instance
Configuring TestOptions instance

So, with the v6 libraries the configuration callback passed to .Configure is only called once, whereas with the v7 libraries it's called once per call.

Interestingly, if after creating my instances concurrently, I then create another one it no longer re-runs the .Configure callback.

This seems like a regression in the v7 code, but I've not been able to track down where that is yet.

[StrawbrryFlurry]

The new .NET 7 way of configuring the authentication options also allows for a race condition to happen, which breaks the Authorization Code Flow of for the OpenIdConnect authentication handler registered through AddMicrosoftIdentityWebApp. If the server initially (before configuring the options for the handler) receives multiple requests at the same time (within the timeframe of creating the options) it will call the options factory multiple times which leads to the "Authorization Code callback handler" to be registered multiple times. If this happens, the handler will send multiple requests to the IDP, trying to get an access token for the provided Authorization Code. See implementation here:

var codeReceivedHandler = options.Events.OnAuthorizationCodeReceived;
options.Events.OnAuthorizationCodeReceived = async context =>
{
  var tokenAcquisition = context!.HttpContext.RequestServices.GetRequiredService<ITokenAcquisitionInternal>();
  await tokenAcquisition.AddAccountToCacheFromAuthorizationCodeAsync(
    context,
    options.Scope,
    openIdConnectScheme
  ).ConfigureAwait(false);
  // If the containing configuration method is called multiple times, it will
  // call this block again through the codeReceivedHandler of the `options.Events.
  // OnAuthorizationCodeReceived` configured through the options factory
  // of a different request
  await codeReceivedHandler(context).ConfigureAwait(false);
};

As I've mentioned before, this leads to the handler calling the IDP multiple times, which fails the second time because the Authorization Code has already been used.

Because we run multiple healthchecks on our containers at- and after startup, we ran into this issue, breaking the authorization code flow. Our workaround is loading the configuration initially, before the host is started:

private static void FixMicrosoftIdentityOptionsMonitorRaceCondition(IServiceProvider services)
{
    var options = services.GetService<IOptionsMonitor<OpenIdConnectOptions>>();

    // By initializing the options before the application starts, we ensure that
    // no race condition can occur.
    options.Get(OpenIdConnectDefaults.AuthenticationScheme);
}

[petedishman]

@StrawbrryFlurry That matches what we were seeing too. This wasn't initially showing up in local dev, but as soon as we pushed to AWS the load balancer healthchecks all kicked in concurrently and triggered this problem.

I hadn't thought of manually requesting the options first but that should help as a temporary workaround. Thanks!

[Tratcher]

@petedishman can you file an issue in https://github.com/dotnet/runtime with your TestOptions repro? There's one change in that area that may have regressed this. dotnet/runtime#66688

[Tratcher]

dotnet/runtime#79529 has been identified as a regression in .NET 7 and fixed for .NET 8. It's currently being considered for a patch in .NET 7. I encourage anyone with an impacted application to comment/vote on that issue.

@jmprieur this issue can be closed.

[jmprieur]

Closing as external

[jmprieur]

@petedishman , @tarekgh, @davidkarlsson, @StrawbrryFlurry
The .NET 7.0 regression is fixed and should be released part of the .NET SDK hot fixes mid February, if I understand correctly.

@StrawbrryFlurry : where do you call FixMicrosoftIdentityOptionsMonitorRaceCondition from?

[StrawbrryFlurry]

@jmprieur We call the method after the Service Provider has been built and before the app has started. e.g:

var builder = WebApplication.CreateBuilder(args);
// ...
var app = builder.Build();
// ..
FixMicrosoftIdentityOptionsMonitorRaceCondition(app.Services);
// ..
app.Run();

[beckerben]

@StrawbrryFlurry thanks a ton for the work around, I was banging my head against the wall trying to figure this one out. I was seeing the error:

MsalUiRequiredException: AADSTS54005: OAuth2 Authorization code was already redeemed, please retry with a new valid code or use an existing refresh token
The weird thing was I only observed this once we enabled websockets on our Azure App Service. Very strange but this workaround seems to have fixed it so thanks again!

[FelipeCostaGualberto]

Hi. Is this fixed already?

[jmprieur]

It should be.
Do you still see the issue in the latest versions of Microsoft.Identity.Web?

[FelipeCostaGualberto]

As the error is quite "random" in my case, I used @StrawbrryFlurry 's workaround and since then I didn't remove it.
I'll try removing it and if I get the error again, I'll let you know.

[DaleyKD]

Is there a chance that this is related to my other issue #2456 ? I'm running .NET 7 in that, but I'm on the latest version of it via VS 2022.

EDIT: It does NOT appear to be the same. When trying the FixMicrosoftIdentityOptionsMonitorRaceCondition, the code is still executed twice.