diff --git a/src/Mvc/Mvc.Core/test/Infrastructure/ControllerActionInvokerTest.cs b/src/Mvc/Mvc.Core/test/Infrastructure/ControllerActionInvokerTest.cs index 825108c704..2fe4f3c9b4 100644 --- a/src/Mvc/Mvc.Core/test/Infrastructure/ControllerActionInvokerTest.cs +++ b/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.Contains("Execution plan of authorization filters (in the following order): None", messages); - Assert.Contains("Execution plan of resource filters (in the following order): None", messages); - Assert.Contains("Execution plan of action filters (in the following order): None", messages); - Assert.Contains("Execution plan of exception filters (in the following order): None", messages); - Assert.Contains("Execution plan of result filters (in the following order): None", messages); - Assert.Contains($"Executing controller factory for controller {controllerName}", messages); - Assert.Contains($"Executed controller factory for controller {controllerName}", messages); - Assert.Contains($"Executing action method {actionName} - Validation state: Valid", messages); - Assert.Contains(messages, m => m.Contains($"Executed action method {actionName}, returned result {actionResultName} in ")); - Assert.Contains($"Before executing action result {actionResultName}.", messages); - Assert.Contains($"After executing action result {actionResultName}.", messages); - Assert.Contains(messages, m => m.Contains($"Executed action {actionName} in ")); + + Assert.Collection( + messages, + m => Assert.Equal($"Route matched with {{}}. Executing controller action with signature {actionSignature} on controller {controllerName}.", m), + m => Assert.Equal("Execution plan of authorization filters (in the following order): None", m), + m => Assert.Equal("Execution plan of resource filters (in the following order): None", m), + m => Assert.Equal("Execution plan of action filters (in the following order): None", m), + 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), + m => Assert.Equal($"Executing controller factory for controller {controllerName}", m), + m => Assert.Equal($"Executed controller factory for controller {controllerName}", m), + m => Assert.Equal($"Executing action method {actionName} - Validation state: Valid", m), + m => Assert.StartsWith($"Executed action method {actionName}, returned result {actionResultName} in ", m), + 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 diff --git a/src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs b/src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs index d9416b4f0f..d2c3d763df 100644 --- a/src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs +++ b/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("other", "value") }, }; + public static object[][] PageRouteValuesTestData { get; } = new object[][] + { + new object[]{ "{page = \"bar\"}", new KeyValuePair("page", "bar") }, + new object[]{ "{page = \"bar\", other = \"value\"}", + new KeyValuePair("page", "bar"), + new KeyValuePair("other", "value") }, + }; + [Theory] [MemberData(nameof(RouteValuesTestData))] - public void ExecutingAction_WithGivenRouteValues_LogsActionAndRouteData(string expectedRouteValuesLogMessage, params KeyValuePair[] routeValues) + public void ExecutingAction_ForControllerAction_WithGivenRouteValues_LogsActionAndRouteData(string expectedRouteValuesLogMessage, params KeyValuePair[] 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[] 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[] 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() { diff --git a/src/Mvc/Mvc.RazorPages/src/PageLoggerExtensions.cs b/src/Mvc/Mvc.RazorPages/src/PageLoggerExtensions.cs index 61e22cb8be..39d07f8145 100644 --- a/src/Mvc/Mvc.RazorPages/src/PageLoggerExtensions.cs +++ b/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); diff --git a/src/Mvc/Mvc.RazorPages/test/Infrastructure/PageActionInvokerTest.cs b/src/Mvc/Mvc.RazorPages/test/Infrastructure/PageActionInvokerTest.cs index 46dd187171..a5f55be7b2 100644 --- a/src/Mvc/Mvc.RazorPages/test/Infrastructure/PageActionInvokerTest.cs +++ b/src/Mvc/Mvc.RazorPages/test/Infrastructure/PageActionInvokerTest.cs @@ -1391,15 +1391,21 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure #region Logs - [Fact] - public async Task InvokeAction_LogsPageFactory() + [Theory] + [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); - Assert.Contains($"Executed page factory for page {pageName}", messages); - } + var pagePath = actionDescriptor.ViewEnginePath; + 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] - public async Task InvokeAction_LogsPageModelFactory() - { - // Arrange - var testSink = new TestSink(); - var loggerFactory = new TestLoggerFactory(testSink, enabled: true); - var logger = loggerFactory.CreateLogger("test"); - - var actionDescriptor = CreateDescriptorForPageModelPage(); - var invoker = CreateInvoker(null, actionDescriptor, logger: logger); - - // Act - await invoker.InvokeAsync(); - - // 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 model factory for page {pageName}", messages); - Assert.Contains($"Executed page model factory for page {pageName}", messages); + Assert.Collection( + messages, + m => Assert.Equal($"Route matched with {{page = \"foo\"}}. Executing page {pagePath}", m), + m => Assert.Equal("Execution plan of authorization filters (in the following order): None", m), + m => Assert.Equal("Execution plan of resource filters (in the following order): None", m), + m => Assert.Equal("Execution plan of action filters (in the following order): None", m), + 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), + m => Assert.Equal($"Executing {factoryType} factory for page {pageName}", m), + m => Assert.Equal($"Executed {factoryType} factory for page {pageName}", m), + m => Assert.Equal($"Executing handler method {methodFullName} - ModelState is Valid", m), + m => Assert.Equal($"Executed handler method {methodName}, returned result {resultName}.", m), + m => Assert.Equal($"Before executing action result {resultName}.", m), + m => Assert.Equal($"After executing action result {resultName}.", m), + m => Assert.StartsWith($"Executed page {pagePath} in ", m)); } #endregion diff --git a/src/Mvc/Mvc.RazorPages/test/PageLoggerExtensionsTest.cs b/src/Mvc/Mvc.RazorPages/test/PageLoggerExtensionsTest.cs index c393ad6bc4..1344e72521 100644 --- a/src/Mvc/Mvc.RazorPages/test/PageLoggerExtensionsTest.cs +++ b/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 (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).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.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).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.ToString with arguments ({expectedArgumentsMessage})", + enumerator.Current.State.ToString()); + } } }