Improve logging - individual filters

src/Microsoft.AspNetCore.Mvc.Core/Formatters/FormatFilter.cs

@@ -6,6 +6,9 @@ using System.Linq;
 using Microsoft.AspNetCore.Mvc.ApiExplorer;
 using Microsoft.AspNetCore.Mvc.Filters;
 using Microsoft.AspNetCore.Mvc.Formatters.Internal;
+using Microsoft.AspNetCore.Mvc.Internal;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Extensions.Options;
 
 namespace Microsoft.AspNetCore.Mvc.Formatters
@@ -17,14 +20,37 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
     public class FormatFilter : IFormatFilter, IResourceFilter, IResultFilter
     {
         private readonly MvcOptions _options;
+        private readonly ILogger _logger;
 
         /// <summary>
         /// Initializes an instance of <see cref="FormatFilter"/>.
         /// </summary>
         /// <param name="options">The <see cref="IOptions{MvcOptions}"/></param>
+        [Obsolete("This constructor is obsolete and will be removed in a future version.")]
         public FormatFilter(IOptions<MvcOptions> options)
+            : this(options, NullLoggerFactory.Instance)
         {
+        }
+
+        /// <summary>
+        /// Initializes an instance of <see cref="FormatFilter"/>.
+        /// </summary>
+        /// <param name="options">The <see cref="IOptions{MvcOptions}"/></param>
+        /// <param name="loggerFactory">The <see cref="ILoggerFactory"/>.</param>
+        public FormatFilter(IOptions<MvcOptions> options, ILoggerFactory loggerFactory)
+        {
+            if (options == null)
+            {
+                throw new ArgumentNullException(nameof(options));
+            }
+
+            if (loggerFactory == null)
+            {
+                throw new ArgumentNullException(nameof(loggerFactory));
+            }
+
             _options = options.Value;
+            _logger = loggerFactory.CreateLogger(GetType());
         }
 
         /// <inheritdoc />
@@ -69,6 +95,8 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
             var contentType = _options.FormatterMappings.GetMediaTypeMappingForFormat(format);
             if (contentType == null)
             {
+                _logger.UnsupportedFormatFilterContentType(format);
+
                 // no contentType exists for the format, return 404
                 context.Result = new NotFoundResult();
                 return;
@@ -83,16 +111,20 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
             }
 
             // Check if support is adequate for requested media type.
-            if (supportedMediaTypes.Count != 0)
+            if (supportedMediaTypes.Count == 0)
             {
-                // We need to check if the action can generate the content type the user asked for. That is, treat the
+                _logger.ActionDoesNotExplicitlySpecifyContentTypes();
-                // request's format and IApiResponseMetadataProvider-provided content types similarly to an Accept
+                return;
-                // header and an output formatter's SupportedMediaTypes: Confirm action supports a more specific media
+            }
-                // type than requested e.g. OK if "text/*" requested and action supports "text/plain".
+
-                if (!IsSuperSetOfAnySupportedMediaType(contentType, supportedMediaTypes))
+            // We need to check if the action can generate the content type the user asked for. That is, treat the
-                {
+            // request's format and IApiResponseMetadataProvider-provided content types similarly to an Accept
-                    context.Result = new NotFoundResult();
+            // header and an output formatter's SupportedMediaTypes: Confirm action supports a more specific media
-                }
+            // type than requested e.g. OK if "text/*" requested and action supports "text/plain".
+            if (!IsSuperSetOfAnySupportedMediaType(contentType, supportedMediaTypes))
+            {
+                _logger.ActionDoesNotSupportFormatFilterContentType(contentType, supportedMediaTypes);
+                context.Result = new NotFoundResult();
             }
         }
 
@@ -145,6 +177,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
             if ((objectResult.ContentTypes != null && objectResult.ContentTypes.Count == 1) ||
                 !string.IsNullOrEmpty(context.HttpContext.Response.ContentType))
             {
+                _logger.CannotApplyFormatFilterContentType(format);
                 return;
             }
 

src/Microsoft.AspNetCore.Mvc.Core/Internal/DisableRequestSizeLimitFilter.cs

@@ -2,8 +2,6 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
-using System.Collections.Generic;
-using System.Diagnostics;
 using Microsoft.AspNetCore.Http.Features;
 using Microsoft.AspNetCore.Mvc.Filters;
 using Microsoft.Extensions.Logging;
@@ -40,23 +38,27 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                 throw new ArgumentNullException(nameof(context));
             }
 
-            if (context.IsEffectivePolicy<IRequestSizePolicy>(this))
+            var effectivePolicy = context.FindEffectivePolicy<IRequestSizePolicy>();
+            if (effectivePolicy != null && effectivePolicy != this)
             {
-                var maxRequestBodySizeFeature = context.HttpContext.Features.Get<IHttpMaxRequestBodySizeFeature>();
+                _logger.NotMostEffectiveFilter(GetType(), effectivePolicy.GetType(), typeof(IRequestSizePolicy));
+                return;
+            }
 
-                if (maxRequestBodySizeFeature == null)
+            var maxRequestBodySizeFeature = context.HttpContext.Features.Get<IHttpMaxRequestBodySizeFeature>();
-                {
+
-                    _logger.FeatureNotFound();
+            if (maxRequestBodySizeFeature == null)
-                }
+            {
-                else if (maxRequestBodySizeFeature.IsReadOnly)
+                _logger.FeatureNotFound();
-                {
+            }
-                    _logger.FeatureIsReadOnly();
+            else if (maxRequestBodySizeFeature.IsReadOnly)
-                }
+            {
-                else
+                _logger.FeatureIsReadOnly();
-                {
+            }
-                    maxRequestBodySizeFeature.MaxRequestBodySize = null;
+            else
-                    _logger.RequestBodySizeLimitDisabled();
+            {
-                }
+                maxRequestBodySizeFeature.MaxRequestBodySize = null;
+                _logger.RequestBodySizeLimitDisabled();
             }
         }
     }

src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs

@@ -96,6 +96,12 @@ namespace Microsoft.AspNetCore.Mvc.Internal
         private static readonly Action<ILogger, MethodInfo, string, string, Exception> _inferredParameterSource;
         private static readonly Action<ILogger, MethodInfo, Exception> _unableToInferParameterSources;
 
+        private static readonly Action<ILogger, string, Exception> _unsupportedFormatFilterContentType;
+        private static readonly Action<ILogger, string, MediaTypeCollection, Exception> _actionDoesNotSupportFormatFilterContentType;
+        private static readonly Action<ILogger, string, Exception> _cannotApplyFormatFilterContentType;
+        private static readonly Action<ILogger, Exception> _actionDoesNotExplicitlySpecifyContentTypes;
+        private static readonly Action<ILogger, Type, Type, Type, Exception> _notMostEffectiveFilter;
+
         static MvcCoreLoggerExtensions()
         {
             _actionExecuting = LoggerMessage.Define<string>(
@@ -337,6 +343,31 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                 LogLevel.Warning,
                 2,
                 "Unable to unambiguously infer binding sources for parameters on '{ActionName}'. More than one parameter may be inferred to bound from body.");
+
+            _unsupportedFormatFilterContentType = LoggerMessage.Define<string>(
+                LogLevel.Debug,
+                1,
+                "Could not find a media type for the format '{FormatFilterContentType}'.");
+
+            _actionDoesNotSupportFormatFilterContentType = LoggerMessage.Define<string, MediaTypeCollection>(
+                LogLevel.Debug,
+                2,
+                "Current action does not support the content type '{FormatFilterContentType}'. The supported content types are '{SupportedMediaTypes}'.");
+
+            _cannotApplyFormatFilterContentType = LoggerMessage.Define<string>(
+                LogLevel.Debug,
+                3,
+                "Cannot apply content type '{FormatFilterContentType}' to the response as current action had explicitly set a preferred content type.");
+
+            _notMostEffectiveFilter = LoggerMessage.Define<Type, Type, Type>(
+                LogLevel.Debug,
+                4,
+                "Execution of filter {OverriddenFilter} is preempted by filter {OverridingFilter} which is the most effective filter implementing policy {FilterPolicy}.");
+
+            _actionDoesNotExplicitlySpecifyContentTypes = LoggerMessage.Define(
+                LogLevel.Debug,
+                5,
+                "Current action does not explicitly specify any content types for the response.");
         }
 
         public static IDisposable ActionScope(this ILogger logger, ActionDescriptor action)
@@ -730,6 +761,34 @@ namespace Microsoft.AspNetCore.Mvc.Internal
             _appliedRequestFormLimits(logger, null);
         }
 
+        public static void NotMostEffectiveFilter(this ILogger logger, Type overridenFilter, Type overridingFilter, Type policyType)
+        {
+            _notMostEffectiveFilter(logger, overridenFilter, overridingFilter, policyType, null);
+        }
+
+        public static void UnsupportedFormatFilterContentType(this ILogger logger, string format)
+        {
+            _unsupportedFormatFilterContentType(logger, format, null);
+        }
+
+        public static void ActionDoesNotSupportFormatFilterContentType(
+            this ILogger logger,
+            string format,
+            MediaTypeCollection supportedMediaTypes)
+        {
+            _actionDoesNotSupportFormatFilterContentType(logger, format, supportedMediaTypes, null);
+        }
+
+        public static void CannotApplyFormatFilterContentType(this ILogger logger, string format)
+        {
+            _cannotApplyFormatFilterContentType(logger, format, null);
+        }
+
+        public static void ActionDoesNotExplicitlySpecifyContentTypes(this ILogger logger)
+        {
+            _actionDoesNotExplicitlySpecifyContentTypes(logger, null);
+        }
+
         public static void ModelStateInvalidFilterExecuting(this ILogger logger) => _modelStateInvalidFilterExecuting(logger, null);
 
         public static void InferredParameterBindingSource(

src/Microsoft.AspNetCore.Mvc.Core/Internal/RequestFormLimitsFilter.cs

@@ -2,8 +2,6 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
-using System.Collections.Generic;
-using System.Diagnostics;
 using Microsoft.AspNetCore.Http.Features;
 using Microsoft.AspNetCore.Mvc.Filters;
 using Microsoft.Extensions.Logging;
@@ -31,21 +29,25 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                 throw new ArgumentNullException(nameof(context));
             }
 
-            if (context.IsEffectivePolicy<IRequestFormLimitsPolicy>(this))
+            var effectivePolicy = context.FindEffectivePolicy<IRequestFormLimitsPolicy>();
+            if (effectivePolicy != null && effectivePolicy != this)
             {
-                var features = context.HttpContext.Features;
+                _logger.NotMostEffectiveFilter(GetType(), effectivePolicy.GetType(), typeof(IRequestFormLimitsPolicy));
-                var formFeature = features.Get<IFormFeature>();
+                return;
+            }
 
-                if (formFeature == null || formFeature.Form == null)
+            var features = context.HttpContext.Features;
-                {
+            var formFeature = features.Get<IFormFeature>();
-                    // Request form has not been read yet, so set the limits
+
-                    features.Set<IFormFeature>(new FormFeature(context.HttpContext.Request, FormOptions));
+            if (formFeature == null || formFeature.Form == null)
-                    _logger.AppliedRequestFormLimits();
+            {
-                }
+                // Request form has not been read yet, so set the limits
-                else
+                features.Set<IFormFeature>(new FormFeature(context.HttpContext.Request, FormOptions));
-                {
+                _logger.AppliedRequestFormLimits();
-                    _logger.CannotApplyRequestFormLimits();
+            }
-                }
+            else
+            {
+                _logger.CannotApplyRequestFormLimits();
             }
         }
     }

src/Microsoft.AspNetCore.Mvc.Core/Internal/RequestSizeLimitFilter.cs

@@ -2,8 +2,6 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
-using System.Collections.Generic;
-using System.Diagnostics;
 using Microsoft.AspNetCore.Http.Features;
 using Microsoft.AspNetCore.Mvc.Filters;
 using Microsoft.Extensions.Logging;
@@ -41,23 +39,27 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                 throw new ArgumentNullException(nameof(context));
             }
 
-            if (context.IsEffectivePolicy<IRequestSizePolicy>(this))
+            var effectivePolicy = context.FindEffectivePolicy<IRequestSizePolicy>();
+            if (effectivePolicy != null && effectivePolicy != this)
             {
-                var maxRequestBodySizeFeature = context.HttpContext.Features.Get<IHttpMaxRequestBodySizeFeature>();
+                _logger.NotMostEffectiveFilter(GetType(), effectivePolicy.GetType(), typeof(IRequestSizePolicy));
+                return;
+            }
 
-                if (maxRequestBodySizeFeature == null)
+            var maxRequestBodySizeFeature = context.HttpContext.Features.Get<IHttpMaxRequestBodySizeFeature>();
-                {
+
-                    _logger.FeatureNotFound();
+            if (maxRequestBodySizeFeature == null)
-                }
+            {
-                else if (maxRequestBodySizeFeature.IsReadOnly)
+                _logger.FeatureNotFound();
-                {
+            }
-                    _logger.FeatureIsReadOnly();
+            else if (maxRequestBodySizeFeature.IsReadOnly)
-                }
+            {
-                else
+                _logger.FeatureIsReadOnly();
-                {
+            }
-                    maxRequestBodySizeFeature.MaxRequestBodySize = Bytes;
+            else
-                    _logger.MaxRequestBodySizeSet(Bytes.ToString());
+            {
-                }
+                maxRequestBodySizeFeature.MaxRequestBodySize = Bytes;
+                _logger.MaxRequestBodySizeSet(Bytes.ToString());
             }
         }
     }

src/Microsoft.AspNetCore.Mvc.Core/Internal/ResponseCacheFilter.cs

@@ -3,6 +3,7 @@
 
 using System;
 using Microsoft.AspNetCore.Mvc.Filters;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Mvc.Internal
 {
@@ -12,15 +13,18 @@ namespace Microsoft.AspNetCore.Mvc.Internal
     public class ResponseCacheFilter : IActionFilter, IResponseCacheFilter
     {
         private readonly ResponseCacheFilterExecutor _executor;
+        private readonly ILogger _logger;
 
         /// <summary>
         /// Creates a new instance of <see cref="ResponseCacheFilter"/>
         /// </summary>
         /// <param name="cacheProfile">The profile which contains the settings for
         /// <see cref="ResponseCacheFilter"/>.</param>
-        public ResponseCacheFilter(CacheProfile cacheProfile)
+        /// <param name="loggerFactory">The <see cref="ILoggerFactory"/>.</param>
+        public ResponseCacheFilter(CacheProfile cacheProfile, ILoggerFactory loggerFactory)
         {
             _executor = new ResponseCacheFilterExecutor(cacheProfile);
+            _logger = loggerFactory.CreateLogger(GetType());
         }
 
         /// <summary>
@@ -86,8 +90,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal
 
             // If there are more filters which can override the values written by this filter,
             // then skip execution of this filter.
-            if (!context.IsEffectivePolicy<IResponseCacheFilter>(this))
+            var effectivePolicy = context.FindEffectivePolicy<IResponseCacheFilter>();
+            if (effectivePolicy != null && effectivePolicy != this)
             {
+                _logger.NotMostEffectiveFilter(GetType(), effectivePolicy.GetType(), typeof(IResponseCacheFilter));
                 return;
             }
 

src/Microsoft.AspNetCore.Mvc.Core/ResponseCacheAttribute.cs

@@ -6,6 +6,7 @@ using Microsoft.AspNetCore.Mvc.Core;
 using Microsoft.AspNetCore.Mvc.Filters;
 using Microsoft.AspNetCore.Mvc.Internal;
 using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 
 namespace Microsoft.AspNetCore.Mvc
@@ -123,12 +124,13 @@ namespace Microsoft.AspNetCore.Mvc
                 throw new ArgumentNullException(nameof(serviceProvider));
             }
 
+            var loggerFactory = serviceProvider.GetRequiredService<ILoggerFactory>();
             var optionsAccessor = serviceProvider.GetRequiredService<IOptions<MvcOptions>>();
             var cacheProfile = GetCacheProfile(optionsAccessor.Value);
 
             // ResponseCacheFilter cannot take any null values. Hence, if there are any null values,
             // the properties convert them to their defaults and are passed on.
-            return new ResponseCacheFilter(cacheProfile);
+            return new ResponseCacheFilter(cacheProfile, loggerFactory);
         }
     }
 }

src/Microsoft.AspNetCore.Mvc.Cors/CorsAuthorizationFilter.cs

@@ -2,13 +2,12 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
-using System.Collections.Generic;
-using System.Linq;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Cors.Infrastructure;
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Mvc.Cors.Internal;
-using Microsoft.AspNetCore.Mvc.Filters;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Extensions.Primitives;
 
 namespace Microsoft.AspNetCore.Mvc.Cors
@@ -20,6 +19,7 @@ namespace Microsoft.AspNetCore.Mvc.Cors
     {
         private readonly ICorsService _corsService;
         private readonly ICorsPolicyProvider _corsPolicyProvider;
+        private readonly ILogger _logger;
 
         /// <summary>
         /// Creates a new instance of <see cref="CorsAuthorizationFilter"/>.
@@ -27,9 +27,39 @@ namespace Microsoft.AspNetCore.Mvc.Cors
         /// <param name="corsService">The <see cref="ICorsService"/>.</param>
         /// <param name="policyProvider">The <see cref="ICorsPolicyProvider"/>.</param>
         public CorsAuthorizationFilter(ICorsService corsService, ICorsPolicyProvider policyProvider)
+            : this(corsService, policyProvider, NullLoggerFactory.Instance)
         {
+        }
+
+        /// <summary>
+        /// Creates a new instance of <see cref="CorsAuthorizationFilter"/>.
+        /// </summary>
+        /// <param name="corsService">The <see cref="ICorsService"/>.</param>
+        /// <param name="policyProvider">The <see cref="ICorsPolicyProvider"/>.</param>
+        /// <param name="loggerFactory">The <see cref="ILoggerFactory"/>.</param>
+        public CorsAuthorizationFilter(
+            ICorsService corsService,
+            ICorsPolicyProvider policyProvider,
+            ILoggerFactory loggerFactory)
+        {
+            if (corsService == null)
+            {
+                throw new ArgumentNullException(nameof(corsService));
+            }
+
+            if (policyProvider == null)
+            {
+                throw new ArgumentNullException(nameof(policyProvider));
+            }
+
+            if (loggerFactory == null)
+            {
+                throw new ArgumentNullException(nameof(loggerFactory));
+            }
+
             _corsService = corsService;
             _corsPolicyProvider = policyProvider;
+            _logger = loggerFactory.CreateLogger(GetType());
         }
 
         /// <summary>
@@ -53,6 +83,7 @@ namespace Microsoft.AspNetCore.Mvc.Cors
             // If this filter is not closest to the action, it is not applicable.
             if (!context.IsEffectivePolicy<ICorsAuthorizationFilter>(this))
             {
+                _logger.NotMostEffectiveFilter(typeof(ICorsAuthorizationFilter));
                 return;
             }
 

src/Microsoft.AspNetCore.Mvc.Cors/Internal/CorsLoggerExtensions.cs

@@ -0,0 +1,26 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.AspNetCore.Mvc.Cors.Internal
+{
+    public static class CorsLoggerExtensions
+    {
+        private static readonly Action<ILogger, Type, Exception> _notMostEffectiveFilter;
+
+        static CorsLoggerExtensions()
+        {
+            _notMostEffectiveFilter = LoggerMessage.Define<Type>(
+               LogLevel.Debug,
+               1,
+               "Skipping the execution of current filter as its not the most effective filter implementing the policy {FilterPolicy}.");
+        }
+
+        public static void NotMostEffectiveFilter(this ILogger logger, Type policyType)
+        {
+            _notMostEffectiveFilter(logger, policyType, null);
+        }
+    }
+}

src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs

@@ -19,6 +19,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
         private static readonly Action<ILogger, string, string, Exception> _handlerMethodExecuted;
         private static readonly Action<ILogger, object, Exception> _pageFilterShortCircuit;
         private static readonly Action<ILogger, string, string[], Exception> _malformedPageDirective;
+        private static readonly Action<ILogger, Type, Exception> _notMostEffectiveFilter;
         private static readonly Action<ILogger, string, string, string, Exception> _beforeExecutingMethodOnFilter;
         private static readonly Action<ILogger, string, string, string, Exception> _afterExecutingMethodOnFilter;
 
@@ -46,6 +47,11 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
                 104,
                 "The page directive at '{FilePath}' is malformed. Please fix the following issues: {Diagnostics}");
 
+            _notMostEffectiveFilter = LoggerMessage.Define<Type>(
+               LogLevel.Debug,
+               1,
+               "Skipping the execution of current filter as its not the most effective filter implementing the policy {FilterPolicy}.");
+
             _beforeExecutingMethodOnFilter = LoggerMessage.Define<string, string, string>(
                 LogLevel.Trace,
                 1,
@@ -122,5 +128,10 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
                 _malformedPageDirective(logger, filePath, messages, null);
             }
         }
+
+        public static void NotMostEffectiveFilter(this ILogger logger, Type policyType)
+        {
+            _notMostEffectiveFilter(logger, policyType, null);
+        }
     }
 }

src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/ResponseCacheFilter.cs

@@ -4,6 +4,7 @@
 using System;
 using Microsoft.AspNetCore.Mvc.Filters;
 using Microsoft.AspNetCore.Mvc.Internal;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
 {
@@ -13,15 +14,18 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
     public class ResponseCacheFilter : IPageFilter, IResponseCacheFilter
     {
         private readonly ResponseCacheFilterExecutor _executor;
+        private readonly ILogger _logger;
 
         /// <summary>
         /// Creates a new instance of <see cref="ResponseCacheFilter"/>
         /// </summary>
         /// <param name="cacheProfile">The profile which contains the settings for
         /// <see cref="ResponseCacheFilter"/>.</param>
-        public ResponseCacheFilter(CacheProfile cacheProfile)
+        /// <param name="loggerFactory">The <see cref="ILoggerFactory"/>.</param>
+        public ResponseCacheFilter(CacheProfile cacheProfile, ILoggerFactory loggerFactory)
         {
             _executor = new ResponseCacheFilterExecutor(cacheProfile);
+            _logger = loggerFactory.CreateLogger(GetType());
         }
 
         /// <summary>
@@ -90,6 +94,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
 
             if (!context.IsEffectivePolicy<IResponseCacheFilter>(this))
             {
+                _logger.NotMostEffectiveFilter(typeof(IResponseCacheFilter));
                 return;
             }
 

src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/ResponseCacheFilterApplicationModelProvider.cs

@@ -4,6 +4,7 @@
 using System;
 using System.Linq;
 using Microsoft.AspNetCore.Mvc.ApplicationModels;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 
 namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
@@ -11,8 +12,9 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
     public class ResponseCacheFilterApplicationModelProvider : IPageApplicationModelProvider
     {
         private readonly MvcOptions _mvcOptions;
+        private readonly ILoggerFactory _loggerFactory;
 
-        public ResponseCacheFilterApplicationModelProvider(IOptions<MvcOptions> mvcOptionsAccessor)
+        public ResponseCacheFilterApplicationModelProvider(IOptions<MvcOptions> mvcOptionsAccessor, ILoggerFactory loggerFactory)
         {
             if (mvcOptionsAccessor == null)
             {
@@ -20,6 +22,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
             }
 
             _mvcOptions = mvcOptionsAccessor.Value;
+            _loggerFactory = loggerFactory ?? throw new ArgumentNullException(nameof(loggerFactory));
         }
 
         // The order is set to execute after the DefaultPageApplicationModelProvider.
@@ -37,7 +40,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
             foreach (var attribute in responseCacheAttributes)
             {
                 var cacheProfile = attribute.GetCacheProfile(_mvcOptions);
-                context.PageApplicationModel.Filters.Add(new ResponseCacheFilter(cacheProfile));
+                context.PageApplicationModel.Filters.Add(new ResponseCacheFilter(cacheProfile, _loggerFactory));
             }
         }
 

src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/MvcViewFeaturesLoggerExtensions.cs

@@ -34,6 +34,8 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal
         private static readonly Action<ILogger, string, Exception> _tempDataCookieLoadSuccess;
         private static readonly Action<ILogger, string, Exception> _tempDataCookieLoadFailure;
 
+        private static readonly Action<ILogger, Type, Exception> _notMostEffectiveFilter;
+
         static MvcViewFeaturesLoggerExtensions()
         {
             _viewComponentExecuting = LoggerMessage.Define<string, string[]>(
@@ -101,6 +103,11 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal
                 LogLevel.Warning,
                 3,
                 "The temp data cookie {CookieName} could not be loaded.");
+
+            _notMostEffectiveFilter = LoggerMessage.Define<Type>(
+                LogLevel.Trace,
+                1,
+                "Skipping the execution of current filter as its not the most effective filter implementing the policy {FilterPolicy}.");
         }
 
         public static IDisposable ViewComponentScope(this ILogger logger, ViewComponentContext context)
@@ -226,6 +233,11 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal
             _tempDataCookieLoadFailure(logger, cookieName, exception);
         }
 
+        public static void NotMostEffectiveFilter(this ILogger logger, Type policyType)
+        {
+            _notMostEffectiveFilter(logger, policyType, null);
+        }
+
         private class ViewComponentLogScope : IReadOnlyList<KeyValuePair<string, object>>
         {
             private readonly ViewComponentDescriptor _descriptor;

src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/ValidateAntiforgeryTokenAuthorizationFilter.cs

@@ -2,8 +2,6 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
-using System.Collections.Generic;
-using System.Diagnostics;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Antiforgery;
 using Microsoft.AspNetCore.Mvc.Filters;
@@ -24,7 +22,7 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal
             }
 
             _antiforgery = antiforgery;
-            _logger = loggerFactory.CreateLogger<ValidateAntiforgeryTokenAuthorizationFilter>();
+            _logger = loggerFactory.CreateLogger(GetType());
         }
 
         public async Task OnAuthorizationAsync(AuthorizationFilterContext context)
@@ -34,7 +32,13 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal
                 throw new ArgumentNullException(nameof(context));
             }
 
-            if (context.IsEffectivePolicy<IAntiforgeryPolicy>(this) && ShouldValidate(context))
+            if (!context.IsEffectivePolicy<IAntiforgeryPolicy>(this))
+            {
+                _logger.NotMostEffectiveFilter(typeof(IAntiforgeryPolicy));
+                return;
+            }
+
+            if (ShouldValidate(context))
             {
                 try
                 {

test/Microsoft.AspNetCore.Mvc.Core.Test/Formatters/FormatFilterTest.cs

@@ -9,6 +9,8 @@ using Microsoft.AspNetCore.Mvc.Filters;
 using Microsoft.AspNetCore.Mvc.ModelBinding;
 using Microsoft.AspNetCore.Mvc.TestCommon;
 using Microsoft.AspNetCore.Routing;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Extensions.Options;
 using Microsoft.Extensions.Primitives;
 using Microsoft.Net.Http.Headers;
@@ -43,7 +45,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
             var resultExecutingContext = mockObjects.CreateResultExecutingContext();
             var resourceExecutingContext = mockObjects.CreateResourceExecutingContext(new IFilterMetadata[] { });
 
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             filter.OnResourceExecuting(resourceExecutingContext);
@@ -92,7 +94,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
                 new IFilterMetadata[] { },
                 new List<IValueProviderFactory>());
 
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             filter.OnResourceExecuting(resourceExecutingContext);
@@ -124,7 +126,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
                 format,
                 MediaTypeHeaderValue.Parse(contentType));
 
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             filter.OnResourceExecuting(resourceExecutingContext);
@@ -147,7 +149,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
             var mockObjects = new MockObjects(format, place);
             var resourceExecutingContext = mockObjects.CreateResourceExecutingContext(new IFilterMetadata[] { });
 
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             filter.OnResourceExecuting(resourceExecutingContext);
@@ -164,7 +166,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
             var mockObjects = new MockObjects();
             var resourceExecutingContext = mockObjects.CreateResourceExecutingContext(new IFilterMetadata[] { });
 
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             filter.OnResourceExecuting(resourceExecutingContext);
@@ -186,7 +188,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
             var mockObjects = new MockObjects(format, place);
             var resourceExecutingContext = mockObjects.CreateResourceExecutingContext(new IFilterMetadata[] { produces });
 
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             filter.OnResourceExecuting(resourceExecutingContext);
@@ -207,7 +209,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
                 "xml",
                 MediaTypeHeaderValue.Parse("application/xml"));
 
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             filter.OnResourceExecuting(resourceExecutingContext);
@@ -228,7 +230,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
                 "xml",
                 MediaTypeHeaderValue.Parse("application/xml;version=1"));
 
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             filter.OnResourceExecuting(resourceExecutingContext);
@@ -254,7 +256,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
                 "xml",
                 MediaTypeHeaderValue.Parse("application/xml"));
 
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             filter.OnResourceExecuting(resourceExecutingContext);
@@ -273,7 +275,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
             // Arrange
             var mockObjects = new MockObjects(format, place);
             var resourceExecutingContext = mockObjects.CreateResourceExecutingContext(new IFilterMetadata[] { });
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             filter.OnResourceExecuting(resourceExecutingContext);
@@ -296,7 +298,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
             var mockObjects = new MockObjects(input, place);
             var context = mockObjects.CreateResultExecutingContext();
             var filterAttribute = new FormatFilterAttribute();
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             var format = filter.GetFormat(context);
@@ -328,7 +330,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
                 new IFilterMetadata[] { },
                 new List<IValueProviderFactory>());
 
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             filter.OnResourceExecuting(resourceExecutingContext);
@@ -363,7 +365,7 @@ namespace Microsoft.AspNetCore.Mvc.Formatters
                 new IFilterMetadata[] { },
                 new List<IValueProviderFactory>());
 
-            var filter = new FormatFilter(mockObjects.OptionsManager);
+            var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance);
 
             // Act
             filter.OnResourceExecuting(resourceExecutingContext);

test/Microsoft.AspNetCore.Mvc.Core.Test/ResponseCacheAttributeTest.cs

@@ -10,6 +10,7 @@ using Microsoft.AspNetCore.Mvc.Filters;
 using Microsoft.AspNetCore.Mvc.Internal;
 using Microsoft.AspNetCore.ResponseCaching;
 using Microsoft.AspNetCore.Routing;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using Microsoft.Extensions.Primitives;
 using Moq;
@@ -339,6 +340,9 @@ namespace Microsoft.AspNetCore.Mvc
             serviceProvider
                 .Setup(s => s.GetService(typeof(IOptions<MvcOptions>)))
                 .Returns(optionsAccessor);
+            serviceProvider
+                .Setup(s => s.GetService(typeof(ILoggerFactory)))
+                .Returns(Mock.Of<ILoggerFactory>());
 
             return serviceProvider.Object;
         }

test/Microsoft.AspNetCore.Mvc.Cors.Test/CorsAuthorizationFilterTest.cs

@@ -124,7 +124,7 @@ namespace Microsoft.AspNetCore.Mvc.Cors
                 .Setup(o => o.GetPolicyAsync(It.IsAny<HttpContext>(), It.IsAny<string>()))
                 .Returns(Task.FromResult(new CorsPolicy()));
 
-            return new CorsAuthorizationFilter(corsService, policyProvider.Object)
+            return new CorsAuthorizationFilter(corsService, policyProvider.Object, Mock.Of<ILoggerFactory>())
             {
                 PolicyName = string.Empty
             };

test/Microsoft.AspNetCore.Mvc.Cors.Test/Internal/CorsApplicationModelProviderTest.cs

@@ -2,15 +2,14 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
-using System.Linq;
-using System.Threading.Tasks;
 using System.Reflection;
+using System.Threading.Tasks;
 using Microsoft.AspNetCore.Cors;
 using Microsoft.AspNetCore.Cors.Infrastructure;
 using Microsoft.AspNetCore.Mvc.ApplicationModels;
-using Microsoft.AspNetCore.Mvc.Cors.Internal;
 using Microsoft.AspNetCore.Mvc.Filters;
 using Microsoft.AspNetCore.Mvc.Internal;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using Moq;
 using Xunit;
@@ -157,7 +156,8 @@ namespace Microsoft.AspNetCore.Mvc.Cors.Internal
             var defaultProvider = new DefaultApplicationModelProvider(Options.Create(new MvcOptions()));
 
             var context = new ApplicationModelProviderContext(new[] { typeof(RegularController).GetTypeInfo() });
-            context.Result.Filters.Add(new CorsAuthorizationFilter(Mock.Of<ICorsService>(), Mock.Of<ICorsPolicyProvider>()));
+            context.Result.Filters.Add(
+                new CorsAuthorizationFilter(Mock.Of<ICorsService>(), Mock.Of<ICorsPolicyProvider>(), Mock.Of<ILoggerFactory>()));
             defaultProvider.OnProvidersExecuting(context);
 
             // Act

test/Microsoft.AspNetCore.Mvc.RazorPages.Test/Internal/ResponseCacheFilterApplicationModelProviderTest.cs

@@ -6,7 +6,9 @@ using System.Reflection;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Authorization;
 using Microsoft.AspNetCore.Mvc.ApplicationModels;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
+using Moq;
 using Xunit;
 
 namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
@@ -18,7 +20,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
         {
             // Arrange
             var options = Options.Create(new MvcOptions());
-            var provider = new ResponseCacheFilterApplicationModelProvider(options);
+            var provider = new ResponseCacheFilterApplicationModelProvider(options, Mock.Of<ILoggerFactory>());
             var typeInfo = typeof(PageWithoutResponseCache).GetTypeInfo();
             var context = GetApplicationProviderContext(typeInfo);
 
@@ -51,7 +53,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
         {
             // Arrange
             var options = Options.Create(new MvcOptions());
-            var provider = new ResponseCacheFilterApplicationModelProvider(options);
+            var provider = new ResponseCacheFilterApplicationModelProvider(options, Mock.Of<ILoggerFactory>());
             var typeInfo = typeof(PageWithResponseCache).GetTypeInfo();
             var context = GetApplicationProviderContext(typeInfo);
 
@@ -97,7 +99,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
                 Duration = 14,
                 VaryByQueryKeys = new[] { "A" },
             });
-            var provider = new ResponseCacheFilterApplicationModelProvider(options);
+            var provider = new ResponseCacheFilterApplicationModelProvider(options, Mock.Of<ILoggerFactory>());
             var typeInfo = typeof(PageWithResponseCacheProfile).GetTypeInfo();
             var context = GetApplicationProviderContext(typeInfo);