diff --git a/src/Mvc/Mvc.Core/src/ChallengeResult.cs b/src/Mvc/Mvc.Core/src/ChallengeResult.cs index 95cb90ed279f..2fc451faa188 100644 --- a/src/Mvc/Mvc.Core/src/ChallengeResult.cs +++ b/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; /// /// An that on execution invokes . /// -public class ChallengeResult : ActionResult +public partial class ChallengeResult : ActionResult { /// /// Initializes a new instance of . @@ -97,8 +98,7 @@ public override async Task ExecuteResultAsync(ActionContext context) var httpContext = context.HttpContext; var loggerFactory = httpContext.RequestServices.GetRequiredService(); var logger = loggerFactory.CreateLogger(); - - 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 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); + } } diff --git a/src/Mvc/Mvc.Core/src/ForbidResult.cs b/src/Mvc/Mvc.Core/src/ForbidResult.cs index a4ac023e87e0..536fcfca37d4 100644 --- a/src/Mvc/Mvc.Core/src/ForbidResult.cs +++ b/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; /// /// An that on execution invokes . /// -public class ForbidResult : ActionResult +public partial class ForbidResult : ActionResult { /// /// Initializes a new instance of . @@ -98,8 +99,7 @@ public override async Task ExecuteResultAsync(ActionContext context) var loggerFactory = httpContext.RequestServices.GetRequiredService(); var logger = loggerFactory.CreateLogger(); - - 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 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); + } } diff --git a/src/Mvc/Mvc.Core/src/Formatters/FormatFilter.cs b/src/Mvc/Mvc.Core/src/Formatters/FormatFilter.cs index d0b74ccdc9f1..83d80a6cd2b3 100644 --- a/src/Mvc/Mvc.Core/src/Formatters/FormatFilter.cs +++ b/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); diff --git a/src/Mvc/Mvc.Core/src/Infrastructure/ClientErrorResultFilter.cs b/src/Mvc/Mvc.Core/src/Infrastructure/ClientErrorResultFilter.cs index e4fddf2cd355..ad32d18f77b3 100644 --- a/src/Mvc/Mvc.Core/src/Infrastructure/ClientErrorResultFilter.cs +++ b/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); + } } diff --git a/src/Mvc/Mvc.Core/src/Infrastructure/ControllerActionInvoker.cs b/src/Mvc/Mvc.Core/src/Infrastructure/ControllerActionInvoker.cs index 3824d233a899..d4b5b94a4b1e 100644 --- a/src/Mvc/Mvc.Core/src/Infrastructure/ControllerActionInvoker.cs +++ b/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(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 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); + } } diff --git a/src/Mvc/Mvc.Core/src/Infrastructure/DefaultOutputFormatterSelector.cs b/src/Mvc/Mvc.Core/src/Infrastructure/DefaultOutputFormatterSelector.cs index fa3e1442d15c..7a5657ddf1c0 100644 --- a/src/Mvc/Mvc.Core/src/Infrastructure/DefaultOutputFormatterSelector.cs +++ b/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 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); diff --git a/src/Mvc/Mvc.Core/src/Infrastructure/FileContentResultExecutor.cs b/src/Mvc/Mvc.Core/src/Infrastructure/FileContentResultExecutor.cs index 5449a4d98697..734f9b5db03b 100644 --- a/src/Mvc/Mvc.Core/src/Infrastructure/FileContentResultExecutor.cs +++ b/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); } diff --git a/src/Mvc/Mvc.Core/src/Infrastructure/FileStreamResultExecutor.cs b/src/Mvc/Mvc.Core/src/Infrastructure/FileStreamResultExecutor.cs index 51b88f7f223b..8341dca9e367 100644 --- a/src/Mvc/Mvc.Core/src/Infrastructure/FileStreamResultExecutor.cs +++ b/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); } diff --git a/src/Mvc/Mvc.Core/src/Infrastructure/ModelStateInvalidFilter.cs b/src/Mvc/Mvc.Core/src/Infrastructure/ModelStateInvalidFilter.cs index 19e5a88fca51..97cae7a7953c 100644 --- a/src/Mvc/Mvc.Core/src/Infrastructure/ModelStateInvalidFilter.cs +++ b/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 for ways to configure this filter. /// -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); + } } diff --git a/src/Mvc/Mvc.Core/src/Infrastructure/ObjectResultExecutor.cs b/src/Mvc/Mvc.Core/src/Infrastructure/ObjectResultExecutor.cs index 4ffcb0662986..1c4ddb95ab88 100644 --- a/src/Mvc/Mvc.Core/src/Infrastructure/ObjectResultExecutor.cs +++ b/src/Mvc/Mvc.Core/src/Infrastructure/ObjectResultExecutor.cs @@ -2,6 +2,7 @@ // The .NET Foundation licenses this file to you under the MIT license. using System.Diagnostics; +using System.Globalization; using System.Text; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Mvc.Formatters; @@ -13,7 +14,7 @@ namespace Microsoft.AspNetCore.Mvc.Infrastructure; /// /// Executes an to write to the response. /// -public class ObjectResultExecutor : IActionResultExecutor +public partial class ObjectResultExecutor : IActionResultExecutor { /// /// Creates a new . @@ -111,13 +112,13 @@ private Task ExecuteAsyncCore(ActionContext context, ObjectResult result, Type? if (selectedFormatter == null) { // No formatter supports this. - Logger.NoFormatter(formatterContext, result.ContentTypes); + Log.NoFormatter(Logger, formatterContext, result.ContentTypes); context.HttpContext.Response.StatusCode = StatusCodes.Status406NotAcceptable; return Task.CompletedTask; } - Logger.ObjectResultExecuting(result, value); + Log.ObjectResultExecuting(Logger, result, value); result.OnFormatting(context); return selectedFormatter.WriteAsync(formatterContext); @@ -142,6 +143,41 @@ private static void InferContentTypes(ActionContext context, ObjectResult result } } - // Removed Log. - // new EventId(1, "BufferingAsyncEnumerable") + // Internal for unit testing + internal static partial class Log + { + // Removed Log. + // new EventId(1, "BufferingAsyncEnumerable") + + public static void ObjectResultExecuting(ILogger logger, ObjectResult result, object? value) + { + if (logger.IsEnabled(LogLevel.Information)) + { + var objectResultType = result.GetType().Name; + var valueType = value == null ? "null" : value.GetType().FullName; + ObjectResultExecuting(logger, objectResultType, valueType); + } + } + + [LoggerMessage(1, LogLevel.Information, "Executing {ObjectResultType}, writing value of type '{Type}'.", EventName = "ObjectResultExecuting", SkipEnabledCheck = true)] + private static partial void ObjectResultExecuting(ILogger logger, string objectResultType, string? type); + + public static void NoFormatter(ILogger logger, OutputFormatterCanWriteContext context, MediaTypeCollection contentTypes) + { + if (logger.IsEnabled(LogLevel.Warning)) + { + var considered = new List(contentTypes); + + if (context.ContentType.HasValue) + { + considered.Add(Convert.ToString(context.ContentType, CultureInfo.InvariantCulture)); + } + + NoFormatter(logger, considered); + } + } + + [LoggerMessage(2, LogLevel.Warning, "No output formatter was found for content types '{ContentTypes}' to write the response.", EventName = "NoFormatter", SkipEnabledCheck = true)] + private static partial void NoFormatter(ILogger logger, List contentTypes); + } } diff --git a/src/Mvc/Mvc.Core/src/Infrastructure/PhysicalFileResultExecutor.cs b/src/Mvc/Mvc.Core/src/Infrastructure/PhysicalFileResultExecutor.cs index 887ff1be3a38..4e339c2acf90 100644 --- a/src/Mvc/Mvc.Core/src/Infrastructure/PhysicalFileResultExecutor.cs +++ b/src/Mvc/Mvc.Core/src/Infrastructure/PhysicalFileResultExecutor.cs @@ -42,7 +42,7 @@ public virtual Task ExecuteAsync(ActionContext context, PhysicalFileResult resul Resources.FormatFileResult_InvalidPath(result.FileName), result.FileName); } - Logger.ExecutingFileResult(result, result.FileName); + Log.ExecutingFileResult(Logger, result, result.FileName); var lastModified = result.LastModified ?? fileInfo.LastModified; var (range, rangeLength, serveBody) = SetHeadersAndLog( @@ -179,6 +179,18 @@ protected class FileMetadata private static partial class Log { + public static void ExecutingFileResult(ILogger logger, FileResult fileResult, string fileName) + { + if (logger.IsEnabled(LogLevel.Information)) + { + var fileResultType = fileResult.GetType().Name; + ExecutingFileResult(logger, fileResultType, fileName, fileResult.FileDownloadName); + } + } + + [LoggerMessage(1, LogLevel.Information, "Executing {FileResultType}, sending file '{FileDownloadPath}' with download name '{FileDownloadName}' ...", EventName = "ExecutingFileResult", SkipEnabledCheck = true)] + private static partial void ExecutingFileResult(ILogger logger, string fileResultType, string fileDownloadPath, string fileDownloadName); + [LoggerMessage(17, LogLevel.Debug, "Writing the requested range of bytes to the body...", EventName = "WritingRangeToBody")] public static partial void WritingRangeToBody(ILogger logger); } diff --git a/src/Mvc/Mvc.Core/src/Infrastructure/ResourceInvoker.Log.cs b/src/Mvc/Mvc.Core/src/Infrastructure/ResourceInvoker.Log.cs new file mode 100644 index 000000000000..f34b1e5e53e0 --- /dev/null +++ b/src/Mvc/Mvc.Core/src/Infrastructure/ResourceInvoker.Log.cs @@ -0,0 +1,119 @@ +// 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 System.Reflection; +using System.Text; +using Microsoft.AspNetCore.Mvc.Abstractions; +using Microsoft.AspNetCore.Mvc.Controllers; +using Microsoft.AspNetCore.Mvc.Filters; +using Microsoft.Extensions.Internal; +using Microsoft.Extensions.Logging; + +namespace Microsoft.AspNetCore.Mvc.Infrastructure; + +internal partial class ResourceInvoker +{ + // Internal for unit testing + internal static partial class Log + { + public static void ExecutingAction(ILogger logger, ActionDescriptor action) + { + if (logger.IsEnabled(LogLevel.Information)) + { + var routeKeys = action.RouteValues.Keys.ToArray(); + var routeValues = action.RouteValues.Values.ToArray(); + var stringBuilder = new StringBuilder(); + stringBuilder.Append('{'); + for (var i = 0; i < routeValues.Length; i++) + { + if (i == routeValues.Length - 1) + { + stringBuilder.Append(FormattableString.Invariant($"{routeKeys[i]} = \"{routeValues[i]}\"")); + } + else + { + stringBuilder.Append(FormattableString.Invariant($"{routeKeys[i]} = \"{routeValues[i]}\", ")); + } + } + stringBuilder.Append('}'); + + if (action.RouteValues.TryGetValue("page", out var page) && page != null) + { + PageExecuting(logger, stringBuilder.ToString(), action.DisplayName); + } + else + { + if (action is ControllerActionDescriptor controllerActionDescriptor) + { + var controllerType = controllerActionDescriptor.ControllerTypeInfo.AsType(); + var controllerName = TypeNameHelper.GetTypeDisplayName(controllerType); + ControllerActionExecuting( + logger, + stringBuilder.ToString(), + controllerActionDescriptor.MethodInfo, + controllerName, + controllerType.Assembly.GetName().Name); + } + else + { + ActionExecuting(logger, stringBuilder.ToString(), action.DisplayName); + } + } + } + } + + [LoggerMessage(101, LogLevel.Information, "Route matched with {RouteData}. Executing action {ActionName}", EventName = "ActionExecuting", SkipEnabledCheck = true)] + private static partial void ActionExecuting(ILogger logger, string routeData, string? actionName); + + [LoggerMessage(102, LogLevel.Information, "Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).", EventName = "ControllerActionExecuting", SkipEnabledCheck = true)] + private static partial void ControllerActionExecuting(ILogger logger, string routeData, MethodInfo methodInfo, string controller, string? assemblyName); + + [LoggerMessage(103, LogLevel.Information, "Route matched with {RouteData}. Executing page {PageName}", EventName = "PageExecuting", SkipEnabledCheck = true)] + private static partial void PageExecuting(ILogger logger, string routeData, string? pageName); + + [LoggerMessage(3, LogLevel.Information, "Authorization failed for the request at filter '{AuthorizationFilter}'.", EventName = "AuthorizationFailure")] + public static partial void AuthorizationFailure(ILogger logger, IFilterMetadata authorizationFilter); + + [LoggerMessage(4, LogLevel.Debug, "Request was short circuited at resource filter '{ResourceFilter}'.", EventName = "ResourceFilterShortCircuit")] + public static partial void ResourceFilterShortCircuited(ILogger logger, IFilterMetadata resourceFilter); + + [LoggerMessage(5, LogLevel.Trace, "Before executing action result {ActionResult}.", EventName = "BeforeExecutingActionResult")] + private static partial void BeforeExecutingActionResult(ILogger logger, Type actionResult); + + public static void BeforeExecutingActionResult(ILogger logger, IActionResult actionResult) + { + BeforeExecutingActionResult(logger, actionResult.GetType()); + } + + [LoggerMessage(6, LogLevel.Trace, "After executing action result {ActionResult}.", EventName = "AfterExecutingActionResult")] + private static partial void AfterExecutingActionResult(ILogger logger, Type actionResult); + + public static void AfterExecutingActionResult(ILogger logger, IActionResult actionResult) + { + AfterExecutingActionResult(logger, actionResult.GetType()); + } + + public static void ExecutedAction(ILogger logger, ActionDescriptor action, TimeSpan timeSpan) + { + // Don't log if logging wasn't enabled at start of request as time will be wildly wrong. + if (logger.IsEnabled(LogLevel.Information)) + { + if (action.RouteValues.TryGetValue("page", out var page) && page != null) + { + PageExecuted(logger, action.DisplayName, timeSpan.TotalMilliseconds); + } + else + { + ActionExecuted(logger, action.DisplayName, timeSpan.TotalMilliseconds); + } + } + } + + [LoggerMessage(104, LogLevel.Information, "Executed page {PageName} in {ElapsedMilliseconds}ms", EventName = "PageExecuted", SkipEnabledCheck = true)] + private static partial void PageExecuted(ILogger logger, string? pageName, double elapsedMilliseconds); + + [LoggerMessage(105, LogLevel.Information, "Executed action {ActionName} in {ElapsedMilliseconds}ms", EventName = "ActionExecuted", SkipEnabledCheck = true)] + private static partial void ActionExecuted(ILogger logger, string? actionName, double elapsedMilliseconds); + } +} diff --git a/src/Mvc/Mvc.Core/src/Infrastructure/ResourceInvoker.cs b/src/Mvc/Mvc.Core/src/Infrastructure/ResourceInvoker.cs index d279ccb1b012..6a1299b883ce 100644 --- a/src/Mvc/Mvc.Core/src/Infrastructure/ResourceInvoker.cs +++ b/src/Mvc/Mvc.Core/src/Infrastructure/ResourceInvoker.cs @@ -108,7 +108,7 @@ static async Task Logged(ResourceInvoker invoker) var actionScope = logger.ActionScope(actionContext.ActionDescriptor); - logger.ExecutingAction(actionContext.ActionDescriptor); + Log.ExecutingAction(logger, actionContext.ActionDescriptor); var filters = invoker._filters; logger.AuthorizationFiltersExecutionPlan(filters); @@ -126,7 +126,7 @@ static async Task Logged(ResourceInvoker invoker) finally { await invoker.ReleaseResourcesCore(actionScope); - logger.ExecutedAction(actionContext.ActionDescriptor, stopwatch.GetElapsedTime()); + Log.ExecutedAction(logger, actionContext.ActionDescriptor, stopwatch.GetElapsedTime()); } } finally @@ -1602,29 +1602,4 @@ private sealed class AuthorizationFilterContextSealed : AuthorizationFilterConte { public AuthorizationFilterContextSealed(ActionContext actionContext, IList filters) : base(actionContext, filters) { } } - - private static partial class Log - { - [LoggerMessage(3, LogLevel.Information, "Authorization failed for the request at filter '{AuthorizationFilter}'.", EventName = "AuthorizationFailure")] - public static partial void AuthorizationFailure(ILogger logger, IFilterMetadata authorizationFilter); - - [LoggerMessage(4, LogLevel.Debug, "Request was short circuited at resource filter '{ResourceFilter}'.", EventName = "ResourceFilterShortCircuit")] - public static partial void ResourceFilterShortCircuited(ILogger logger, IFilterMetadata resourceFilter); - - [LoggerMessage(5, LogLevel.Trace, "Before executing action result {ActionResult}.", EventName = "BeforeExecutingActionResult")] - private static partial void BeforeExecutingActionResult(ILogger logger, Type actionResult); - - public static void BeforeExecutingActionResult(ILogger logger, IActionResult actionResult) - { - BeforeExecutingActionResult(logger, actionResult.GetType()); - } - - [LoggerMessage(6, LogLevel.Trace, "After executing action result {ActionResult}.", EventName = "AfterExecutingActionResult")] - private static partial void AfterExecutingActionResult(ILogger logger, Type actionResult); - - public static void AfterExecutingActionResult(ILogger logger, IActionResult actionResult) - { - AfterExecutingActionResult(logger, actionResult.GetType()); - } - } } diff --git a/src/Mvc/Mvc.Core/src/Infrastructure/VirtualFileResultExecutor.cs b/src/Mvc/Mvc.Core/src/Infrastructure/VirtualFileResultExecutor.cs index 59c8a0976943..a1a08718e0d9 100644 --- a/src/Mvc/Mvc.Core/src/Infrastructure/VirtualFileResultExecutor.cs +++ b/src/Mvc/Mvc.Core/src/Infrastructure/VirtualFileResultExecutor.cs @@ -53,7 +53,7 @@ public virtual Task ExecuteAsync(ActionContext context, VirtualFileResult result Resources.FormatFileResult_InvalidPath(result.FileName), result.FileName); } - Logger.ExecutingFileResult(result, result.FileName); + Log.ExecutingFileResult(Logger, result, result.FileName); var lastModified = result.LastModified ?? fileInfo.LastModified; var (range, rangeLength, serveBody) = SetHeadersAndLog( @@ -161,6 +161,18 @@ protected virtual Stream GetFileStream(IFileInfo fileInfo) private static partial class Log { + public static void ExecutingFileResult(ILogger logger, FileResult fileResult, string fileName) + { + if (logger.IsEnabled(LogLevel.Information)) + { + var fileResultType = fileResult.GetType().Name; + ExecutingFileResult(logger, fileResultType, fileName, fileResult.FileDownloadName); + } + } + + [LoggerMessage(1, LogLevel.Information, "Executing {FileResultType}, sending file '{FileDownloadPath}' with download name '{FileDownloadName}' ...", EventName = "ExecutingFileResult", SkipEnabledCheck = true)] + private static partial void ExecutingFileResult(ILogger logger, string fileResultType, string fileDownloadPath, string fileDownloadName); + [LoggerMessage(17, LogLevel.Debug, "Writing the requested range of bytes to the body...", EventName = "WritingRangeToBody")] public static partial void WritingRangeToBody(ILogger logger); } diff --git a/src/Mvc/Mvc.Core/src/ModelBinding/Binders/BodyModelBinder.cs b/src/Mvc/Mvc.Core/src/ModelBinding/Binders/BodyModelBinder.cs index 0227ad2f78e1..5ce406fbc876 100644 --- a/src/Mvc/Mvc.Core/src/ModelBinding/Binders/BodyModelBinder.cs +++ b/src/Mvc/Mvc.Core/src/ModelBinding/Binders/BodyModelBinder.cs @@ -17,7 +17,7 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders; /// An which binds models from the request body using an /// when a model has the binding source . /// -public class BodyModelBinder : IModelBinder +public partial class BodyModelBinder : IModelBinder { private readonly IList _formatters; private readonly Func _readerFactory; @@ -129,12 +129,12 @@ public async Task BindModelAsync(ModelBindingContext bindingContext) if (_formatters[i].CanRead(formatterContext)) { formatter = _formatters[i]; - _logger.InputFormatterSelected(formatter, formatterContext); + Log.InputFormatterSelected(_logger, formatter, formatterContext); break; } else { - _logger.InputFormatterRejected(_formatters[i], formatterContext); + Log.InputFormatterRejected(_logger, _formatters[i], formatterContext); } } @@ -151,7 +151,7 @@ public async Task BindModelAsync(ModelBindingContext bindingContext) } } - _logger.NoInputFormatterSelected(formatterContext); + Log.NoInputFormatterSelected(_logger, formatterContext); var message = Resources.FormatUnsupportedContentType(httpContext.Request.ContentType); var exception = new UnsupportedContentTypeException(message); @@ -206,4 +206,52 @@ private static bool ShouldHandleException(IInputFormatter formatter) return policy == InputFormatterExceptionPolicy.AllExceptions; } + + private partial class Log + { + public static void InputFormatterSelected(ILogger logger, IInputFormatter inputFormatter, InputFormatterContext formatterContext) + { + if (logger.IsEnabled(LogLevel.Debug)) + { + var contentType = formatterContext.HttpContext.Request.ContentType; + InputFormatterSelected(logger, inputFormatter, contentType); + } + } + + [LoggerMessage(1, LogLevel.Debug, "Selected input formatter '{InputFormatter}' for content type '{ContentType}'.", EventName = "InputFormatterSelected", SkipEnabledCheck = true)] + private static partial void InputFormatterSelected(ILogger logger, IInputFormatter inputFormatter, string? contentType); + + public static void InputFormatterRejected(ILogger logger, IInputFormatter inputFormatter, InputFormatterContext formatterContext) + { + if (logger.IsEnabled(LogLevel.Debug)) + { + var contentType = formatterContext.HttpContext.Request.ContentType; + InputFormatterRejected(logger, inputFormatter, contentType); + } + } + + [LoggerMessage(2, LogLevel.Debug, "Rejected input formatter '{InputFormatter}' for content type '{ContentType}'.", EventName = "InputFormatterRejected", SkipEnabledCheck = true)] + private static partial void InputFormatterRejected(ILogger logger, IInputFormatter inputFormatter, string? contentType); + + public static void NoInputFormatterSelected(ILogger logger, InputFormatterContext formatterContext) + { + if (logger.IsEnabled(LogLevel.Debug)) + { + var contentType = formatterContext.HttpContext.Request.ContentType; + NoInputFormatterSelected(logger, contentType); + if (formatterContext.HttpContext.Request.HasFormContentType) + { + var modelType = formatterContext.ModelType.FullName; + var modelName = formatterContext.ModelName; + RemoveFromBodyAttribute(logger, modelName, modelType); + } + } + } + + [LoggerMessage(3, LogLevel.Debug, "No input formatter was found to support the content type '{ContentType}' for use with the [FromBody] attribute.", EventName = "NoInputFormatterSelected", SkipEnabledCheck = true)] + private static partial void NoInputFormatterSelected(ILogger logger, string? contentType); + + [LoggerMessage(4, LogLevel.Debug, "To use model binding, remove the [FromBody] attribute from the property or parameter named '{ModelName}' with model type '{ModelType}'.", EventName = "RemoveFromBodyAttribute", SkipEnabledCheck = true)] + private static partial void RemoveFromBodyAttribute(ILogger logger, string modelName, string? modelType); + } } diff --git a/src/Mvc/Mvc.Core/src/ModelBinding/Binders/CollectionModelBinder.cs b/src/Mvc/Mvc.Core/src/ModelBinding/Binders/CollectionModelBinder.cs index b00944ddf766..116c6f6c66dc 100644 --- a/src/Mvc/Mvc.Core/src/ModelBinding/Binders/CollectionModelBinder.cs +++ b/src/Mvc/Mvc.Core/src/ModelBinding/Binders/CollectionModelBinder.cs @@ -11,6 +11,7 @@ using Microsoft.AspNetCore.Mvc.ModelBinding.Metadata; using Microsoft.AspNetCore.Mvc.ModelBinding.Validation; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Internal; namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders; @@ -18,7 +19,7 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders; /// implementation for binding collection values. /// /// Type of elements in the collection. -public class CollectionModelBinder : ICollectionModelBinder +public partial class CollectionModelBinder : ICollectionModelBinder { private static readonly IValueProvider EmptyValueProvider = new CompositeValueProvider(); private readonly int _maxModelBindingCollectionSize = MvcOptions.DefaultMaxModelBindingCollectionSize; @@ -151,7 +152,7 @@ public virtual async Task BindModelAsync(ModelBindingContext bindingContext) CollectionResult result; if (valueProviderResult == ValueProviderResult.None) { - Logger.NoNonIndexBasedFormatFoundForCollection(bindingContext); + Log.NoNonIndexBasedFormatFoundForCollection(Logger, bindingContext); result = await BindComplexCollection(bindingContext); } else @@ -305,7 +306,7 @@ internal async Task BindSimpleCollection( // Used when the ValueProvider contains the collection to be bound as multiple elements, e.g. foo[0], foo[1]. private Task BindComplexCollection(ModelBindingContext bindingContext) { - Logger.AttemptingToBindCollectionUsingIndices(bindingContext); + Log.AttemptingToBindCollectionUsingIndices(Logger, bindingContext); var indexPropertyName = ModelNames.CreatePropertyModelName(bindingContext.ModelName, "index"); @@ -486,4 +487,54 @@ protected virtual void CopyToModel(object target, IEnumerable sourceC var indexes = (string[]?)valueProviderResult; return (indexes == null || indexes.Length == 0) ? null : indexes; } + + private static partial class Log + { + public static void AttemptingToBindCollectionUsingIndices(ILogger logger, ModelBindingContext bindingContext) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + var modelName = bindingContext.ModelName; + + var enumerableType = ClosedGenericMatcher.ExtractGenericInterface(bindingContext.ModelType, typeof(IEnumerable<>)); + if (enumerableType != null) + { + var elementType = enumerableType.GenericTypeArguments[0]; + if (elementType.IsGenericType && elementType.GetGenericTypeDefinition() == typeof(KeyValuePair<,>)) + { + AttemptingToBindCollectionOfKeyValuePair(logger, modelName); + return; + } + } + + AttemptingToBindCollectionUsingIndices(logger, modelName); + } + + [LoggerMessage(29, LogLevel.Debug, + "Attempting to bind model using indices. Example formats include: " + + "[0]=value1&[1]=value2, " + + "{ModelName}[0]=value1&{ModelName}[1]=value2, " + + "{ModelName}.index=zero&{ModelName}.index=one&{ModelName}[zero]=value1&{ModelName}[one]=value2", + EventName = "AttemptingToBindCollectionUsingIndices", + SkipEnabledCheck = true)] + private static partial void AttemptingToBindCollectionUsingIndices(ILogger logger, string modelName); + + [LoggerMessage(30, LogLevel.Debug, + "Attempting to bind collection of KeyValuePair. Example formats include: " + + "[0].Key=key1&[0].Value=value1&[1].Key=key2&[1].Value=value2, " + + "{ModelName}[0].Key=key1&{ModelName}[0].Value=value1&{ModelName}[1].Key=key2&{ModelName}[1].Value=value2, " + + "{ModelName}[key1]=value1&{ModelName}[key2]=value2", + EventName = "AttemptingToBindCollectionOfKeyValuePair", + SkipEnabledCheck = true)] + private static partial void AttemptingToBindCollectionOfKeyValuePair(ILogger logger, string modelName); + + public static void NoNonIndexBasedFormatFoundForCollection(ILogger logger, ModelBindingContext bindingContext) + => NoNonIndexBasedFormatFoundForCollection(logger, bindingContext.ModelName); + + [LoggerMessage(28, LogLevel.Debug, "Could not bind to collection using a format like {ModelName}=value1&{ModelName}=value2", EventName = "NoNonIndexBasedFormatFoundForCollection")] + private static partial void NoNonIndexBasedFormatFoundForCollection(ILogger logger, string modelName); + } } diff --git a/src/Mvc/Mvc.Core/src/ModelBinding/Binders/ComplexObjectModelBinder.cs b/src/Mvc/Mvc.Core/src/ModelBinding/Binders/ComplexObjectModelBinder.cs index 51c494f812d5..b3740b533758 100644 --- a/src/Mvc/Mvc.Core/src/ModelBinding/Binders/ComplexObjectModelBinder.cs +++ b/src/Mvc/Mvc.Core/src/ModelBinding/Binders/ComplexObjectModelBinder.cs @@ -656,7 +656,7 @@ private int CanBindAnyModelItem(ModelBindingContext bindingContext) return GreedyPropertiesMayHaveData; } - _logger.CannotBindToComplexType(bindingContext); + Log.CannotBindToComplexType(_logger, bindingContext); return NoDataAvailable; } @@ -747,5 +747,11 @@ public static void NoPublicSettableItems(ILogger logger, ModelBindingContext bin { NoPublicSettableItems(logger, bindingContext.ModelName, bindingContext.ModelType); } + + public static void CannotBindToComplexType(ILogger logger, ModelBindingContext bindingContext) + => CannotBindToComplexType(logger, bindingContext.ModelType); + + [LoggerMessage(18, LogLevel.Debug, "Could not bind to model of type '{ModelType}' as there were no values in the request for any of the properties.", EventName = "CannotBindToComplexType")] + private static partial void CannotBindToComplexType(ILogger logger, Type modelType); } } diff --git a/src/Mvc/Mvc.Core/src/ModelBinding/Binders/ComplexTypeModelBinder.cs b/src/Mvc/Mvc.Core/src/ModelBinding/Binders/ComplexTypeModelBinder.cs index 606cf3ab5182..c72769f52cd9 100644 --- a/src/Mvc/Mvc.Core/src/ModelBinding/Binders/ComplexTypeModelBinder.cs +++ b/src/Mvc/Mvc.Core/src/ModelBinding/Binders/ComplexTypeModelBinder.cs @@ -16,7 +16,7 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders; /// implementation for binding complex types. /// [Obsolete("This type is obsolete and will be removed in a future version. Use ComplexObjectModelBinder instead.")] -public class ComplexTypeModelBinder : IModelBinder +public partial class ComplexTypeModelBinder : IModelBinder { // Don't want a new public enum because communication between the private and internal methods of this class // should not be exposed. Can't use an internal enum because types of [TheoryData] values must be public. @@ -358,7 +358,7 @@ private int CanBindAnyModelProperties(ModelBindingContext bindingContext) // level object. So we return false. if (bindingContext.ModelMetadata.Properties.Count == 0) { - _logger.NoPublicSettableProperties(bindingContext); + Log.NoPublicSettableProperties(_logger, bindingContext); return NoDataAvailable; } @@ -424,7 +424,7 @@ private int CanBindAnyModelProperties(ModelBindingContext bindingContext) return GreedyPropertiesMayHaveData; } - _logger.CannotBindToComplexType(bindingContext); + Log.CannotBindToComplexType(_logger, bindingContext); return NoDataAvailable; } @@ -592,4 +592,19 @@ private static void AddModelError( modelState.AddModelError(modelName, exception, bindingContext.ModelMetadata); } } + + private static partial class Log + { + public static void NoPublicSettableProperties(ILogger logger, ModelBindingContext bindingContext) + => NoPublicSettableProperties(logger, bindingContext.ModelName, bindingContext.ModelType); + + [LoggerMessage(17, LogLevel.Debug, "Could not bind to model with name '{ModelName}' and type '{ModelType}' as the type has no public settable properties.", EventName = "NoPublicSettableProperties")] + private static partial void NoPublicSettableProperties(ILogger logger, string modelName, Type modelType); + + public static void CannotBindToComplexType(ILogger logger, ModelBindingContext bindingContext) + => CannotBindToComplexType(logger, bindingContext.ModelType); + + [LoggerMessage(18, LogLevel.Debug, "Could not bind to model of type '{ModelType}' as there were no values in the request for any of the properties.", EventName = "CannotBindToComplexType")] + private static partial void CannotBindToComplexType(ILogger logger, Type modelType); + } } diff --git a/src/Mvc/Mvc.Core/src/ModelBinding/Binders/DictionaryModelBinder.cs b/src/Mvc/Mvc.Core/src/ModelBinding/Binders/DictionaryModelBinder.cs index 6af4fbf9c95a..36c97f95236f 100644 --- a/src/Mvc/Mvc.Core/src/ModelBinding/Binders/DictionaryModelBinder.cs +++ b/src/Mvc/Mvc.Core/src/ModelBinding/Binders/DictionaryModelBinder.cs @@ -15,7 +15,7 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding.Binders; /// /// Type of keys in the dictionary. /// Type of values in the dictionary. -public class DictionaryModelBinder : CollectionModelBinder> where TKey : notnull +public partial class DictionaryModelBinder : CollectionModelBinder> where TKey : notnull { private readonly IModelBinder _valueBinder; @@ -140,7 +140,7 @@ public override async Task BindModelAsync(ModelBindingContext bindingContext) return; } - Logger.NoKeyValueFormatForDictionaryModelBinder(bindingContext); + Log.NoKeyValueFormatForDictionaryModelBinder(Logger, bindingContext); if (bindingContext.ValueProvider is not IEnumerableValueProvider enumerableValueProvider) { @@ -262,4 +262,13 @@ public override bool CanCreateInstance(Type targetType) return base.CanCreateInstance(targetType); } + + private static partial class Log + { + public static void NoKeyValueFormatForDictionaryModelBinder(ILogger logger, ModelBindingContext bindingContext) + => NoKeyValueFormatForDictionaryModelBinder(logger, bindingContext.ModelName); + + [LoggerMessage(33, LogLevel.Debug, "Attempting to bind model with name '{ModelName}' using the format {ModelName}[key1]=value1&{ModelName}[key2]=value2", EventName = "NoKeyValueFormatForDictionaryModelBinder")] + private static partial void NoKeyValueFormatForDictionaryModelBinder(ILogger logger, string modelName); + } } diff --git a/src/Mvc/Mvc.Core/src/ModelBinding/ParameterBinder.Log.cs b/src/Mvc/Mvc.Core/src/ModelBinding/ParameterBinder.Log.cs new file mode 100644 index 000000000000..7c0dd27a63fc --- /dev/null +++ b/src/Mvc/Mvc.Core/src/ModelBinding/ParameterBinder.Log.cs @@ -0,0 +1,255 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using Microsoft.AspNetCore.Mvc.Abstractions; +using Microsoft.AspNetCore.Mvc.Controllers; +using Microsoft.AspNetCore.Mvc.ModelBinding.Metadata; +using Microsoft.Extensions.Logging; + +namespace Microsoft.AspNetCore.Mvc.ModelBinding; + +public partial class ParameterBinder +{ + private static partial class Log + { + public static void AttemptingToBindParameterOrProperty( + ILogger logger, + ParameterDescriptor parameter, + ModelMetadata modelMetadata) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + switch (modelMetadata.MetadataKind) + { + case ModelMetadataKind.Parameter: + AttemptingToBindParameter(logger, modelMetadata.ParameterName, modelMetadata.ModelType); + break; + case ModelMetadataKind.Property: + AttemptingToBindProperty( + logger, + modelMetadata.ContainerType, + modelMetadata.PropertyName, + modelMetadata.ModelType); + break; + case ModelMetadataKind.Type: + if (parameter is ControllerParameterDescriptor parameterDescriptor) + { + AttemptingToBindParameter( + logger, + parameterDescriptor.ParameterInfo.Name, + modelMetadata.ModelType); + } + else + { + // Likely binding a page handler parameter. Due to various special cases, parameter.Name may + // be empty. No way to determine actual name. + AttemptingToBindParameter(logger, parameter.Name, modelMetadata.ModelType); + } + break; + } + } + + [LoggerMessage(22, LogLevel.Debug, "Attempting to bind parameter '{ParameterName}' of type '{ModelType}' ...", EventName = "AttemptingToBindParameter", SkipEnabledCheck = true)] + private static partial void AttemptingToBindParameter(ILogger logger, string? parameterName, Type modelType); + + [LoggerMessage(39, LogLevel.Debug, "Attempting to bind property '{PropertyContainerType}.{PropertyName}' of type '{ModelType}' ...", EventName = "AttemptingToBindProperty", SkipEnabledCheck = true)] + private static partial void AttemptingToBindProperty(ILogger logger, Type? propertyContainerType, string? propertyName, Type modelType); + + public static void DoneAttemptingToBindParameterOrProperty( + ILogger logger, + ParameterDescriptor parameter, + ModelMetadata modelMetadata) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + switch (modelMetadata.MetadataKind) + { + case ModelMetadataKind.Parameter: + DoneAttemptingToBindParameter(logger, modelMetadata.ParameterName, modelMetadata.ModelType); + break; + case ModelMetadataKind.Property: + DoneAttemptingToBindProperty( + logger, + modelMetadata.ContainerType, + modelMetadata.PropertyName, + modelMetadata.ModelType); + break; + case ModelMetadataKind.Type: + if (parameter is ControllerParameterDescriptor parameterDescriptor) + { + DoneAttemptingToBindParameter( + logger, + parameterDescriptor.ParameterInfo.Name, + modelMetadata.ModelType); + } + else + { + // Likely binding a page handler parameter. Due to various special cases, parameter.Name may + // be empty. No way to determine actual name. + DoneAttemptingToBindParameter(logger, parameter.Name, modelMetadata.ModelType); + } + break; + } + } + + [LoggerMessage(23, LogLevel.Debug, "Done attempting to bind parameter '{ParameterName}' of type '{ModelType}'.", EventName = "DoneAttemptingToBindParameter", SkipEnabledCheck = true)] + private static partial void DoneAttemptingToBindParameter(ILogger logger, string? parameterName, Type modelType); + + [LoggerMessage(40, LogLevel.Debug, "Done attempting to bind property '{PropertyContainerType}.{PropertyName}' of type '{ModelType}'.", EventName = "DoneAttemptingToBindProperty", SkipEnabledCheck = true)] + private static partial void DoneAttemptingToBindProperty(ILogger logger, Type? propertyContainerType, string? propertyName, Type modelType); + + public static void AttemptingToValidateParameterOrProperty( + ILogger logger, + ParameterDescriptor parameter, + ModelMetadata modelMetadata) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + switch (modelMetadata.MetadataKind) + { + case ModelMetadataKind.Parameter: + AttemptingToValidateParameter(logger, modelMetadata.ParameterName, modelMetadata.ModelType); + break; + case ModelMetadataKind.Property: + AttemptingToValidateProperty( + logger, + modelMetadata.ContainerType, + modelMetadata.PropertyName, + modelMetadata.ModelType); + break; + case ModelMetadataKind.Type: + if (parameter is ControllerParameterDescriptor parameterDescriptor) + { + AttemptingToValidateParameter( + logger, + parameterDescriptor.ParameterInfo.Name, + modelMetadata.ModelType); + } + else + { + // Likely binding a page handler parameter. Due to various special cases, parameter.Name may + // be empty. No way to determine actual name. This case is less likely than for binding logging + // (above). Should occur only with a legacy IModelMetadataProvider implementation. + AttemptingToValidateParameter(logger, parameter.Name, modelMetadata.ModelType); + } + break; + } + } + + [LoggerMessage(26, LogLevel.Debug, "Attempting to validate the bound parameter '{ParameterName}' of type '{ModelType}' ...", EventName = "AttemptingToValidateParameter", SkipEnabledCheck = true)] + private static partial void AttemptingToValidateParameter(ILogger logger, string? parameterName, Type modelType); + + [LoggerMessage(41, LogLevel.Debug, "Attempting to validate the bound property '{PropertyContainerType}.{PropertyName}' of type '{ModelType}' ...", EventName = "AttemptingToValidateProperty", SkipEnabledCheck = true)] + private static partial void AttemptingToValidateProperty(ILogger logger, Type? propertyContainerType, string? propertyName, Type modelType); + + public static void DoneAttemptingToValidateParameterOrProperty( + ILogger logger, + ParameterDescriptor parameter, + ModelMetadata modelMetadata) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + switch (modelMetadata.MetadataKind) + { + case ModelMetadataKind.Parameter: + DoneAttemptingToValidateParameter( + logger, + modelMetadata.ParameterName, + modelMetadata.ModelType); + break; + case ModelMetadataKind.Property: + DoneAttemptingToValidateProperty( + logger, + modelMetadata.ContainerType, + modelMetadata.PropertyName, + modelMetadata.ModelType); + break; + case ModelMetadataKind.Type: + if (parameter is ControllerParameterDescriptor parameterDescriptor) + { + DoneAttemptingToValidateParameter( + logger, + parameterDescriptor.ParameterInfo.Name, + modelMetadata.ModelType); + } + else + { + // Likely binding a page handler parameter. Due to various special cases, parameter.Name may + // be empty. No way to determine actual name. This case is less likely than for binding logging + // (above). Should occur only with a legacy IModelMetadataProvider implementation. + DoneAttemptingToValidateParameter(logger, parameter.Name, modelMetadata.ModelType); + } + break; + } + } + + [LoggerMessage(27, LogLevel.Debug, "Done attempting to validate the bound parameter '{ParameterName}' of type '{ModelType}'.", EventName = "DoneAttemptingToValidateParameter")] + private static partial void DoneAttemptingToValidateParameter(ILogger logger, string? parameterName, Type modelType); + + [LoggerMessage(42, LogLevel.Debug, "Done attempting to validate the bound property '{PropertyContainerType}.{PropertyName}' of type '{ModelType}'.", EventName = "DoneAttemptingToValidateProperty")] + private static partial void DoneAttemptingToValidateProperty(ILogger logger, Type? propertyContainerType, string? propertyName, Type modelType); + + public static void ParameterBinderRequestPredicateShortCircuit( + ILogger logger, + ParameterDescriptor parameter, + ModelMetadata modelMetadata) + { + if (!logger.IsEnabled(LogLevel.Debug)) + { + return; + } + + switch (modelMetadata.MetadataKind) + { + case ModelMetadataKind.Parameter: + ParameterBinderRequestPredicateShortCircuitOfParameter( + logger, + modelMetadata.ParameterName); + break; + case ModelMetadataKind.Property: + ParameterBinderRequestPredicateShortCircuitOfProperty( + logger, + modelMetadata.ContainerType, + modelMetadata.PropertyName); + break; + case ModelMetadataKind.Type: + if (parameter is ControllerParameterDescriptor controllerParameterDescriptor) + { + ParameterBinderRequestPredicateShortCircuitOfParameter( + logger, + controllerParameterDescriptor.ParameterInfo.Name); + } + else + { + // Likely binding a page handler parameter. Due to various special cases, parameter.Name may + // be empty. No way to determine actual name. This case is less likely than for binding logging + // (above). Should occur only with a legacy IModelMetadataProvider implementation. + ParameterBinderRequestPredicateShortCircuitOfParameter(logger, parameter.Name); + } + break; + } + } + + [LoggerMessage(47, LogLevel.Debug, "Skipped binding property '{PropertyContainerType}.{PropertyName}' since its binding information disallowed it for the current request.", + EventName = "ParameterBinderRequestPredicateShortCircuitOfProperty", + SkipEnabledCheck = true)] + private static partial void ParameterBinderRequestPredicateShortCircuitOfProperty(ILogger logger, Type? propertyContainerType, string? propertyName); + + [LoggerMessage(48, LogLevel.Debug, "Skipped binding parameter '{ParameterName}' since its binding information disallowed it for the current request.", + EventName = "ParameterBinderRequestPredicateShortCircuitOfParameter", + SkipEnabledCheck = true)] + private static partial void ParameterBinderRequestPredicateShortCircuitOfParameter(ILogger logger, string? parameterName); + } +} diff --git a/src/Mvc/Mvc.Core/src/ModelBinding/ParameterBinder.cs b/src/Mvc/Mvc.Core/src/ModelBinding/ParameterBinder.cs index 6ba93782b356..54386437510f 100644 --- a/src/Mvc/Mvc.Core/src/ModelBinding/ParameterBinder.cs +++ b/src/Mvc/Mvc.Core/src/ModelBinding/ParameterBinder.cs @@ -1,8 +1,6 @@ // 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.Abstractions; using Microsoft.AspNetCore.Mvc.Infrastructure; using Microsoft.AspNetCore.Mvc.ModelBinding.Validation; @@ -14,7 +12,7 @@ namespace Microsoft.AspNetCore.Mvc.ModelBinding; /// /// Binds and validates models specified by a . /// -public class ParameterBinder +public partial class ParameterBinder { private readonly IModelMetadataProvider _modelMetadataProvider; private readonly IModelBinderFactory _modelBinderFactory; @@ -136,11 +134,11 @@ public virtual async ValueTask BindModelAsync( throw new ArgumentNullException(nameof(metadata)); } - Logger.AttemptingToBindParameterOrProperty(parameter, metadata); + Log.AttemptingToBindParameterOrProperty(Logger, parameter, metadata); if (parameter.BindingInfo?.RequestPredicate?.Invoke(actionContext) == false) { - Logger.ParameterBinderRequestPredicateShortCircuit(parameter, metadata); + Log.ParameterBinderRequestPredicateShortCircuit(Logger, parameter, metadata); return ModelBindingResult.Failed(); } @@ -171,13 +169,13 @@ public virtual async ValueTask BindModelAsync( await modelBinder.BindModelAsync(modelBindingContext); - Logger.DoneAttemptingToBindParameterOrProperty(parameter, metadata); + Log.DoneAttemptingToBindParameterOrProperty(Logger, parameter, metadata); var modelBindingResult = modelBindingContext.Result; if (_objectModelValidator is ObjectModelValidator baseObjectValidator) { - Logger.AttemptingToValidateParameterOrProperty(parameter, metadata); + Log.AttemptingToValidateParameterOrProperty(Logger, parameter, metadata); EnforceBindRequiredAndValidate( baseObjectValidator, @@ -188,7 +186,7 @@ public virtual async ValueTask BindModelAsync( modelBindingResult, container); - Logger.DoneAttemptingToValidateParameterOrProperty(parameter, metadata); + Log.DoneAttemptingToValidateParameterOrProperty(Logger, parameter, metadata); } else { diff --git a/src/Mvc/Mvc.Core/src/MvcCoreLoggerExtensions.cs b/src/Mvc/Mvc.Core/src/MvcCoreLoggerExtensions.cs index b7d96bbad69e..cd8c3885931e 100644 --- a/src/Mvc/Mvc.Core/src/MvcCoreLoggerExtensions.cs +++ b/src/Mvc/Mvc.Core/src/MvcCoreLoggerExtensions.cs @@ -1,24 +1,14 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. -#nullable disable -#pragma warning disable CA1810 // Initialize all static fields inline. - using System.Collections; using System.Globalization; using System.Linq; -using System.Reflection; -using System.Text; using Microsoft.AspNetCore.Mvc.Abstractions; -using Microsoft.AspNetCore.Mvc.ApplicationModels; -using Microsoft.AspNetCore.Mvc.Controllers; using Microsoft.AspNetCore.Mvc.Filters; -using Microsoft.AspNetCore.Mvc.Formatters; using Microsoft.AspNetCore.Mvc.ModelBinding; using Microsoft.AspNetCore.Mvc.ModelBinding.Metadata; -using Microsoft.Extensions.Internal; using Microsoft.Extensions.Logging; -using Microsoft.Net.Http.Headers; namespace Microsoft.AspNetCore.Mvc; @@ -27,486 +17,11 @@ internal static partial class MvcCoreLoggerExtensions 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; - - private static readonly Action _pageExecuting; - private static readonly Action _pageExecuted; - - private static readonly Action _challengeResultExecuting; - private static readonly Action _actionMethodExecuting; - private static readonly Action _actionMethodExecutingWithArguments; - private static readonly Action _actionMethodExecuted; - - private static readonly Action _logFilterExecutionPlan; - private static readonly Action _beforeExecutingMethodOnFilter; - private static readonly Action _afterExecutingMethodOnFilter; - private static readonly Action _executingFileResult; - private static readonly Action _executingFileResultWithNoFileName; - private static readonly Action _resultFilterShortCircuit; - private static readonly Action _actionFilterShortCircuit; - private static readonly Action _exceptionFilterShortCircuit; - - private static readonly Action _forbidResultExecuting; - private static readonly Action _signOutResultExecuting; - private static readonly Action _objectResultExecuting; - private static readonly Action, Exception> _noFormatter; - private static readonly Action _formatterSelected; - private static readonly Action _inputFormatterSelected; - private static readonly Action _inputFormatterRejected; - private static readonly Action _noInputFormatterSelected; - private static readonly Action _removeFromBodyAttribute; - private static readonly Action _noActionsMatched; - private static readonly Action _modelStateInvalidFilterExecuting; - - private static readonly Action _inferredParameterSource; - private static readonly Action _foundNoValueForPropertyInRequest; - private static readonly Action _foundNoValueForParameterInRequest; - private static readonly Action _foundNoValueInRequest; - private static readonly Action _parameterBinderRequestPredicateShortCircuitOfProperty; - private static readonly Action _parameterBinderRequestPredicateShortCircuitOfParameter; - private static readonly Action _noPublicSettableProperties; - private static readonly Action _cannotBindToComplexType; - private static readonly Action _cannotBindToFilesCollectionDueToUnsupportedContentType; - private static readonly Action _cannotCreateHeaderModelBinderCompatVersion_2_0; - private static readonly Action _noNonIndexBasedFormatFoundForCollection; - private static readonly Action _attemptingToBindCollectionUsingIndices; - private static readonly Action _attemptingToBindCollectionOfKeyValuePair; - private static readonly Action _noKeyValueFormatForDictionaryModelBinder; - private static readonly Action _attemptingToBindParameterModel; - private static readonly Action _doneAttemptingToBindParameterModel; - private static readonly Action _attemptingToBindPropertyModel; - private static readonly Action _doneAttemptingToBindPropertyModel; - private static readonly Action _attemptingToBindModel; - private static readonly Action _doneAttemptingToBindModel; - private static readonly Action _attemptingToBindParameter; - private static readonly Action _doneAttemptingToBindParameter; - private static readonly Action _attemptingToBindProperty; - private static readonly Action _doneAttemptingToBindProperty; - private static readonly Action _attemptingToValidateProperty; - private static readonly Action _doneAttemptingToValidateProperty; - private static readonly Action _attemptingToValidateParameter; - private static readonly Action _doneAttemptingToValidateParameter; - private static readonly Action _actionDoesNotSupportFormatFilterContentType; - private static readonly Action _ifUnmodifiedSincePreconditionFailed; - private static readonly Action _ifRangeLastModifiedPreconditionFailed; - private static readonly Action _ifRangeETagPreconditionFailed; - private static readonly Action _transformingClientError; - - static MvcCoreLoggerExtensions() - { - LogDefineOptions SkipEnabledCheckLogOptions = new() { SkipEnabledCheck = true }; - _controllerFactoryExecuting = LoggerMessage.Define( - LogLevel.Debug, - new EventId(1, "ControllerFactoryExecuting"), - "Executing controller factory for controller {Controller} ({AssemblyName})", - SkipEnabledCheckLogOptions); - - _controllerFactoryExecuted = LoggerMessage.Define( - LogLevel.Debug, - new EventId(2, "ControllerFactoryExecuted"), - "Executed controller factory for controller {Controller} ({AssemblyName})", - SkipEnabledCheckLogOptions); - - _actionExecuting = LoggerMessage.Define( - LogLevel.Information, - new EventId(1, "ActionExecuting"), - "Route matched with {RouteData}. Executing action {ActionName}", - SkipEnabledCheckLogOptions); - - _controllerActionExecuting = LoggerMessage.Define( - LogLevel.Information, - new EventId(3, "ControllerActionExecuting"), - "Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName}).", - SkipEnabledCheckLogOptions); - - _actionExecuted = LoggerMessage.Define( - LogLevel.Information, - new EventId(2, "ActionExecuted"), - "Executed action {ActionName} in {ElapsedMilliseconds}ms", - SkipEnabledCheckLogOptions); - - _pageExecuting = LoggerMessage.Define( - LogLevel.Information, - new EventId(3, "PageExecuting"), - "Route matched with {RouteData}. Executing page {PageName}", - SkipEnabledCheckLogOptions); - - _pageExecuted = LoggerMessage.Define( - LogLevel.Information, - new EventId(4, "PageExecuted"), - "Executed page {PageName} in {ElapsedMilliseconds}ms", - SkipEnabledCheckLogOptions); - - _challengeResultExecuting = LoggerMessage.Define( - LogLevel.Information, - new EventId(1, "ChallengeResultExecuting"), - "Executing ChallengeResult with authentication schemes ({Schemes}).", - SkipEnabledCheckLogOptions); - _actionMethodExecuting = LoggerMessage.Define( - LogLevel.Information, - new EventId(1, "ActionMethodExecuting"), - "Executing action method {ActionName} - Validation state: {ValidationState}", - SkipEnabledCheckLogOptions); - - _actionMethodExecutingWithArguments = LoggerMessage.Define( - LogLevel.Trace, - new EventId(1, "ActionMethodExecutingWithArguments"), - "Executing action method {ActionName} with arguments ({Arguments})", - SkipEnabledCheckLogOptions); - - _actionMethodExecuted = LoggerMessage.Define( - LogLevel.Information, - new EventId(2, "ActionMethodExecuted"), - "Executed action method {ActionName}, returned result {ActionResult} in {ElapsedMilliseconds}ms.", - SkipEnabledCheckLogOptions); - - _logFilterExecutionPlan = LoggerMessage.Define( - LogLevel.Debug, - new EventId(1, "FilterExecutionPlan"), - "Execution plan of {FilterType} filters (in the following order): {Filters}", - SkipEnabledCheckLogOptions); - - _beforeExecutingMethodOnFilter = LoggerMessage.Define( - LogLevel.Trace, - new EventId(2, "BeforeExecutingMethodOnFilter"), - "{FilterType}: Before executing {Method} on filter {Filter}."); - - _afterExecutingMethodOnFilter = LoggerMessage.Define( - LogLevel.Trace, - new EventId(3, "AfterExecutingMethodOnFilter"), - "{FilterType}: After executing {Method} on filter {Filter}."); - _executingFileResult = LoggerMessage.Define( - LogLevel.Information, - new EventId(1, "ExecutingFileResult"), - "Executing {FileResultType}, sending file '{FileDownloadPath}' with download name '{FileDownloadName}' ...", - SkipEnabledCheckLogOptions); - - _executingFileResultWithNoFileName = LoggerMessage.Define( - LogLevel.Information, - new EventId(2, "ExecutingFileResultWithNoFileName"), - "Executing {FileResultType}, sending file with download name '{FileDownloadName}' ...", - SkipEnabledCheckLogOptions); - _resultFilterShortCircuit = LoggerMessage.Define( - LogLevel.Debug, - new EventId(5, "ResultFilterShortCircuit"), - "Request was short circuited at result filter '{ResultFilter}'."); - - _actionFilterShortCircuit = LoggerMessage.Define( - LogLevel.Debug, - new EventId(3, "ActionFilterShortCircuit"), - "Request was short circuited at action filter '{ActionFilter}'."); - - _exceptionFilterShortCircuit = LoggerMessage.Define( - LogLevel.Debug, - new EventId(4, "ExceptionFilterShortCircuit"), - "Request was short circuited at exception filter '{ExceptionFilter}'."); - - _forbidResultExecuting = LoggerMessage.Define( - LogLevel.Information, - new EventId(1, "ForbidResultExecuting"), - formatString: $"Executing {nameof(ForbidResult)} with authentication schemes ({{Schemes}}).", - SkipEnabledCheckLogOptions); - _signOutResultExecuting = LoggerMessage.Define( - LogLevel.Information, - new EventId(1, "SignOutResultExecuting"), - formatString: $"Executing {nameof(SignOutResult)} with authentication schemes ({{Schemes}}).", - SkipEnabledCheckLogOptions); - _noFormatter = LoggerMessage.Define>( - LogLevel.Warning, - new EventId(1, "NoFormatter"), - "No output formatter was found for content types '{ContentTypes}' to write the response.", - SkipEnabledCheckLogOptions); - - _objectResultExecuting = LoggerMessage.Define( - LogLevel.Information, - new EventId(1, "ObjectResultExecuting"), - "Executing {ObjectResultType}, writing value of type '{Type}'.", - SkipEnabledCheckLogOptions); - - _formatterSelected = LoggerMessage.Define( - LogLevel.Debug, - new EventId(2, "FormatterSelected"), - "Selected output formatter '{OutputFormatter}' and content type '{ContentType}' to write the response.", - SkipEnabledCheckLogOptions); - _inputFormatterSelected = LoggerMessage.Define( - LogLevel.Debug, - new EventId(1, "InputFormatterSelected"), - "Selected input formatter '{InputFormatter}' for content type '{ContentType}'.", - SkipEnabledCheckLogOptions); - - _inputFormatterRejected = LoggerMessage.Define( - LogLevel.Debug, - new EventId(2, "InputFormatterRejected"), - "Rejected input formatter '{InputFormatter}' for content type '{ContentType}'.", - SkipEnabledCheckLogOptions); - - _noInputFormatterSelected = LoggerMessage.Define( - LogLevel.Debug, - new EventId(3, "NoInputFormatterSelected"), - "No input formatter was found to support the content type '{ContentType}' for use with the [FromBody] attribute.", - SkipEnabledCheckLogOptions); - - _removeFromBodyAttribute = LoggerMessage.Define( - LogLevel.Debug, - new EventId(4, "RemoveFromBodyAttribute"), - "To use model binding, remove the [FromBody] attribute from the property or parameter named '{ModelName}' with model type '{ModelType}'.", - SkipEnabledCheckLogOptions); - _noActionsMatched = LoggerMessage.Define( - LogLevel.Debug, - new EventId(3, "NoActionsMatched"), - "No actions matched the current request. Route values: {RouteValues}", - SkipEnabledCheckLogOptions); - _modelStateInvalidFilterExecuting = LoggerMessage.Define( - LogLevel.Debug, - new EventId(1, "ModelStateInvalidFilterExecuting"), - "The request has model state errors, returning an error response."); - - _inferredParameterSource = LoggerMessage.Define( - LogLevel.Debug, - new EventId(1, "InferredParameterSource"), - "Inferred binding source for '{ParameterName}` on `{ActionName}` as {BindingSource}.", - SkipEnabledCheckLogOptions); - _actionDoesNotSupportFormatFilterContentType = LoggerMessage.Define( - LogLevel.Debug, - new EventId(2, "ActionDoesNotSupportFormatFilterContentType"), - "Current action does not support the content type '{FormatFilterContentType}'. The supported content types are '{SupportedMediaTypes}'."); - _attemptingToBindPropertyModel = LoggerMessage.Define( - LogLevel.Debug, - new EventId(13, "AttemptingToBindPropertyModel"), - "Attempting to bind property '{PropertyContainerType}.{PropertyName}' of type '{ModelType}' using the name '{ModelName}' in request data ...", - SkipEnabledCheckLogOptions); - - _doneAttemptingToBindPropertyModel = LoggerMessage.Define( - LogLevel.Debug, - new EventId(14, "DoneAttemptingToBindPropertyModel"), - "Done attempting to bind property '{PropertyContainerType}.{PropertyName}' of type '{ModelType}'.", - SkipEnabledCheckLogOptions); - - _foundNoValueForPropertyInRequest = LoggerMessage.Define( - LogLevel.Debug, - new EventId(15, "FoundNoValueForPropertyInRequest"), - "Could not find a value in the request with name '{ModelName}' for binding property '{PropertyContainerType}.{ModelFieldName}' of type '{ModelType}'.", - SkipEnabledCheckLogOptions); - - _foundNoValueForParameterInRequest = LoggerMessage.Define( - LogLevel.Debug, - new EventId(16, "FoundNoValueForParameterInRequest"), - "Could not find a value in the request with name '{ModelName}' for binding parameter '{ModelFieldName}' of type '{ModelType}'.", - SkipEnabledCheckLogOptions); - - _noPublicSettableProperties = LoggerMessage.Define( - LogLevel.Debug, - new EventId(17, "NoPublicSettableProperties"), - "Could not bind to model with name '{ModelName}' and type '{ModelType}' as the type has no public settable properties."); - - _cannotBindToComplexType = LoggerMessage.Define( - LogLevel.Debug, - new EventId(18, "CannotBindToComplexType"), - "Could not bind to model of type '{ModelType}' as there were no values in the request for any of the properties."); - - _cannotBindToFilesCollectionDueToUnsupportedContentType = LoggerMessage.Define( - LogLevel.Debug, - new EventId(19, "CannotBindToFilesCollectionDueToUnsupportedContentType"), - "Could not bind to model with name '{ModelName}' and type '{ModelType}' as the request did not have a content type of either 'application/x-www-form-urlencoded' or 'multipart/form-data'."); - _attemptingToBindParameter = LoggerMessage.Define( - LogLevel.Debug, - new EventId(22, "AttemptingToBindParameter"), - "Attempting to bind parameter '{ParameterName}' of type '{ModelType}' ...", - SkipEnabledCheckLogOptions); - - _doneAttemptingToBindParameter = LoggerMessage.Define( - LogLevel.Debug, - new EventId(23, "DoneAttemptingToBindParameter"), - "Done attempting to bind parameter '{ParameterName}' of type '{ModelType}'.", - SkipEnabledCheckLogOptions); - - _attemptingToBindModel = LoggerMessage.Define( - LogLevel.Debug, - new EventId(24, "AttemptingToBindModel"), - "Attempting to bind model of type '{ModelType}' using the name '{ModelName}' in request data ...", - SkipEnabledCheckLogOptions); - - _doneAttemptingToBindModel = LoggerMessage.Define( - LogLevel.Debug, - new EventId(25, "DoneAttemptingToBindModel"), - "Done attempting to bind model of type '{ModelType}' using the name '{ModelName}'.", - SkipEnabledCheckLogOptions); - - _attemptingToValidateParameter = LoggerMessage.Define( - LogLevel.Debug, - new EventId(26, "AttemptingToValidateParameter"), - "Attempting to validate the bound parameter '{ParameterName}' of type '{ModelType}' ...", - SkipEnabledCheckLogOptions); - - _doneAttemptingToValidateParameter = LoggerMessage.Define( - LogLevel.Debug, - new EventId(27, "DoneAttemptingToValidateParameter"), - "Done attempting to validate the bound parameter '{ParameterName}' of type '{ModelType}'.", - SkipEnabledCheckLogOptions); - - _noNonIndexBasedFormatFoundForCollection = LoggerMessage.Define( - LogLevel.Debug, - new EventId(28, "NoNonIndexBasedFormatFoundForCollection"), - "Could not bind to collection using a format like {ModelName}=value1&{ModelName}=value2"); - - _attemptingToBindCollectionUsingIndices = LoggerMessage.Define( - LogLevel.Debug, - new EventId(29, "AttemptingToBindCollectionUsingIndices"), - "Attempting to bind model using indices. Example formats include: " + - "[0]=value1&[1]=value2, " + - "{ModelName}[0]=value1&{ModelName}[1]=value2, " + - "{ModelName}.index=zero&{ModelName}.index=one&{ModelName}[zero]=value1&{ModelName}[one]=value2", - SkipEnabledCheckLogOptions); - - _attemptingToBindCollectionOfKeyValuePair = LoggerMessage.Define( - LogLevel.Debug, - new EventId(30, "AttemptingToBindCollectionOfKeyValuePair"), - "Attempting to bind collection of KeyValuePair. Example formats include: " + - "[0].Key=key1&[0].Value=value1&[1].Key=key2&[1].Value=value2, " + - "{ModelName}[0].Key=key1&{ModelName}[0].Value=value1&{ModelName}[1].Key=key2&{ModelName}[1].Value=value2, " + - "{ModelName}[key1]=value1&{ModelName}[key2]=value2", - SkipEnabledCheckLogOptions); - - _noKeyValueFormatForDictionaryModelBinder = LoggerMessage.Define( - LogLevel.Debug, - new EventId(33, "NoKeyValueFormatForDictionaryModelBinder"), - "Attempting to bind model with name '{ModelName}' using the format {ModelName}[key1]=value1&{ModelName}[key2]=value2"); - _ifUnmodifiedSincePreconditionFailed = LoggerMessage.Define( - LogLevel.Debug, - new EventId(35, "IfUnmodifiedSincePreconditionFailed"), - "Current request's If-Unmodified-Since header check failed as the file was modified (at '{lastModified}') after the If-Unmodified-Since date '{IfUnmodifiedSinceDate}'."); - - _ifRangeLastModifiedPreconditionFailed = LoggerMessage.Define( - LogLevel.Debug, - new EventId(36, "IfRangeLastModifiedPreconditionFailed"), - "Could not serve range as the file was modified (at {LastModified}) after the if-Range's last modified date '{IfRangeLastModified}'."); - - _ifRangeETagPreconditionFailed = LoggerMessage.Define( - LogLevel.Debug, - new EventId(37, "IfRangeETagPreconditionFailed"), - "Could not serve range as the file's current etag '{CurrentETag}' does not match the If-Range etag '{IfRangeETag}'."); - _attemptingToBindProperty = LoggerMessage.Define( - LogLevel.Debug, - new EventId(39, "AttemptingToBindProperty"), - "Attempting to bind property '{PropertyContainerType}.{PropertyName}' of type '{ModelType}' ...", - SkipEnabledCheckLogOptions); - - _doneAttemptingToBindProperty = LoggerMessage.Define( - LogLevel.Debug, - new EventId(40, "DoneAttemptingToBindProperty"), - "Done attempting to bind property '{PropertyContainerType}.{PropertyName}' of type '{ModelType}'.", - SkipEnabledCheckLogOptions); - - _attemptingToValidateProperty = LoggerMessage.Define( - LogLevel.Debug, - new EventId(41, "AttemptingToValidateProperty"), - "Attempting to validate the bound property '{PropertyContainerType}.{PropertyName}' of type '{ModelType}' ...", - SkipEnabledCheckLogOptions); - - _doneAttemptingToValidateProperty = LoggerMessage.Define( - LogLevel.Debug, - new EventId(42, "DoneAttemptingToValidateProperty"), - "Done attempting to validate the bound property '{PropertyContainerType}.{PropertyName}' of type '{ModelType}'.", - SkipEnabledCheckLogOptions); - - _cannotCreateHeaderModelBinderCompatVersion_2_0 = LoggerMessage.Define( - LogLevel.Debug, - new EventId(43, "CannotCreateHeaderModelBinderCompatVersion20"), - "Could not create a binder for type '{ModelType}' as this binder only supports 'System.String' type or a collection of 'System.String'."); - - _attemptingToBindParameterModel = LoggerMessage.Define( - LogLevel.Debug, - new EventId(44, "AttemptingToBindParameterModel"), - "Attempting to bind parameter '{ParameterName}' of type '{ModelType}' using the name '{ModelName}' in request data ...", - SkipEnabledCheckLogOptions); - - _doneAttemptingToBindParameterModel = LoggerMessage.Define( - LogLevel.Debug, - new EventId(45, "DoneAttemptingToBindParameterModel"), - "Done attempting to bind parameter '{ParameterName}' of type '{ModelType}'.", - SkipEnabledCheckLogOptions); - - _foundNoValueInRequest = LoggerMessage.Define( - LogLevel.Debug, - new EventId(46, "FoundNoValueInRequest"), - "Could not find a value in the request with name '{ModelName}' of type '{ModelType}'.", - SkipEnabledCheckLogOptions); - - _parameterBinderRequestPredicateShortCircuitOfProperty = LoggerMessage.Define( - LogLevel.Debug, - new EventId(47, "ParameterBinderRequestPredicateShortCircuitOfProperty"), - "Skipped binding property '{PropertyContainerType}.{PropertyName}' since its binding information disallowed it for the current request.", - SkipEnabledCheckLogOptions); - - _parameterBinderRequestPredicateShortCircuitOfParameter = LoggerMessage.Define( - LogLevel.Debug, - new EventId(48, "ParameterBinderRequestPredicateShortCircuitOfParameter"), - "Skipped binding parameter '{ParameterName}' since its binding information disallowed it for the current request.", - SkipEnabledCheckLogOptions); - - _transformingClientError = LoggerMessage.Define( - LogLevel.Trace, - new EventId(49, "ClientErrorResultFilter"), - "Replacing {InitialActionResultType} with status code {StatusCode} with {ReplacedActionResultType}."); - } - public static IDisposable ActionScope(this ILogger logger, ActionDescriptor action) { return logger.BeginScope(new ActionLogScope(action)); } - public static void ExecutingAction(this ILogger logger, ActionDescriptor action) - { - if (logger.IsEnabled(LogLevel.Information)) - { - var routeKeys = action.RouteValues.Keys.ToArray(); - var routeValues = action.RouteValues.Values.ToArray(); - var stringBuilder = new StringBuilder(); - stringBuilder.Append('{'); - for (var i = 0; i < routeValues.Length; i++) - { - if (i == routeValues.Length - 1) - { - stringBuilder.Append(FormattableString.Invariant($"{routeKeys[i]} = \"{routeValues[i]}\"")); - } - else - { - stringBuilder.Append(FormattableString.Invariant($"{routeKeys[i]} = \"{routeValues[i]}\", ")); - } - } - stringBuilder.Append('}'); - - if (action.RouteValues.TryGetValue("page", out var page) && page != null) - { - _pageExecuting(logger, stringBuilder.ToString(), action.DisplayName, null); - } - else - { - if (action is ControllerActionDescriptor controllerActionDescriptor) - { - var controllerType = controllerActionDescriptor.ControllerTypeInfo.AsType(); - var controllerName = TypeNameHelper.GetTypeDisplayName(controllerType); - _controllerActionExecuting( - logger, - stringBuilder.ToString(), - controllerActionDescriptor.MethodInfo, - controllerName, - controllerType.Assembly.GetName().Name, - null); - } - else - { - _actionExecuting(logger, stringBuilder.ToString(), action.DisplayName, null); - } - } - } - } - public static void AuthorizationFiltersExecutionPlan(this ILogger logger, IEnumerable filters) { if (!logger.IsEnabled(LogLevel.Debug)) @@ -562,274 +77,38 @@ public static void ResultFiltersExecutionPlan(this ILogger logger, IEnumerable routeValueDictionary) + public static void NoActionsMatched(this ILogger logger, IDictionary routeValueDictionary) { if (logger.IsEnabled(LogLevel.Debug)) { - string[] routeValues = null; - if (routeValueDictionary != null) + string[]? routeValues = null; + if (routeValueDictionary is not null) { routeValues = routeValueDictionary .Select(pair => pair.Key + "=" + Convert.ToString(pair.Value, CultureInfo.InvariantCulture)) .ToArray(); } - _noActionsMatched(logger, routeValues, null); - } - } - - public static void ChallengeResultExecuting(this ILogger logger, IList schemes) - { - if (logger.IsEnabled(LogLevel.Information)) - { - _challengeResultExecuting(logger, schemes.ToArray(), null); - } - } - - public static void ActionMethodExecuting(this 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, null); - - 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, null); - } - } - } - - public static void ActionMethodExecuted(this 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, null); - } - } - - public static void ExecutingFileResult(this ILogger logger, FileResult fileResult) - { - if (logger.IsEnabled(LogLevel.Information)) - { - var fileResultType = fileResult.GetType().Name; - _executingFileResultWithNoFileName(logger, fileResultType, fileResult.FileDownloadName, null); - } - } - - public static void ExecutingFileResult(this ILogger logger, FileResult fileResult, string fileName) - { - if (logger.IsEnabled(LogLevel.Information)) - { - var fileResultType = fileResult.GetType().Name; - _executingFileResult(logger, fileResultType, fileName, fileResult.FileDownloadName, null); - } - } - - public static void ResultFilterShortCircuited( - this ILogger logger, - IFilterMetadata filter) - { - _resultFilterShortCircuit(logger, filter, null); - } - - public static void ExceptionFilterShortCircuited( - this ILogger logger, - IFilterMetadata filter) - { - _exceptionFilterShortCircuit(logger, filter, null); - } - - public static void ActionFilterShortCircuited( - this ILogger logger, - IFilterMetadata filter) - { - _actionFilterShortCircuit(logger, filter, null); - } - - public static void ForbidResultExecuting(this ILogger logger, IList authenticationSchemes) - { - if (logger.IsEnabled(LogLevel.Information)) - { - _forbidResultExecuting(logger, authenticationSchemes.ToArray(), null); + NoActionsMatched(logger, routeValues); } } - public static void SignOutResultExecuting(this ILogger logger, IList authenticationSchemes) - { - if (logger.IsEnabled(LogLevel.Information)) - { - _signOutResultExecuting(logger, authenticationSchemes.ToArray(), null); - } - } - - public static void ObjectResultExecuting(this ILogger logger, ObjectResult result, object value) - { - if (logger.IsEnabled(LogLevel.Information)) - { - var objectResultType = result.GetType().Name; - var valueType = value == null ? "null" : value.GetType().FullName; - _objectResultExecuting(logger, objectResultType, valueType, null); - } - } - - public static void NoFormatter( - this ILogger logger, - OutputFormatterCanWriteContext context, - MediaTypeCollection contentTypes) - { - if (logger.IsEnabled(LogLevel.Warning)) - { - var considered = new List(contentTypes); - - if (context.ContentType.HasValue) - { - considered.Add(Convert.ToString(context.ContentType, CultureInfo.InvariantCulture)); - } - - _noFormatter(logger, considered, null); - } - } - - public static void FormatterSelected( - this ILogger logger, - IOutputFormatter outputFormatter, - OutputFormatterCanWriteContext context) - { - if (logger.IsEnabled(LogLevel.Debug)) - { - var contentType = Convert.ToString(context.ContentType, CultureInfo.InvariantCulture); - _formatterSelected(logger, outputFormatter, contentType, null); - } - } - - public static void InputFormatterSelected( - this ILogger logger, - IInputFormatter inputFormatter, - InputFormatterContext formatterContext) - { - if (logger.IsEnabled(LogLevel.Debug)) - { - var contentType = formatterContext.HttpContext.Request.ContentType; - _inputFormatterSelected(logger, inputFormatter, contentType, null); - } - } - - public static void InputFormatterRejected( - this ILogger logger, - IInputFormatter inputFormatter, - InputFormatterContext formatterContext) - { - if (logger.IsEnabled(LogLevel.Debug)) - { - var contentType = formatterContext.HttpContext.Request.ContentType; - _inputFormatterRejected(logger, inputFormatter, contentType, null); - } - } - - public static void NoInputFormatterSelected( - this ILogger logger, - InputFormatterContext formatterContext) - { - if (logger.IsEnabled(LogLevel.Debug)) - { - var contentType = formatterContext.HttpContext.Request.ContentType; - _noInputFormatterSelected(logger, contentType, null); - if (formatterContext.HttpContext.Request.HasFormContentType) - { - var modelType = formatterContext.ModelType.FullName; - var modelName = formatterContext.ModelName; - _removeFromBodyAttribute(logger, modelName, modelType, null); - } - } - } - - public static void ActionDoesNotSupportFormatFilterContentType( - this ILogger logger, - string format, - MediaTypeCollection supportedMediaTypes) - { - _actionDoesNotSupportFormatFilterContentType(logger, format, supportedMediaTypes, null); - } - - public static void ModelStateInvalidFilterExecuting(this ILogger logger) => _modelStateInvalidFilterExecuting(logger, null); + [LoggerMessage(3, LogLevel.Debug, "No actions matched the current request. Route values: {RouteValues}", EventName = "NoActionsMatched", SkipEnabledCheck = true)] + private static partial void NoActionsMatched(ILogger logger, string[]? routeValues); - public static void InferredParameterBindingSource( - this ILogger logger, - ParameterModel parameterModel, - BindingSource bindingSource) - { - if (logger.IsEnabled(LogLevel.Debug)) - { - _inferredParameterSource(logger, parameterModel.Action.ActionMethod, parameterModel.ParameterName, bindingSource.DisplayName, null); - } - } - - public static void IfUnmodifiedSincePreconditionFailed( - this ILogger logger, - DateTimeOffset? lastModified, - DateTimeOffset? ifUnmodifiedSinceDate) - { - _ifUnmodifiedSincePreconditionFailed(logger, lastModified, ifUnmodifiedSinceDate, null); - } + [LoggerMessage(5, LogLevel.Debug, "Request was short circuited at result filter '{ResultFilter}'.", EventName = "ResultFilterShortCircuit")] + public static partial void ResultFilterShortCircuited(this ILogger logger, IFilterMetadata resultFilter); - public static void IfRangeLastModifiedPreconditionFailed( - this ILogger logger, - DateTimeOffset? lastModified, - DateTimeOffset? ifRangeLastModifiedDate) - { - _ifRangeLastModifiedPreconditionFailed(logger, lastModified, ifRangeLastModifiedDate, null); - } + [LoggerMessage(4, LogLevel.Debug, "Request was short circuited at exception filter '{ExceptionFilter}'.", EventName = "ExceptionFilterShortCircuit")] + public static partial void ExceptionFilterShortCircuited(this ILogger logger, IFilterMetadata exceptionFilter); - public static void IfRangeETagPreconditionFailed( - this ILogger logger, - EntityTagHeaderValue currentETag, - EntityTagHeaderValue ifRangeTag) - { - _ifRangeETagPreconditionFailed(logger, currentETag, ifRangeTag, null); - } + [LoggerMessage(63, LogLevel.Debug, "Request was short circuited at action filter '{ActionFilter}'.", EventName = "ActionFilterShortCircuit")] + public static partial void ActionFilterShortCircuited(this ILogger logger, IFilterMetadata actionFilter); public static void FoundNoValueInRequest(this ILogger logger, ModelBindingContext bindingContext) { @@ -842,51 +121,49 @@ public static void FoundNoValueInRequest(this ILogger logger, ModelBindingContex switch (modelMetadata.MetadataKind) { case ModelMetadataKind.Parameter: - _foundNoValueForParameterInRequest( + FoundNoValueForParameterInRequest( logger, bindingContext.ModelName, modelMetadata.ParameterName, - bindingContext.ModelType, - null); + bindingContext.ModelType); break; case ModelMetadataKind.Property: - _foundNoValueForPropertyInRequest( + FoundNoValueForPropertyInRequest( logger, bindingContext.ModelName, modelMetadata.ContainerType, modelMetadata.PropertyName, - bindingContext.ModelType, - null); + bindingContext.ModelType); break; case ModelMetadataKind.Type: - _foundNoValueInRequest( + FoundNoValueInRequest( logger, bindingContext.ModelName, - bindingContext.ModelType, - null); + bindingContext.ModelType); break; } } - public static void NoPublicSettableProperties(this ILogger logger, ModelBindingContext bindingContext) - { - _noPublicSettableProperties(logger, bindingContext.ModelName, bindingContext.ModelType, null); - } + [LoggerMessage(15, LogLevel.Debug, "Could not find a value in the request with name '{ModelName}' for binding property '{PropertyContainerType}.{ModelFieldName}' of type '{ModelType}'.", + EventName = "FoundNoValueForPropertyInRequest", + SkipEnabledCheck = true)] + private static partial void FoundNoValueForPropertyInRequest(ILogger logger, string modelName, Type? propertyContainerType, string? modelFieldName, Type modelType); - public static void CannotBindToComplexType(this ILogger logger, ModelBindingContext bindingContext) - { - _cannotBindToComplexType(logger, bindingContext.ModelType, null); - } + [LoggerMessage(16, LogLevel.Debug, "Could not find a value in the request with name '{ModelName}' for binding parameter '{ModelFieldName}' of type '{ModelType}'.", + EventName = "FoundNoValueForParameterInRequest", + SkipEnabledCheck = true)] + private static partial void FoundNoValueForParameterInRequest(ILogger logger, string modelName, string? modelFieldName, Type modelType); + + [LoggerMessage(46, LogLevel.Debug, "Could not find a value in the request with name '{ModelName}' of type '{ModelType}'.", EventName = "FoundNoValueInRequest", SkipEnabledCheck = true)] + private static partial void FoundNoValueInRequest(ILogger logger, string modelName, Type modelType); public static void CannotBindToFilesCollectionDueToUnsupportedContentType(this ILogger logger, ModelBindingContext bindingContext) - { - _cannotBindToFilesCollectionDueToUnsupportedContentType(logger, bindingContext.ModelName, bindingContext.ModelType, null); - } + => CannotBindToFilesCollectionDueToUnsupportedContentType(logger, bindingContext.ModelName, bindingContext.ModelType); - public static void CannotCreateHeaderModelBinderCompatVersion_2_0(this ILogger logger, Type modelType) - { - _cannotCreateHeaderModelBinderCompatVersion_2_0(logger, modelType, null); - } + [LoggerMessage(19, LogLevel.Debug, + "Could not bind to model with name '{ModelName}' and type '{ModelType}' as the request did not have a content type of either 'application/x-www-form-urlencoded' or 'multipart/form-data'.", + EventName = "CannotBindToFilesCollectionDueToUnsupportedContentType")] + private static partial void CannotBindToFilesCollectionDueToUnsupportedContentType(ILogger logger, string modelName, Type modelType); public static void AttemptingToBindModel(this ILogger logger, ModelBindingContext bindingContext) { @@ -899,320 +176,72 @@ public static void AttemptingToBindModel(this ILogger logger, ModelBindingContex switch (modelMetadata.MetadataKind) { case ModelMetadataKind.Parameter: - _attemptingToBindParameterModel( - logger, - modelMetadata.ParameterName, - modelMetadata.ModelType, - bindingContext.ModelName, - null); - break; - case ModelMetadataKind.Property: - _attemptingToBindPropertyModel( - logger, - modelMetadata.ContainerType, - modelMetadata.PropertyName, - modelMetadata.ModelType, - bindingContext.ModelName, - null); - break; - case ModelMetadataKind.Type: - _attemptingToBindModel(logger, bindingContext.ModelType, bindingContext.ModelName, null); - break; - } - } - - public static void DoneAttemptingToBindModel(this ILogger logger, ModelBindingContext bindingContext) - { - if (!logger.IsEnabled(LogLevel.Debug)) - { - return; - } - - var modelMetadata = bindingContext.ModelMetadata; - switch (modelMetadata.MetadataKind) - { - case ModelMetadataKind.Parameter: - _doneAttemptingToBindParameterModel( + AttemptingToBindParameterModel( logger, modelMetadata.ParameterName, modelMetadata.ModelType, - null); + bindingContext.ModelName); break; case ModelMetadataKind.Property: - _doneAttemptingToBindPropertyModel( + AttemptingToBindPropertyModel( logger, modelMetadata.ContainerType, modelMetadata.PropertyName, modelMetadata.ModelType, - null); + bindingContext.ModelName); break; case ModelMetadataKind.Type: - _doneAttemptingToBindModel(logger, bindingContext.ModelType, bindingContext.ModelName, null); + AttemptingToBindModel(logger, bindingContext.ModelType, bindingContext.ModelName); break; } } - public static void AttemptingToBindParameterOrProperty( - this ILogger logger, - ParameterDescriptor parameter, - ModelMetadata modelMetadata) - { - if (!logger.IsEnabled(LogLevel.Debug)) - { - return; - } - - switch (modelMetadata.MetadataKind) - { - case ModelMetadataKind.Parameter: - _attemptingToBindParameter(logger, modelMetadata.ParameterName, modelMetadata.ModelType, null); - break; - case ModelMetadataKind.Property: - _attemptingToBindProperty( - logger, - modelMetadata.ContainerType, - modelMetadata.PropertyName, - modelMetadata.ModelType, - null); - break; - case ModelMetadataKind.Type: - if (parameter is ControllerParameterDescriptor parameterDescriptor) - { - _attemptingToBindParameter( - logger, - parameterDescriptor.ParameterInfo.Name, - modelMetadata.ModelType, - null); - } - else - { - // Likely binding a page handler parameter. Due to various special cases, parameter.Name may - // be empty. No way to determine actual name. - _attemptingToBindParameter(logger, parameter.Name, modelMetadata.ModelType, null); - } - break; - } - } + [LoggerMessage(44, LogLevel.Debug, "Attempting to bind parameter '{ParameterName}' of type '{ModelType}' using the name '{ModelName}' in request data ...", EventName = "AttemptingToBindParameterModel", SkipEnabledCheck = true)] + private static partial void AttemptingToBindParameterModel(ILogger logger, string? parameterName, Type modelType, string modelName); - public static void DoneAttemptingToBindParameterOrProperty( - this ILogger logger, - ParameterDescriptor parameter, - ModelMetadata modelMetadata) - { - if (!logger.IsEnabled(LogLevel.Debug)) - { - return; - } + [LoggerMessage(13, LogLevel.Debug, "Attempting to bind property '{PropertyContainerType}.{PropertyName}' of type '{ModelType}' using the name '{ModelName}' in request data ...", EventName = "AttemptingToBindPropertyModel", SkipEnabledCheck = true)] + private static partial void AttemptingToBindPropertyModel(ILogger logger, Type? propertyContainerType, string? propertyName, Type modelType, string modelName); - switch (modelMetadata.MetadataKind) - { - case ModelMetadataKind.Parameter: - _doneAttemptingToBindParameter(logger, modelMetadata.ParameterName, modelMetadata.ModelType, null); - break; - case ModelMetadataKind.Property: - _doneAttemptingToBindProperty( - logger, - modelMetadata.ContainerType, - modelMetadata.PropertyName, - modelMetadata.ModelType, - null); - break; - case ModelMetadataKind.Type: - if (parameter is ControllerParameterDescriptor parameterDescriptor) - { - _doneAttemptingToBindParameter( - logger, - parameterDescriptor.ParameterInfo.Name, - modelMetadata.ModelType, - null); - } - else - { - // Likely binding a page handler parameter. Due to various special cases, parameter.Name may - // be empty. No way to determine actual name. - _doneAttemptingToBindParameter(logger, parameter.Name, modelMetadata.ModelType, null); - } - break; - } - } - - public static void AttemptingToValidateParameterOrProperty( - this ILogger logger, - ParameterDescriptor parameter, - ModelMetadata modelMetadata) - { - if (!logger.IsEnabled(LogLevel.Debug)) - { - return; - } - - switch (modelMetadata.MetadataKind) - { - case ModelMetadataKind.Parameter: - _attemptingToValidateParameter(logger, modelMetadata.ParameterName, modelMetadata.ModelType, null); - break; - case ModelMetadataKind.Property: - _attemptingToValidateProperty( - logger, - modelMetadata.ContainerType, - modelMetadata.PropertyName, - modelMetadata.ModelType, - null); - break; - case ModelMetadataKind.Type: - if (parameter is ControllerParameterDescriptor parameterDescriptor) - { - _attemptingToValidateParameter( - logger, - parameterDescriptor.ParameterInfo.Name, - modelMetadata.ModelType, - null); - } - else - { - // Likely binding a page handler parameter. Due to various special cases, parameter.Name may - // be empty. No way to determine actual name. This case is less likely than for binding logging - // (above). Should occur only with a legacy IModelMetadataProvider implementation. - _attemptingToValidateParameter(logger, parameter.Name, modelMetadata.ModelType, null); - } - break; - } - } - - public static void DoneAttemptingToValidateParameterOrProperty( - this ILogger logger, - ParameterDescriptor parameter, - ModelMetadata modelMetadata) + [LoggerMessage(24, LogLevel.Debug, "Attempting to bind model of type '{ModelType}' using the name '{ModelName}' in request data ...", EventName = "AttemptingToBindModel", SkipEnabledCheck = true)] + private static partial void AttemptingToBindModel(ILogger logger, Type modelType, string modelName); + + public static void DoneAttemptingToBindModel(this ILogger logger, ModelBindingContext bindingContext) { if (!logger.IsEnabled(LogLevel.Debug)) { return; } + var modelMetadata = bindingContext.ModelMetadata; switch (modelMetadata.MetadataKind) { case ModelMetadataKind.Parameter: - _doneAttemptingToValidateParameter( + DoneAttemptingToBindParameterModel( logger, modelMetadata.ParameterName, - modelMetadata.ModelType, - null); + modelMetadata.ModelType); break; case ModelMetadataKind.Property: - _doneAttemptingToValidateProperty( + DoneAttemptingToBindPropertyModel( logger, modelMetadata.ContainerType, modelMetadata.PropertyName, - modelMetadata.ModelType, - null); + modelMetadata.ModelType); break; case ModelMetadataKind.Type: - if (parameter is ControllerParameterDescriptor parameterDescriptor) - { - _doneAttemptingToValidateParameter( - logger, - parameterDescriptor.ParameterInfo.Name, - modelMetadata.ModelType, - null); - } - else - { - // Likely binding a page handler parameter. Due to various special cases, parameter.Name may - // be empty. No way to determine actual name. This case is less likely than for binding logging - // (above). Should occur only with a legacy IModelMetadataProvider implementation. - _doneAttemptingToValidateParameter(logger, parameter.Name, modelMetadata.ModelType, null); - } + DoneAttemptingToBindModel(logger, bindingContext.ModelType, bindingContext.ModelName); break; } } - public static void NoNonIndexBasedFormatFoundForCollection(this ILogger logger, ModelBindingContext bindingContext) - { - var modelName = bindingContext.ModelName; - _noNonIndexBasedFormatFoundForCollection(logger, modelName, modelName, null); - } - - public static void AttemptingToBindCollectionUsingIndices(this ILogger logger, ModelBindingContext bindingContext) - { - if (!logger.IsEnabled(LogLevel.Debug)) - { - return; - } - - var modelName = bindingContext.ModelName; + [LoggerMessage(14, LogLevel.Debug, "Done attempting to bind property '{PropertyContainerType}.{PropertyName}' of type '{ModelType}'.", EventName = "DoneAttemptingToBindPropertyModel")] + private static partial void DoneAttemptingToBindPropertyModel(ILogger logger, Type? propertyContainerType, string? propertyName, Type modelType); - var enumerableType = ClosedGenericMatcher.ExtractGenericInterface(bindingContext.ModelType, typeof(IEnumerable<>)); - if (enumerableType != null) - { - var elementType = enumerableType.GenericTypeArguments[0]; - if (elementType.IsGenericType && elementType.GetGenericTypeDefinition() == typeof(KeyValuePair<,>)) - { - _attemptingToBindCollectionOfKeyValuePair(logger, modelName, modelName, modelName, modelName, modelName, modelName, null); - return; - } - } + [LoggerMessage(25, LogLevel.Debug, "Done attempting to bind model of type '{ModelType}' using the name '{ModelName}'.", EventName = "DoneAttemptingToBindModel", SkipEnabledCheck = true)] + private static partial void DoneAttemptingToBindModel(ILogger logger, Type modelType, string modelName); - _attemptingToBindCollectionUsingIndices(logger, modelName, modelName, modelName, modelName, modelName, modelName, null); - } - - public static void NoKeyValueFormatForDictionaryModelBinder(this ILogger logger, ModelBindingContext bindingContext) - { - _noKeyValueFormatForDictionaryModelBinder( - logger, - bindingContext.ModelName, - bindingContext.ModelName, - bindingContext.ModelName, - null); - } - - public static void ParameterBinderRequestPredicateShortCircuit( - this ILogger logger, - ParameterDescriptor parameter, - ModelMetadata modelMetadata) - { - if (!logger.IsEnabled(LogLevel.Debug)) - { - return; - } - - switch (modelMetadata.MetadataKind) - { - case ModelMetadataKind.Parameter: - _parameterBinderRequestPredicateShortCircuitOfParameter( - logger, - modelMetadata.ParameterName, - null); - break; - case ModelMetadataKind.Property: - _parameterBinderRequestPredicateShortCircuitOfProperty( - logger, - modelMetadata.ContainerType, - modelMetadata.PropertyName, - null); - break; - case ModelMetadataKind.Type: - if (parameter is ControllerParameterDescriptor controllerParameterDescriptor) - { - _parameterBinderRequestPredicateShortCircuitOfParameter( - logger, - controllerParameterDescriptor.ParameterInfo.Name, - null); - } - else - { - // Likely binding a page handler parameter. Due to various special cases, parameter.Name may - // be empty. No way to determine actual name. This case is less likely than for binding logging - // (above). Should occur only with a legacy IModelMetadataProvider implementation. - _parameterBinderRequestPredicateShortCircuitOfParameter(logger, parameter.Name, null); - } - break; - } - } - - public static void TransformingClientError(this ILogger logger, Type initialType, Type replacedType, int? statusCode) - { - _transformingClientError(logger, initialType, statusCode, replacedType, null); - } + [LoggerMessage(45, LogLevel.Debug, "Done attempting to bind parameter '{ParameterName}' of type '{ModelType}'.", EventName = "DoneAttemptingToBindParameterModel", SkipEnabledCheck = true)] + private static partial void DoneAttemptingToBindParameterModel(ILogger logger, string? parameterName, Type modelType); private static void LogFilterExecutionPlan( ILogger logger, @@ -1225,32 +254,11 @@ private static void LogFilterExecutionPlan( filterList = GetFilterList(filters); } - _logFilterExecutionPlan(logger, filterType, filterList, null); + LogFilterExecutionPlan(logger, filterType, filterList); } - 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); - } + [LoggerMessage(1, LogLevel.Debug, "Execution plan of {FilterType} filters (in the following order): {Filters}", EventName = "FilterExecutionPlan", SkipEnabledCheck = true)] + private static partial void LogFilterExecutionPlan(ILogger logger, string filterType, string[] filters); private static string[] GetFilterList(IEnumerable filters) { @@ -1269,7 +277,7 @@ private static string[] GetFilterList(IEnumerable filters) return filterList.ToArray(); } - private class ActionLogScope : IReadOnlyList> + private sealed class ActionLogScope : IReadOnlyList> { private readonly ActionDescriptor _action; diff --git a/src/Mvc/Mvc.Core/src/SignOutResult.cs b/src/Mvc/Mvc.Core/src/SignOutResult.cs index 555c7402f0ea..adb914173c5d 100644 --- a/src/Mvc/Mvc.Core/src/SignOutResult.cs +++ b/src/Mvc/Mvc.Core/src/SignOutResult.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.AspNetCore.Http; using Microsoft.AspNetCore.Mvc.Core; @@ -12,7 +13,7 @@ namespace Microsoft.AspNetCore.Mvc; /// /// An that on execution invokes . /// -public class SignOutResult : ActionResult, IResult +public partial class SignOutResult : ActionResult, IResult { /// /// Initializes a new instance of with the default sign out scheme. @@ -114,8 +115,7 @@ private async Task ExecuteAsync(HttpContext httpContext) var loggerFactory = httpContext.RequestServices.GetRequiredService(); var logger = loggerFactory.CreateLogger(); - - logger.SignOutResultExecuting(AuthenticationSchemes); + Log.SignOutResultExecuting(logger, AuthenticationSchemes); if (AuthenticationSchemes.Count == 0) { @@ -129,4 +129,18 @@ private async Task ExecuteAsync(HttpContext httpContext) } } } + + private static partial class Log + { + public static void SignOutResultExecuting(ILogger logger, IList authenticationSchemes) + { + if (logger.IsEnabled(LogLevel.Information)) + { + SignOutResultExecuting(logger, authenticationSchemes.ToArray()); + } + } + + [LoggerMessage(1, LogLevel.Information, $"Executing {nameof(SignOutResult)} with authentication schemes ({{Schemes}}).", EventName = "SignOutResultExecuting", SkipEnabledCheck = true)] + private static partial void SignOutResultExecuting(ILogger logger, string[] schemes); + } } diff --git a/src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs b/src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs index 338d2322511e..91030bc8bfe5 100644 --- a/src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs +++ b/src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs @@ -1,4 +1,4 @@ -// Licensed to the .NET Foundation under one or more agreements. +// Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. using System.Reflection; @@ -6,6 +6,7 @@ using Microsoft.AspNetCore.Mvc.Abstractions; using Microsoft.AspNetCore.Mvc.Filters; using Microsoft.AspNetCore.Mvc.Formatters; +using Microsoft.AspNetCore.Mvc.Infrastructure; using Microsoft.Extensions.Logging.Testing; using Moq; @@ -15,19 +16,19 @@ public class MvcCoreLoggerExtensionsTest { public static object[][] RouteValuesTestData { get; } = new object[][] { - new object[]{ "{}" }, - new object[]{ "{foo = \"bar\"}", new KeyValuePair("foo", "bar") }, - new object[]{ "{foo = \"bar\", other = \"value\"}", - new KeyValuePair("foo", "bar"), - new KeyValuePair("other", "value") }, + new object[]{ "{}" }, + new object[]{ "{foo = \"bar\"}", new KeyValuePair("foo", "bar") }, + new object[]{ "{foo = \"bar\", other = \"value\"}", + new KeyValuePair("foo", "bar"), + 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") }, + new object[]{ "{page = \"bar\"}", new KeyValuePair("page", "bar") }, + new object[]{ "{page = \"bar\", other = \"value\"}", + new KeyValuePair("page", "bar"), + new KeyValuePair("other", "value") }, }; [Theory] @@ -52,7 +53,7 @@ public void ExecutingAction_ForControllerAction_WithGivenRouteValues_LogsActionA } // Act - logger.ExecutingAction(action); + ResourceInvoker.Log.ExecutingAction(logger, action); // Assert var write = Assert.Single(testSink.Writes); @@ -82,7 +83,7 @@ public void ExecutingAction_ForAction_WithGivenRouteValues_LogsActionAndRouteDat } // Act - logger.ExecutingAction(action); + ResourceInvoker.Log.ExecutingAction(logger, action); // Assert var write = Assert.Single(testSink.Writes); @@ -111,7 +112,7 @@ public void ExecutingAction_ForPage_WithGivenRouteValues_LogsPageAndRouteData(st } // Act - logger.ExecutingAction(action); + ResourceInvoker.Log.ExecutingAction(logger, action); // Assert var write = Assert.Single(testSink.Writes); @@ -412,7 +413,7 @@ public void NoFormatter_LogsListOfContentTypes() context.SetupGet(x => x.ContentType).Returns("application/json"); // Act - logger.NoFormatter(context.Object, mediaTypes); + ObjectResultExecutor.Log.NoFormatter(logger, context.Object, mediaTypes); // Assert var write = Assert.Single(testSink.Writes); @@ -441,7 +442,7 @@ public void ExecutingControllerFactory_LogsControllerName() }; // Act - logger.ExecutingControllerFactory(context); + ControllerActionInvoker.Log.ExecutingControllerFactory(logger, context); // Assert var write = Assert.Single(testSink.Writes); @@ -469,7 +470,7 @@ public void ExecutedControllerFactory_LogsControllerName() }; // Act - logger.ExecutedControllerFactory(context); + ControllerActionInvoker.Log.ExecutedControllerFactory(logger, context); // Assert var write = Assert.Single(testSink.Writes);