Update MvcCoreLoggerExtensions to use LoggerMessageAttribute

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);
+    }
 }