From f69b2d791c5a097c097384aeb4704842247a7291 Mon Sep 17 00:00:00 2001 From: Pranav K Date: Sun, 27 Feb 2022 13:28:56 -0800 Subject: [PATCH] Update MvcCoreLoggerExtensions to use LoggerMessageAttribute MvcCoreLoggerExtensions includes the log messages for a whole slew of MVC types. Consequently it re-uses event ids and is hard maintain. This PR simultaenously updates the type to use LoggerMessageAttribute, while also attempts to move as many of the individual log statements to the appropriate type. This change unearthed incorrect reuse of event ids within the same type that has also been corrected by assigning new ids. Fixes https://github.com/dotnet/aspnetcore/issues/32087 --- src/Mvc/Mvc.Core/src/ChallengeResult.cs | 20 +- src/Mvc/Mvc.Core/src/ForbidResult.cs | 20 +- .../Mvc.Core/src/Formatters/FormatFilter.cs | 5 +- .../Infrastructure/ClientErrorResultFilter.cs | 12 +- .../Infrastructure/ControllerActionInvoker.cs | 88 +- .../DefaultOutputFormatterSelector.cs | 18 +- .../FileContentResultExecutor.cs | 14 +- .../FileStreamResultExecutor.cs | 14 +- .../Infrastructure/ModelStateInvalidFilter.cs | 10 +- .../Infrastructure/ObjectResultExecutor.cs | 46 +- .../PhysicalFileResultExecutor.cs | 14 +- .../src/Infrastructure/ResourceInvoker.Log.cs | 119 ++ .../src/Infrastructure/ResourceInvoker.cs | 29 +- .../VirtualFileResultExecutor.cs | 14 +- .../ModelBinding/Binders/BodyModelBinder.cs | 56 +- .../Binders/CollectionModelBinder.cs | 57 +- .../Binders/ComplexObjectModelBinder.cs | 8 +- .../Binders/ComplexTypeModelBinder.cs | 21 +- .../Binders/DictionaryModelBinder.cs | 13 +- .../src/ModelBinding/ParameterBinder.Log.cs | 255 ++++ .../src/ModelBinding/ParameterBinder.cs | 14 +- .../Mvc.Core/src/MvcCoreLoggerExtensions.cs | 1126 +---------------- src/Mvc/Mvc.Core/src/SignOutResult.cs | 20 +- .../test/MvcCoreLoggerExtensionsTest.cs | 33 +- 24 files changed, 870 insertions(+), 1156 deletions(-) create mode 100644 src/Mvc/Mvc.Core/src/Infrastructure/ResourceInvoker.Log.cs create mode 100644 src/Mvc/Mvc.Core/src/ModelBinding/ParameterBinder.Log.cs 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);