diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/ControllerActionInvoker.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/ControllerActionInvoker.cs index bb01965a79..3dd9a5c339 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/ControllerActionInvoker.cs +++ b/src/Microsoft.AspNetCore.Mvc.Core/Internal/ControllerActionInvoker.cs @@ -115,6 +115,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal var actionExecutingContext = _actionExecutingContext; _diagnosticSource.BeforeOnActionExecution(actionExecutingContext, filter); + _logger.BeforeExecutingMethodOnFilter( + MvcCoreLoggerExtensions.ActionFilter, + nameof(IAsyncActionFilter.OnActionExecutionAsync), + filter); var task = filter.OnActionExecutionAsync(actionExecutingContext, InvokeNextActionFilterAwaitedAsync); if (task.Status != TaskStatus.RanToCompletion) @@ -149,6 +153,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal } _diagnosticSource.AfterOnActionExecution(_actionExecutedContext, filter); + _logger.AfterExecutingMethodOnFilter( + MvcCoreLoggerExtensions.ActionFilter, + nameof(IAsyncActionFilter.OnActionExecutionAsync), + filter); goto case State.ActionEnd; } @@ -162,10 +170,18 @@ namespace Microsoft.AspNetCore.Mvc.Internal var actionExecutingContext = _actionExecutingContext; _diagnosticSource.BeforeOnActionExecuting(actionExecutingContext, filter); + _logger.BeforeExecutingMethodOnFilter( + MvcCoreLoggerExtensions.ActionFilter, + nameof(IActionFilter.OnActionExecuting), + filter); filter.OnActionExecuting(actionExecutingContext); _diagnosticSource.AfterOnActionExecuting(actionExecutingContext, filter); + _logger.AfterExecutingMethodOnFilter( + MvcCoreLoggerExtensions.ActionFilter, + nameof(IActionFilter.OnActionExecuting), + filter); if (actionExecutingContext.Result != null) { @@ -204,10 +220,18 @@ namespace Microsoft.AspNetCore.Mvc.Internal var actionExecutedContext = _actionExecutedContext; _diagnosticSource.BeforeOnActionExecuted(actionExecutedContext, filter); + _logger.BeforeExecutingMethodOnFilter( + MvcCoreLoggerExtensions.ActionFilter, + nameof(IActionFilter.OnActionExecuted), + filter); filter.OnActionExecuted(actionExecutedContext); _diagnosticSource.AfterOnActionExecuted(actionExecutedContext, filter); + _logger.AfterExecutingMethodOnFilter( + MvcCoreLoggerExtensions.ActionFilter, + nameof(IActionFilter.OnActionExecuted), + filter); goto case State.ActionEnd; } diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs index 7027dd64e5..c1a297f133 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs @@ -21,6 +21,9 @@ namespace Microsoft.AspNetCore.Mvc.Internal { internal static class MvcCoreLoggerExtensions { + public const string ActionFilter = "Action Filter"; + private static readonly string[] _noFilters = new[] { "None" }; + private static readonly double TimestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency; private static readonly Action _actionExecuting; @@ -33,6 +36,12 @@ namespace Microsoft.AspNetCore.Mvc.Internal private static readonly Action _actionMethodExecuting; private static readonly Action _actionMethodExecuted; + private static readonly Action _logFilterExecutionPlan; + private static readonly Action _beforeExecutingMethodOnFilter; + private static readonly Action _afterExecutingMethodOnFilter; + private static readonly Action _beforeExecutingActionResult; + private static readonly Action _afterExecutingActionResult; + private static readonly Action _ambiguousActions; private static readonly Action _constraintMismatch; @@ -119,6 +128,31 @@ namespace Microsoft.AspNetCore.Mvc.Internal 2, "Executed action method {ActionName}, returned result {ActionResult}."); + _logFilterExecutionPlan = LoggerMessage.Define( + LogLevel.Debug, + 1, + "Execution plan of {FilterType} filters (in the following order): {Filters}"); + + _beforeExecutingMethodOnFilter = LoggerMessage.Define( + LogLevel.Trace, + 2, + "{FilterType}: Before executing {Method} on filter {Filter}."); + + _afterExecutingMethodOnFilter = LoggerMessage.Define( + LogLevel.Trace, + 3, + "{FilterType}: After executing {Method} on filter {Filter}."); + + _beforeExecutingActionResult = LoggerMessage.Define( + LogLevel.Trace, + 4, + "Before executing action result {ActionResult}."); + + _afterExecutingActionResult = LoggerMessage.Define( + LogLevel.Trace, + 5, + "After executing action result {ActionResult}."); + _ambiguousActions = LoggerMessage.Define( LogLevel.Error, 1, @@ -315,6 +349,79 @@ namespace Microsoft.AspNetCore.Mvc.Internal _actionExecuting(logger, action.DisplayName, null); } + public static void AuthorizationFiltersExecutionPlan(this ILogger logger, IEnumerable filters) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + var authorizationFilters = filters.Where(f => f is IAuthorizationFilter || f is IAsyncAuthorizationFilter); + LogFilterExecutionPlan(logger, "authorization", authorizationFilters); + } + + public static void ResourceFiltersExecutionPlan(this ILogger logger, IEnumerable filters) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + var resourceFilters = filters.Where(f => f is IResourceFilter || f is IAsyncResourceFilter); + LogFilterExecutionPlan(logger, "resource", resourceFilters); + } + + public static void ActionFiltersExecutionPlan(this ILogger logger, IEnumerable filters) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + var actionFilters = filters.Where(f => f is IActionFilter || f is IAsyncActionFilter); + LogFilterExecutionPlan(logger, "action", actionFilters); + } + + public static void ExceptionFiltersExecutionPlan(this ILogger logger, IEnumerable filters) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + var exceptionFilters = filters.Where(f => f is IExceptionFilter || f is IAsyncExceptionFilter); + LogFilterExecutionPlan(logger, "exception", exceptionFilters); + } + + public static void ResultFiltersExecutionPlan(this ILogger logger, IEnumerable filters) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + var resultFilters = filters.Where(f => f is IResultFilter || f is IAsyncResultFilter); + LogFilterExecutionPlan(logger, "result", resultFilters); + } + + public static void BeforeExecutingMethodOnFilter( + this ILogger logger, + string filterType, + string methodName, + IFilterMetadata filter) + { + _beforeExecutingMethodOnFilter(logger, filterType, methodName, filter.GetType(), null); + } + + public static void AfterExecutingMethodOnFilter( + this ILogger logger, + string filterType, + string methodName, + IFilterMetadata filter) + { + _afterExecutingMethodOnFilter(logger, filterType, methodName, filter.GetType(), null); + } + public static void ExecutedAction(this ILogger logger, ActionDescriptor action, long startTimestamp) { // Don't log if logging wasn't enabled at start of request as time will be wildly wrong. @@ -358,6 +465,16 @@ namespace Microsoft.AspNetCore.Mvc.Internal _contentResultExecuting(logger, contentType, null); } + public static void BeforeExecutingActionResult(this ILogger logger, IActionResult actionResult) + { + _beforeExecutingActionResult(logger, actionResult.GetType(), null); + } + + public static void AfterExecutingActionResult(this ILogger logger, IActionResult actionResult) + { + _afterExecutingActionResult(logger, actionResult.GetType(), null); + } + public static void ActionMethodExecuting(this ILogger logger, ControllerContext context, object[] arguments) { if (logger.IsEnabled(LogLevel.Information)) @@ -636,6 +753,37 @@ namespace Microsoft.AspNetCore.Mvc.Internal } } + private static void LogFilterExecutionPlan( + ILogger logger, + string filterType, + IEnumerable filters) + { + var filterList = _noFilters; + if (filters.Any()) + { + filterList = GetFilterList(filters); + } + + _logFilterExecutionPlan(logger, filterType, filterList, null); + } + + private static string[] GetFilterList(IEnumerable filters) + { + var filterList = new List(); + foreach (var filter in filters) + { + if (filter is IOrderedFilter orderedFilter) + { + filterList.Add($"{filter.GetType()} (Order: {orderedFilter.Order})"); + } + else + { + filterList.Add(filter.GetType().ToString()); + } + } + return filterList.ToArray(); + } + private class ActionLogScope : IReadOnlyList> { private readonly ActionDescriptor _action; diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/ResourceInvoker.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/ResourceInvoker.cs index 83cec5e6bf..c8b26c0009 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/ResourceInvoker.cs +++ b/src/Microsoft.AspNetCore.Mvc.Core/Internal/ResourceInvoker.cs @@ -89,6 +89,12 @@ namespace Microsoft.AspNetCore.Mvc.Internal { _logger.ExecutingAction(_actionContext.ActionDescriptor); + _logger.AuthorizationFiltersExecutionPlan(_filters); + _logger.ResourceFiltersExecutionPlan(_filters); + _logger.ActionFiltersExecutionPlan(_filters); + _logger.ExceptionFiltersExecutionPlan(_filters); + _logger.ResultFiltersExecutionPlan(_filters); + var startTimestamp = _logger.IsEnabled(LogLevel.Information) ? Stopwatch.GetTimestamp() : 0; try @@ -146,6 +152,7 @@ namespace Microsoft.AspNetCore.Mvc.Internal var actionContext = _actionContext; _diagnosticSource.BeforeActionResult(actionContext, result); + _logger.BeforeExecutingActionResult(result); try { @@ -154,6 +161,7 @@ namespace Microsoft.AspNetCore.Mvc.Internal finally { _diagnosticSource.AfterActionResult(actionContext, result); + _logger.AfterExecutingActionResult(result); } } @@ -210,6 +218,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal var authorizationContext = _authorizationContext; _diagnosticSource.BeforeOnAuthorizationAsync(authorizationContext, filter); + _logger.BeforeExecutingMethodOnFilter( + FilterTypeConstants.AuthorizationFilter, + nameof(IAsyncAuthorizationFilter.OnAuthorizationAsync), + filter); var task = filter.OnAuthorizationAsync(authorizationContext); if (task.Status != TaskStatus.RanToCompletion) @@ -230,6 +242,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal var authorizationContext = _authorizationContext; _diagnosticSource.AfterOnAuthorizationAsync(authorizationContext, filter); + _logger.AfterExecutingMethodOnFilter( + FilterTypeConstants.AuthorizationFilter, + nameof(IAsyncAuthorizationFilter.OnAuthorizationAsync), + filter); if (authorizationContext.Result != null) { @@ -248,10 +264,18 @@ namespace Microsoft.AspNetCore.Mvc.Internal var authorizationContext = _authorizationContext; _diagnosticSource.BeforeOnAuthorization(authorizationContext, filter); + _logger.BeforeExecutingMethodOnFilter( + FilterTypeConstants.AuthorizationFilter, + nameof(IAuthorizationFilter.OnAuthorization), + filter); filter.OnAuthorization(authorizationContext); _diagnosticSource.AfterOnAuthorization(authorizationContext, filter); + _logger.AfterExecutingMethodOnFilter( + FilterTypeConstants.AuthorizationFilter, + nameof(IAuthorizationFilter.OnAuthorization), + filter); if (authorizationContext.Result != null) { @@ -330,6 +354,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal var resourceExecutingContext = _resourceExecutingContext; _diagnosticSource.BeforeOnResourceExecution(resourceExecutingContext, filter); + _logger.BeforeExecutingMethodOnFilter( + FilterTypeConstants.ResourceFilter, + nameof(IAsyncResourceFilter.OnResourceExecutionAsync), + filter); var task = filter.OnResourceExecutionAsync(resourceExecutingContext, InvokeNextResourceFilterAwaitedAsync); if (task.Status != TaskStatus.RanToCompletion) @@ -357,6 +385,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal }; _diagnosticSource.AfterOnResourceExecution(_resourceExecutedContext, filter); + _logger.AfterExecutingMethodOnFilter( + FilterTypeConstants.ResourceFilter, + nameof(IAsyncResourceFilter.OnResourceExecutionAsync), + filter); // A filter could complete a Task without setting a result if (_resourceExecutingContext.Result != null) @@ -377,10 +409,18 @@ namespace Microsoft.AspNetCore.Mvc.Internal var resourceExecutingContext = _resourceExecutingContext; _diagnosticSource.BeforeOnResourceExecuting(resourceExecutingContext, filter); + _logger.BeforeExecutingMethodOnFilter( + FilterTypeConstants.ResourceFilter, + nameof(IResourceFilter.OnResourceExecuting), + filter); filter.OnResourceExecuting(resourceExecutingContext); _diagnosticSource.AfterOnResourceExecuting(resourceExecutingContext, filter); + _logger.AfterExecutingMethodOnFilter( + FilterTypeConstants.ResourceFilter, + nameof(IResourceFilter.OnResourceExecuting), + filter); if (resourceExecutingContext.Result != null) { @@ -413,10 +453,18 @@ namespace Microsoft.AspNetCore.Mvc.Internal var resourceExecutedContext = _resourceExecutedContext; _diagnosticSource.BeforeOnResourceExecuted(resourceExecutedContext, filter); + _logger.BeforeExecutingMethodOnFilter( + FilterTypeConstants.ResourceFilter, + nameof(IResourceFilter.OnResourceExecuted), + filter); filter.OnResourceExecuted(resourceExecutedContext); _diagnosticSource.AfterOnResourceExecuted(resourceExecutedContext, filter); + _logger.AfterExecutingMethodOnFilter( + FilterTypeConstants.ResourceFilter, + nameof(IResourceFilter.OnResourceExecuted), + filter); goto case State.ResourceEnd; } @@ -440,9 +488,9 @@ namespace Microsoft.AspNetCore.Mvc.Internal } case State.ResourceInside: - { - goto case State.ExceptionBegin; - } + { + goto case State.ExceptionBegin; + } case State.ExceptionBegin: { @@ -500,6 +548,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal if (exceptionContext?.Exception != null && !exceptionContext.ExceptionHandled) { _diagnosticSource.BeforeOnExceptionAsync(exceptionContext, filter); + _logger.BeforeExecutingMethodOnFilter( + FilterTypeConstants.ExceptionFilter, + nameof(IAsyncExceptionFilter.OnExceptionAsync), + filter); var task = filter.OnExceptionAsync(exceptionContext); if (task.Status != TaskStatus.RanToCompletion) @@ -523,6 +575,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal var exceptionContext = _exceptionContext; _diagnosticSource.AfterOnExceptionAsync(exceptionContext, filter); + _logger.AfterExecutingMethodOnFilter( + FilterTypeConstants.ExceptionFilter, + nameof(IAsyncExceptionFilter.OnExceptionAsync), + filter); if (exceptionContext.Exception == null || exceptionContext.ExceptionHandled) { @@ -559,10 +615,18 @@ namespace Microsoft.AspNetCore.Mvc.Internal if (exceptionContext?.Exception != null && !exceptionContext.ExceptionHandled) { _diagnosticSource.BeforeOnException(exceptionContext, filter); + _logger.BeforeExecutingMethodOnFilter( + FilterTypeConstants.ExceptionFilter, + nameof(IExceptionFilter.OnException), + filter); filter.OnException(exceptionContext); _diagnosticSource.AfterOnException(exceptionContext, filter); + _logger.AfterExecutingMethodOnFilter( + FilterTypeConstants.ExceptionFilter, + nameof(IExceptionFilter.OnException), + filter); if (exceptionContext.Exception == null || exceptionContext.ExceptionHandled) { @@ -710,6 +774,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal var resultExecutingContext = _resultExecutingContext; _diagnosticSource.BeforeOnResultExecution(resultExecutingContext, filter); + _logger.BeforeExecutingMethodOnFilter( + FilterTypeConstants.ResultFilter, + nameof(IAsyncResultFilter.OnResultExecutionAsync), + filter); var task = filter.OnResultExecutionAsync(resultExecutingContext, InvokeNextResultFilterAwaitedAsync); if (task.Status != TaskStatus.RanToCompletion) @@ -746,6 +814,11 @@ namespace Microsoft.AspNetCore.Mvc.Internal } _diagnosticSource.AfterOnResultExecution(_resultExecutedContext, filter); + _logger.AfterExecutingMethodOnFilter( + FilterTypeConstants.ResultFilter, + nameof(IAsyncResultFilter.OnResultExecutionAsync), + filter); + goto case State.ResultEnd; } @@ -758,10 +831,18 @@ namespace Microsoft.AspNetCore.Mvc.Internal var resultExecutingContext = _resultExecutingContext; _diagnosticSource.BeforeOnResultExecuting(resultExecutingContext, filter); + _logger.BeforeExecutingMethodOnFilter( + FilterTypeConstants.ResultFilter, + nameof(IResultFilter.OnResultExecuting), + filter); filter.OnResultExecuting(resultExecutingContext); _diagnosticSource.AfterOnResultExecuting(resultExecutingContext, filter); + _logger.AfterExecutingMethodOnFilter( + FilterTypeConstants.ResultFilter, + nameof(IResultFilter.OnResultExecuting), + filter); if (_resultExecutingContext.Cancel) { @@ -800,10 +881,18 @@ namespace Microsoft.AspNetCore.Mvc.Internal var resultExecutedContext = _resultExecutedContext; _diagnosticSource.BeforeOnResultExecuted(resultExecutedContext, filter); + _logger.BeforeExecutingMethodOnFilter( + FilterTypeConstants.ResultFilter, + nameof(IResultFilter.OnResultExecuted), + filter); filter.OnResultExecuted(resultExecutedContext); _diagnosticSource.AfterOnResultExecuted(resultExecutedContext, filter); + _logger.AfterExecutingMethodOnFilter( + FilterTypeConstants.ResultFilter, + nameof(IResultFilter.OnResultExecuted), + filter); goto case State.ResultEnd; } @@ -1124,5 +1213,14 @@ namespace Microsoft.AspNetCore.Mvc.Internal ResultEnd, InvokeEnd, } + + private static class FilterTypeConstants + { + public const string AuthorizationFilter = "Authorization Filter"; + public const string ResourceFilter = "Resource Filter"; + public const string ActionFilter = "Action Filter"; + public const string ExceptionFilter = "Exception Filter"; + public const string ResultFilter = "Result Filter"; + } } } diff --git a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageActionInvoker.cs b/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageActionInvoker.cs index ca3c962bf3..0a8396a997 100644 --- a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageActionInvoker.cs +++ b/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageActionInvoker.cs @@ -88,7 +88,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal await Next(ref next, ref scope, ref state, ref isCompleted); } } - + protected override void ReleaseResources() { if (_pageModel != null && CacheEntry.ReleaseModel != null) @@ -163,7 +163,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal { return; } - + var valueProvider = await CompositeValueProvider.CreateAsync(_pageContext, _pageContext.ValueProviderFactories); for (var i = 0; i < _handler.Parameters.Count; i++) @@ -232,7 +232,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal break; } } - + _diagnosticSource.BeforeHandlerMethod(_pageContext, handler, _arguments, _instance); _logger.ExecutingHandlerMethod(_pageContext, handler, arguments); @@ -342,6 +342,10 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal var handlerSelectedContext = _handlerSelectedContext; _diagnosticSource.BeforeOnPageHandlerSelection(handlerSelectedContext, filter); + _logger.BeforeExecutingMethodOnFilter( + PageLoggerExtensions.PageFilter, + nameof(IAsyncPageFilter.OnPageHandlerSelectionAsync), + filter); var task = filter.OnPageHandlerSelectionAsync(handlerSelectedContext); if (task.Status != TaskStatus.RanToCompletion) @@ -361,6 +365,10 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal var filter = (IAsyncPageFilter)state; _diagnosticSource.AfterOnPageHandlerSelection(_handlerSelectedContext, filter); + _logger.AfterExecutingMethodOnFilter( + PageLoggerExtensions.PageFilter, + nameof(IAsyncPageFilter.OnPageHandlerSelectionAsync), + filter); goto case State.PageSelectHandlerNext; } @@ -374,6 +382,10 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal var handlerSelectedContext = _handlerSelectedContext; _diagnosticSource.BeforeOnPageHandlerSelected(handlerSelectedContext, filter); + _logger.BeforeExecutingMethodOnFilter( + PageLoggerExtensions.PageFilter, + nameof(IPageFilter.OnPageHandlerSelected), + filter); filter.OnPageHandlerSelected(handlerSelectedContext); @@ -420,7 +432,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal { if (_handlerExecutingContext == null) { - _handlerExecutingContext = new PageHandlerExecutingContext(_pageContext, _filters,_handler, _arguments, _instance); + _handlerExecutingContext = new PageHandlerExecutingContext(_pageContext, _filters, _handler, _arguments, _instance); } state = current.Filter; @@ -441,6 +453,10 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal var handlerExecutingContext = _handlerExecutingContext; _diagnosticSource.BeforeOnPageHandlerExecution(handlerExecutingContext, filter); + _logger.BeforeExecutingMethodOnFilter( + PageLoggerExtensions.PageFilter, + nameof(IAsyncPageFilter.OnPageHandlerExecutionAsync), + filter); var task = filter.OnPageHandlerExecutionAsync(handlerExecutingContext, InvokeNextPageFilterAwaitedAsync); if (task.Status != TaskStatus.RanToCompletion) @@ -476,6 +492,10 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal } _diagnosticSource.AfterOnPageHandlerExecution(_handlerExecutedContext, filter); + _logger.AfterExecutingMethodOnFilter( + PageLoggerExtensions.PageFilter, + nameof(IAsyncPageFilter.OnPageHandlerExecutionAsync), + filter); goto case State.PageEnd; } @@ -489,10 +509,18 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal var handlerExecutingContext = _handlerExecutingContext; _diagnosticSource.BeforeOnPageHandlerExecuting(handlerExecutingContext, filter); + _logger.BeforeExecutingMethodOnFilter( + PageLoggerExtensions.PageFilter, + nameof(IPageFilter.OnPageHandlerExecuting), + filter); filter.OnPageHandlerExecuting(handlerExecutingContext); _diagnosticSource.AfterOnPageHandlerExecuting(handlerExecutingContext, filter); + _logger.AfterExecutingMethodOnFilter( + PageLoggerExtensions.PageFilter, + nameof(IPageFilter.OnPageHandlerExecuting), + filter); if (handlerExecutingContext.Result != null) { @@ -532,10 +560,18 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal var handlerExecutedContext = _handlerExecutedContext; _diagnosticSource.BeforeOnPageHandlerExecuted(handlerExecutedContext, filter); + _logger.BeforeExecutingMethodOnFilter( + PageLoggerExtensions.PageFilter, + nameof(IPageFilter.OnPageHandlerExecuted), + filter); filter.OnPageHandlerExecuted(handlerExecutedContext); _diagnosticSource.AfterOnPageHandlerExecuted(handlerExecutedContext, filter); + _logger.AfterExecutingMethodOnFilter( + PageLoggerExtensions.PageFilter, + nameof(IPageFilter.OnPageHandlerExecuted), + filter); goto case State.PageEnd; } diff --git a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs b/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs index 7289f0da2c..a3eeedbd32 100644 --- a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs @@ -13,10 +13,14 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal { internal static class PageLoggerExtensions { + public const string PageFilter = "Page Filter"; + private static readonly Action _handlerMethodExecuting; private static readonly Action _handlerMethodExecuted; private static readonly Action _pageFilterShortCircuit; private static readonly Action _malformedPageDirective; + private static readonly Action _beforeExecutingMethodOnFilter; + private static readonly Action _afterExecutingMethodOnFilter; static PageLoggerExtensions() { @@ -41,6 +45,16 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal LogLevel.Warning, 104, "The page directive at '{FilePath}' is malformed. Please fix the following issues: {Diagnostics}"); + + _beforeExecutingMethodOnFilter = LoggerMessage.Define( + LogLevel.Trace, + 1, + "{FilterType}: Before executing {Method} on filter {Filter}."); + + _afterExecutingMethodOnFilter = LoggerMessage.Define( + LogLevel.Trace, + 2, + "{FilterType}: After executing {Method} on filter {Filter}."); } public static void ExecutingHandlerMethod(this ILogger logger, PageContext context, HandlerMethodDescriptor handler, object[] arguments) @@ -78,6 +92,16 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal } } + public static void BeforeExecutingMethodOnFilter(this ILogger logger, string filterType, string methodName, IFilterMetadata filter) + { + _beforeExecutingMethodOnFilter(logger, filterType, methodName, filter.GetType().ToString(), null); + } + + public static void AfterExecutingMethodOnFilter(this ILogger logger, string filterType, string methodName, IFilterMetadata filter) + { + _afterExecutingMethodOnFilter(logger, filterType, methodName, filter.GetType().ToString(), null); + } + public static void PageFilterShortCircuited( this ILogger logger, IFilterMetadata filter) diff --git a/test/Microsoft.AspNetCore.Mvc.Core.Test/Internal/ControllerActionInvokerTest.cs b/test/Microsoft.AspNetCore.Mvc.Core.Test/Internal/ControllerActionInvokerTest.cs index 8570830236..0d93254154 100644 --- a/test/Microsoft.AspNetCore.Mvc.Core.Test/Internal/ControllerActionInvokerTest.cs +++ b/test/Microsoft.AspNetCore.Mvc.Core.Test/Internal/ControllerActionInvokerTest.cs @@ -33,44 +33,6 @@ namespace Microsoft.AspNetCore.Mvc.Internal { #region Diagnostics - [Fact] - public async Task Invoke_Success_LogsCorrectValues() - { - // Arrange - var sink = new TestSink(); - var loggerFactory = new TestLoggerFactory(sink, enabled: true); - var logger = loggerFactory.CreateLogger(); - - var displayName = "A.B.C"; - var actionDescriptor = Mock.Of(a => a.DisplayName == displayName); - actionDescriptor.MethodInfo = typeof(TestController).GetMethod(nameof(TestController.ActionMethod)); - actionDescriptor.ControllerTypeInfo = typeof(TestController).GetTypeInfo(); - actionDescriptor.FilterDescriptors = new List(); - actionDescriptor.Parameters = new List(); - actionDescriptor.BoundProperties = new List(); - - var filter = Mock.Of(); - var invoker = CreateInvoker( - new[] { filter }, - actionDescriptor, - controller: new TestController(), - logger: logger); - - // Act - await invoker.InvokeAsync(); - - // Assert - Assert.Single(sink.Scopes); - Assert.Equal(displayName, sink.Scopes[0].Scope?.ToString()); - - Assert.Equal(4, sink.Writes.Count); - Assert.Equal($"Executing action {displayName}", sink.Writes[0].State?.ToString()); - Assert.Equal($"Executing action method {displayName} with arguments ((null)) - ModelState is Valid", sink.Writes[1].State?.ToString()); - Assert.Equal($"Executed action method {displayName}, returned result {Result.GetType().FullName}.", sink.Writes[2].State?.ToString()); - // This message has the execution time embedded, which we don't want to verify. - Assert.StartsWith($"Executed action {displayName} ", sink.Writes[3].State?.ToString()); - } - [Fact] public async Task Invoke_WritesDiagnostic_ActionSelected() { diff --git a/test/Microsoft.AspNetCore.Mvc.Core.Test/Internal/MvcCoreLoggerExtensionsTest.cs b/test/Microsoft.AspNetCore.Mvc.Core.Test/Internal/MvcCoreLoggerExtensionsTest.cs new file mode 100644 index 0000000000..fc7f747395 --- /dev/null +++ b/test/Microsoft.AspNetCore.Mvc.Core.Test/Internal/MvcCoreLoggerExtensionsTest.cs @@ -0,0 +1,300 @@ +// 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 Microsoft.AspNetCore.Mvc.Filters; +using Microsoft.Extensions.Logging.Testing; +using Moq; +using Xunit; + +namespace Microsoft.AspNetCore.Mvc.Internal +{ + public class MvcCoreLoggerExtensionsTest + { + [Fact] + public void LogsFilters_OnlyWhenLogger_IsEnabled() + { + // Arrange + var authFilter = Mock.Of(); + var asyncAuthFilter = Mock.Of(); + var actionFilter = Mock.Of(); + var asyncActionFilter = Mock.Of(); + var exceptionFilter = Mock.Of(); + var asyncExceptionFilter = Mock.Of(); + var resultFilter = Mock.Of(); + var asyncResultFilter = Mock.Of(); + var resourceFilter = Mock.Of(); + var asyncResourceFilter = Mock.Of(); + var filters = new IFilterMetadata[] + { + actionFilter, + asyncActionFilter, + authFilter, + asyncAuthFilter, + exceptionFilter, + asyncExceptionFilter, + resultFilter, + asyncResultFilter, + resourceFilter, + asyncResourceFilter + }; + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: false); + var logger = loggerFactory.CreateLogger("test"); + + // Act + logger.AuthorizationFiltersExecutionPlan(filters); + logger.ResourceFiltersExecutionPlan(filters); + logger.ActionFiltersExecutionPlan(filters); + logger.ExceptionFiltersExecutionPlan(filters); + logger.ResultFiltersExecutionPlan(filters); + + // Assert + Assert.Empty(testSink.Writes); + } + + [Fact] + public void LogsListOfAuthorizationFilters() + { + // Arrange + var authFilter = Mock.Of(); + var asyncAuthFilter = Mock.Of(); + var orderedAuthFilterMock = new Mock(); + orderedAuthFilterMock.SetupGet(f => f.Order).Returns(-100); + var orderedAuthFilter = orderedAuthFilterMock.Object; + var actionFilter = Mock.Of(); + var asyncActionFilter = Mock.Of(); + var exceptionFilter = Mock.Of(); + var asyncExceptionFilter = Mock.Of(); + var resultFilter = Mock.Of(); + var asyncResultFilter = Mock.Of(); + var resourceFilter = Mock.Of(); + var asyncResourceFilter = Mock.Of(); + var filters = new IFilterMetadata[] + { + actionFilter, + asyncActionFilter, + authFilter, + asyncAuthFilter, + orderedAuthFilter, + exceptionFilter, + asyncExceptionFilter, + resultFilter, + asyncResultFilter, + resourceFilter, + asyncResourceFilter + }; + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + // Act + logger.AuthorizationFiltersExecutionPlan(filters); + + // Assert + Assert.Single(testSink.Writes); + var write = testSink.Writes[0]; + Assert.Equal( + "Execution plan of authorization filters (in the following order): " + + $"{authFilter.GetType()}, {asyncAuthFilter.GetType()}, {orderedAuthFilter.GetType()} (Order: -100)", + write.State.ToString()); + } + + [Fact] + public void LogsListOfResourceFilters() + { + // Arrange + var authFilter = Mock.Of(); + var asyncAuthFilter = Mock.Of(); + var actionFilter = Mock.Of(); + var asyncActionFilter = Mock.Of(); + var exceptionFilter = Mock.Of(); + var asyncExceptionFilter = Mock.Of(); + var resultFilter = Mock.Of(); + var asyncResultFilter = Mock.Of(); + var resourceFilter = Mock.Of(); + var asyncResourceFilter = Mock.Of(); + var orderedresourceFilterMock = new Mock(); + orderedresourceFilterMock.SetupGet(f => f.Order).Returns(-100); + var orderedResourceFilter = orderedresourceFilterMock.Object; + var filters = new IFilterMetadata[] + { + actionFilter, + asyncActionFilter, + authFilter, + asyncAuthFilter, + exceptionFilter, + asyncExceptionFilter, + resultFilter, + asyncResultFilter, + resourceFilter, + asyncResourceFilter, + orderedResourceFilter, + }; + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + // Act + logger.ResourceFiltersExecutionPlan(filters); + + // Assert + Assert.Single(testSink.Writes); + var write = testSink.Writes[0]; + Assert.Equal( + "Execution plan of resource filters (in the following order): " + + $"{resourceFilter.GetType()}, {asyncResourceFilter.GetType()}, {orderedResourceFilter.GetType()} (Order: -100)", + write.State.ToString()); + } + + [Fact] + public void LogsListOfActionFilters() + { + // Arrange + var authFilter = Mock.Of(); + var asyncAuthFilter = Mock.Of(); + var actionFilter = Mock.Of(); + var asyncActionFilter = Mock.Of(); + var orderedActionFilterMock = new Mock(); + orderedActionFilterMock.SetupGet(f => f.Order).Returns(-100); + var orderedActionFilter = orderedActionFilterMock.Object; + var exceptionFilter = Mock.Of(); + var asyncExceptionFilter = Mock.Of(); + var resultFilter = Mock.Of(); + var asyncResultFilter = Mock.Of(); + var resourceFilter = Mock.Of(); + var asyncResourceFilter = Mock.Of(); + var filters = new IFilterMetadata[] + { + actionFilter, + asyncActionFilter, + orderedActionFilter, + authFilter, + asyncAuthFilter, + exceptionFilter, + asyncExceptionFilter, + resultFilter, + asyncResultFilter, + resourceFilter, + asyncResourceFilter, + }; + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + // Act + logger.ActionFiltersExecutionPlan(filters); + + // Assert + Assert.Single(testSink.Writes); + var write = testSink.Writes[0]; + Assert.Equal( + "Execution plan of action filters (in the following order): " + + $"{actionFilter.GetType()}, {asyncActionFilter.GetType()}, {orderedActionFilter.GetType()} (Order: -100)", + write.State.ToString()); + } + + [Fact] + public void LogsListOfExceptionFilters() + { + // Arrange + var authFilter = Mock.Of(); + var asyncAuthFilter = Mock.Of(); + var actionFilter = Mock.Of(); + var asyncActionFilter = Mock.Of(); + var exceptionFilter = Mock.Of(); + var asyncExceptionFilter = Mock.Of(); + var orderedExceptionFilterMock = new Mock(); + orderedExceptionFilterMock.SetupGet(f => f.Order).Returns(-100); + var orderedExceptionFilter = orderedExceptionFilterMock.Object; + var resultFilter = Mock.Of(); + var asyncResultFilter = Mock.Of(); + var resourceFilter = Mock.Of(); + var asyncResourceFilter = Mock.Of(); + var filters = new IFilterMetadata[] + { + actionFilter, + asyncActionFilter, + authFilter, + asyncAuthFilter, + exceptionFilter, + asyncExceptionFilter, + orderedExceptionFilter, + resultFilter, + asyncResultFilter, + resourceFilter, + asyncResourceFilter, + }; + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + // Act + logger.ExceptionFiltersExecutionPlan(filters); + + // Assert + Assert.Single(testSink.Writes); + var write = testSink.Writes[0]; + Assert.Equal( + "Execution plan of exception filters (in the following order): " + + $"{exceptionFilter.GetType()}, {asyncExceptionFilter.GetType()}, {orderedExceptionFilter.GetType()} (Order: -100)", + write.State.ToString()); + } + + [Fact] + public void LogsListOfResultFilters() + { + // Arrange + var authFilter = Mock.Of(); + var asyncAuthFilter = Mock.Of(); + var actionFilter = Mock.Of(); + var asyncActionFilter = Mock.Of(); + var exceptionFilter = Mock.Of(); + var asyncExceptionFilter = Mock.Of(); + var orderedResultFilterMock = new Mock(); + orderedResultFilterMock.SetupGet(f => f.Order).Returns(-100); + var orderedResultFilter = orderedResultFilterMock.Object; + var resultFilter = Mock.Of(); + var asyncResultFilter = Mock.Of(); + var resourceFilter = Mock.Of(); + var asyncResourceFilter = Mock.Of(); + var filters = new IFilterMetadata[] + { + actionFilter, + asyncActionFilter, + authFilter, + asyncAuthFilter, + exceptionFilter, + asyncExceptionFilter, + resultFilter, + asyncResultFilter, + orderedResultFilter, + resourceFilter, + asyncResourceFilter, + }; + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + // Act + logger.ResultFiltersExecutionPlan(filters); + + // Assert + Assert.Single(testSink.Writes); + var write = testSink.Writes[0]; + Assert.Equal( + "Execution plan of result filters (in the following order): " + + $"{resultFilter.GetType()}, {asyncResultFilter.GetType()}, {orderedResultFilter.GetType()} (Order: -100)", + write.State.ToString()); + } + + public interface IOrderedAuthorizeFilter : IAuthorizationFilter, IAsyncAuthorizationFilter, IOrderedFilter { } + + public interface IOrderedResourceFilter : IResourceFilter, IAsyncResourceFilter, IOrderedFilter { } + + public interface IOrderedActionFilter : IActionFilter, IAsyncActionFilter, IOrderedFilter { } + + public interface IOrderedExceptionFilter : IExceptionFilter, IAsyncExceptionFilter, IOrderedFilter { } + + public interface IOrderedResultFilter : IResultFilter, IAsyncResultFilter, IOrderedFilter { } + } +} diff --git a/test/Microsoft.AspNetCore.Mvc.RazorPages.Test/Internal/PageActionInvokerTest.cs b/test/Microsoft.AspNetCore.Mvc.RazorPages.Test/Internal/PageActionInvokerTest.cs index 4cd7c46907..b8a53d3953 100644 --- a/test/Microsoft.AspNetCore.Mvc.RazorPages.Test/Internal/PageActionInvokerTest.cs +++ b/test/Microsoft.AspNetCore.Mvc.RazorPages.Test/Internal/PageActionInvokerTest.cs @@ -35,36 +35,6 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal { #region Diagnostics - [Fact] - public async Task Invoke_Success_LogsCorrectValues() - { - // Arrange - var sink = new TestSink(); - var loggerFactory = new TestLoggerFactory(sink, enabled: true); - var logger = loggerFactory.CreateLogger(); - - var actionDescriptor = CreateDescriptorForSimplePage(); - - var displayName = "/A/B/C"; - actionDescriptor.DisplayName = displayName; - - var invoker = CreateInvoker(filters: null, actionDescriptor: actionDescriptor, logger: logger); - - // Act - await invoker.InvokeAsync(); - - // Assert - Assert.Single(sink.Scopes); - Assert.Equal(displayName, sink.Scopes[0].Scope?.ToString()); - - Assert.Equal(4, sink.Writes.Count); - Assert.Equal($"Executing action {displayName}", sink.Writes[0].State?.ToString()); - Assert.Equal($"Executing handler method OnGetHandler1 with arguments ((null)) - ModelState is Valid", sink.Writes[1].State?.ToString()); - Assert.Equal($"Executed handler method OnGetHandler1, returned result {typeof(PageResult).FullName}.", sink.Writes[2].State?.ToString()); - // This message has the execution time embedded, which we don't want to verify. - Assert.StartsWith($"Executed action {displayName} ", sink.Writes[3].State?.ToString()); - } - [Fact] public async Task Invoke_WritesDiagnostic_ActionSelected() {