Modify info level logging for pages (#7733)

Addresses #7602

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

@@ -34,6 +34,9 @@ namespace Microsoft.AspNetCore.Mvc.Internal
         private static readonly Action<ILogger, string, string, Exception> _actionExecuting;
         private static readonly Action<ILogger, string, double, Exception> _actionExecuted;
 
+        private static readonly Action<ILogger, string, string, Exception> _pageExecuting;
+        private static readonly Action<ILogger, string, double, Exception> _pageExecuted;
+
         private static readonly Action<ILogger, string[], Exception> _challengeResultExecuting;
 
         private static readonly Action<ILogger, string, Exception> _contentResultExecuting;
@@ -158,6 +161,16 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                 2,
                 "Executed action {ActionName} in {ElapsedMilliseconds}ms");
 
+            _pageExecuting = LoggerMessage.Define<string, string>(
+                LogLevel.Information,
+                3,
+                "Route matched with {RouteData}. Executing page {PageName}");
+
+            _pageExecuted = LoggerMessage.Define<string, double>(
+                LogLevel.Information,
+                4,
+                "Executed page {PageName} in {ElapsedMilliseconds}ms");
+
             _challengeResultExecuting = LoggerMessage.Define<string[]>(
                 LogLevel.Information,
                 1,
@@ -682,8 +695,14 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                         stringBuilder.Append($"{routeKeys[i]} = \"{routeValues[i]}\", ");
                     }
                 }
-
+                if (action.RouteValues["page"] != null)
-                _actionExecuting(logger, stringBuilder.ToString(), action.DisplayName, 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);
+                }
             }
         }
 

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

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<ILogger, string, string[], ModelValidationState, Exception> _handlerMethodExecuting;
+        private static readonly Action<ILogger, ModelValidationState, Exception> _implicitHandlerMethodExecuting;
         private static readonly Action<ILogger, string, string, Exception> _handlerMethodExecuted;
+        private static readonly Action<ILogger, string, Exception> _implicitHandlerMethodExecuted;
         private static readonly Action<ILogger, object, Exception> _pageFilterShortCircuit;
         private static readonly Action<ILogger, string, string[], Exception> _malformedPageDirective;
         private static readonly Action<ILogger, string, Exception> _unsupportedAreaPath;
@@ -34,10 +36,20 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Internal
                 "Executing handler method {HandlerName} with arguments ({Arguments}) - ModelState is {ValidationState}");
 
             _handlerMethodExecuted = LoggerMessage.Define<string, string>(
-                LogLevel.Debug,
+                LogLevel.Information,
                 102,
                 "Executed handler method {HandlerName}, returned result {ActionResult}.");
 
+            _implicitHandlerMethodExecuting = LoggerMessage.Define<ModelValidationState>(
+                LogLevel.Information,
+                103,
+                "Executing an implicit handler method - ModelState is {ValidationState}");
+
+            _implicitHandlerMethodExecuted = LoggerMessage.Define<string>(
+                LogLevel.Information,
+                104,
+                "Executed an implicit handler method, returned result {ActionResult}.");
+
             _pageFilterShortCircuit = LoggerMessage.Define<object>(
                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);