ValidatePrincipal in CookieAuthenticationHandler not being called on some requests

[guylando]

The result of this bug is that once in a while in a multi-user scenerio, the wrong user appears in httpcontext.User. Investigating the issue, I registered a custom function for OnValidatePrincipal event and discovered that it is not being called for the problematic requests. This line not being called:
https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication.Cookies/CookieAuthenticationHandler.cs#L161
I registered a custom middleware after .UseAuthentication and I see those requests in my middleware even though they do not trigger the OnValidatePrincipal event.
I am now investigating further to see why OnValidatePrincipal is not called.
Anybody got any idea?

This is the code flow:

https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication/AuthenticationMiddleware.cs#L54
https://github.com/aspnet/HttpAbstractions/blob/dev/src/Microsoft.AspNetCore.Authentication.Abstractions/AuthenticationHttpContextExtensions.cs#L31
https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication/AuthenticationHandler.cs#L124
https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication.Cookies/CookieAuthenticationHandler.cs#L154
ValidatePrincipal: https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication.Cookies/Events/CookieAuthenticationEvents.cs#L114

[guylando]

OK I did the following now which helped find the problem: turned on trace level logging + in the middleware decrypted the cookie ticket to check the identity in the cookie compared to the identity in the http context.

Conclusions:

In the problematic request which has the bug the log message:
info: Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler[8]
AuthenticationScheme: Identity.Application was successfully authenticated.
Happens immediately without ValidatePrincipal being called.

After decrypting the cookie ticket, the user in the ticket is NOT EQUAL to the user who was just authenticated by the CookieAuthenticationHandler.

Looking at AuthenticationHandler source code ( https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication/AuthenticationHandler.cs#L148 ) I found out that this happens because of the HandleAuthenticateOnceAsync method logic which in the buggy request prevents loading the correct user from the cookie and instead it uses a wrong user taken from some previous request saved in the _authenticateTask data member.

So basically the problem is that a previous task saved information in _authenticateTask which prevents some random future task from being correctly authenticated.

@HaoK @Tratcher
Can someone please help with this and explain if the _authenticateTask data member is thread safe and the logic surrounding it is correct? why would the buggy request have this data member already initialized? how is it possible? shouldnt it have not been initialized since this is a new request?

[Tratcher]

Note the validator Identity uses with ValidatePrincipal is rate limited, it only runs every 30 minutes to avoid a large performance hit accessing the database. That's likely why you don't see it execute most of the time.

[Tratcher]

Please share your Startup code. Or at least Startup.ConfigureServices. I wonder if you have registered everything correctly.

[guylando]

I know that, I registered a custom validator (because I wanted to perform validation on every request) and I call the identity validator inside. But that doesn't effect what I described in the previous comment.

Can you please comment on what I wrote regarding what I saw happening with _authenticateTask? What might make that happen?

The startup is 1000+ lines of code which mostely are not related to identity and its a private project so its problematic to share but I debugged the problem and came to the specific lines causing this behavior which I described in the previous comment. Would be glad to get a response on that.

[Tratcher]

Handlers are created per-request so thread-safety should be a nominal concern. The _authenticateTask caches the result of AuthenticateAsync because calling it again should yield exactly the same result even if not cached. E.g. it would read the same cookie and deserialize it in the same way.

[guylando]

But as I describe, if it would read in this case the cookie then it would get another result. Thats what I observed. Also in the observed case the handler holds a data member from previous request. How could that happen?

[Tratcher]

At least share the Startup code related to Identity and Auth. Descriptions often overlook usage problems.

[Tratcher]

A handler should not hold anything from a prior request because it should have been re-created for each request. We'd need a repro to debug and figure out what's going on.

[Tratcher]

You'd have to customize the DI registration of IAuthenticationHandlerProvider or CookieAuthenticationHandler to cause these kinds of problems.

[guylando]

Here it is, thanks for the help:
==UPDATE: DELETED THE CODE SINCE ITS NOT RELEVANT ANYMORE==

[guylando]

I have verified (breakpoint in the end of ConfigureServices) and all the CookieAuthenticationHandler in the service collection are Transient.

[Tratcher]

Thanks. That's a lot of configuration... the Domain settings are especially odd, but I don't see anything that would affect the behavior you report.

The next step would be to create a minimal repro app, something where you can share the whole project. We can try, but you're in the best position with an existing repro.

[HaoK]

Also can you include what's in UtilsGL.CustomValidatePrincipalAsync<IIdentityUserGL>

[guylando]

@Tratcher That's hard because even in our project it happens only once in a while only in some situations...if you have an idea what else to add to debug I can do that and post the debug messages.
I am thinking maybe to add a middleware before the authentication middleware with some debug message maybe.
A workaround for this issue will be to add a middleware after the authentication middleware and in that middleware to decrypt the ticket and assign the principal to the http context.

@HaoK The code of UtilsGL.CustomValidatePrincipalAsync does not get executed at all in the situation I described (i have put a debug message in the first line) so why would it be the cause of the problem? I am limited in what code I can post so I try to post only the essential.

[guylando]

Here are logs when user [email protected] makes 2 POST requests to same url, one is processed correctly and the second one is buggy with the behavior I described:

  Request starting HTTP/1.1 POST http://xxx.com/a/b application/x-www-form-urlencoded; charset=UTF-8 237

@#####:LogInformation
@#####:UTC TIME: 1/10/2018 2:26:45 PM
@#####:Log message: CustomValidatePrincipalAsync started with user: [email protected]

info: CustomValidatePrincipalAsync[0]

  @#####:Log message: CustomValidatePrincipalAsync started with user: [email protected]

@#####:LogInformation
@#####:UTC TIME: 1/10/2018 2:26:45 PM
@#####:Log message: CustomValidatePrincipalAsync principal before: [email protected]

info: CustomValidatePrincipalAsync[0]

  @#####:Log message: CustomValidatePrincipalAsync principal before: [email protected]

@#####:LogInformation
@#####:UTC TIME: 1/10/2018 2:26:45 PM
@#####:Log message: CustomValidatePrincipalAsync principal after: [email protected]

info: CustomValidatePrincipalAsync[0]

  @#####:Log message: CustomValidatePrincipalAsync principal after: [email protected]

info: Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler[8]
AuthenticationScheme: Identity.Application was successfully authenticated.
@#####:LogInformation
@#####:UTC TIME: 1/10/2018 2:26:45 PM
@#####:Current User Id: 2
@#####:Current User Name: [email protected]
@#####:Log message: Info: HideExceptionsMiddleware found default schema: Identity.Application

info: vvv.GL.Middlewares.HideExceptionsMiddleware[0]

  @#####:Log message: Info: HideExceptionsMiddleware found default schema: Identity.Application

info: Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler[8]
AuthenticationScheme: Identity.Application was successfully authenticated.
@#####:LogInformation
@#####:UTC TIME: 1/10/2018 2:26:45 PM
@#####:Current User Id: 2
@#####:Current User Name: [email protected]
@#####:Log message: Info: HideExceptionsMiddleware result Succeeded: True result.Ticket.Properties.Items: {".persistent":"",".issued":"Wed, 10 Jan 2018 14:26:30 GMT",".expires":"Thu, 11 Jan 2018 20:26:30 GMT"} result.Principal.Identity.Name: [email protected]

info: vvv.GL.Middlewares.HideExceptionsMiddleware[0]

info: Microsoft.AspNetCore.SignalR.Messaging.MessageBus[0]
RemoveTopic(c-d599adec-9a02-420a-97c8-d8c2288bebe5)
info: Microsoft.AspNetCore.SignalR.Messaging.MessageBus[0]
RemoveTopic(c-72f00e49-820e-4931-884f-140fac5d5f4f)
info: Microsoft.AspNetCore.SignalR.Messaging.MessageBus[0]
RemoveTopic(hc-lobby.d599adec-9a02-420a-97c8-d8c2288bebe5)
info: Microsoft.AspNetCore.SignalR.Messaging.MessageBus[0]
RemoveTopic(hc-lobby.72f00e49-820e-4931-884f-140fac5d5f4f)
@#####:LogInformation
@#####:UTC TIME: 1/10/2018 2:26:45 PM
@#####:Current User Id: 2
@#####:Current User Name: [email protected]
@#####:Log message: Info: HideExceptionsMiddleware user: [email protected] binding null: True
ticket principal name: [email protected]

info: Microsoft.AspNetCore.Authorization.DefaultAuthorizationService[1]
Authorization was successful for user: [email protected].
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
Executing action method vvv.uuuu.CL.Controllers.aController.b (vvv.uuuu.CL) with arguments (342557) - ModelState is Valid
@#####:LogInformation
@#####:UTC TIME: 1/10/2018 2:26:45 PM
@#####:Current User Id: 2
@#####:Current User Name: [email protected]
@#####:Log message: b guid: 342557 userid: 2

info: Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.PartialViewResultExecutor[1]
Executing PartialViewResult, running view at path /Views/Mobile/c/a/_b.cshtml.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Executed action vvv.uuuu.CL.Controllers.aController.b (vvv.uuuu.CL) in 585.7251ms
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
Request finished in 888.321ms 200 text/html; charset=utf-8
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]

---

---

---

  Request starting HTTP/1.1 POST http://xxx.com/a/b application/x-www-form-urlencoded; charset=UTF-8 237

info: Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler[8]
AuthenticationScheme: Identity.Application was successfully authenticated.
@#####:LogInformation
@#####:UTC TIME: 1/10/2018 2:26:53 PM
@#####:Current User Id: 59
@#####:Current User Name: [email protected]
@#####:Log message: Info: HideExceptionsMiddleware found default schema: Identity.Application

info: Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler[8]
AuthenticationScheme: Identity.Application was successfully authenticated.
@#####:LogInformation
@#####:UTC TIME: 1/10/2018 2:26:53 PM
@#####:Current User Id: 59
@#####:Current User Name: [email protected]
@#####:Log message: Info: HideExceptionsMiddleware result Succeeded: True result.Ticket.Properties.Items: {".persistent":"",".issued":"Wed, 10 Jan 2018 14:26:30 GMT",".expires":"Thu, 11 Jan 2018 20:26:30 GMT"} result.Principal.Identity.Name: [email protected]

@#####:LogInformation
@#####:UTC TIME: 1/10/2018 2:26:53 PM
@#####:Current User Id: 59
@#####:Current User Name: [email protected]
@#####:Log message: Info: HideExceptionsMiddleware user: [email protected] binding null: True cookie:

ticket principal name: [email protected]

[guylando]

As you see the problem is that from reason the second request didn't go through all the ordinary steps and it came immidietly to:
info: Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler[8]
AuthenticationScheme: Identity.Application was successfully authenticated.

because of HandleAuthenticateOnceAsync

[guylando]

And then the _authenticateTask has user [email protected] which probably was a user from some previous request \ other request, instead of the user [email protected] which appears in cookie ticket

[HaoK]

As @Tratcher said, we are going to need a repro or at least more code to figure out what's going on. Can you show the relevant code/middleware you are using to generate the logs messages/ticket principals/context user

[guylando]

The CustomValidatePrincipalAsync log is just printing contest.Principal.Identity.Name in custom OnValidatePrincipal function.

The HideExceptionsMiddleware middleware is registered after UseAuthentication and has code taken from authentication middleware for debugging purpose (code below)

And other log messages are from .net framework code with debug level trace turned on.

================================================================================================================================
                // START COPY FROM https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication/AuthenticationMiddleware.cs
                if (context.Request.Path.Value == "/a/b")
                {
                    context.Features.Set<IAuthenticationFeature>(new AuthenticationFeature
                    {
                        OriginalPath = context.Request.Path,
                        OriginalPathBase = context.Request.PathBase
                    });

                    // REVIEW: alternatively could depend on a routing middleware to do this

                    // Give any IAuthenticationRequestHandler schemes a chance to handle the request
                    var handlers = context.RequestServices.GetRequiredService<IAuthenticationHandlerProvider>();
                    foreach (var scheme in await Schemes.GetRequestHandlerSchemesAsync())
                    {
                        var handler = await handlers.GetHandlerAsync(context, scheme.Name) as IAuthenticationRequestHandler;
                        if (handler != null && await handler.HandleRequestAsync())
                        {
                            return;
                        }
                    }

                    var defaultAuthenticate = await Schemes.GetDefaultAuthenticateSchemeAsync();
                    if (defaultAuthenticate != null)
                    {
                        this.mLogger.LogInformation(infoMessage: "Info: HideExceptionsMiddleware found default schema: " + defaultAuthenticate.Name);
                        // https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication/AuthenticationMiddleware.cs#L54
                        // https://github.com/aspnet/HttpAbstractions/blob/dev/src/Microsoft.AspNetCore.Authentication.Abstractions/AuthenticationHttpContextExtensions.cs#L31
                        // https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication/AuthenticationHandler.cs#L124
                        // https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication.Cookies/CookieAuthenticationHandler.cs#L154
                        // ValidatePrincipal: https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication.Cookies/Events/CookieAuthenticationEvents.cs#L114
                        // UtilsGL.CustomValidatePrincipalAsync
                        var result = await context.AuthenticateAsync(defaultAuthenticate.Name);
                        this.mLogger.LogInformation(infoMessage: result.None ? "Info: HideExceptionsMiddleware result none" : "Info: HideExceptionsMiddleware result Succeeded: " + result.Succeeded
                            + " result.Ticket.Properties.Items: " + Newtonsoft.Json.JsonConvert.SerializeObject(result.Ticket.Properties.Items)
                            + " result.Principal.Identity.Name: " + (result.Principal.Identity.Name ?? "anonymous"));
                        if (result?.Principal != null)
                        {
                            context.User = result.Principal;
                        }
                    }
                    else
                    {
                        this.mLogger.LogInformation(infoMessage: "Info: HideExceptionsMiddleware did not find default schema");
                    }


                    var cookieOptions = cookiesOptionsFactory.Create(IdentityConstants.ApplicationScheme);
                    string cookie = cookieOptions.CookieManager.GetRequestCookie(context, cookieOptions.Cookie.Name);
                    byte[] binding = context.Features.Get<ITlsTokenBindingFeature>()?.GetProvidedTokenBindingId();
                    var ticket = cookieOptions.TicketDataFormat.Unprotect(cookie, binding == null ? null : Convert.ToBase64String(binding));
                    

                    this.mLogger.LogInformation(infoMessage: "Info: HideExceptionsMiddleware user: " + (context.User.Identity.Name ?? "anonymous")
                        + " binding null: " + (binding == null) + " cookie: " + cookie + " ;;; ticket principal name: " + (ticket?.Principal?.Identity?.Name ?? "")
                        + " Identity.Application.MSB cookie: "
                        + (context.Request.Cookies.ContainsKey("Identity.Application.MSB") ? context.Request.Cookies["Identity.Application.MSB"] : "none")
                        + " AntiforgeryCookie.MSB cookie: "
                        + (context.Request.Cookies.ContainsKey("AntiforgeryCookie.MSB") ? context.Request.Cookies["AntiforgeryCookie.MSB"] : "none")
                        + " antiforgery form parameter __RequestVerificationToken: "
                        + (context.Request.Form.ContainsKey("__RequestVerificationToken") ? context.Request.Form["__RequestVerificationToken"].ToString() : "none")
                        + " stacktrace: " + Environment.StackTrace);
                }

                // END OF COPY FROM https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication/AuthenticationMiddleware.cs
                // ================================================================================================================================

[guylando]

This happens only on our azure server which runs kestrel with iis (it doesnt happen in the development computer) and only when multiple users have logged on\off. And it happens only sometimes when user is making 2 requests quickly (the first request is always good, the second one sometimes has the bug).
So its probably really hard to reproduce.

[guylando]

Then I get sometimes:
Antiforgery token validation failed. The provided antiforgery token was meant for a different claims-based user than the current user.
Obviously hehehe...

[guylando]

I try to assume there is a bug related to _authenticateTask so I try to understand where it could happen. It must be started from AuthenticationMiddleware.cs so
https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication/AuthenticationMiddleware.cs#L54
calls AuthenticateAsync here:
https://github.com/aspnet/HttpAbstractions/blob/dev/src/Microsoft.AspNetCore.Authentication.Abstractions/AuthenticationHttpContextExtensions.cs#L31
which calls AuthenticateAsync of IAuthenticationService.
IAuthenticationService is registered as Scoped and not Transient here:
https://github.com/aspnet/HttpAbstractions/blob/dev/src/Microsoft.AspNetCore.Authentication.Core/AuthenticationCoreServiceCollectionExtensions.cs#L27
and on AuthenticateAsync executes:
https://github.com/aspnet/HttpAbstractions/blob/dev/src/Microsoft.AspNetCore.Authentication.Core/AuthenticationService.cs#L69
which executes: (and which by the way does claims transformation afterwards)
https://github.com/aspnet/Security/blob/dev/src/Microsoft.AspNetCore.Authentication/AuthenticationHandler.cs#L124
which calls HandleAuthenticateOnceAsync.

So assuming there is a scope\threading bug, the AuthenticationHandler is retrieved in AuthenticationService using GetHandlerAsync method of IAuthenticationHandlerProvider.
IAuthenticationHandlerProvider is registered in https://github.com/aspnet/HttpAbstractions/blob/dev/src/Microsoft.AspNetCore.Authentication.Core/AuthenticationCoreServiceCollectionExtensions.cs#L29 as scoped implemented by AuthenticationHandlerProvider.
Handlers are created only once by AuthenticationHandlerProvider and stored in https://github.com/aspnet/HttpAbstractions/blob/dev/src/Microsoft.AspNetCore.Authentication.Core/AuthenticationHandlerProvider.cs#L40.
AuthenticationHandlerProvider is injected to AuthenticationService and stored in a property.
AuthenticationService is created\retrieved from http context IOC container in https://github.com/aspnet/HttpAbstractions/blob/dev/src/Microsoft.AspNetCore.Authentication.Abstractions/AuthenticationHttpContextExtensions.cs#L31

Thinking about it, it most probably is not a scope issue because if it was a scope issue then the error would happen often and not in such rare case. It smells like a threading problem because of all the requirements of number of users and requests timing to reproduce.

Are different requests always on a different thread in kestrel+iis environment? because otherwise if two requests are handled by the same thread then they might both touch the same data member _authenticateTask and cause the problem (scoped http context is per thread no? so if two threads handle same request there is a mass)
I see in .net core 2 they changed the threading model of kestrel: https://stackoverflow.com/questions/40948857/is-kestrel-using-a-single-thread-for-processing-requests-like-node-js
requests can hop threads: dotnet/aspnetcore#1371 (comment)

I will add printing thread id to the log messages. Maybe that can give a clue.

[Tratcher]

Requests all execute on thread-pool threads but there's no shared thread context, the HttpContext is captured on the stack. The only thing we've seen cause bad cross threading issues is accidental uses of async void methods in place of async Task, or intentional multi-threading via Task.Run. Individual requests are not supposed to be processed by multiple threads.

[guylando]

I have now added the following in startup.cs Configure to check on _authenticateTask:

        ```

// TODO DELETE START===========================

        app.Use(async (context, next) => {
            var handlers = context.RequestServices.GetRequiredService<IAuthenticationHandlerProvider>();
            var handler = await handlers.GetHandlerAsync(context, "Identity.Application") as CookieAuthenticationHandler;
            FieldInfo field = typeof(AuthenticationHandler<CookieAuthenticationOptions>).GetField("_authenticateTask", BindingFlags.NonPublic | BindingFlags.Instance);
            Console.WriteLine("================\r\n_authenticateTask before UseAuthentication: " + (field?.GetValue(handler) ?? "null") + "\r\n==============");
            await next();
        });

        // TODO DELETE END ============================

app.UseAuthentication();

        // TODO DELETE START===========================

        app.Use(async (context, next) => {
            var handlers = context.RequestServices.GetRequiredService<IAuthenticationHandlerProvider>();
            var handler = await handlers.GetHandlerAsync(context, "Identity.Application") as CookieAuthenticationHandler;
            FieldInfo field = typeof(AuthenticationHandler<CookieAuthenticationOptions>).GetField("_authenticateTask", BindingFlags.NonPublic | BindingFlags.Instance);
            Console.WriteLine("================\r\n_authenticateTask after UseAuthentication: " + (field?.GetValue(handler) ?? "null") + "\r\n==============");
            await next();
        });

        // TODO DELETE END ============================

[guylando]

YESSS!

normal request:

_authenticateTask before UseAuthentication: null

================
_authenticateTask after UseAuthentication: System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Authentication.AuthenticateResult]

THE BUGGY REQUEST:

================
_authenticateTask before UseAuthentication: System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Authentication.AuthenticateResult]

info================
_authenticateTask after UseAuthentication: System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Authentication.AuthenticateResult]

!!!!

[guylando]

I think this proves that this is some bug in the framework, no?
And a temporary workaround is to change to null the _authenticateTask datamember using reflection inside a middleware called before UseAuthentication.
What do you think?

[HaoK]

What's before UseAuthentication in your configure. Is your print out actually at the start of the pipeline?

[guylando]

loggerFactory.AddDebug(LogLevel.Trace);
loggerFactory.AddConsole(minLevel: LogLevel.Trace);
loggerFactory.AddPostgresql(LogLevel.Trace, logsDAL, serviceProvider, contextAccessor);
app.UseDeveloperExceptionPage();
app.Use(async (context, next) => {
	var handlers = context.RequestServices.GetRequiredService<IAuthenticationHandlerProvider>();
	var handler = await handlers.GetHandlerAsync(context, "Identity.Application") as CookieAuthenticationHandler;
	FieldInfo field = typeof(AuthenticationHandler<CookieAuthenticationOptions>).GetField("_authenticateTask", BindingFlags.NonPublic | BindingFlags.Instance);
	Console.WriteLine("\r\n================\r\n_authenticateTask before UseAuthentication: " + (field?.GetValue(handler) ?? "null") + "\r\n==============");
	await next();
});
Microsoft.Extensions.Logging.ILogger startupLogger = loggerFactory.CreateLogger<Startup>();
Directory.CreateDirectory(ConstantsGL.MainSiteImageMagickCacheDirectory);
MagickAnyCPU.CacheDirectory = ConstantsGL.MainSiteImageMagickCacheDirectory;
memoryCache.Set<ConcurrentDictionary<string, long>>(....);
Mapper.Initialize(...);
executing a few indepedent tasks to run in background (which don't effect the pipeline)
app.UseStatusCodePagesWithRedirects("/Home/ErrorStatus?errorStatus={0}");
app.UseAuthentication();
app.Use(async (context, next) => {
	var handlers = context.RequestServices.GetRequiredService<IAuthenticationHandlerProvider>();
	var handler = await handlers.GetHandlerAsync(context, "Identity.Application") as CookieAuthenticationHandler;
	FieldInfo field = typeof(AuthenticationHandler<CookieAuthenticationOptions>).GetField("_authenticateTask", BindingFlags.NonPublic | BindingFlags.Instance);
	Console.WriteLine("\r\n================\r\n_authenticateTask after UseAuthentication: " + (field?.GetValue(handler) ?? "null") + "\r\n==============");
	await next();
});
			

[guylando]

As you see there is nothing meaningful before the first print out

[Tratcher]

It looks like you can reproduce this pretty consistently. How are you generating the requests for your repro?

[guylando]

I have an ajax post request in the site generated by a button (I add the csrf token to the post request).
I connect with one user, make 3-4 requests, disconnect, connect with other user, make quickly 2-3 requests one after another. On second or third request of the second user it happens, sometimes need to repeat this further and connect with third user and perform fast requests.
UPDATE: Note that I could reproduce it only in IIS+kestrel environment on the server and couldn't reproduce on my development machine which uses HttpSys.

[guylando]

I tried the solution of adding the middleware which changes to null the data member _authenticateTask
and then other errors came up which led me to clearing
_handlerMap property of AuthenticationHandlerProvider in the middleware before UseAuthentication and this actually solved the problem. Remind you that AuthenticationHandlerProvider is Scoped and not Transient (unlike the AuthenticationHandler) -
https://github.com/aspnet/HttpAbstractions/blob/dev/src/Microsoft.AspNetCore.Authentication.Core/AuthenticationCoreServiceCollectionExtensions.cs#L29 and it saves AuthenticationHandlers in the _handlerMap data member. So the buggy request has encountered previously saved handlers in _handlerMap and used them and that caused the bug. So adding the following middleware before UseAuthentication solved it for me:

public class ClearAuthenticationMiddleware
    {
        #region Fields

        private readonly RequestDelegate mNext;

        #endregion

        #region Constructor

        public ClearAuthenticationMiddleware(RequestDelegate next)
        {
            this.mNext = next;
        }

        #endregion Constructor

        public async Task Invoke(HttpContext context)
        {
            var handlers = context.RequestServices.GetRequiredService<IAuthenticationHandlerProvider>();
            FieldInfo field = typeof(AuthenticationHandlerProvider).GetField("_handlerMap", BindingFlags.NonPublic | BindingFlags.Instance);
            Dictionary<string, IAuthenticationHandler> val = field.GetValue(handlers) as Dictionary<string, IAuthenticationHandler>;
            val.Clear();
            await this.mNext.Invoke(context);
        }
    }

Since it does no harm to clear this in the beginning of the authentication middleware, maybe you should add it (one line performing .Clear() on _handlerMap) to help solve such bugs, EVEN IF it was caused from some code misuse. The argument in favor of doing this is that the authentication middleware is responsible for authentication and if someone called AuthenticationHandlerProvider GetHandlerAsync previously somehow and caused a bad AuthenticationHandler to be saved in _handlerMap, it SHOULD NOT cause the authentication middleware to skip authenticating the user using the cookie (in case of cookie authentication) which is the situation now (and also possibly will solve some scoping\threading rare edge case which is hard to find). @HaoK @Tratcher
Closing it since my workaround\solution solved it for me (unless you want to keep it open to investigate).

[Tratcher]

Re-opening until we can find the root cause. It appears to be a DI scoping bug, but it's not clear how that would be caused. @pakrym can you find a reference to the bug causing cross thread contamination via loggers with corrupt async state?

[Eilon]

@guylando - can you try temporarily disabling the loggers to see if that is somehow corrupting some cross-thread state?

@pakrym - I'm parking this on your plate so you can contemplate this further.

[pakrym]

@Tratcher there was no bug, it was internal support issue which I was never able to repro, but it went away after moving to AsyncLocal from CallContext.SetData.

@Eilon loggers are not the cause. It's just another issue where I've seen cross thread contamination. I suspect that it was caused by the use of CallContext and how Kestrel handles it but have no proof.

I don't think we can move forward on this without a repro.

[Eilon]

@pakrym ok thanks for the update, will take it off your plate.

[guylando]

I will try to reproduce without the loggers.
The issue in aspnet/KestrelHttpServer#1720 seems like something that could have lead to same problem as in my case and maybe the solution of clearing _handlerMap will solve the problem in that issue (and they have a reproduction example) and then it will maybe shed some more light on this.

[guylando]

Ok now this is the first line in Startup.cs configure:

app.Use(async (context, next) => {
                var handlers = context.RequestServices.GetRequiredService<IAuthenticationHandlerProvider>();
                var handler = await handlers.GetHandlerAsync(context, "Identity.Application") as CookieAuthenticationHandler;
                FieldInfo field = typeof(AuthenticationHandler<CookieAuthenticationOptions>).GetField("_authenticateTask", BindingFlags.NonPublic | BindingFlags.Instance);
                Console.WriteLine("\r\n================\r\n_authenticateTask before UseAuthentication: " + (field?.GetValue(handler) ?? "null") + "\r\n==============");
                await next.Invoke();
            });

And here are the logs:

Hosting environment: Development
Content root path: C:\inetpub\xxxx\approot\
Now listening on: http://localhost:32600
Application started. Press Ctrl+C to shut down.

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Authentication.AuthenticateResult]
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Authentication.AuthenticateResult]
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============

================
_authenticateTask before UseAuthentication: null
==============
================
_authenticateTask before UseAuthentication: null
==============
================
_authenticateTask before UseAuthentication: null
==============
================
_authenticateTask before UseAuthentication: System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Authentication.AuthenticateResult]
==============
================
_authenticateTask before UseAuthentication: null
==============
================
_authenticateTask before UseAuthentication: null
==============
================
_authenticateTask before UseAuthentication: null
==============
================
_authenticateTask before UseAuthentication: System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Authentication.AuthenticateResult]
==============
================
_authenticateTask before UseAuthentication: null
==============

[guylando]

Steps I did to reproduce:
1)Site in IIS with Kestrel on azure server ("load user profile" specified in app pool advanced settings).
2)Added the specified code first in Configure in Startup.cs
3)Logged to site and performed several POST requests to same form rapidly.
4)Logged out and logged in with another user.
5)Made several rapid requests to the same POST url as previously (the second\third request usually triggers the bug for sure but as you see in the logs it happens randomly many times).

I would still recommend to clear the handlers map in the beggining of the authentication middleware so that the authentication middleware will perform its work without possibly being tempered like it happens here. Probably its better until another solution is found.

NOTE: I printed the message regarding _authenticateTask just because thats the code I used before, but after investigating it further I now know that the problem is not related to _authenticateTask and its related to the handlers map in the provider.

[Eilon]

@guylando thanks for the extra info. Is there anything else you can share about the configuration of your app? Any customizations to DI? Or other custom services? Any custom auth behavior?

[guylando]

• I use the ordinary framework IOC container with no customizations.

• What could be relevant if the log messages show the corruption right at the beginning of the pipeline?

• Can temporarily building the services collection in the middle of ConfigureServices (in order to use a DAL object to retrieve and bind configurations from the database to an object and later add this object as a singleton to the services collection) have any effect on the MVC pipeline? I wouldn't think so. It performs this operation but later the original services collection is the one that is built into the system services provider used for the application.

• All the custom net core identity auth behavior under the auth middleware didn't even run yet when the corruption already happens on the new request.

• I have several Kestrel websites running on the server, don't know if its relevant.

• I use memory cache a lot.

• I use several background working threads to load stuff from the database into the memory cache periodically. Since they are run in same manner all the time and do the same work, I don't see why the observed behavior corruption of specific requests only once in a while would be related to them. They do not modify the http context.

• Also since this does not happen in HttpSys environment I guess it probably has something to do with Kestrel which is being run on the server.

• Currently the app works well when I am using the solution I wrote here: ValidatePrincipal in CookieAuthenticationHandler not being called on some requests #1602 (comment)

[Eilon]

• Can temporarily building the services collection in the middle of ConfigureServices (in order to use a DAL object to retrieve and bind configurations from the database to an object and later add this object as a singleton to the services collection) have any effect on the MVC pipeline? I wouldn't think so. It performs this operation but later the original services collection is the one that is built into the system services provider used for the application.

This is possibly a problem though it's hard to say without seeing the code. If any services from one container "pollute" the other container, there could be some odd behavior.

Unfortunately, without seeing more about the code, we're at a loss of what the problem could be. We reviewed several code paths and were not able to find anything in ASP.NET Core that could lead to this behavior.

If you can send us a small app that reproduces the problem we will investigate further.

[guylando]

It will be hard to reproduce it in a small app since so much dependencies exist in our project so I don't think it will be possible in the near future especially since we have a working workaround. Maybe if the problem will return and we will have no other choice, otherwise we have a pretty tight schedule right now and reproducing this in a small app would take at-least a full day or two.

[guylando]

Note that the issue in aspnet/KestrelHttpServer#1720 sounds similar if not identical and they claim having a working reproduction https://github.com/antonGritsenko/aspnetcoreLogout

[Eilon]

@guylando thanks again for the extra info, we'll do our best to investigate this.

[Eilon]

Hi @guylando , we were not able to find out anything else about what could be causing this. Unfortunately without a specific repro app we cannot investigate this any further.

[guylando]

When just adding the following middleware before .UseAuthentication in startup.cs, it triggers the log a lot even though it probably shouldn't have:

public async Task Invoke(HttpContext context)
        {
            var handlers = context.RequestServices.GetRequiredService<IAuthenticationHandlerProvider>();
            FieldInfo field = typeof(AuthenticationHandlerProvider).GetField("_handlerMap", BindingFlags.NonPublic | BindingFlags.Instance);
            Dictionary<string, IAuthenticationHandler> val = field.GetValue(handlers) as Dictionary<string, IAuthenticationHandler>;
            if (val.Count > 0)
            {
                Console.WriteLine("\r\n================\r\n_handlerMap length before UseAuthentication: " + val.Count + "\r\n==============");
                val.Clear();
                Console.WriteLine("\r\n================\r\n_handlerMap before UseAuthentication after clearing it: " + val.Count + "\r\n==============");
            }
            await this.mNext.Invoke(context);
        }

In your environment it is never triggered when you put this as a kestrel app behind iis?
@Eilon
Or is it expected that _handlerMap is not empty before the Authentication middleware?

[Tratcher]

https://github.com/aspnet/HttpAbstractions/blob/816516f193afcb7ce6b564facc2a36d7e86604ea/src/Microsoft.AspNetCore.Authentication.Core/AuthenticationHandlerProvider.cs#L42-L60
https://github.com/aspnet/HttpAbstractions/blob/a3c5a197668f7f59f3f536024866a8d2a904f5cd/src/Microsoft.AspNetCore.Authentication.Core/AuthenticationCoreServiceCollectionExtensions.cs#L29
AuthenticationHandlerProvider has a scoped lifetime so it's expected to be empty at the start of every request. IIS Windows Auth, UseAuthentication, or an explicit call to AuthenticateAsync (or related methods) are the only things that should populate this collection.

[guylando]

what do you mean by IIS Windows auth? because actually we are using iis, maybe related?

[Tratcher]

The IISIntegration components call AuthenticateAsync to initialize HttpContext.User early in the pipeline.
https://github.com/aspnet/IISIntegration/blob/6e54256fca6f2ae25525bfbc0a7ca966e0d1780d/src/Microsoft.AspNetCore.Server.IISIntegration/IISMiddleware.cs#L133-L137

With later versions of ANCM this should not happen unless you've enabled windows auth in IIS. This would add a handler to the map, but it should not affect cookie auth in any way.

[guylando]

our Main method has:

                        .UseIISIntegration()
                        .UseKestrel()

and the versions are 2.1.0-rtm-30733