Test PageActionInvoker logs and fix declaring type name for handler in logs (#12326)

* Test PageActionInvoker logs and fix declaring type name for handler

src/Mvc/Mvc.Core/test/Infrastructure/ControllerActionInvokerTest.cs

@@ -1484,23 +1484,26 @@ namespace Microsoft.AspNetCore.Mvc.Infrastructure
 
             // Assert
             var messages = testSink.Writes.Select(write => write.State.ToString()).ToList();
+            var actionSignature = $"{typeof(IActionResult).FullName} {nameof(TestController.ActionMethod)}()";
             var controllerName = $"{typeof(ControllerActionInvokerTest).FullName}+{nameof(TestController)} ({typeof(ControllerActionInvokerTest).Assembly.GetName().Name})";
             var actionName = $"{typeof(ControllerActionInvokerTest).FullName}+{nameof(TestController)}.{nameof(TestController.ActionMethod)} ({typeof(ControllerActionInvokerTest).Assembly.GetName().Name})";
             var actionResultName = $"{typeof(CommonResourceInvokerTest).FullName}+{nameof(TestResult)}";
-            Assert.Equal(13, messages.Count);
+
-            Assert.Contains($"Route matched with {{}}. Executing controller action with signature {typeof(IActionResult).FullName} {nameof(TestController.ActionMethod)}() on controller {controllerName}.", messages);
+            Assert.Collection(
-            Assert.Contains("Execution plan of authorization filters (in the following order): None", messages);
+                messages,
-            Assert.Contains("Execution plan of resource filters (in the following order): None", messages);
+                m => Assert.Equal($"Route matched with {{}}. Executing controller action with signature {actionSignature} on controller {controllerName}.", m),
-            Assert.Contains("Execution plan of action filters (in the following order): None", messages);
+                m => Assert.Equal("Execution plan of authorization filters (in the following order): None", m),
-            Assert.Contains("Execution plan of exception filters (in the following order): None", messages);
+                m => Assert.Equal("Execution plan of resource filters (in the following order): None", m),
-            Assert.Contains("Execution plan of result filters (in the following order): None", messages);
+                m => Assert.Equal("Execution plan of action filters (in the following order): None", m),
-            Assert.Contains($"Executing controller factory for controller {controllerName}", messages);
+                m => Assert.Equal("Execution plan of exception filters (in the following order): None", m),
-            Assert.Contains($"Executed controller factory for controller {controllerName}", messages);
+                m => Assert.Equal("Execution plan of result filters (in the following order): None", m),
-            Assert.Contains($"Executing action method {actionName} - Validation state: Valid", messages);
+                m => Assert.Equal($"Executing controller factory for controller {controllerName}", m),
-            Assert.Contains(messages, m => m.Contains($"Executed action method {actionName}, returned result {actionResultName} in "));
+                m => Assert.Equal($"Executed controller factory for controller {controllerName}", m),
-            Assert.Contains($"Before executing action result {actionResultName}.", messages);
+                m => Assert.Equal($"Executing action method {actionName} - Validation state: Valid", m),
-            Assert.Contains($"After executing action result {actionResultName}.", messages);
+                m => Assert.StartsWith($"Executed action method {actionName}, returned result {actionResultName} in ", m),
-            Assert.Contains(messages, m => m.Contains($"Executed action {actionName} in "));
+                m => Assert.Equal($"Before executing action result {actionResultName}.", m),
+                m => Assert.Equal($"After executing action result {actionResultName}.", m),
+                m => Assert.StartsWith($"Executed action {actionName} in ", m));
         }
 
         #endregion

src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs

@@ -5,6 +5,7 @@ using System;
 using System.Collections.Generic;
 using System.Reflection;
 using Microsoft.AspNetCore.Http;
+using Microsoft.AspNetCore.Mvc.Abstractions;
 using Microsoft.AspNetCore.Mvc.Filters;
 using Microsoft.AspNetCore.Mvc.Formatters;
 using Microsoft.Extensions.Logging.Testing;
@@ -24,9 +25,17 @@ namespace Microsoft.AspNetCore.Mvc
                 new KeyValuePair<string, string>("other", "value") },
         };
 
+        public static object[][] PageRouteValuesTestData { get; } = new object[][]
+        {
+            new object[]{ "{page = \"bar\"}", new KeyValuePair<string, string>("page", "bar") },
+            new object[]{ "{page = \"bar\", other = \"value\"}",
+                new KeyValuePair<string, string>("page", "bar"),
+                new KeyValuePair<string, string>("other", "value") },
+        };
+
         [Theory]
         [MemberData(nameof(RouteValuesTestData))]
-        public void ExecutingAction_WithGivenRouteValues_LogsActionAndRouteData(string expectedRouteValuesLogMessage, params KeyValuePair<string, string>[] routeValues)
+        public void ExecutingAction_ForControllerAction_WithGivenRouteValues_LogsActionAndRouteData(string expectedRouteValuesLogMessage, params KeyValuePair<string, string>[] routeValues)
         {
             // Arrange
             var testSink = new TestSink();
@@ -56,6 +65,64 @@ namespace Microsoft.AspNetCore.Mvc
                 write.State.ToString());
         }
 
+        [Theory]
+        [MemberData(nameof(RouteValuesTestData))]
+        public void ExecutingAction_ForAction_WithGivenRouteValues_LogsActionAndRouteData(string expectedRouteValuesLogMessage, params KeyValuePair<string, string>[] routeValues)
+        {
+            // Arrange
+            var testSink = new TestSink();
+            var loggerFactory = new TestLoggerFactory(testSink, enabled: true);
+            var logger = loggerFactory.CreateLogger("test");
+
+            var action = new ActionDescriptor
+            {
+                DisplayName = "foobar",
+            };
+
+            foreach (var routeValue in routeValues)
+            {
+                action.RouteValues.Add(routeValue);
+            }
+
+            // Act
+            logger.ExecutingAction(action);
+
+            // Assert
+            var write = Assert.Single(testSink.Writes);
+            Assert.Equal(
+                $"Route matched with {expectedRouteValuesLogMessage}. Executing action {action.DisplayName}",
+                write.State.ToString());
+        }
+
+        [Theory]
+        [MemberData(nameof(PageRouteValuesTestData))]
+        public void ExecutingAction_ForPage_WithGivenRouteValues_LogsPageAndRouteData(string expectedRouteValuesLogMessage, params KeyValuePair<string, string>[] routeValues)
+        {
+            // Arrange
+            var testSink = new TestSink();
+            var loggerFactory = new TestLoggerFactory(testSink, enabled: true);
+            var logger = loggerFactory.CreateLogger("test");
+
+            var action = new ActionDescriptor
+            {
+                DisplayName = "/Pages/Foo",
+            };
+
+            foreach (var routeValue in routeValues)
+            {
+                action.RouteValues.Add(routeValue);
+            }
+
+            // Act
+            logger.ExecutingAction(action);
+
+            // Assert
+            var write = Assert.Single(testSink.Writes);
+            Assert.Equal(
+                $"Route matched with {expectedRouteValuesLogMessage}. Executing page {action.DisplayName}",
+                write.State.ToString());
+        }
+
         [Fact]
         public void LogsFilters_OnlyWhenLogger_IsEnabled()
         {

src/Mvc/Mvc.RazorPages/src/PageLoggerExtensions.cs

@@ -150,7 +150,8 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages
         {
             if (logger.IsEnabled(LogLevel.Information))
             {
-                var handlerName = handler.MethodInfo.DeclaringType.FullName + "." + handler.MethodInfo.Name;
+                var declaringTypeName = TypeNameHelper.GetTypeDisplayName(handler.MethodInfo.DeclaringType);
+                var handlerName = declaringTypeName + "." + handler.MethodInfo.Name;
 
                 var validationState = context.ModelState.ValidationState;
                 _handlerMethodExecuting(logger, handlerName, validationState, null);

src/Mvc/Mvc.RazorPages/test/Infrastructure/PageActionInvokerTest.cs

@@ -1391,15 +1391,21 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure
 
         #region Logs
 
-        [Fact]
+        [Theory]
-        public async Task InvokeAction_LogsPageFactory()
+        [InlineData(false)]
+        [InlineData(true)]
+        public async Task InvokeAction_ForPage_Logs(bool hasPageModel)
         {
             // Arrange
             var testSink = new TestSink();
             var loggerFactory = new TestLoggerFactory(testSink, enabled: true);
             var logger = loggerFactory.CreateLogger("test");
 
-            var actionDescriptor = CreateDescriptorForSimplePage();
+            var actionDescriptor = hasPageModel 
+                ? CreateDescriptorForPageModelPage() 
+                : CreateDescriptorForSimplePage();
+            actionDescriptor.ViewEnginePath = "/Pages/Foo";
+            actionDescriptor.RouteValues.Add("page", "foo");
             var invoker = CreateInvoker(null, actionDescriptor, logger: logger);
 
             // Act
@@ -1408,29 +1414,29 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure
             // Assert
             var messages = testSink.Writes.Select(write => write.State.ToString()).ToList();
             var pageName = $"{typeof(PageActionInvokerTest).FullName}+{nameof(TestPage)} ({typeof(PageActionInvokerTest).Assembly.GetName().Name})";
-            Assert.Contains($"Executing page factory for page {pageName}", messages);
+            var pagePath = actionDescriptor.ViewEnginePath;
-            Assert.Contains($"Executed page factory for page {pageName}", messages);
+            var methodFullName = hasPageModel
-        }
+                ? $"{typeof(PageActionInvokerTest).FullName}+{nameof(TestPageModel)}.{nameof(TestPageModel.OnGetHandler1)}"
+                : $"{typeof(PageActionInvokerTest).FullName}+{nameof(TestPage)}.{nameof(TestPage.OnGetHandler1)}";
+            var methodName = nameof(TestPage.OnGetHandler1);
+            var resultName = typeof(PageResult).FullName;
+            var factoryType = hasPageModel ? "page model" : "page";
 
-        [Fact]
+            Assert.Collection(
-        public async Task InvokeAction_LogsPageModelFactory()
+                messages,
-        {
+                m => Assert.Equal($"Route matched with {{page = \"foo\"}}. Executing page {pagePath}", m),
-            // Arrange
+                m => Assert.Equal("Execution plan of authorization filters (in the following order): None", m),
-            var testSink = new TestSink();
+                m => Assert.Equal("Execution plan of resource filters (in the following order): None", m),
-            var loggerFactory = new TestLoggerFactory(testSink, enabled: true);
+                m => Assert.Equal("Execution plan of action filters (in the following order): None", m),
-            var logger = loggerFactory.CreateLogger("test");
+                m => Assert.Equal("Execution plan of exception filters (in the following order): None", m),
-
+                m => Assert.Equal("Execution plan of result filters (in the following order): None", m),
-            var actionDescriptor = CreateDescriptorForPageModelPage();
+                m => Assert.Equal($"Executing {factoryType} factory for page {pageName}", m),
-            var invoker = CreateInvoker(null, actionDescriptor, logger: logger);
+                m => Assert.Equal($"Executed {factoryType} factory for page {pageName}", m),
-
+                m => Assert.Equal($"Executing handler method {methodFullName} - ModelState is Valid", m),
-            // Act
+                m => Assert.Equal($"Executed handler method {methodName}, returned result {resultName}.", m),
-            await invoker.InvokeAsync();
+                m => Assert.Equal($"Before executing action result {resultName}.", m),
-
+                m => Assert.Equal($"After executing action result {resultName}.", m),
-            // Assert
+                m => Assert.StartsWith($"Executed page {pagePath} in ", m));
-            var messages = testSink.Writes.Select(write => write.State.ToString()).ToList();
-            var pageName = $"{typeof(PageActionInvokerTest).FullName}+{nameof(TestPage)} ({typeof(PageActionInvokerTest).Assembly.GetName().Name})";
-            Assert.Contains($"Executing page model factory for page {pageName}", messages);
-            Assert.Contains($"Executed page model factory for page {pageName}", messages);
         }
 
         #endregion

src/Mvc/Mvc.RazorPages/test/PageLoggerExtensionsTest.cs

@@ -4,6 +4,7 @@
 using System;
 using System.Reflection;
 using Microsoft.AspNetCore.Mvc.RazorPages;
+using Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure;
 using Microsoft.Extensions.Logging.Testing;
 using Xunit;
 
@@ -122,5 +123,68 @@ namespace Microsoft.AspNetCore.Mvc
                 "System.ValueTuple<int, string> (System.Private.CoreLib)",
                 write.State.ToString());
         }
+
+        [Theory]
+        [InlineData(true)]
+        [InlineData(false)]
+        public void ExecutingHandlerMethod_LogsHandlerNameAndModelState(bool isValidModelState)
+        {
+            // Arrange
+            var testSink = new TestSink();
+            var loggerFactory = new TestLoggerFactory(testSink, enabled: true);
+            var logger = loggerFactory.CreateLogger("test");
+
+            var context = new PageContext();
+            if (!isValidModelState)
+            {
+                context.ModelState.AddModelError("foo", "bar");
+            }
+            var handler = new HandlerMethodDescriptor
+            {
+                // Using a generic type to verify the use of a clean name
+                MethodInfo = typeof(ValueTuple<int, string>).GetMethod(nameof(ToString)),
+            };
+
+            // Act
+            logger.ExecutingHandlerMethod(context, handler, null);
+
+            // Assert
+            var write = Assert.Single(testSink.Writes);
+            var validationState = isValidModelState ? "Valid" : "Invalid";
+            Assert.Equal(
+                $"Executing handler method System.ValueTuple<int, string>.ToString - ModelState is {validationState}",
+                write.State.ToString());
+        }
+
+        [Theory]
+        [InlineData("")]
+        [InlineData("foo", "foo")]
+        [InlineData("foo, 42", "foo", 42)]
+        public void ExecutingHandlerMethod_WithArguments_LogsArguments(string expectedArgumentsMessage, params object[] arguments)
+        {
+            // Arrange
+            var testSink = new TestSink();
+            var loggerFactory = new TestLoggerFactory(testSink, enabled: true);
+            var logger = loggerFactory.CreateLogger("test");
+
+            var context = new PageContext();
+            var handler = new HandlerMethodDescriptor
+            {
+                // Using a generic type to verify the use of a clean name
+                MethodInfo = typeof(ValueTuple<int, string>).GetMethod(nameof(ToString)),
+            };
+
+            // Act
+            logger.ExecutingHandlerMethod(context, handler, arguments);
+
+            // Assert
+            Assert.Equal(2, testSink.Writes.Count);
+            var enumerator = testSink.Writes.GetEnumerator();
+            enumerator.MoveNext();
+            enumerator.MoveNext();
+            Assert.Equal(
+                $"Executing handler method System.ValueTuple<int, string>.ToString with arguments ({expectedArgumentsMessage})",
+                enumerator.Current.State.ToString());
+        }
     }
 }