Double log entries during authentication

[Eternal21]

trafficstars

I'm using this package in ASP.NET Core WebAPI 6.0. Whenever my ApiKey authenticates, I end up with doubled log entries like this:

2022-05-10 18:57:54.2716|DEBUG|AuthenticationScheme: ApiKey was successfully authenticated. 
2022-05-10 18:57:54.2954|DEBUG|AuthenticationScheme: ApiKey was successfully authenticated 

2022-05-10 18:57:56.8659|DEBUG|AuthenticationScheme: ApiKey was successfully authenticated 
2022-05-10 18:57:56.8659|DEBUG|AuthenticationScheme: ApiKey was successfully authenticated 

2022-05-10 18:58:01.1008|DEBUG|AuthenticationScheme: ApiKey was successfully authenticated
2022-05-10 18:58:01.1008|DEBUG|AuthenticationScheme: ApiKey was successfully authenticated

2022-05-10 18:58:06.8723|DEBUG|AuthenticationScheme: ApiKey was successfully authenticated 
2022-05-10 18:58:06.8723|DEBUG|AuthenticationScheme: ApiKey was successfully authenticated

2022-05-10 18:58:10.1049|DEBUG|AuthenticationScheme: ApiKey was successfully authenticated 
2022-05-10 18:58:10.1049|DEBUG|AuthenticationScheme: ApiKey was successfully authenticated

It almost looks like I have two log sinks, but for debug purposes I made sure to turn them all off like this:

return Host.CreateDefaultBuilder(args)
  .ConfigureWebHostDefaults(webBuilder =>
  {
      webBuilder.UseStartup<Startup>();
  })
  .ConfigureLogging(logging =>
  {
      logging.ClearProviders();
      logging.AddDebug(); // when this line is commented out I get NO log entries, otherwise I get DOUBLE log entries
  });

If I comment out the AddDebug() line above I get no log entries. When I uncomment it, I get double log entries, so this proves it's not double sinks that are the issue. The actual log line comes from this Microsoft nuget: https://github.com/aspnet/Security/blob/26d27d871b7992022c082dc207e3d126e1d9d278/src/Microsoft.AspNetCore.Authentication/LoggingExtensions.cs#L46

I am using the ApiKeyHandler as following:

.AddApiKeyInHeader<ApiKeyProvider>(options =>
  {
      options.IgnoreAuthenticationIfAllowAnonymous = true;
      options.SuppressWWWAuthenticateHeader = true;
      options.KeyName = "X-Api-Key";
  })

Searching on google, I was able to find people with similar double line entries, but each case was using a different scheme. There's a guy with a double cookie log entires, double Bearer log entries, etc. Sadly none of them have a resolution:

1. https://github.com/IdentityServer/IdentityServer4/issues/2756
2. https://stackoverflow.com/questions/42257481/authorization-with-asp-net-core-webapi
3. https://stackoverflow.com/questions/43748434/asp-net-core-defaultauthorizationservice-runs-twice-for-jwt-tokens

Any ideas what's causing the double entries? Any suggestions on steps I should take to debug it further? Thanks.

[Eternal21]

I also verified the authentication happens only once, by subscribing to the OnAuthenticationSucceeded event, and making sure it only gets hit once:

.AddApiKeyInHeader<ApiKeyProvider>(options =>
{
  options.Events.OnAuthenticationSucceeded += OnAuthenticationSucceeded; // only gets hit once
  ...

[Eternal21]

Here's the log message with the source context information:

[1]AspNetCore.Authentication.ApiKey.ApiKeyInHeaderHandler: 2022-05-11 12:13:09.2722|DEBUG|AuthenticationScheme: ApiKey was successfully authenticated. 
[1]AspNetCore.Authentication.ApiKey.ApiKeyInHeaderHandler: 2022-05-11 12:13:09.2722|DEBUG|AuthenticationScheme: ApiKey was successfully authenticated. 

The source is: AspNetCore.Authentication.ApiKey.ApiKeyInHeaderHandler

I also ran the log with Trace level enabled, and it does look like the auth takes place twice internally:

Microsoft.AspNetCore.Hosting.Diagnostics: Information: Request starting HTTP/1.1 GET https://localhost:5001/api/test - -
Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler: Debug: AuthenticationScheme: Bearer was not authenticated.
AspNetCore.Authentication.ApiKey.ApiKeyInHeaderHandler: Debug: AuthenticationScheme: ApiKey was successfully authenticated.
(FIRST) Microsoft.AspNetCore.Authorization.DefaultAuthorizationService: Debug: Authorization was successful.
Microsoft.AspNetCore.Routing.EndpointMiddleware: Information: Executing endpoint 'TestService.WebApi.Api.Test.TestController.Get (TestService.WebApi)'
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Information: Route matched with {action = "Get", controller = "Tests"}. Executing controller action with signature... 
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Execution plan of authorization filters (in the following order): Microsoft.AspNetCore.Mvc.Authorization.AuthorizeFilter
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Execution plan of resource filters (in the following order): None
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Execution plan of action filters (in the following order): Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter (Order: -3000), Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter (Order: -2000)
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Execution plan of exception filters (in the following order): None
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Execution plan of result filters (in the following order): Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter (Order: -2000)
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Authorization Filter: Before executing OnAuthorizationAsync on filter Microsoft.AspNetCore.Mvc.Authorization.AuthorizeFilter.
(SECOND) AspNetCore.Authentication.ApiKey.ApiKeyInHeaderHandler: Debug: AuthenticationScheme: ApiKey was successfully authenticated.
Microsoft.AspNetCore.Authorization.DefaultAuthorizationService: Debug: Authorization was successful.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Authorization Filter: After executing OnAuthorizationAsync on filter Microsoft.AspNetCore.Mvc.Authorization.AuthorizeFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Executing controller factory for controller TestService.WebApi.Api.Tetsts.TestController (TestService.WebApi)
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Executed controller factory for controller TestService.WebApi.Api.Tetsts.TestController (TestService.WebApi)
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Information: Executing action method TestService.WebApi.Api.Tetsts.TestController.Get (TestService.WebApi) - Validation state: Valid

[mihirdilip]

Hi @Eternal21, thank you for all the information you have provided.

Looking at your debug trace logs, although ApiKeyInHeaderHandler logs appears twice, the 2 sets of asp.net middleware pipeline logs are different.

I tried it on some of my sample projects (.NET 6, .NET 5 and .NET Core 3.1) and non of them generated duplicate log entries for me. I will need more details on what version of .net you are using, what version of this ApiKey library you are using and also how is your Startup class setup along with how and where you are using Authorize filter in order for me to help you with this.

Microsoft.AspNetCore.Hosting.Diagnostics: Information: Request starting HTTP/1.1 GET https://localhost:44304/api/values - -
Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware: Trace: All hosts are allowed.
Microsoft.AspNetCore.Routing.Matching.DfaMatcher: Debug: 1 candidate(s) found for the request path '/api/values'
Microsoft.AspNetCore.Routing.Matching.DfaMatcher: Debug: Endpoint 'SampleWebApi_6_0.Controllers.ValuesController.Get (SampleWebApi_6_0)' with route pattern 'api/Values' is valid for the request path '/api/values'
Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware: Debug: Request matched endpoint 'SampleWebApi_6_0.Controllers.ValuesController.Get (SampleWebApi_6_0)'
AspNetCore.Authentication.ApiKey.ApiKeyInHeaderHandler: Debug: AuthenticationScheme: ApiKey was successfully authenticated.
Microsoft.AspNetCore.Authorization.DefaultAuthorizationService: Debug: Authorization was successful.
Microsoft.AspNetCore.Routing.EndpointMiddleware: Information: Executing endpoint 'SampleWebApi_6_0.Controllers.ValuesController.Get (SampleWebApi_6_0)'
'iisexpress.exe' (CoreCLR: clrhost): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.3\System.Linq.Expressions.dll'. Skipped loading symbols. Module is optimized and the debugger option 'Just My Code' is enabled.
'iisexpress.exe' (CoreCLR: clrhost): Loaded 'Anonymously Hosted DynamicMethods Assembly'. 
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Information: Route matched with {action = "Get", controller = "Values"}. Executing controller action with signature Microsoft.AspNetCore.Mvc.ActionResult`1[System.Collections.Generic.IEnumerable`1[System.String]] Get() on controller SampleWebApi_6_0.Controllers.ValuesController (SampleWebApi_6_0).
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Execution plan of authorization filters (in the following order): None
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Execution plan of resource filters (in the following order): None
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Execution plan of action filters (in the following order): Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter (Order: -3000), Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter (Order: -2000)
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Execution plan of exception filters (in the following order): None
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Execution plan of result filters (in the following order): Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter (Order: -2000)
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Executing controller factory for controller SampleWebApi_6_0.Controllers.ValuesController (SampleWebApi_6_0)
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Debug: Executed controller factory for controller SampleWebApi_6_0.Controllers.ValuesController (SampleWebApi_6_0)
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Information: Executing action method SampleWebApi_6_0.Controllers.ValuesController.Get (SampleWebApi_6_0) - Validation state: Valid
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Information: Executed action method SampleWebApi_6_0.Controllers.ValuesController.Get (SampleWebApi_6_0), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 0.2182ms.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Action Filter: Before executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Action Filter: After executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Action Filter: Before executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Action Filter: After executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Result Filter: Before executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Result Filter: After executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Before executing action result Microsoft.AspNetCore.Mvc.ObjectResult.
Microsoft.AspNetCore.Mvc.Infrastructure.DefaultOutputFormatterSelector: Debug: List of registered output formatters, in the following order: Microsoft.AspNetCore.Mvc.Formatters.HttpNoContentOutputFormatter, Microsoft.AspNetCore.Mvc.Formatters.StringOutputFormatter, Microsoft.AspNetCore.Mvc.Formatters.StreamOutputFormatter, Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonOutputFormatter
Microsoft.AspNetCore.Mvc.Infrastructure.DefaultOutputFormatterSelector: Debug: No information found on request to perform content negotiation.
Microsoft.AspNetCore.Mvc.Infrastructure.DefaultOutputFormatterSelector: Debug: Attempting to select an output formatter without using a content type as no explicit content types were specified for the response.
Microsoft.AspNetCore.Mvc.Infrastructure.DefaultOutputFormatterSelector: Debug: Attempting to select the first formatter in the output formatters list which can write the result.
Microsoft.AspNetCore.Mvc.Infrastructure.DefaultOutputFormatterSelector: Debug: Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonOutputFormatter' and content type 'application/json' to write the response.
Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor: Information: Executing ObjectResult, writing value of type 'System.String[]'.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: After executing action result Microsoft.AspNetCore.Mvc.ObjectResult.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Result Filter: Before executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Trace: Result Filter: After executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker: Information: Executed action SampleWebApi_6_0.Controllers.ValuesController.Get (SampleWebApi_6_0) in 69.608ms
Microsoft.AspNetCore.Routing.EndpointMiddleware: Information: Executed endpoint 'SampleWebApi_6_0.Controllers.ValuesController.Get (SampleWebApi_6_0)'
Microsoft.AspNetCore.Hosting.Diagnostics: Information: Request finished HTTP/1.1 GET https://localhost:44304/api/values - - - 200 - application/json;+charset=utf-8 4126.9643ms

[Eternal21]

@mihirdilip Thanks for the response. I will try to reproduce this with a minimum sample project and share the repo if it happens.

[Eternal21]

@mihirdilip I was able to reproduce the issue with the following repo: https://github.com/Eternal21/double-log-issue

To run the repo, just run IISExpress configuration, and hit it using the following request from Postman: GET http://localhost:19333/WeatherForecast after adding the following header: X-API-KEY: testKey

It is due to me adding BearerOrApiKey policy scheme, but I don't understand why it's happening. I basically have a need for endpoints to accept either Bearer or ApiKey authentication. The policy scheme checks if the request's Authorization header contains Bearer token. If it does, it uses Bearer authentication, otherwise it uses ApiKey authentication. In my actual code I have the .AddJwtBearer() authentication configured, but didn't need that to reproduce the issue here. The AddPolicyScheme was enough to trigger the problem. See the screenshot below of the exact changes that cause the issue. Any ideas? Thanks.

[mihirdilip]

I am not on PC so couldn't try it. Replying from my phone. One thing I would suggest to try is on this line replace ApiKeyDefaults.AuthenticationScheme with "BearerOrApiKey"

And on this line change it to .AddApiKeyInHeaderOrQueryParams<ApiKeyProvider>("ApiKey", options =>

[Eternal21]

You may be on to something with the AddAuthentication. Your suggestion did not work, but replacing this line: builder.Services.AddAuthentication(ApiKeyDefaults.AuthenticationScheme) with this builder.Services.AddAuthentication() eliminates the double log. So that AddAuthentication line definitely has something to do with it.

Sadly this doesn't fix my actual code. I already had the default set to Bearer. When I removed it, it still logged double. When I changed it to BearerOrApiKey it started logging triple entries!. I suspect it's the .AddJwtBearer causing the issue. I'll try adding it to sample code to reproduce with it instead.

[mihirdilip]

Yh it would be good to see code with .AddJwtBearer

[Eternal21]

I added the AddJwtBearer scheme to the repo. Same results. Removing the defaults from AddAuthentication(...) fixes the double logging. Unfortunately it only fixes it in this sample code and not my real app, even though the AddAuthentication() section is now exactly the same as in my real code. In any case, I guess you can close this issue, since I can't reproduce with sample app. At least I know that it truly is double authenticating now, just need to figure out why. I'll report more information if I figure it out on my end.

[mihirdilip]

How about trying this? Note the scheme names "Bearer" and "ApiKey".

builder.Services.AddAuthentication(options => // this also fixes the double log
    {
        options.DefaultAuthenticateScheme = "BearerOrApiKey";
        options.DefaultChallengeScheme = "BearerOrApiKey";
    })
    .AddJwtBearer("Bearer", options =>
    {
        options.SaveToken = true;
        options.TokenValidationParameters = new TokenValidationParameters 
        {
            ValidateIssuer = false,
            ValidateAudience = false,
            ValidateLifetime = true,
            ValidateIssuerSigningKey = true,
            IssuerSigningKey = new SymmetricSecurityKey(Encoding.UTF8.GetBytes("secret")),
            // ClockSkew = TimeSpan.Zero // default value is 5 minutes
        };
        // see: https://docs.microsoft.com/en-us/aspnet/core/signalr/authn-and-authz?view=aspnetcore-5.0#built-in-jwt-authentication
        options.Events = new JwtBearerEvents
        {
            OnMessageReceived = context =>
            {
                var accessToken = context.Request.Query["access_token"];
        
                // if the request is for our hub:
                var path = context.HttpContext.Request.Path;
                if (!string.IsNullOrEmpty(accessToken) && path.StartsWithSegments("/message-hub"))
                    context.Token = accessToken;
                return Task.CompletedTask;
            }
        };
    })
    .AddApiKeyInHeaderOrQueryParams<ApiKeyProvider>("ApiKey",  options =>
    {
        options.Realm = "Sample Web API";
        options.KeyName = "X-API-KEY";
    })
    .AddPolicyScheme("BearerOrApiKey", "BearerOrApiKey", options =>
    {
        options.ForwardDefaultSelector = context =>
        {
            string authorization = context.Request.Headers[HeaderNames.Authorization];
            if (!string.IsNullOrEmpty(authorization) && authorization.StartsWith("Bearer "))
                return "Bearer";
            return "ApiKey";
        };
    });

[Eternal21]

This causes double entries in the sample code. That can then be fixed by not passing anything to AddAuthentication options.

[Eternal21]

I also noticed the following. With the setup from your post above, even if I explicitly set the endpoint to be authenticated with ApiKey as shown below. I still get double authentication:

[mihirdilip]

In that case don't pass anything to AddAuthentication since you are using [Authorize] attribute with your preferred scheme name anyways.

[Eternal21]

The only other thing I found is which default in particular causes double log entries in sample app. But again, this doesn't help in my real app. Something else is going on and I'm giving up, since I can't reproduce it in the sample. At the very least I know that the OnAuthenticationSucceeded event only gets hit once, so at least validation is not being performed twice.

options.DefaultScheme = "ApiKey"; // causes double log entries
options.DefaultAuthenticateScheme = "ApiKey"; // causes double log entries
options.DefaultChallengeScheme = "ApiKey";
options.DefaultForbidScheme = "ApiKey";
options.DefaultSignInScheme = "ApiKey";
options.DefaultSignOutScheme = "ApiKey";

[mihirdilip]

I am closing this as the thread is no longer active.