Mvc.Core logging for controller and page factories (#11526)

* Mvc.Core logging for controller and page factories

* Fixed name in loosely related test

* Renamed model to page model

* Extensions tests

* Controller Tests

* Page tests

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<string, object>(StringComparer.OrdinalIgnoreCase);
 
                         var task = BindArgumentsAsync();

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<ILogger, string, string, Exception> _controllerFactoryExecuting;
+        private static readonly Action<ILogger, string, string, Exception> _controllerFactoryExecuted;
+
         private static readonly Action<ILogger, string, string, Exception> _actionExecuting;
         private static readonly Action<ILogger, string, MethodInfo, string, string, Exception> _controllerActionExecuting;
         private static readonly Action<ILogger, string, double, Exception> _actionExecuted;
@@ -152,6 +155,16 @@ namespace Microsoft.AspNetCore.Mvc
 
         static MvcCoreLoggerExtensions()
         {
+            _controllerFactoryExecuting = LoggerMessage.Define<string, string>(
+                LogLevel.Debug,
+                new EventId(1, "ControllerFactoryExecuting"),
+                "Executing controller factory for controller {Controller} ({AssemblyName})");
+
+            _controllerFactoryExecuted = LoggerMessage.Define<string, string>(
+                LogLevel.Debug,
+                new EventId(2, "ControllerFactoryExecuted"),
+                "Executed controller factory for controller {Controller} ({AssemblyName})");
+
             _actionExecuting = LoggerMessage.Define<string, string>(
                 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<IFilterMetadata> filters)
         {
             var filterList = new List<string>();

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();

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<FilterDescriptor>(),
+                Parameters = new List<ParameterDescriptor>(),
+                BoundProperties = new List<ParameterDescriptor>(),
+                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,

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<int, string>).GetTypeInfo()
+                }
+            };
+
+            // Act
+            logger.ExecutingControllerFactory(context);
+
+            // Assert
+            var write = Assert.Single(testSink.Writes);
+            Assert.Equal(
+                "Executing controller factory for controller " +
+                "System.ValueTuple<int, string> (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<int, string>).GetTypeInfo()
+                }
+            };
+
+            // Act
+            logger.ExecutedControllerFactory(context);
+
+            // Assert
+            var write = Assert.Single(testSink.Writes);
+            Assert.Equal(
+                "Executed controller factory for controller " +
+                "System.ValueTuple<int, string> (System.Private.CoreLib)",
+                write.State.ToString());
+        }
+
         public interface IOrderedAuthorizeFilter : IAuthorizationFilter, IAsyncAuthorizationFilter, IOrderedFilter { }
 
         public interface IOrderedResourceFilter : IResourceFilter, IAsyncResourceFilter, IOrderedFilter { }

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;

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<ILogger, string, string, Exception> _pageModelFactoryExecuting;
+        private static readonly Action<ILogger, string, string, Exception> _pageModelFactoryExecuted;
+        private static readonly Action<ILogger, string, string, Exception> _pageFactoryExecuting;
+        private static readonly Action<ILogger, string, string, Exception> _pageFactoryExecuted;
         private static readonly Action<ILogger, string, ModelValidationState, Exception> _handlerMethodExecuting;
         private static readonly Action<ILogger, ModelValidationState, Exception> _implicitHandlerMethodExecuting;
         private static readonly Action<ILogger, string, string[], Exception> _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<string, string>(
+                LogLevel.Debug,
+                new EventId(101, "ExecutingModelFactory"),
+               "Executing page model factory for page {Page} ({AssemblyName})");
+
+            _pageModelFactoryExecuted = LoggerMessage.Define<string, string>(
+                LogLevel.Debug,
+                new EventId(102, "ExecutedModelFactory"),
+                "Executed page model factory for page {Page} ({AssemblyName})");
+
+            _pageFactoryExecuting = LoggerMessage.Define<string, string>(
+                LogLevel.Debug,
+                new EventId(101, "ExecutingPageFactory"),
+               "Executing page factory for page {Page} ({AssemblyName})");
+
+            _pageFactoryExecuted = LoggerMessage.Define<string, string>(
+                LogLevel.Debug,
+                new EventId(102, "ExecutedPageFactory"),
+                "Executed page factory for page {Page} ({AssemblyName})");
+
             _handlerMethodExecuting = LoggerMessage.Define<string, ModelValidationState>(
                 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))

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<HandlerParameterDescriptor>(),
                     },
                     new HandlerMethodDescriptor()
                     {
                         HttpMethod = "GET",
-                        MethodInfo = typeof(PageModel).GetTypeInfo().GetMethod(nameof(TestPageModel.OnGetHandler2)),
+                        MethodInfo = typeof(TestPageModel).GetTypeInfo().GetMethod(nameof(TestPageModel.OnGetHandler2)),
                         Parameters = new List<HandlerParameterDescriptor>(),
                     },
                 },

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<int, string>).GetTypeInfo()
+                }
+            };
+
+            // Act
+            logger.ExecutingPageFactory(context);
+
+            // Assert
+            var write = Assert.Single(testSink.Writes);
+            Assert.Equal(
+                "Executing page factory for page " +
+                "System.ValueTuple<int, string> (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<int, string>).GetTypeInfo()
+                }
+            };
+
+            // Act
+            logger.ExecutedPageFactory(context);
+
+            // Assert
+            var write = Assert.Single(testSink.Writes);
+            Assert.Equal(
+                "Executed page factory for page " +
+                "System.ValueTuple<int, string> (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<int, string>).GetTypeInfo()
+                }
+            };
+
+            // Act
+            logger.ExecutingPageModelFactory(context);
+
+            // Assert
+            var write = Assert.Single(testSink.Writes);
+            Assert.Equal(
+                "Executing page model factory for page " +
+                "System.ValueTuple<int, string> (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<int, string>).GetTypeInfo()
+                }
+            };
+
+            // Act
+            logger.ExecutedPageModelFactory(context);
+
+            // Assert
+            var write = Assert.Single(testSink.Writes);
+            Assert.Equal(
+                "Executed page model factory for page " +
+                "System.ValueTuple<int, string> (System.Private.CoreLib)",
+                write.State.ToString());
+        }
+    }
+}