diff --git a/src/Mvc/Mvc.Core/src/Infrastructure/ControllerActionInvoker.cs b/src/Mvc/Mvc.Core/src/Infrastructure/ControllerActionInvoker.cs index ee0b0a2e1f..0303162b63 100644 --- a/src/Mvc/Mvc.Core/src/Infrastructure/ControllerActionInvoker.cs +++ b/src/Mvc/Mvc.Core/src/Infrastructure/ControllerActionInvoker.cs @@ -64,8 +64,12 @@ namespace Microsoft.AspNetCore.Mvc.Infrastructure _cursor.Reset(); + _logger.ExecutingControllerFactory(controllerContext); + _instance = _cacheEntry.ControllerFactory(controllerContext); + _logger.ExecutedControllerFactory(controllerContext); + _arguments = new Dictionary(StringComparer.OrdinalIgnoreCase); var task = BindArgumentsAsync(); @@ -469,7 +473,7 @@ namespace Microsoft.AspNetCore.Mvc.Infrastructure } catch (Exception ex) { - // Wrap non task-wrapped exceptions in a Task, + // Wrap non task-wrapped exceptions in a Task, // as this isn't done automatically since the method is not async. return Task.FromException(ex); } diff --git a/src/Mvc/Mvc.Core/src/MvcCoreLoggerExtensions.cs b/src/Mvc/Mvc.Core/src/MvcCoreLoggerExtensions.cs index 17a94f3edf..ed74b23e24 100644 --- a/src/Mvc/Mvc.Core/src/MvcCoreLoggerExtensions.cs +++ b/src/Mvc/Mvc.Core/src/MvcCoreLoggerExtensions.cs @@ -27,6 +27,9 @@ namespace Microsoft.AspNetCore.Mvc public const string ActionFilter = "Action Filter"; private static readonly string[] _noFilters = new[] { "None" }; + private static readonly Action _controllerFactoryExecuting; + private static readonly Action _controllerFactoryExecuted; + private static readonly Action _actionExecuting; private static readonly Action _controllerActionExecuting; private static readonly Action _actionExecuted; @@ -152,6 +155,16 @@ namespace Microsoft.AspNetCore.Mvc static MvcCoreLoggerExtensions() { + _controllerFactoryExecuting = LoggerMessage.Define( + LogLevel.Debug, + new EventId(1, "ControllerFactoryExecuting"), + "Executing controller factory for controller {Controller} ({AssemblyName})"); + + _controllerFactoryExecuted = LoggerMessage.Define( + LogLevel.Debug, + new EventId(2, "ControllerFactoryExecuted"), + "Executed controller factory for controller {Controller} ({AssemblyName})"); + _actionExecuting = LoggerMessage.Define( LogLevel.Information, new EventId(1, "ActionExecuting"), @@ -1628,6 +1641,30 @@ namespace Microsoft.AspNetCore.Mvc _logFilterExecutionPlan(logger, filterType, filterList, null); } + public static void ExecutingControllerFactory(this ILogger logger, ControllerContext context) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + var controllerType = context.ActionDescriptor.ControllerTypeInfo.AsType(); + var controllerName = TypeNameHelper.GetTypeDisplayName(controllerType); + _controllerFactoryExecuting(logger, controllerName, controllerType.Assembly.GetName().Name, null); + } + + public static void ExecutedControllerFactory(this ILogger logger, ControllerContext context) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + var controllerType = context.ActionDescriptor.ControllerTypeInfo.AsType(); + var controllerName = TypeNameHelper.GetTypeDisplayName(controllerType); + _controllerFactoryExecuted(logger, controllerName, controllerType.Assembly.GetName().Name, null); + } + private static string[] GetFilterList(IEnumerable filters) { var filterList = new List(); diff --git a/src/Mvc/Mvc.Core/test/Controllers/ControllerFactoryProviderTest.cs b/src/Mvc/Mvc.Core/test/Controllers/ControllerFactoryProviderTest.cs index d8a7ed6c7f..8e45533263 100644 --- a/src/Mvc/Mvc.Core/test/Controllers/ControllerFactoryProviderTest.cs +++ b/src/Mvc/Mvc.Core/test/Controllers/ControllerFactoryProviderTest.cs @@ -64,7 +64,7 @@ namespace Microsoft.AspNetCore.Mvc.Controllers } [Fact] - public void CreateControllerReleaser_UsesControllerActivatorAndPropertyActivator() + public void CreateControllerFactory_UsesControllerActivatorAndPropertyActivator() { // Arrange var expectedProperty1 = new object(); diff --git a/src/Mvc/Mvc.Core/test/Infrastructure/ControllerActionInvokerTest.cs b/src/Mvc/Mvc.Core/test/Infrastructure/ControllerActionInvokerTest.cs index dda560bba4..f8488947a3 100644 --- a/src/Mvc/Mvc.Core/test/Infrastructure/ControllerActionInvokerTest.cs +++ b/src/Mvc/Mvc.Core/test/Infrastructure/ControllerActionInvokerTest.cs @@ -21,6 +21,7 @@ using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Internal; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Logging.Testing; using Microsoft.Extensions.Options; using Moq; using Xunit; @@ -1453,6 +1454,43 @@ namespace Microsoft.AspNetCore.Mvc.Infrastructure #endregion + #region Logs + + [Fact] + public async Task InvokeAsync_LogsControllerFactory() + { + // Arrange + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + var actionDescriptor = new ControllerActionDescriptor() + { + ControllerTypeInfo = typeof(TestController).GetTypeInfo(), + FilterDescriptors = new List(), + Parameters = new List(), + BoundProperties = new List(), + MethodInfo = typeof(TestController).GetMethod(nameof(TestController.ActionMethod)), + }; + + var invoker = CreateInvoker( + new IFilterMetadata[0], + actionDescriptor, + new TestController(), + logger: logger); + + // Act + await invoker.InvokeAsync(); + + // Assert + var messages = testSink.Writes.Select(write => write.State.ToString()).ToList(); + var controllerName = $"{typeof(ControllerActionInvokerTest).FullName}+{nameof(TestController)} ({typeof(ControllerActionInvokerTest).Assembly.GetName().Name})"; + Assert.Contains($"Executing controller factory for controller {controllerName}", messages); + Assert.Contains($"Executed controller factory for controller {controllerName}", messages); + } + + #endregion + protected override IActionInvoker CreateInvoker( IFilterMetadata[] filters, Exception exception = null, diff --git a/src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs b/src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs index 37688c2107..75172e22e3 100644 --- a/src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs +++ b/src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs @@ -1,6 +1,8 @@ // 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 System; +using System.Reflection; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Mvc.Filters; using Microsoft.AspNetCore.Mvc.Formatters; @@ -315,6 +317,62 @@ namespace Microsoft.AspNetCore.Mvc write.State.ToString()); } + [Fact] + public void ExecutingControllerFactory_LogsControllerName() + { + // Arrange + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + var context = new ControllerContext + { + ActionDescriptor = new Controllers.ControllerActionDescriptor + { + // Using a generic type to verify the use of a clean name + ControllerTypeInfo = typeof(ValueTuple).GetTypeInfo() + } + }; + + // Act + logger.ExecutingControllerFactory(context); + + // Assert + var write = Assert.Single(testSink.Writes); + Assert.Equal( + "Executing controller factory for controller " + + "System.ValueTuple (System.Private.CoreLib)", + write.State.ToString()); + } + + [Fact] + public void ExecutedControllerFactory_LogsControllerName() + { + // Arrange + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + var context = new ControllerContext + { + ActionDescriptor = new Controllers.ControllerActionDescriptor + { + // Using a generic type to verify the use of a clean name + ControllerTypeInfo = typeof(ValueTuple).GetTypeInfo() + } + }; + + // Act + logger.ExecutedControllerFactory(context); + + // Assert + var write = Assert.Single(testSink.Writes); + Assert.Equal( + "Executed controller factory for controller " + + "System.ValueTuple (System.Private.CoreLib)", + write.State.ToString()); + } + public interface IOrderedAuthorizeFilter : IAuthorizationFilter, IAsyncAuthorizationFilter, IOrderedFilter { } public interface IOrderedResourceFilter : IResourceFilter, IAsyncResourceFilter, IOrderedFilter { } diff --git a/src/Mvc/Mvc.RazorPages/src/Infrastructure/PageActionInvoker.cs b/src/Mvc/Mvc.RazorPages/src/Infrastructure/PageActionInvoker.cs index 7ac20bfe05..c7ab590f16 100644 --- a/src/Mvc/Mvc.RazorPages/src/Infrastructure/PageActionInvoker.cs +++ b/src/Mvc/Mvc.RazorPages/src/Infrastructure/PageActionInvoker.cs @@ -138,8 +138,13 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure { if (HasPageModel) { + _logger.ExecutingPageModelFactory(_pageContext); + // Since this is a PageModel, we need to activate it, and then run a handler method on the model. _pageModel = CacheEntry.ModelFactory(_pageContext); + + _logger.ExecutedPageModelFactory(_pageContext); + _pageContext.ViewData.Model = _pageModel; return _pageModel; @@ -156,8 +161,12 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure _htmlHelperOptions); _viewContext.ExecutingFilePath = _pageContext.ActionDescriptor.RelativePath; + _logger.ExecutingPageFactory(_pageContext); + _page = (PageBase)CacheEntry.PageFactory(_pageContext, _viewContext); + _logger.ExecutedPageFactory(_pageContext); + if (_actionDescriptor.ModelTypeInfo == _actionDescriptor.PageTypeInfo) { _pageContext.ViewData.Model = _page; diff --git a/src/Mvc/Mvc.RazorPages/src/PageLoggerExtensions.cs b/src/Mvc/Mvc.RazorPages/src/PageLoggerExtensions.cs index a48b9a744a..61e22cb8be 100644 --- a/src/Mvc/Mvc.RazorPages/src/PageLoggerExtensions.cs +++ b/src/Mvc/Mvc.RazorPages/src/PageLoggerExtensions.cs @@ -5,6 +5,7 @@ using System; using Microsoft.AspNetCore.Mvc.Filters; using Microsoft.AspNetCore.Mvc.ModelBinding; using Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure; +using Microsoft.Extensions.Internal; using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.Mvc.RazorPages @@ -13,6 +14,10 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages { public const string PageFilter = "Page Filter"; + private static readonly Action _pageModelFactoryExecuting; + private static readonly Action _pageModelFactoryExecuted; + private static readonly Action _pageFactoryExecuting; + private static readonly Action _pageFactoryExecuted; private static readonly Action _handlerMethodExecuting; private static readonly Action _implicitHandlerMethodExecuting; private static readonly Action _handlerMethodExecutingWithArguments; @@ -27,6 +32,26 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages { // These numbers start at 101 intentionally to avoid conflict with the IDs used by ResourceInvoker. + _pageModelFactoryExecuting = LoggerMessage.Define( + LogLevel.Debug, + new EventId(101, "ExecutingModelFactory"), + "Executing page model factory for page {Page} ({AssemblyName})"); + + _pageModelFactoryExecuted = LoggerMessage.Define( + LogLevel.Debug, + new EventId(102, "ExecutedModelFactory"), + "Executed page model factory for page {Page} ({AssemblyName})"); + + _pageFactoryExecuting = LoggerMessage.Define( + LogLevel.Debug, + new EventId(101, "ExecutingPageFactory"), + "Executing page factory for page {Page} ({AssemblyName})"); + + _pageFactoryExecuted = LoggerMessage.Define( + LogLevel.Debug, + new EventId(102, "ExecutedPageFactory"), + "Executed page factory for page {Page} ({AssemblyName})"); + _handlerMethodExecuting = LoggerMessage.Define( LogLevel.Information, new EventId(101, "ExecutingHandlerMethod"), @@ -73,6 +98,54 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages "{FilterType}: After executing {Method} on filter {Filter}."); } + public static void ExecutingPageModelFactory(this ILogger logger, PageContext context) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + var pageType = context.ActionDescriptor.PageTypeInfo.AsType(); + var pageName = TypeNameHelper.GetTypeDisplayName(pageType); + _pageModelFactoryExecuting(logger, pageName, pageType.Assembly.GetName().Name, null); + } + + public static void ExecutedPageModelFactory(this ILogger logger, PageContext context) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + var pageType = context.ActionDescriptor.PageTypeInfo.AsType(); + var pageName = TypeNameHelper.GetTypeDisplayName(pageType); + _pageModelFactoryExecuted(logger, pageName, pageType.Assembly.GetName().Name, null); + } + + public static void ExecutingPageFactory(this ILogger logger, PageContext context) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + var pageType = context.ActionDescriptor.PageTypeInfo.AsType(); + var pageName = TypeNameHelper.GetTypeDisplayName(pageType); + _pageFactoryExecuting(logger, pageName, pageType.Assembly.GetName().Name, null); + } + + public static void ExecutedPageFactory(this ILogger logger, PageContext context) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + var pageType = context.ActionDescriptor.PageTypeInfo.AsType(); + var pageName = TypeNameHelper.GetTypeDisplayName(pageType); + _pageFactoryExecuted(logger, pageName, pageType.Assembly.GetName().Name, null); + } + public static void ExecutingHandlerMethod(this ILogger logger, PageContext context, HandlerMethodDescriptor handler, object[] arguments) { if (logger.IsEnabled(LogLevel.Information)) diff --git a/src/Mvc/Mvc.RazorPages/test/Infrastructure/PageActionInvokerTest.cs b/src/Mvc/Mvc.RazorPages/test/Infrastructure/PageActionInvokerTest.cs index 3a948272a9..46dd187171 100644 --- a/src/Mvc/Mvc.RazorPages/test/Infrastructure/PageActionInvokerTest.cs +++ b/src/Mvc/Mvc.RazorPages/test/Infrastructure/PageActionInvokerTest.cs @@ -23,6 +23,7 @@ using Microsoft.AspNetCore.Testing; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Logging.Testing; using Microsoft.Extensions.Options; using Moq; using Xunit; @@ -1388,6 +1389,52 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure #endregion + #region Logs + + [Fact] + public async Task InvokeAction_LogsPageFactory() + { + // Arrange + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + var actionDescriptor = CreateDescriptorForSimplePage(); + 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 factory for page {pageName}", messages); + Assert.Contains($"Executed page factory for page {pageName}", messages); + } + + [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); + } + + #endregion + protected override IActionInvoker CreateInvoker( IFilterMetadata[] filters, Exception exception = null, @@ -1635,13 +1682,13 @@ namespace Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure new HandlerMethodDescriptor() { HttpMethod = "GET", - MethodInfo = typeof(PageModel).GetTypeInfo().GetMethod(nameof(TestPageModel.OnGetHandler1)), + MethodInfo = typeof(TestPageModel).GetTypeInfo().GetMethod(nameof(TestPageModel.OnGetHandler1)), Parameters = new List(), }, new HandlerMethodDescriptor() { HttpMethod = "GET", - MethodInfo = typeof(PageModel).GetTypeInfo().GetMethod(nameof(TestPageModel.OnGetHandler2)), + MethodInfo = typeof(TestPageModel).GetTypeInfo().GetMethod(nameof(TestPageModel.OnGetHandler2)), Parameters = new List(), }, }, diff --git a/src/Mvc/Mvc.RazorPages/test/PageLoggerExtensionsTest.cs b/src/Mvc/Mvc.RazorPages/test/PageLoggerExtensionsTest.cs new file mode 100644 index 0000000000..c393ad6bc4 --- /dev/null +++ b/src/Mvc/Mvc.RazorPages/test/PageLoggerExtensionsTest.cs @@ -0,0 +1,126 @@ +// 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 System; +using System.Reflection; +using Microsoft.AspNetCore.Mvc.RazorPages; +using Microsoft.Extensions.Logging.Testing; +using Xunit; + +namespace Microsoft.AspNetCore.Mvc +{ + public class PageLoggerExtensionsTest + { + [Fact] + public void ExecutingPageFactory_LogsPageName() + { + // Arrange + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + var context = new PageContext + { + ActionDescriptor = new CompiledPageActionDescriptor + { + // Using a generic type to verify the use of a clean name + PageTypeInfo = typeof(ValueTuple).GetTypeInfo() + } + }; + + // Act + logger.ExecutingPageFactory(context); + + // Assert + var write = Assert.Single(testSink.Writes); + Assert.Equal( + "Executing page factory for page " + + "System.ValueTuple (System.Private.CoreLib)", + write.State.ToString()); + } + + [Fact] + public void ExecutedPageFactory_LogsPageName() + { + // Arrange + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + var context = new PageContext + { + ActionDescriptor = new CompiledPageActionDescriptor + { + // Using a generic type to verify the use of a clean name + PageTypeInfo = typeof(ValueTuple).GetTypeInfo() + } + }; + + // Act + logger.ExecutedPageFactory(context); + + // Assert + var write = Assert.Single(testSink.Writes); + Assert.Equal( + "Executed page factory for page " + + "System.ValueTuple (System.Private.CoreLib)", + write.State.ToString()); + } + + [Fact] + public void ExecutingPageModelFactory_LogsPageName() + { + // Arrange + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + var context = new PageContext + { + ActionDescriptor = new CompiledPageActionDescriptor + { + // Using a generic type to verify the use of a clean name + PageTypeInfo = typeof(ValueTuple).GetTypeInfo() + } + }; + + // Act + logger.ExecutingPageModelFactory(context); + + // Assert + var write = Assert.Single(testSink.Writes); + Assert.Equal( + "Executing page model factory for page " + + "System.ValueTuple (System.Private.CoreLib)", + write.State.ToString()); + } + + [Fact] + public void ExecutedPageModelFactory_LogsPageName() + { + // Arrange + var testSink = new TestSink(); + var loggerFactory = new TestLoggerFactory(testSink, enabled: true); + var logger = loggerFactory.CreateLogger("test"); + + var context = new PageContext + { + ActionDescriptor = new CompiledPageActionDescriptor + { + // Using a generic type to verify the use of a clean name + PageTypeInfo = typeof(ValueTuple).GetTypeInfo() + } + }; + + // Act + logger.ExecutedPageModelFactory(context); + + // Assert + var write = Assert.Single(testSink.Writes); + Assert.Equal( + "Executed page model factory for page " + + "System.ValueTuple (System.Private.CoreLib)", + write.State.ToString()); + } + } +}