diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs index c840f785b1..0cee994b44 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs @@ -34,6 +34,9 @@ namespace Microsoft.AspNetCore.Mvc.Internal private static readonly Action _actionExecuting; private static readonly Action _actionExecuted; + private static readonly Action _pageExecuting; + private static readonly Action _pageExecuted; + private static readonly Action _challengeResultExecuting; private static readonly Action _contentResultExecuting; @@ -158,6 +161,16 @@ namespace Microsoft.AspNetCore.Mvc.Internal 2, "Executed action {ActionName} in {ElapsedMilliseconds}ms"); + _pageExecuting = LoggerMessage.Define( + LogLevel.Information, + 3, + "Route matched with {RouteData}. Executing page {PageName}"); + + _pageExecuted = LoggerMessage.Define( + LogLevel.Information, + 4, + "Executed page {PageName} in {ElapsedMilliseconds}ms"); + _challengeResultExecuting = LoggerMessage.Define( LogLevel.Information, 1, @@ -682,8 +695,14 @@ namespace Microsoft.AspNetCore.Mvc.Internal stringBuilder.Append($"{routeKeys[i]} = \"{routeValues[i]}\", "); } } - - _actionExecuting(logger, stringBuilder.ToString(), action.DisplayName, null); + if (action.RouteValues["page"] != null) + { + _pageExecuting(logger, stringBuilder.ToString(), action.DisplayName, null); + } + else + { + _actionExecuting(logger, stringBuilder.ToString(), action.DisplayName, null); + } } } @@ -765,7 +784,14 @@ namespace Microsoft.AspNetCore.Mvc.Internal // Don't log if logging wasn't enabled at start of request as time will be wildly wrong. if (logger.IsEnabled(LogLevel.Information)) { - _actionExecuted(logger, action.DisplayName, timeSpan.TotalMilliseconds, null); + if (action.RouteValues["page"] != null) + { + _pageExecuted(logger, action.DisplayName, timeSpan.TotalMilliseconds, null); + } + else + { + _actionExecuted(logger, action.DisplayName, timeSpan.TotalMilliseconds, null); + } } } diff --git a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageActionInvoker.cs b/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageActionInvoker.cs index 9684c711f0..4f91b0346e 100644 --- a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageActionInvoker.cs +++ b/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageActionInvoker.cs @@ -275,7 +275,9 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal // Pages have an implicit 'return Page()' even without a handler method. if (_result == null) { + _logger.ExecutingImplicitHandlerMethod(_pageContext); _result = new PageResult(); + _logger.ExecutedImplicitHandlerMethod(_result); } // Ensure ViewData is set on PageResult for backwards compatibility (For example, Identity UI accesses diff --git a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs b/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs index a5d7c960d4..1ff89f5512 100644 --- a/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Mvc.RazorPages/Internal/PageLoggerExtensions.cs @@ -16,7 +16,9 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal public const string PageFilter = "Page Filter"; private static readonly Action _handlerMethodExecuting; + private static readonly Action _implicitHandlerMethodExecuting; private static readonly Action _handlerMethodExecuted; + private static readonly Action _implicitHandlerMethodExecuted; private static readonly Action _pageFilterShortCircuit; private static readonly Action _malformedPageDirective; private static readonly Action _unsupportedAreaPath; @@ -34,10 +36,20 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal "Executing handler method {HandlerName} with arguments ({Arguments}) - ModelState is {ValidationState}"); _handlerMethodExecuted = LoggerMessage.Define( - LogLevel.Debug, + LogLevel.Information, 102, "Executed handler method {HandlerName}, returned result {ActionResult}."); + _implicitHandlerMethodExecuting = LoggerMessage.Define( + LogLevel.Information, + 103, + "Executing an implicit handler method - ModelState is {ValidationState}"); + + _implicitHandlerMethodExecuted = LoggerMessage.Define( + LogLevel.Information, + 104, + "Executed an implicit handler method, returned result {ActionResult}."); + _pageFilterShortCircuit = LoggerMessage.Define( LogLevel.Debug, 3, @@ -73,7 +85,7 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal { if (logger.IsEnabled(LogLevel.Information)) { - var handlerName = handler.MethodInfo.Name; + var handlerName = handler.MethodInfo.DeclaringType.FullName + "." + handler.MethodInfo.Name; string[] convertedArguments; if (arguments == null) @@ -95,15 +107,33 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal } } + public static void ExecutingImplicitHandlerMethod(this ILogger logger, PageContext context) + { + if (logger.IsEnabled(LogLevel.Information)) + { + var validationState = context.ModelState.ValidationState; + + _implicitHandlerMethodExecuting(logger, validationState, null); + } + } + public static void ExecutedHandlerMethod(this ILogger logger, PageContext context, HandlerMethodDescriptor handler, IActionResult result) { - if (logger.IsEnabled(LogLevel.Debug)) + if (logger.IsEnabled(LogLevel.Information)) { var handlerName = handler.MethodInfo.Name; _handlerMethodExecuted(logger, handlerName, Convert.ToString(result), null); } } + public static void ExecutedImplicitHandlerMethod(this ILogger logger, IActionResult result) + { + if (logger.IsEnabled(LogLevel.Information)) + { + _implicitHandlerMethodExecuted(logger, Convert.ToString(result), null); + } + } + public static void BeforeExecutingMethodOnFilter(this ILogger logger, string filterType, string methodName, IFilterMetadata filter) { _beforeExecutingMethodOnFilter(logger, filterType, methodName, filter.GetType().ToString(), null);