Possible bug in Microsoft.AspNet.WebApi 5.2.5 and onwards: HttpContext.Current.User is no longer available during the LogRequest event of HttpApplication

[stanisls]

This problem was discovered when using SerilogWeb.Classic UserName enricher. When ApplicationLifecycle module emits the final log entry for a request, the user name of the authenticated user is no longer captured by the UserName enricher.

It looks like HttpContext.Current.User.Identity.IsAuthenticated becomes 'false' by that point in time.
https://github.com/serilog-web/classic/blob/master/src/SerilogWeb.Classic/Classic/Enrichers/UserNameEnricher.cs

The problem first appered after updating to Microsoft.AspNet.WebApi 5.2.5 and is still in 5.2.6. The following screenshot of the logged data illustrates the problem. The only change between the 3 runs was a bump in versions of the Microsoft.AspNet.WebApi.* nuget packages.

For more information, see a related bug report at SerilogWeb.Classic project:
serilog-web/classic#55

[tsimbalar]

Just to add a bit more information coming from how SerilogWeb.Classic works...

The log event is generated during the LogRequest event of the HttpApplication:

https://github.com/serilog-web/classic/blob/master/src/SerilogWeb.Classic/Classic/ApplicationLifecycleModule.cs#L256

The current user information is extracted from HttpContext.Current.User (technically the new HttpContextWrapper(HttpContext.Current))
https://github.com/serilog-web/classic/blob/d32c124dc9ab917647489f5699bc94745c2252bb/src/SerilogWeb.Classic/Classic/Enrichers/UserNameEnricher.cs#L54

To summarize, it looks like HttpContext.Current.User is no longer available during the LogRequest event of HttpApplication.

[Eilon]

This is... very... weird... because ASP.NET MVC has nothing to do with those events. They're all in System.Web and I don't think MVC can affect those events in any way at all.

Are you certain there wasn't an update to .NET Framework itself at the same time? Maybe via Windows Update? (Not that I would expect that to have such a change, but it would at least make more sense.)

[stanisls]

There were no other updates - only an update of the version number of the following nuget packages:
Microsoft.AspNet.WebApi
Microsoft.AspNet.WebApi.Client
Microsoft.AspNet.WebApi.Core
Microsoft.AspNet.WebApi.WebHost

Moreover, when I downgrade back to 5.2.4 the corerct behavior is restored.

I first noted this in our business application, and then replicated in a minimalistic project.

Anyway, the code says more than a thousand words. Here is a repo with the test code:
https://github.com/stanisls/TestCurrentContext
Just check out one of the test vestion numbers to see the effect (you'll need a locally running Seq or configure logging to go to some other destination).
Maybe I am doing something strange there (e.g.: using a custom Json-based membership provider), but I still suspect the behaviour should have been consistent between the different Microsoft.AspNet.WebApi.* versions

[tsimbalar]

@stanisls thanks a lot for the repro !

I haven't had the opportunity to download/try it, but just reviewing it, I see in WebApiConfig :

config.SuppressHostPrincipal();

https://github.com/stanisls/TestCurrentContext/blob/fcb7b8389165fcc01a2d7c3496002a46c7ab180b/TestCurrentContext/App_Start/WebApiConfig.cs#L17

Based on the documentation :

To disable host-level authentication inside the Web API pipeline, call config.SuppressHostPrincipal() in your configuration. This causes Web API to remove the IPrincipal from any request that enters the Web API pipeline. Effectively, it "un-authenticates" the request.

so I guess that would explain the fact that the Principal/User is "forgotten" ... not sure whether that should have changed in between versions though ...

[stanisls]

Good catch! That's inherited legacy code for you, with some copy-pasting. Though in this case copy-pasting was a good thing.

Commenting that config line out restores the behaviour of the UserName enricher in the final event.

So, actually, 5.2.5 and onwards fixed the bug that SuppressHostPrincipal was not honoured. Can some of the devs from AspNetWebStack confirm this and, if so, close the issue?

[Eilon]

Wow great investigation!

@mkArtakMSFT / @dougbu / @davidfowl - can any of you confirm this?

[dougbu]

So confirmed 😺

In f9e06d6 I fixed a bug affecting both Owin's PassiveAuthenticationMessageHandler and Hosting's SuppressHostPrincipalMessageHandler. See #119 for more information about the issue. That commit was part of the 5.2.5 release.

[Eilon]

Thanks @dougbu , so I guess we can close the issue?

[dougbu]

Yes