Better logs in AuthorizationMiddleware (#43862)

src/Security/Authorization/Policy/src/AuthorizationMiddleware.cs

@@ -6,6 +6,7 @@ using Microsoft.AspNetCore.Authorization.Policy;
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Http.Features.Authentication;
 using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Authorization;
 
@@ -25,13 +26,15 @@ public class AuthorizationMiddleware
     private readonly IAuthorizationPolicyProvider _policyProvider;
     private readonly bool _canCache;
     private readonly AuthorizationPolicyCache? _policyCache;
+    private readonly ILogger<AuthorizationMiddleware>? _logger;
 
     /// <summary>
     /// Initializes a new instance of <see cref="AuthorizationMiddleware"/>.
     /// </summary>
     /// <param name="next">The next middleware in the application middleware pipeline.</param>
     /// <param name="policyProvider">The <see cref="IAuthorizationPolicyProvider"/>.</param>
-    public AuthorizationMiddleware(RequestDelegate next, IAuthorizationPolicyProvider policyProvider)
+    public AuthorizationMiddleware(RequestDelegate next,
+        IAuthorizationPolicyProvider policyProvider)
     {
         _next = next ?? throw new ArgumentNullException(nameof(next));
         _policyProvider = policyProvider ?? throw new ArgumentNullException(nameof(policyProvider));
@@ -44,7 +47,24 @@ public class AuthorizationMiddleware
     /// <param name="next">The next middleware in the application middleware pipeline.</param>
     /// <param name="policyProvider">The <see cref="IAuthorizationPolicyProvider"/>.</param>
     /// <param name="services">The <see cref="IServiceProvider"/>.</param>
-    public AuthorizationMiddleware(RequestDelegate next, IAuthorizationPolicyProvider policyProvider, IServiceProvider services) : this(next, policyProvider)
+    /// <param name="logger">The <see cref="ILogger"/>.</param>
+    public AuthorizationMiddleware(RequestDelegate next,
+        IAuthorizationPolicyProvider policyProvider,
+        IServiceProvider services,
+        ILogger<AuthorizationMiddleware> logger) : this(next, policyProvider, services)
+    {
+        _logger = logger;
+    }
+
+    /// <summary>
+    /// Initializes a new instance of <see cref="AuthorizationMiddleware"/>.
+    /// </summary>
+    /// <param name="next">The next middleware in the application middleware pipeline.</param>
+    /// <param name="policyProvider">The <see cref="IAuthorizationPolicyProvider"/>.</param>
+    /// <param name="services">The <see cref="IServiceProvider"/>.</param>
+    public AuthorizationMiddleware(RequestDelegate next,
+        IAuthorizationPolicyProvider policyProvider,
+        IServiceProvider services) : this(next, policyProvider)
     {
         ArgumentNullException.ThrowIfNull(services);
 
@@ -108,7 +128,6 @@ public class AuthorizationMiddleware
         var policyEvaluator = context.RequestServices.GetRequiredService<IPolicyEvaluator>();
 
         var authenticateResult = await policyEvaluator.AuthenticateAsync(policy, context);
-
         if (authenticateResult?.Succeeded ?? false)
         {
             if (context.Features.Get<IAuthenticateResultFeature>() is IAuthenticateResultFeature authenticateResultFeature)
@@ -130,6 +149,11 @@ public class AuthorizationMiddleware
             return;
         }
 
+        if (authenticateResult != null && !authenticateResult.Succeeded)
+        {
+            _logger?.LogDebug("Policy authentication schemes {policyName} did not succeed", String.Join(", ", policy.AuthenticationSchemes));
+        }
+
         object? resource;
         if (AppContext.TryGetSwitch(SuppressUseHttpContextAsAuthorizationResource, out var useEndpointAsResource) && useEndpointAsResource)
         {

src/Security/Authorization/Policy/src/PublicAPI.Unshipped.txt

@@ -1,5 +1,6 @@
 #nullable enable
 Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.AuthorizationMiddleware(Microsoft.AspNetCore.Http.RequestDelegate! next, Microsoft.AspNetCore.Authorization.IAuthorizationPolicyProvider! policyProvider, System.IServiceProvider! services) -> void
+Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.AuthorizationMiddleware(Microsoft.AspNetCore.Http.RequestDelegate! next, Microsoft.AspNetCore.Authorization.IAuthorizationPolicyProvider! policyProvider, System.IServiceProvider! services, Microsoft.Extensions.Logging.ILogger<Microsoft.AspNetCore.Authorization.AuthorizationMiddleware!>! logger) -> void
 static Microsoft.AspNetCore.Builder.AuthorizationEndpointConventionBuilderExtensions.RequireAuthorization<TBuilder>(this TBuilder builder, Microsoft.AspNetCore.Authorization.AuthorizationPolicy! policy) -> TBuilder
 static Microsoft.AspNetCore.Builder.AuthorizationEndpointConventionBuilderExtensions.RequireAuthorization<TBuilder>(this TBuilder builder, System.Action<Microsoft.AspNetCore.Authorization.AuthorizationPolicyBuilder!>! configurePolicy) -> TBuilder
 static Microsoft.Extensions.DependencyInjection.PolicyServiceCollectionExtensions.AddAuthorizationBuilder(this Microsoft.Extensions.DependencyInjection.IServiceCollection! services) -> Microsoft.AspNetCore.Authorization.AuthorizationBuilder!

src/Security/Authorization/test/AuthorizationMiddlewareTests.cs

@@ -6,11 +6,11 @@ using Microsoft.AspNetCore.Authentication;
 using Microsoft.AspNetCore.Authorization.Policy;
 using Microsoft.AspNetCore.Authorization.Test.TestObjects;
 using Microsoft.AspNetCore.Builder;
-using Microsoft.AspNetCore.Hosting;
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Routing;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using Microsoft.Extensions.Primitives;
 using Moq;
@@ -46,8 +46,9 @@ public class AuthorizationMiddlewareTests
         var policyProvider = new Mock<IAuthorizationPolicyProvider>();
         policyProvider.Setup(p => p.GetFallbackPolicyAsync()).ReturnsAsync(policy);
         var next = new TestRequestDelegate();
+        var logger = new Mock<ILogger<AuthorizationMiddleware>>();
 
-        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object);
+        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object, logger: logger.Object);
         var context = GetHttpContext(anonymous: true);
 
         // Act
@@ -85,8 +86,9 @@ public class AuthorizationMiddlewareTests
         policyProvider.Setup(p => p.GetDefaultPolicyAsync()).ReturnsAsync(policy);
         policyProvider.Setup(p => p.GetFallbackPolicyAsync()).ReturnsAsync(policy);
         var next = new TestRequestDelegate();
+        var logger = new Mock<ILogger<AuthorizationMiddleware>>();
 
-        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object);
+        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object, logger: logger.Object);
         var context = GetHttpContext(anonymous: true, endpoint: CreateEndpoint());
 
         // Act
@@ -106,8 +108,9 @@ public class AuthorizationMiddlewareTests
         policyProvider.Setup(p => p.GetFallbackPolicyAsync()).ReturnsAsync(policy);
         var next = new TestRequestDelegate();
         var authenticationService = new TestAuthenticationService();
+        var logger = new Mock<ILogger<AuthorizationMiddleware>>();
 
-        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object);
+        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object, logger: logger.Object);
         var context = GetHttpContext(anonymous: true, endpoint: CreateEndpoint(new AuthorizeAttribute()), authenticationService: authenticationService);
 
         // Act
@@ -126,8 +129,9 @@ public class AuthorizationMiddlewareTests
         policyProvider.Setup(p => p.GetDefaultPolicyAsync()).ReturnsAsync(policy);
         var next = new TestRequestDelegate();
         var authenticationService = new TestAuthenticationService();
+        var logger = new Mock<ILogger<AuthorizationMiddleware>>();
 
-        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object);
+        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object, logger: logger.Object);
         var context = GetHttpContext(anonymous: true, endpoint: CreateEndpoint(new AuthorizeAttribute()), authenticationService: authenticationService);
 
         // Act
@@ -147,8 +151,9 @@ public class AuthorizationMiddlewareTests
         policyProvider.Setup(p => p.GetDefaultPolicyAsync()).ReturnsAsync(policy);
         var next = new TestRequestDelegate();
         var authenticationService = new TestAuthenticationService();
+        var logger = new Mock<ILogger<AuthorizationMiddleware>>();
 
-        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object);
+        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object, logger: logger.Object);
         var context = GetHttpContext(endpoint: CreateEndpoint(new AuthorizeAttribute() { AuthenticationSchemes = "whatever" }), authenticationService: authenticationService);
 
         // Act
@@ -168,8 +173,9 @@ public class AuthorizationMiddlewareTests
         policyProvider.Setup(p => p.GetDefaultPolicyAsync()).ReturnsAsync(policy);
         var next = new TestRequestDelegate();
         var authenticationService = new TestAuthenticationService();
+        var logger = new Mock<ILogger<AuthorizationMiddleware>>();
 
-        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object);
+        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object, logger: logger.Object);
         var context = GetHttpContext(anonymous: true, endpoint: CreateEndpoint(new AuthorizeAttribute()), authenticationService: authenticationService);
 
         // Act
@@ -193,7 +199,8 @@ public class AuthorizationMiddlewareTests
         policyProvider.Setup(p => p.GetFallbackPolicyAsync()).ReturnsAsync(policy)
             .Callback(() => getFallbackPolicyCount++);
         var next = new TestRequestDelegate();
-        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object);
+        var logger = new Mock<ILogger<AuthorizationMiddleware>>();
+        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object, logger: logger.Object);
         var context = GetHttpContext(anonymous: true, endpoint: CreateEndpoint(new AuthorizeAttribute("whatever")));
 
         // Act & Assert
@@ -235,12 +242,13 @@ public class AuthorizationMiddlewareTests
             .Callback(() => getFallbackPolicyCount++);
         policyProvider.Setup(p => p.AllowsCachingPolicies).Returns(true);
         var next = new TestRequestDelegate();
+        var logger = new Mock<ILogger<AuthorizationMiddleware>>();
 
         var endpoint = CreateEndpoint(new AuthorizeAttribute("whatever"));
         var services = new ServiceCollection()
             .AddAuthorization()
             .AddSingleton(CreateDataSource(endpoint)).BuildServiceProvider();
-        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object, services);
+        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object, services, logger.Object);
         var context = GetHttpContext(anonymous: true, endpoint: endpoint);
 
         // Act & Assert
@@ -299,7 +307,8 @@ public class AuthorizationMiddlewareTests
         var services = new ServiceCollection()
             .AddAuthorization()
             .AddSingleton(CreateDataSource(endpoint)).BuildServiceProvider();
-        var middleware = CreateMiddleware(next.Invoke, policyProvider, services);
+        var logger = new Mock<ILogger<AuthorizationMiddleware>>();
+        var middleware = CreateMiddleware(next.Invoke, policyProvider, services, logger.Object);
         var context = GetHttpContext(anonymous: true, endpoint: endpoint);
 
         // Act & Assert
@@ -332,7 +341,8 @@ public class AuthorizationMiddlewareTests
         policyProvider.Setup(p => p.GetFallbackPolicyAsync()).ReturnsAsync(policy)
             .Callback(() => getFallbackPolicyCount++);
         var next = new TestRequestDelegate();
-        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object);
+        var logger = new Mock<ILogger<AuthorizationMiddleware>>();
+        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object, logger: logger.Object);
         var context = GetHttpContext(anonymous: true, endpoint: CreateEndpoint(new AuthorizeAttribute("whatever")));
 
         // Act & Assert
@@ -444,8 +454,9 @@ public class AuthorizationMiddlewareTests
         policyProvider.Setup(p => p.GetDefaultPolicyAsync()).ReturnsAsync(policy);
         var next = new TestRequestDelegate();
         var authenticationService = new TestAuthenticationService();
+        var logger = new Mock<ILogger<AuthorizationMiddleware>>();
 
-        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object);
+        var middleware = CreateMiddleware(next.Invoke, policyProvider.Object, logger: logger.Object);
         var context = GetHttpContext(endpoint: CreateEndpoint(new AuthorizeAttribute()), authenticationService: authenticationService);
 
         // Act
@@ -824,11 +835,11 @@ public class AuthorizationMiddlewareTests
         Assert.True(app.Properties.ContainsKey("__AuthorizationMiddlewareSet"));
     }
 
-    private AuthorizationMiddleware CreateMiddleware(RequestDelegate requestDelegate = null, IAuthorizationPolicyProvider policyProvider = null, IServiceProvider services = null)
+    private AuthorizationMiddleware CreateMiddleware(RequestDelegate requestDelegate = null, IAuthorizationPolicyProvider policyProvider = null, IServiceProvider services = null, ILogger<AuthorizationMiddleware> logger = null)
     {
         requestDelegate = requestDelegate ?? ((context) => Task.CompletedTask);
         services ??= new ServiceCollection().BuildServiceProvider();
-        return new AuthorizationMiddleware(requestDelegate, policyProvider, services);
+        return new AuthorizationMiddleware(requestDelegate, policyProvider, services, logger);
     }
 
     private Endpoint CreateEndpoint(params object[] metadata)

src/Security/perf/Microbenchmarks/AuthorizationMiddlewareBenchmark.cs

@@ -1,4 +1,4 @@
-// Licensed to the .NET Foundation under one or more agreements.
+// Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 
 using BenchmarkDotNet.Attributes;