Update MvcCoreLoggerExtensions to use LoggerMessageAttribute

MvcCoreLoggerExtensions includes the log messages for a whole slew of MVC types. Consequently
it re-uses event ids and is hard maintain. This PR simultaenously updates the type to use
LoggerMessageAttribute, while also attempts to move as many of the individual log statements to the
appropriate type.

This change unearthed incorrect reuse of event ids within the same type that has also been corrected by assigning
new ids.

Fixes dotnet#32087

src/Mvc/Mvc.Core/src/ChallengeResult.cs

@@ -1,6 +1,7 @@
 // Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 
+using System.Linq;
 using Microsoft.AspNetCore.Authentication;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Logging;
@@ -10,7 +11,7 @@ namespace Microsoft.AspNetCore.Mvc;
 /// <summary>
 /// An <see cref="ActionResult"/> that on execution invokes <see cref="M:HttpContext.ChallengeAsync"/>.
 /// </summary>
-public class ChallengeResult : ActionResult
+public partial class ChallengeResult : ActionResult
 {
     /// <summary>
     /// Initializes a new instance of <see cref="ChallengeResult"/>.
@@ -97,8 +98,7 @@ public override async Task ExecuteResultAsync(ActionContext context)
         var httpContext = context.HttpContext;
         var loggerFactory = httpContext.RequestServices.GetRequiredService<ILoggerFactory>();
         var logger = loggerFactory.CreateLogger<ChallengeResult>();
-
-        logger.ChallengeResultExecuting(AuthenticationSchemes);
+        Log.ChallengeResultExecuting(logger, AuthenticationSchemes);
 
         if (AuthenticationSchemes != null && AuthenticationSchemes.Count > 0)
         {
@@ -112,4 +112,18 @@ public override async Task ExecuteResultAsync(ActionContext context)
             await httpContext.ChallengeAsync(Properties);
         }
     }
+
+    private static partial class Log
+    {
+        public static void ChallengeResultExecuting(ILogger logger, IList<string> schemes)
+        {
+            if (logger.IsEnabled(LogLevel.Information))
+            {
+                ChallengeResultExecuting(logger, schemes.ToArray());
+            }
+        }
+
+        [LoggerMessage(1, LogLevel.Information, "Executing ChallengeResult with authentication schemes ({Schemes}).", EventName = "ChallengeResultExecuting", SkipEnabledCheck = true)]
+        private static partial void ChallengeResultExecuting(ILogger logger, string[] schemes);
+    }
 }

src/Mvc/Mvc.Core/src/ForbidResult.cs

@@ -1,6 +1,7 @@
 // Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 
+using System.Linq;
 using Microsoft.AspNetCore.Authentication;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Logging;
@@ -10,7 +11,7 @@ namespace Microsoft.AspNetCore.Mvc;
 /// <summary>
 /// An <see cref="ActionResult"/> that on execution invokes <see cref="M:HttpContext.ForbidAsync"/>.
 /// </summary>
-public class ForbidResult : ActionResult
+public partial class ForbidResult : ActionResult
 {
     /// <summary>
     /// Initializes a new instance of <see cref="ForbidResult"/>.
@@ -98,8 +99,7 @@ public override async Task ExecuteResultAsync(ActionContext context)
 
         var loggerFactory = httpContext.RequestServices.GetRequiredService<ILoggerFactory>();
         var logger = loggerFactory.CreateLogger<ForbidResult>();
-
-        logger.ForbidResultExecuting(AuthenticationSchemes);
+        Log.ForbidResultExecuting(logger, AuthenticationSchemes);
 
         if (AuthenticationSchemes != null && AuthenticationSchemes.Count > 0)
         {
@@ -113,4 +113,18 @@ public override async Task ExecuteResultAsync(ActionContext context)
             await httpContext.ForbidAsync(Properties);
         }
     }
+
+    private static partial class Log
+    {
+        public static void ForbidResultExecuting(ILogger logger, IList<string> authenticationSchemes)
+        {
+            if (logger.IsEnabled(LogLevel.Information))
+            {
+                ForbidResultExecuting(logger, authenticationSchemes.ToArray());
+            }
+        }
+
+        [LoggerMessage(1, LogLevel.Information, $"Executing {nameof(ForbidResult)} with authentication schemes ({{Schemes}}).", EventName = "ForbidResultExecuting", SkipEnabledCheck =  true)]
+        private static partial void ForbidResultExecuting(ILogger logger, string[] schemes);
+    }
 }

src/Mvc/Mvc.Core/src/Formatters/FormatFilter.cs

@@ -110,7 +110,7 @@ public void OnResourceExecuting(ResourceExecutingContext context)
         // type than requested e.g. OK if "text/*" requested and action supports "text/plain".
         if (!IsSuperSetOfAnySupportedMediaType(contentType, supportedMediaTypes))
         {
-            _logger.ActionDoesNotSupportFormatFilterContentType(contentType, supportedMediaTypes);
+            Log.ActionDoesNotSupportFormatFilterContentType(_logger, contentType, supportedMediaTypes);
             context.Result = new NotFoundResult();
         }
     }
@@ -185,6 +185,9 @@ private static partial class Log
         [LoggerMessage(1, LogLevel.Debug, "Could not find a media type for the format '{FormatFilterContentType}'.", EventName = "UnsupportedFormatFilterContentType")]
         public static partial void UnsupportedFormatFilterContentType(ILogger logger, string formatFilterContentType);
 
+        [LoggerMessage(2, LogLevel.Debug, "Current action does not support the content type '{FormatFilterContentType}'. The supported content types are '{SupportedMediaTypes}'.", EventName = "ActionDoesNotSupportFormatFilterContentType")]
+        public static partial void ActionDoesNotSupportFormatFilterContentType(ILogger logger, string formatFilterContentType, MediaTypeCollection supportedMediaTypes);
+
         [LoggerMessage(3, LogLevel.Debug, "Cannot apply content type '{FormatFilterContentType}' to the response as current action had explicitly set a preferred content type.", EventName = "CannotApplyFormatFilterContentType")]
         public static partial void CannotApplyFormatFilterContentType(ILogger logger, string formatFilterContentType);
 

src/Mvc/Mvc.Core/src/Infrastructure/ClientErrorResultFilter.cs

@@ -1,14 +1,12 @@
 // Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 
-#nullable enable
-
 using Microsoft.AspNetCore.Mvc.Filters;
 using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Mvc.Infrastructure;
 
-internal class ClientErrorResultFilter : IAlwaysRunResultFilter, IOrderedFilter
+internal partial class ClientErrorResultFilter : IAlwaysRunResultFilter, IOrderedFilter
 {
     internal const int FilterOrder = -2000;
     private readonly IClientErrorFactory _clientErrorFactory;
@@ -56,7 +54,13 @@ public void OnResultExecuting(ResultExecutingContext context)
             return;
         }
 
-        _logger.TransformingClientError(context.Result.GetType(), result.GetType(), clientError.StatusCode);
+        Log.TransformingClientError(_logger, context.Result.GetType(), result.GetType(), clientError.StatusCode);
         context.Result = result;
     }
+
+    private static partial class Log
+    {
+        [LoggerMessage(49, LogLevel.Trace, "Replacing {InitialActionResultType} with status code {StatusCode} with {ReplacedActionResultType}.", EventName = "ClientErrorResultFilter")]
+        public static partial void TransformingClientError(ILogger logger, Type initialActionResultType, Type replacedActionResultType, int? statusCode);
+    }
 }

src/Mvc/Mvc.Core/src/Infrastructure/ControllerActionInvoker.cs

@@ -4,16 +4,18 @@
 #nullable enable
 
 using System.Diagnostics;
+using System.Globalization;
 using System.Runtime.ExceptionServices;
 using Microsoft.AspNetCore.Mvc.Abstractions;
 using Microsoft.AspNetCore.Mvc.Filters;
+using Microsoft.AspNetCore.Mvc.ModelBinding;
 using Microsoft.Extensions.Internal;
 using Microsoft.Extensions.Logging;
 using Resources = Microsoft.AspNetCore.Mvc.Core.Resources;
 
 namespace Microsoft.AspNetCore.Mvc.Infrastructure;
 
-internal class ControllerActionInvoker : ResourceInvoker, IActionInvoker
+internal partial class ControllerActionInvoker : ResourceInvoker, IActionInvoker
 {
     private readonly ControllerActionInvokerCacheEntry _cacheEntry;
     private readonly ControllerContext _controllerContext;
@@ -64,12 +66,10 @@ private Task Next(ref State next, ref Scope scope, ref object? state, ref bool i
                     var controllerContext = _controllerContext;
 
                     _cursor.Reset();
-
-                    _logger.ExecutingControllerFactory(controllerContext);
+                    Log.ExecutingControllerFactory(_logger, controllerContext);
 
                     _instance = _cacheEntry.ControllerFactory(controllerContext);
-
-                    _logger.ExecutedControllerFactory(controllerContext);
+                    Log.ExecutedControllerFactory(_logger, controllerContext);
 
                     _arguments = new Dictionary<string, object?>(StringComparer.OrdinalIgnoreCase);
 
@@ -424,7 +424,7 @@ static async Task Logged(ControllerActionInvoker invoker)
                     controllerContext,
                     arguments,
                     controller);
-                logger.ActionMethodExecuting(controllerContext, orderedArguments);
+                Log.ActionMethodExecuting(logger, controllerContext, orderedArguments);
                 var stopwatch = ValueStopwatch.StartNew();
                 var actionResultValueTask = actionMethodExecutor.Execute(invoker._mapper, objectMethodExecutor, controller!, orderedArguments);
                 if (actionResultValueTask.IsCompletedSuccessfully)
@@ -437,7 +437,7 @@ static async Task Logged(ControllerActionInvoker invoker)
                 }
 
                 invoker._result = result;
-                logger.ActionMethodExecuted(controllerContext, result, stopwatch.GetElapsedTime());
+                Log.ActionMethodExecuted(logger, controllerContext, result, stopwatch.GetElapsedTime());
             }
             finally
             {
@@ -584,4 +584,78 @@ private sealed class ActionExecutedContextSealed : ActionExecutedContext
     {
         public ActionExecutedContextSealed(ActionContext actionContext, IList<IFilterMetadata> filters, object controller) : base(actionContext, filters, controller) { }
     }
+
+    // Internal for unit testing
+    internal static new partial class Log
+    {
+        public static void ExecutingControllerFactory(ILogger logger, ControllerContext context)
+        {
+            if (!logger.IsEnabled(LogLevel.Debug))
+            {
+                return;
+            }
+
+            var controllerType = context.ActionDescriptor.ControllerTypeInfo.AsType();
+            var controllerName = TypeNameHelper.GetTypeDisplayName(controllerType);
+            ExecutingControllerFactory(logger, controllerName, controllerType.Assembly.GetName().Name);
+        }
+
+        [LoggerMessage(1, LogLevel.Debug, "Executing controller factory for controller {Controller} ({AssemblyName})", EventName = "ControllerFactoryExecuting", SkipEnabledCheck = true)]
+        private static partial void ExecutingControllerFactory(ILogger logger, string controller, string? assemblyName);
+
+        public static void ExecutedControllerFactory(ILogger logger, ControllerContext context)
+        {
+            if (!logger.IsEnabled(LogLevel.Debug))
+            {
+                return;
+            }
+
+            var controllerType = context.ActionDescriptor.ControllerTypeInfo.AsType();
+            var controllerName = TypeNameHelper.GetTypeDisplayName(controllerType);
+            ExecutedControllerFactory(logger, controllerName, controllerType.Assembly.GetName().Name);
+        }
+
+        [LoggerMessage(2, LogLevel.Debug, "Executed controller factory for controller {Controller} ({AssemblyName})", EventName = "ControllerFactoryExecuted", SkipEnabledCheck = true)]
+        private static partial void ExecutedControllerFactory(ILogger logger, string controller, string? assemblyName);
+
+        public static void ActionMethodExecuting(ILogger logger, ControllerContext context, object?[]? arguments)
+        {
+            if (logger.IsEnabled(LogLevel.Information))
+            {
+                var actionName = context.ActionDescriptor.DisplayName;
+
+                var validationState = context.ModelState.ValidationState;
+                ActionMethodExecuting(logger, actionName, validationState);
+
+                if (arguments != null && logger.IsEnabled(LogLevel.Trace))
+                {
+                    var convertedArguments = new string?[arguments.Length];
+                    for (var i = 0; i < arguments.Length; i++)
+                    {
+                        convertedArguments[i] = Convert.ToString(arguments[i], CultureInfo.InvariantCulture);
+                    }
+
+                    ActionMethodExecutingWithArguments(logger, actionName, convertedArguments);
+                }
+            }
+        }
+
+        [LoggerMessage(101, LogLevel.Information, "Executing action method {ActionName} - Validation state: {ValidationState}", EventName = "ActionMethodExecuting", SkipEnabledCheck = true)]
+        private static partial void ActionMethodExecuting(ILogger logger, string? actionName, ModelValidationState validationState);
+
+        [LoggerMessage(102, LogLevel.Trace, "Executing action method {ActionName} with arguments ({Arguments})", EventName = "ActionMethodExecutingWithArguments", SkipEnabledCheck = true)]
+        private static partial void ActionMethodExecutingWithArguments(ILogger logger, string? actionName, string?[] arguments);
+
+        public static void ActionMethodExecuted(ILogger logger, ControllerContext context, IActionResult result, TimeSpan timeSpan)
+        {
+            if (logger.IsEnabled(LogLevel.Information))
+            {
+                var actionName = context.ActionDescriptor.DisplayName;
+                ActionMethodExecuted(logger, actionName, Convert.ToString(result, CultureInfo.InvariantCulture), timeSpan.TotalMilliseconds);
+            }
+        }
+
+        [LoggerMessage(103, LogLevel.Information, "Executed action method {ActionName}, returned result {ActionResult} in {ElapsedMilliseconds}ms.", EventName = "ActionMethodExecuted", SkipEnabledCheck = true)]
+        private static partial void ActionMethodExecuted(ILogger logger, string? actionName, string? actionResult, double elapsedMilliseconds);
+    }
 }

src/Mvc/Mvc.Core/src/Infrastructure/DefaultOutputFormatterSelector.cs

@@ -4,6 +4,7 @@
 #nullable enable
 
 using System.Collections.ObjectModel;
+using System.Globalization;
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Mvc.Core;
 using Microsoft.AspNetCore.Mvc.Formatters;
@@ -157,7 +158,7 @@ public DefaultOutputFormatterSelector(IOptions<MvcOptions> options, ILoggerFacto
 
         if (selectedFormatter != null)
         {
-            _logger.FormatterSelected(selectedFormatter, context);
+            Log.FormatterSelected(_logger, selectedFormatter, context);
         }
 
         return selectedFormatter;
@@ -299,6 +300,21 @@ private static void ValidateContentTypes(MediaTypeCollection contentTypes)
 
     private static partial class Log
     {
+        public static void FormatterSelected(
+            ILogger logger,
+            IOutputFormatter outputFormatter,
+            OutputFormatterCanWriteContext context)
+        {
+            if (logger.IsEnabled(LogLevel.Debug))
+            {
+                var contentType = Convert.ToString(context.ContentType, CultureInfo.InvariantCulture);
+                FormatterSelected(logger, outputFormatter, contentType);
+            }
+        }
+
+        [LoggerMessage(2, LogLevel.Debug, "Selected output formatter '{OutputFormatter}' and content type '{ContentType}' to write the response.", EventName = "FormatterSelected", SkipEnabledCheck = true)]
+        public static partial void FormatterSelected(ILogger logger, IOutputFormatter outputFormatter, string? contentType);
+
         [LoggerMessage(4, LogLevel.Debug, "No information found on request to perform content negotiation.", EventName = "NoAcceptForNegotiation")]
         public static partial void NoAcceptForNegotiation(ILogger logger);
 

src/Mvc/Mvc.Core/src/Infrastructure/FileContentResultExecutor.cs

@@ -35,7 +35,7 @@ public virtual Task ExecuteAsync(ActionContext context, FileContentResult result
             throw new ArgumentNullException(nameof(result));
         }
 
-        Logger.ExecutingFileResult(result);
+        Log.ExecutingFileResult(Logger, result);
 
         var (range, rangeLength, serveBody) = SetHeadersAndLog(
             context,
@@ -88,6 +88,18 @@ protected virtual Task WriteFileAsync(ActionContext context, FileContentResult r
 
     private static partial class Log
     {
+        public static void ExecutingFileResult(ILogger logger, FileResult fileResult)
+        {
+            if (logger.IsEnabled(LogLevel.Information))
+            {
+                var fileResultType = fileResult.GetType().Name;
+                ExecutingFileResultWithNoFileName(logger, fileResultType, fileResult.FileDownloadName);
+            }
+        }
+
+        [LoggerMessage(2, LogLevel.Information, "Executing {FileResultType}, sending file with download name '{FileDownloadName}' ...", EventName = "ExecutingFileResultWithNoFileName", SkipEnabledCheck = true)]
+        private static partial void ExecutingFileResultWithNoFileName(ILogger logger, string fileResultType, string fileDownloadName);
+
         [LoggerMessage(17, LogLevel.Debug, "Writing the requested range of bytes to the body...", EventName = "WritingRangeToBody")]
         public static partial void WritingRangeToBody(ILogger logger);
     }

src/Mvc/Mvc.Core/src/Infrastructure/FileStreamResultExecutor.cs

@@ -37,7 +37,7 @@ public virtual async Task ExecuteAsync(ActionContext context, FileStreamResult r
 
         using (result.FileStream)
         {
-            Logger.ExecutingFileResult(result);
+            Log.ExecutingFileResult(Logger, result);
 
             long? fileLength = null;
             if (result.FileStream.CanSeek)
@@ -100,6 +100,18 @@ protected virtual Task WriteFileAsync(
 
     private static partial class Log
     {
+        public static void ExecutingFileResult(ILogger logger, FileResult fileResult)
+        {
+            if (logger.IsEnabled(LogLevel.Information))
+            {
+                var fileResultType = fileResult.GetType().Name;
+                ExecutingFileResultWithNoFileName(logger, fileResultType, fileResult.FileDownloadName);
+            }
+        }
+
+        [LoggerMessage(1, LogLevel.Information, "Executing {FileResultType}, sending file with download name '{FileDownloadName}' ...", EventName = "ExecutingFileResultWithNoFileName", SkipEnabledCheck = true)]
+        private static partial void ExecutingFileResultWithNoFileName(ILogger logger, string fileResultType, string fileDownloadName);
+
         [LoggerMessage(17, LogLevel.Debug, "Writing the requested range of bytes to the body...", EventName = "WritingRangeToBody")]
         public static partial void WritingRangeToBody(ILogger logger);
     }

src/Mvc/Mvc.Core/src/Infrastructure/ModelStateInvalidFilter.cs

@@ -14,7 +14,7 @@ namespace Microsoft.AspNetCore.Mvc.Infrastructure;
 /// added to all types and actions annotated with <see cref="ApiControllerAttribute"/>.
 /// See <see cref="ApiBehaviorOptions"/> for ways to configure this filter.
 /// </summary>
-public class ModelStateInvalidFilter : IActionFilter, IOrderedFilter
+public partial class ModelStateInvalidFilter : IActionFilter, IOrderedFilter
 {
     internal const int FilterOrder = -2000;
 
@@ -75,8 +75,14 @@ public void OnActionExecuting(ActionExecutingContext context)
     {
         if (context.Result == null && !context.ModelState.IsValid)
         {
-            _logger.ModelStateInvalidFilterExecuting();
+            Log.ModelStateInvalidFilterExecuting(_logger);
             context.Result = _apiBehaviorOptions.InvalidModelStateResponseFactory(context);
         }
     }
+
+    private static partial class Log
+    {
+        [LoggerMessage(1, LogLevel.Debug, "The request has model state errors, returning an error response.", EventName = "ModelStateInvalidFilterExecuting")]
+        public static partial void ModelStateInvalidFilterExecuting(ILogger logger);
+    }
 }