huahaofeng
/
aspnetcore
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

Improve logging - filter pipeline execution 

Related to issue #6498: When enabling "Trace" logging for MVC loggers, I should be buried in log messages
This commit is contained in:
Kiran Challa 2017-12-07 15:00:09 -08:00
parent 5d9f04cf34
commit 4c4a7b3c6c
8 changed files with 637 additions and 75 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

24
src/Microsoft.AspNetCore.Mvc.Core/Internal/ControllerActionInvoker.cs
View File

@ -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;
}

148
src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs
View File

@ -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<ILogger, string, Exception> _actionExecuting;
@ -33,6 +36,12 @@ namespace Microsoft.AspNetCore.Mvc.Internal
private static readonly Action<ILogger, string, string[], ModelValidationState, Exception> _actionMethodExecuting;
private static readonly Action<ILogger, string, string, Exception> _actionMethodExecuted;
private static readonly Action<ILogger, string, string[], Exception> _logFilterExecutionPlan;
private static readonly Action<ILogger, string, string, Type, Exception> _beforeExecutingMethodOnFilter;
private static readonly Action<ILogger, string, string, Type, Exception> _afterExecutingMethodOnFilter;
private static readonly Action<ILogger, Type, Exception> _beforeExecutingActionResult;
private static readonly Action<ILogger, Type, Exception> _afterExecutingActionResult;
private static readonly Action<ILogger, string, Exception> _ambiguousActions;
private static readonly Action<ILogger, string, string, IActionConstraint, Exception> _constraintMismatch;
@ -119,6 +128,31 @@ namespace Microsoft.AspNetCore.Mvc.Internal
2,
"Executed action method {ActionName}, returned result {ActionResult}.");
_logFilterExecutionPlan = LoggerMessage.Define<string, string[]>(
LogLevel.Debug,
1,
"Execution plan of {FilterType} filters (in the following order): {Filters}");
_beforeExecutingMethodOnFilter = LoggerMessage.Define<string, string, Type>(
LogLevel.Trace,
2,
"{FilterType}: Before executing {Method} on filter {Filter}.");
_afterExecutingMethodOnFilter = LoggerMessage.Define<string, string, Type>(
LogLevel.Trace,
3,
"{FilterType}: After executing {Method} on filter {Filter}.");
_beforeExecutingActionResult = LoggerMessage.Define<Type>(
LogLevel.Trace,
4,
"Before executing action result {ActionResult}.");
_afterExecutingActionResult = LoggerMessage.Define<Type>(
LogLevel.Trace,
5,
"After executing action result {ActionResult}.");
_ambiguousActions = LoggerMessage.Define<string>(
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<IFilterMetadata> 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<IFilterMetadata> 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<IFilterMetadata> 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<IFilterMetadata> 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<IFilterMetadata> 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<IFilterMetadata> filters)
{
var filterList = _noFilters;
if (filters.Any())
{
filterList = GetFilterList(filters);
}
_logFilterExecutionPlan(logger, filterType, filterList, null);
}
private static string[] GetFilterList(IEnumerable<IFilterMetadata> filters)
{
var filterList = new List<string>();
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<KeyValuePair<string, object>>
{
private readonly ActionDescriptor _action;

104
src/Microsoft.AspNetCore.Mvc.Core/Internal/ResourceInvoker.cs
View File

@ -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";
}
}
}

44
src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageActionInvoker.cs
View File

@ -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;
}

24
src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs
View File

@ -13,10 +13,14 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
{
internal static class PageLoggerExtensions
{
public const string PageFilter = "Page Filter";
private static readonly Action<ILogger, string, string[], ModelValidationState, Exception> _handlerMethodExecuting;
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, string, string, string, Exception> _beforeExecutingMethodOnFilter;
private static readonly Action<ILogger, string, string, string, Exception> _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<string, string, string>(
LogLevel.Trace,
1,
"{FilterType}: Before executing {Method} on filter {Filter}.");
_afterExecutingMethodOnFilter = LoggerMessage.Define<string, string, string>(
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)

38
test/Microsoft.AspNetCore.Mvc.Core.Test/Internal/ControllerActionInvokerTest.cs
View File

@ -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<ControllerActionInvoker>();
var displayName = "A.B.C";
var actionDescriptor = Mock.Of<ControllerActionDescriptor>(a => a.DisplayName == displayName);
actionDescriptor.MethodInfo = typeof(TestController).GetMethod(nameof(TestController.ActionMethod));
actionDescriptor.ControllerTypeInfo = typeof(TestController).GetTypeInfo();
actionDescriptor.FilterDescriptors = new List<FilterDescriptor>();
actionDescriptor.Parameters = new List<ParameterDescriptor>();
actionDescriptor.BoundProperties = new List<ParameterDescriptor>();
var filter = Mock.Of<IFilterMetadata>();
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()
{

300
test/Microsoft.AspNetCore.Mvc.Core.Test/Internal/MvcCoreLoggerExtensionsTest.cs Normal file
View File

@ -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<IAuthorizationFilter>();
var asyncAuthFilter = Mock.Of<IAsyncAuthorizationFilter>();
var actionFilter = Mock.Of<IActionFilter>();
var asyncActionFilter = Mock.Of<IAsyncActionFilter>();
var exceptionFilter = Mock.Of<IExceptionFilter>();
var asyncExceptionFilter = Mock.Of<IAsyncExceptionFilter>();
var resultFilter = Mock.Of<IResultFilter>();
var asyncResultFilter = Mock.Of<IAsyncResultFilter>();
var resourceFilter = Mock.Of<IResourceFilter>();
var asyncResourceFilter = Mock.Of<IAsyncResourceFilter>();
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<IAuthorizationFilter>();
var asyncAuthFilter = Mock.Of<IAsyncAuthorizationFilter>();
var orderedAuthFilterMock = new Mock<IOrderedAuthorizeFilter>();
orderedAuthFilterMock.SetupGet(f => f.Order).Returns(-100);
var orderedAuthFilter = orderedAuthFilterMock.Object;
var actionFilter = Mock.Of<IActionFilter>();
var asyncActionFilter = Mock.Of<IAsyncActionFilter>();
var exceptionFilter = Mock.Of<IExceptionFilter>();
var asyncExceptionFilter = Mock.Of<IAsyncExceptionFilter>();
var resultFilter = Mock.Of<IResultFilter>();
var asyncResultFilter = Mock.Of<IAsyncResultFilter>();
var resourceFilter = Mock.Of<IResourceFilter>();
var asyncResourceFilter = Mock.Of<IAsyncResourceFilter>();
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<IAuthorizationFilter>();
var asyncAuthFilter = Mock.Of<IAsyncAuthorizationFilter>();
var actionFilter = Mock.Of<IActionFilter>();
var asyncActionFilter = Mock.Of<IAsyncActionFilter>();
var exceptionFilter = Mock.Of<IExceptionFilter>();
var asyncExceptionFilter = Mock.Of<IAsyncExceptionFilter>();
var resultFilter = Mock.Of<IResultFilter>();
var asyncResultFilter = Mock.Of<IAsyncResultFilter>();
var resourceFilter = Mock.Of<IResourceFilter>();
var asyncResourceFilter = Mock.Of<IAsyncResourceFilter>();
var orderedresourceFilterMock = new Mock<IOrderedResourceFilter>();
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<IAuthorizationFilter>();
var asyncAuthFilter = Mock.Of<IAsyncAuthorizationFilter>();
var actionFilter = Mock.Of<IActionFilter>();
var asyncActionFilter = Mock.Of<IAsyncActionFilter>();
var orderedActionFilterMock = new Mock<IOrderedActionFilter>();
orderedActionFilterMock.SetupGet(f => f.Order).Returns(-100);
var orderedActionFilter = orderedActionFilterMock.Object;
var exceptionFilter = Mock.Of<IExceptionFilter>();
var asyncExceptionFilter = Mock.Of<IAsyncExceptionFilter>();
var resultFilter = Mock.Of<IResultFilter>();
var asyncResultFilter = Mock.Of<IAsyncResultFilter>();
var resourceFilter = Mock.Of<IResourceFilter>();
var asyncResourceFilter = Mock.Of<IAsyncResourceFilter>();
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<IAuthorizationFilter>();
var asyncAuthFilter = Mock.Of<IAsyncAuthorizationFilter>();
var actionFilter = Mock.Of<IActionFilter>();
var asyncActionFilter = Mock.Of<IAsyncActionFilter>();
var exceptionFilter = Mock.Of<IExceptionFilter>();
var asyncExceptionFilter = Mock.Of<IAsyncExceptionFilter>();
var orderedExceptionFilterMock = new Mock<IOrderedExceptionFilter>();
orderedExceptionFilterMock.SetupGet(f => f.Order).Returns(-100);
var orderedExceptionFilter = orderedExceptionFilterMock.Object;
var resultFilter = Mock.Of<IResultFilter>();
var asyncResultFilter = Mock.Of<IAsyncResultFilter>();
var resourceFilter = Mock.Of<IResourceFilter>();
var asyncResourceFilter = Mock.Of<IAsyncResourceFilter>();
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<IAuthorizationFilter>();
var asyncAuthFilter = Mock.Of<IAsyncAuthorizationFilter>();
var actionFilter = Mock.Of<IActionFilter>();
var asyncActionFilter = Mock.Of<IAsyncActionFilter>();
var exceptionFilter = Mock.Of<IExceptionFilter>();
var asyncExceptionFilter = Mock.Of<IAsyncExceptionFilter>();
var orderedResultFilterMock = new Mock<IOrderedResultFilter>();
orderedResultFilterMock.SetupGet(f => f.Order).Returns(-100);
var orderedResultFilter = orderedResultFilterMock.Object;
var resultFilter = Mock.Of<IResultFilter>();
var asyncResultFilter = Mock.Of<IAsyncResultFilter>();
var resourceFilter = Mock.Of<IResourceFilter>();
var asyncResourceFilter = Mock.Of<IAsyncResourceFilter>();
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 { }
}
}

30
test/Microsoft.AspNetCore.Mvc.RazorPages.Test/Internal/PageActionInvokerTest.cs
View File

@ -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<PageActionInvoker>();
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()
{