From c8cabde1f16980e8596f31b697786b049bd9d997 Mon Sep 17 00:00:00 2001 From: Kiran Challa Date: Fri, 8 Dec 2017 11:17:02 -0800 Subject: [PATCH] Improve logging - individual filters --- .../Formatters/FormatFilter.cs | 51 +++++++++++++--- .../Internal/DisableRequestSizeLimitFilter.cs | 36 +++++------ .../Internal/MvcCoreLoggerExtensions.cs | 59 +++++++++++++++++++ .../Internal/RequestFormLimitsFilter.cs | 32 +++++----- .../Internal/RequestSizeLimitFilter.cs | 36 +++++------ .../Internal/ResponseCacheFilter.cs | 10 +++- .../ResponseCacheAttribute.cs | 4 +- .../CorsAuthorizationFilter.cs | 37 +++++++++++- .../Internal/CorsLoggerExtensions.cs | 26 ++++++++ .../Internal/PageLoggerExtensions.cs | 11 ++++ .../Internal/ResponseCacheFilter.cs | 7 ++- ...onseCacheFilterApplicationModelProvider.cs | 7 ++- .../MvcViewFeaturesLoggerExtensions.cs | 12 ++++ ...dateAntiforgeryTokenAuthorizationFilter.cs | 12 ++-- .../Formatters/FormatFilterTest.cs | 28 +++++---- .../ResponseCacheAttributeTest.cs | 4 ++ .../CorsAuthorizationFilterTest.cs | 2 +- .../CorsApplicationModelProviderTest.cs | 8 +-- ...CacheFilterApplicationModelProviderTest.cs | 8 ++- 19 files changed, 298 insertions(+), 92 deletions(-) create mode 100644 src/Microsoft.AspNetCore.Mvc.Cors/Internal/CorsLoggerExtensions.cs diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Formatters/FormatFilter.cs b/src/Microsoft.AspNetCore.Mvc.Core/Formatters/FormatFilter.cs index 995a7ae60c..dd7b568fce 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Formatters/FormatFilter.cs +++ b/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; /// /// Initializes an instance of . /// /// The + [Obsolete("This constructor is obsolete and will be removed in a future version.")] public FormatFilter(IOptions options) + : this(options, NullLoggerFactory.Instance) { + } + + /// + /// Initializes an instance of . + /// + /// The + /// The . + public FormatFilter(IOptions 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()); } /// @@ -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 - // request's format and IApiResponseMetadataProvider-provided content types similarly to an Accept - // 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)) - { - context.Result = new NotFoundResult(); - } + _logger.ActionDoesNotExplicitlySpecifyContentTypes(); + return; + } + + // 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 + // 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; } diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/DisableRequestSizeLimitFilter.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/DisableRequestSizeLimitFilter.cs index 09a68a3b8b..51595bbaa6 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/DisableRequestSizeLimitFilter.cs +++ b/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(this)) + var effectivePolicy = context.FindEffectivePolicy(); + if (effectivePolicy != null && effectivePolicy != this) { - var maxRequestBodySizeFeature = context.HttpContext.Features.Get(); + _logger.NotMostEffectiveFilter(GetType(), effectivePolicy.GetType(), typeof(IRequestSizePolicy)); + return; + } - if (maxRequestBodySizeFeature == null) - { - _logger.FeatureNotFound(); - } - else if (maxRequestBodySizeFeature.IsReadOnly) - { - _logger.FeatureIsReadOnly(); - } - else - { - maxRequestBodySizeFeature.MaxRequestBodySize = null; - _logger.RequestBodySizeLimitDisabled(); - } + var maxRequestBodySizeFeature = context.HttpContext.Features.Get(); + + if (maxRequestBodySizeFeature == null) + { + _logger.FeatureNotFound(); + } + else if (maxRequestBodySizeFeature.IsReadOnly) + { + _logger.FeatureIsReadOnly(); + } + else + { + maxRequestBodySizeFeature.MaxRequestBodySize = null; + _logger.RequestBodySizeLimitDisabled(); } } } diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs index c1a297f133..c20e14f764 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs @@ -96,6 +96,12 @@ namespace Microsoft.AspNetCore.Mvc.Internal private static readonly Action _inferredParameterSource; private static readonly Action _unableToInferParameterSources; + private static readonly Action _unsupportedFormatFilterContentType; + private static readonly Action _actionDoesNotSupportFormatFilterContentType; + private static readonly Action _cannotApplyFormatFilterContentType; + private static readonly Action _actionDoesNotExplicitlySpecifyContentTypes; + private static readonly Action _notMostEffectiveFilter; + static MvcCoreLoggerExtensions() { _actionExecuting = LoggerMessage.Define( @@ -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( + LogLevel.Debug, + 1, + "Could not find a media type for the format '{FormatFilterContentType}'."); + + _actionDoesNotSupportFormatFilterContentType = LoggerMessage.Define( + LogLevel.Debug, + 2, + "Current action does not support the content type '{FormatFilterContentType}'. The supported content types are '{SupportedMediaTypes}'."); + + _cannotApplyFormatFilterContentType = LoggerMessage.Define( + LogLevel.Debug, + 3, + "Cannot apply content type '{FormatFilterContentType}' to the response as current action had explicitly set a preferred content type."); + + _notMostEffectiveFilter = LoggerMessage.Define( + 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( diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/RequestFormLimitsFilter.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/RequestFormLimitsFilter.cs index 62c31d53af..c60e7e2ea2 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/RequestFormLimitsFilter.cs +++ b/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(this)) + var effectivePolicy = context.FindEffectivePolicy(); + if (effectivePolicy != null && effectivePolicy != this) { - var features = context.HttpContext.Features; - var formFeature = features.Get(); + _logger.NotMostEffectiveFilter(GetType(), effectivePolicy.GetType(), typeof(IRequestFormLimitsPolicy)); + return; + } - if (formFeature == null || formFeature.Form == null) - { - // Request form has not been read yet, so set the limits - features.Set(new FormFeature(context.HttpContext.Request, FormOptions)); - _logger.AppliedRequestFormLimits(); - } - else - { - _logger.CannotApplyRequestFormLimits(); - } + var features = context.HttpContext.Features; + var formFeature = features.Get(); + + if (formFeature == null || formFeature.Form == null) + { + // Request form has not been read yet, so set the limits + features.Set(new FormFeature(context.HttpContext.Request, FormOptions)); + _logger.AppliedRequestFormLimits(); + } + else + { + _logger.CannotApplyRequestFormLimits(); } } } diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/RequestSizeLimitFilter.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/RequestSizeLimitFilter.cs index 3b63566e91..c5653f99a5 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/RequestSizeLimitFilter.cs +++ b/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(this)) + var effectivePolicy = context.FindEffectivePolicy(); + if (effectivePolicy != null && effectivePolicy != this) { - var maxRequestBodySizeFeature = context.HttpContext.Features.Get(); + _logger.NotMostEffectiveFilter(GetType(), effectivePolicy.GetType(), typeof(IRequestSizePolicy)); + return; + } - if (maxRequestBodySizeFeature == null) - { - _logger.FeatureNotFound(); - } - else if (maxRequestBodySizeFeature.IsReadOnly) - { - _logger.FeatureIsReadOnly(); - } - else - { - maxRequestBodySizeFeature.MaxRequestBodySize = Bytes; - _logger.MaxRequestBodySizeSet(Bytes.ToString()); - } + var maxRequestBodySizeFeature = context.HttpContext.Features.Get(); + + if (maxRequestBodySizeFeature == null) + { + _logger.FeatureNotFound(); + } + else if (maxRequestBodySizeFeature.IsReadOnly) + { + _logger.FeatureIsReadOnly(); + } + else + { + maxRequestBodySizeFeature.MaxRequestBodySize = Bytes; + _logger.MaxRequestBodySizeSet(Bytes.ToString()); } } } diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/ResponseCacheFilter.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/ResponseCacheFilter.cs index 6ca409f601..55d63fc975 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/ResponseCacheFilter.cs +++ b/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; /// /// Creates a new instance of /// /// The profile which contains the settings for /// . - public ResponseCacheFilter(CacheProfile cacheProfile) + /// The . + public ResponseCacheFilter(CacheProfile cacheProfile, ILoggerFactory loggerFactory) { _executor = new ResponseCacheFilterExecutor(cacheProfile); + _logger = loggerFactory.CreateLogger(GetType()); } /// @@ -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(this)) + var effectivePolicy = context.FindEffectivePolicy(); + if (effectivePolicy != null && effectivePolicy != this) { + _logger.NotMostEffectiveFilter(GetType(), effectivePolicy.GetType(), typeof(IResponseCacheFilter)); return; } diff --git a/src/Microsoft.AspNetCore.Mvc.Core/ResponseCacheAttribute.cs b/src/Microsoft.AspNetCore.Mvc.Core/ResponseCacheAttribute.cs index e72747a326..a3e2d6aaf4 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/ResponseCacheAttribute.cs +++ b/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(); var optionsAccessor = serviceProvider.GetRequiredService>(); 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); } } } diff --git a/src/Microsoft.AspNetCore.Mvc.Cors/CorsAuthorizationFilter.cs b/src/Microsoft.AspNetCore.Mvc.Cors/CorsAuthorizationFilter.cs index 87f23963d1..0d853eae9d 100644 --- a/src/Microsoft.AspNetCore.Mvc.Cors/CorsAuthorizationFilter.cs +++ b/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; /// /// Creates a new instance of . @@ -27,9 +27,39 @@ namespace Microsoft.AspNetCore.Mvc.Cors /// The . /// The . public CorsAuthorizationFilter(ICorsService corsService, ICorsPolicyProvider policyProvider) + : this(corsService, policyProvider, NullLoggerFactory.Instance) { + } + + /// + /// Creates a new instance of . + /// + /// The . + /// The . + /// The . + 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()); } /// @@ -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(this)) { + _logger.NotMostEffectiveFilter(typeof(ICorsAuthorizationFilter)); return; } diff --git a/src/Microsoft.AspNetCore.Mvc.Cors/Internal/CorsLoggerExtensions.cs b/src/Microsoft.AspNetCore.Mvc.Cors/Internal/CorsLoggerExtensions.cs new file mode 100644 index 0000000000..c3fab172b9 --- /dev/null +++ b/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 _notMostEffectiveFilter; + + static CorsLoggerExtensions() + { + _notMostEffectiveFilter = LoggerMessage.Define( + 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); + } + } +} diff --git a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs b/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs index a3eeedbd32..7a88fcd71d 100644 --- a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs @@ -19,6 +19,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal private static readonly Action _handlerMethodExecuted; private static readonly Action _pageFilterShortCircuit; private static readonly Action _malformedPageDirective; + private static readonly Action _notMostEffectiveFilter; private static readonly Action _beforeExecutingMethodOnFilter; private static readonly Action _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( + LogLevel.Debug, + 1, + "Skipping the execution of current filter as its not the most effective filter implementing the policy {FilterPolicy}."); + _beforeExecutingMethodOnFilter = LoggerMessage.Define( 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); + } } } diff --git a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/ResponseCacheFilter.cs b/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/ResponseCacheFilter.cs index dbf177051e..6fde160028 100644 --- a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/ResponseCacheFilter.cs +++ b/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; /// /// Creates a new instance of /// /// The profile which contains the settings for /// . - public ResponseCacheFilter(CacheProfile cacheProfile) + /// The . + public ResponseCacheFilter(CacheProfile cacheProfile, ILoggerFactory loggerFactory) { _executor = new ResponseCacheFilterExecutor(cacheProfile); + _logger = loggerFactory.CreateLogger(GetType()); } /// @@ -90,6 +94,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal if (!context.IsEffectivePolicy(this)) { + _logger.NotMostEffectiveFilter(typeof(IResponseCacheFilter)); return; } diff --git a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/ResponseCacheFilterApplicationModelProvider.cs b/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/ResponseCacheFilterApplicationModelProvider.cs index 5abfc77f1e..27a8a7cb9b 100644 --- a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/ResponseCacheFilterApplicationModelProvider.cs +++ b/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 mvcOptionsAccessor) + public ResponseCacheFilterApplicationModelProvider(IOptions 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)); } } diff --git a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/MvcViewFeaturesLoggerExtensions.cs b/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/MvcViewFeaturesLoggerExtensions.cs index 2f0145a466..7d4f11c24e 100644 --- a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/MvcViewFeaturesLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/MvcViewFeaturesLoggerExtensions.cs @@ -34,6 +34,8 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal private static readonly Action _tempDataCookieLoadSuccess; private static readonly Action _tempDataCookieLoadFailure; + private static readonly Action _notMostEffectiveFilter; + static MvcViewFeaturesLoggerExtensions() { _viewComponentExecuting = LoggerMessage.Define( @@ -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( + 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> { private readonly ViewComponentDescriptor _descriptor; diff --git a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/ValidateAntiforgeryTokenAuthorizationFilter.cs b/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/ValidateAntiforgeryTokenAuthorizationFilter.cs index aa34b96012..7225eb76c1 100644 --- a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/ValidateAntiforgeryTokenAuthorizationFilter.cs +++ b/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(); + _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(this) && ShouldValidate(context)) + if (!context.IsEffectivePolicy(this)) + { + _logger.NotMostEffectiveFilter(typeof(IAntiforgeryPolicy)); + return; + } + + if (ShouldValidate(context)) { try { diff --git a/test/Microsoft.AspNetCore.Mvc.Core.Test/Formatters/FormatFilterTest.cs b/test/Microsoft.AspNetCore.Mvc.Core.Test/Formatters/FormatFilterTest.cs index 3d39437a25..b33698b52a 100644 --- a/test/Microsoft.AspNetCore.Mvc.Core.Test/Formatters/FormatFilterTest.cs +++ b/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()); - 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()); - 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()); - var filter = new FormatFilter(mockObjects.OptionsManager); + var filter = new FormatFilter(mockObjects.OptionsManager, NullLoggerFactory.Instance); // Act filter.OnResourceExecuting(resourceExecutingContext); diff --git a/test/Microsoft.AspNetCore.Mvc.Core.Test/ResponseCacheAttributeTest.cs b/test/Microsoft.AspNetCore.Mvc.Core.Test/ResponseCacheAttributeTest.cs index aa048c19f7..c8d3921444 100644 --- a/test/Microsoft.AspNetCore.Mvc.Core.Test/ResponseCacheAttributeTest.cs +++ b/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))) .Returns(optionsAccessor); + serviceProvider + .Setup(s => s.GetService(typeof(ILoggerFactory))) + .Returns(Mock.Of()); return serviceProvider.Object; } diff --git a/test/Microsoft.AspNetCore.Mvc.Cors.Test/CorsAuthorizationFilterTest.cs b/test/Microsoft.AspNetCore.Mvc.Cors.Test/CorsAuthorizationFilterTest.cs index ea94fad440..9bcefed3af 100644 --- a/test/Microsoft.AspNetCore.Mvc.Cors.Test/CorsAuthorizationFilterTest.cs +++ b/test/Microsoft.AspNetCore.Mvc.Cors.Test/CorsAuthorizationFilterTest.cs @@ -124,7 +124,7 @@ namespace Microsoft.AspNetCore.Mvc.Cors .Setup(o => o.GetPolicyAsync(It.IsAny(), It.IsAny())) .Returns(Task.FromResult(new CorsPolicy())); - return new CorsAuthorizationFilter(corsService, policyProvider.Object) + return new CorsAuthorizationFilter(corsService, policyProvider.Object, Mock.Of()) { PolicyName = string.Empty }; diff --git a/test/Microsoft.AspNetCore.Mvc.Cors.Test/Internal/CorsApplicationModelProviderTest.cs b/test/Microsoft.AspNetCore.Mvc.Cors.Test/Internal/CorsApplicationModelProviderTest.cs index ffe3d48149..fb3eecb51a 100644 --- a/test/Microsoft.AspNetCore.Mvc.Cors.Test/Internal/CorsApplicationModelProviderTest.cs +++ b/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(), Mock.Of())); + context.Result.Filters.Add( + new CorsAuthorizationFilter(Mock.Of(), Mock.Of(), Mock.Of())); defaultProvider.OnProvidersExecuting(context); // Act diff --git a/test/Microsoft.AspNetCore.Mvc.RazorPages.Test/Internal/ResponseCacheFilterApplicationModelProviderTest.cs b/test/Microsoft.AspNetCore.Mvc.RazorPages.Test/Internal/ResponseCacheFilterApplicationModelProviderTest.cs index 8b782173ce..f2ccc1ad94 100644 --- a/test/Microsoft.AspNetCore.Mvc.RazorPages.Test/Internal/ResponseCacheFilterApplicationModelProviderTest.cs +++ b/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()); 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()); 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()); var typeInfo = typeof(PageWithResponseCacheProfile).GetTypeInfo(); var context = GetApplicationProviderContext(typeInfo);