IIS logs missing username (empty cs-username)

[CrescentFresh]

IIS logs record "-" for username ("cs-username") when using IdentityServer3.AccessTokenValidation. Rolling back to Thinktecture.IdentityServer.AccessTokenValidation fixes the issue.

Simple reproduce: https://github.com/CrescentFresh/AccessTokenValidationIISLogging

There you will find three projects:

• IdentityServer3 standalone host with inmemory configuration
• a project that successfully logs the username of the authenticated identity ("johnny"); this uses package Thinktecture.IdentityServer.AccessTokenValidation
• a project that unsuccessfully logs the username of the authenticated identity ("-"); this uses package IdentityServer3.AccessTokenValidation

With the exception of the bearer token validation package the two test projects are identical, and set up the name of the request's identity ("johnny") as follows:

app.UseIdentityServerBearerTokenAuthentication(new IdentityServerBearerTokenAuthenticationOptions
{
    Authority = "http://localhost:49907/core",
    ValidationMode = ValidationMode.Local, // JWT
    Provider = new OAuthBearerAuthenticationProvider()
    {
        OnValidateIdentity = ctx =>
        {
            var claims = new List<Claim>(ctx.Ticket.Identity.Claims);
            claims.Add(new Claim("name", "johnny"));
            var identity = new ClaimsIdentity(claims, 
                ctx.Ticket.Identity.AuthenticationType, "name", "role");
            return Task.FromResult(ctx.Validated(identity));
        }
    }
});

(Note that it does not matter where the name claim originates: even when present in the jwt generated by idsrv3 (as opposed to fake'd into the request's identity as above), username still is not logged. The above sample was the most direct way to illustrate the problem.)

The test projects install into the local IIS's Default Web Site (aka localhost) on port 80 and cs-username is configured to be logged for said website. The idsrv3 project is standalone on launches with the debugger. There's a batch file flush_iis_logbuffer.cmd in the repo to help in flushing iis' log buffer to disk to help speed up diagnosis.

Repro (run in debug mode with the idsrv3 standalone project as the startup project):

1. request a token with a POST to http://localhost:49907/core/connect/token: grant_type=client_credentials&scope=read&client_id=client&client_secret=secret
2. GET http://localhost/AccessTokenValidationIISLogging.Thinktecture/
3. GET http://localhost/AccessTokenValidationIISLogging.IdentityServer3/
4. Find the relevant iis logs. Sample entries found:

#Software: Microsoft Internet Information Services 8.5
#Version: 1.0
#Date: 2016-02-17 21:10:21
#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) cs(Referer) sc-status sc-substatus sc-win32-status time-taken
2016-02-17 21:24:48 ::1 GET /AccessTokenValidationIISLogging.Thinktecture/ - 80 johnny ::1 Mozilla/5.0... - 200 0 0 38402
2016-02-17 21:25:08 ::1 GET /AccessTokenValidationIISLogging.IdentityServer3/ - 80 - ::1 Mozilla/5.0... - 200 0 0 13843

Expected output in the logs is that "johnny" appears in both requests, however it only appears for requests to http://localhost/AccessTokenValidationIISLogging.Thinktecture.

[brockallen]

Did you call JwtSecurityTokenHandler.InboundClaimTypeMap.Clear(); in your web api project?

[CrescentFresh]

Yes. Actually both working and non-working projects do:

JwtSecurityTokenHandler.InboundClaimTypeMap = new Dictionary<string, string>();
JwtSecurityTokenHandler.OutboundClaimTypeMap = new Dictionary<string, string>();

[brockallen]

Not sure then. Where does IIS pull from to populate that log? Environment variable?

[CrescentFresh]

I thought it pulled from the current request thread's IPrincipal.Identity.Name property. I cannot imagine where else it would get it from.

[brockallen]

Any resolution?

[CrescentFresh]

We have used Thinktecture.IdentityServer.AccessTokenValidation for the past year, only recently upgrading to IdentityServer3.AccessTokenValidation.

I had forgotten about this issue until we just noticed our iis logs are once again missing all usernames.

Please re-open.

[CrescentFresh]

Upgrading the reproduce sample at https://github.com/CrescentFresh/AccessTokenValidationIISLogging to use the latest nuget package for IdentityServer3.AccessTokenValidation (2.13.0) and the problem is still there, empty username is being logged.

The project using Thinktecture.IdentityServer.AccessTokenValidation logs the username successfully:

2017-02-07 17:39:25 ::1 GET /AccessTokenValidationIISLogging.IdentityServer3/ - 80 - ::1 Mozilla/5.0+(Windows+NT+10.0;+WOW64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/55.0.2883.87+Safari/537.36 - 200 0 0 1201
2017-02-07 17:39:32 ::1 GET /AccessTokenValidationIISLogging.Thinktecture/ - 80 johnny ::1 Mozilla/5.0+(Windows+NT+10.0;+WOW64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/55.0.2883.87+Safari/537.36 - 200 0 0 1082

[CrescentFresh]

Familiarizing myself with the code, I find the fundamental change between new and old code is this bit of code that creates a tangent pipeline:

new Lazy<AppFunc>(() => 
{
    var localBuilder = app.New();
    localBuilder.UseOAuthBearerAuthentication(options.LocalValidationOptions.Value);
    localBuilder.Run(ctx => next(ctx.Environment));
    return localBuilder.Build();
});

My hunch as to the cause of this behavior is that while this inner pipeline is authenticated, the "outer pipeline" remains anonymous. Is that even possible? My gut says I'm off-base.

[CrescentFresh]

Not sure if I did it right but there is a pull request that fixes this issue.

[CrescentFresh]

I've opened a new pull request against the dev branch.