From 082d57bb9d93b4820efb1d49feb59103fe983300 Mon Sep 17 00:00:00 2001 From: Pranav K Date: Tue, 9 Apr 2019 15:56:35 -0700 Subject: [PATCH 1/6] Don't log action and page handler arguments Fixes https://github.com/aspnet/AspNetCore/issues/9121 --- .../src/Internal/MvcCoreLoggerExtensions.cs | 23 +------------------ .../src/Internal/PageLoggerExtensions.cs | 23 ++++--------------- 2 files changed, 5 insertions(+), 41 deletions(-) diff --git a/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs b/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs index c840f785b10b..277f7b97d2e7 100644 --- a/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs +++ b/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs @@ -39,7 +39,6 @@ internal static class MvcCoreLoggerExtensions private static readonly Action _contentResultExecuting; private static readonly Action _actionMethodExecuting; - private static readonly Action _actionMethodExecutingWithArguments; private static readonly Action _actionMethodExecuted; private static readonly Action _logFilterExecutionPlan; @@ -173,11 +172,6 @@ static MvcCoreLoggerExtensions() 1, "Executing action method {ActionName} - Validation state: {ValidationState}"); - _actionMethodExecutingWithArguments = LoggerMessage.Define( - LogLevel.Information, - 1, - "Executing action method {ActionName} with arguments ({Arguments}) - Validation state: {ValidationState}"); - _actionMethodExecuted = LoggerMessage.Define( LogLevel.Information, 2, @@ -814,22 +808,7 @@ public static void ActionMethodExecuting(this ILogger logger, ControllerContext var actionName = context.ActionDescriptor.DisplayName; var validationState = context.ModelState.ValidationState; - - string[] convertedArguments; - if (arguments == null) - { - _actionMethodExecuting(logger, actionName, validationState, null); - } - else - { - convertedArguments = new string[arguments.Length]; - for (var i = 0; i < arguments.Length; i++) - { - convertedArguments[i] = Convert.ToString(arguments[i]); - } - - _actionMethodExecutingWithArguments(logger, actionName, convertedArguments, validationState, null); - } + _actionMethodExecuting(logger, actionName, validationState, null); } } diff --git a/src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs b/src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs index a5d7c960d48c..c74766e535a4 100644 --- a/src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs +++ b/src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs @@ -15,7 +15,7 @@ internal static class PageLoggerExtensions { public const string PageFilter = "Page Filter"; - private static readonly Action _handlerMethodExecuting; + private static readonly Action _handlerMethodExecuting; private static readonly Action _handlerMethodExecuted; private static readonly Action _pageFilterShortCircuit; private static readonly Action _malformedPageDirective; @@ -28,10 +28,10 @@ static PageLoggerExtensions() { // These numbers start at 101 intentionally to avoid conflict with the IDs used by ResourceInvoker. - _handlerMethodExecuting = LoggerMessage.Define( + _handlerMethodExecuting = LoggerMessage.Define( LogLevel.Information, 101, - "Executing handler method {HandlerName} with arguments ({Arguments}) - ModelState is {ValidationState}"); + "Executing handler method {HandlerName} - ModelState is {ValidationState}"); _handlerMethodExecuted = LoggerMessage.Define( LogLevel.Debug, @@ -75,23 +75,8 @@ public static void ExecutingHandlerMethod(this ILogger logger, PageContext conte { var handlerName = handler.MethodInfo.Name; - string[] convertedArguments; - if (arguments == null) - { - convertedArguments = null; - } - else - { - convertedArguments = new string[arguments.Length]; - for (var i = 0; i < arguments.Length; i++) - { - convertedArguments[i] = Convert.ToString(arguments[i]); - } - } - var validationState = context.ModelState.ValidationState; - - _handlerMethodExecuting(logger, handlerName, convertedArguments, validationState, null); + _handlerMethodExecuting(logger, handlerName, validationState, null); } } From 4aa9981ef0bdbf334e063063d21989e28022b185 Mon Sep 17 00:00:00 2001 From: Pranav K Date: Wed, 10 Apr 2019 06:23:34 -0700 Subject: [PATCH 2/6] Log arguments at Debug --- .../src/Internal/MvcCoreLoggerExtensions.cs | 17 +++++++++++++++++ .../src/Internal/PageLoggerExtensions.cs | 18 ++++++++++++++++++ 2 files changed, 35 insertions(+) diff --git a/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs b/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs index 277f7b97d2e7..fae92b3e639f 100644 --- a/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs +++ b/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs @@ -39,6 +39,7 @@ internal static class MvcCoreLoggerExtensions private static readonly Action _contentResultExecuting; private static readonly Action _actionMethodExecuting; + private static readonly Action _actionMethodExecutingWithArguments; private static readonly Action _actionMethodExecuted; private static readonly Action _logFilterExecutionPlan; @@ -172,6 +173,11 @@ static MvcCoreLoggerExtensions() 1, "Executing action method {ActionName} - Validation state: {ValidationState}"); + _actionMethodExecutingWithArguments = LoggerMessage.Define( + LogLevel.Debug, + 3, + "Executing action method {ActionName} with arguments ({Arguments})"); + _actionMethodExecuted = LoggerMessage.Define( LogLevel.Information, 2, @@ -809,6 +815,17 @@ public static void ActionMethodExecuting(this ILogger logger, ControllerContext var validationState = context.ModelState.ValidationState; _actionMethodExecuting(logger, actionName, validationState, null); + + if (arguments != null && logger.IsEnabled(LogLevel.Debug)) + { + var convertedArguments = new string[arguments.Length]; + for (var i = 0; i < arguments.Length; i++) + { + convertedArguments[i] = Convert.ToString(arguments[i]); + } + + _actionMethodExecutingWithArguments(logger, actionName, convertedArguments, null); + } } } diff --git a/src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs b/src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs index c74766e535a4..6c38409f7da9 100644 --- a/src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs +++ b/src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs @@ -16,6 +16,7 @@ internal static class PageLoggerExtensions public const string PageFilter = "Page Filter"; private static readonly Action _handlerMethodExecuting; + private static readonly Action _handlerMethodExecutingWithArguments; private static readonly Action _handlerMethodExecuted; private static readonly Action _pageFilterShortCircuit; private static readonly Action _malformedPageDirective; @@ -33,6 +34,12 @@ static PageLoggerExtensions() 101, "Executing handler method {HandlerName} - ModelState is {ValidationState}"); + _handlerMethodExecutingWithArguments = LoggerMessage.Define( + LogLevel.Debug, + 103, + "Executing handler method {HandlerName} with arguments ({Arguments})"); + "Executing handler method {HandlerName} - ModelState is {ValidationState}"); + _handlerMethodExecuted = LoggerMessage.Define( LogLevel.Debug, 102, @@ -77,6 +84,17 @@ public static void ExecutingHandlerMethod(this ILogger logger, PageContext conte var validationState = context.ModelState.ValidationState; _handlerMethodExecuting(logger, handlerName, validationState, null); + + if (arguments != null && logger.IsEnabled(LogLevel.Debug)) + { + var convertedArguments = new string[arguments.Length]; + for (var i = 0; i < arguments.Length; i++) + { + convertedArguments[i] = Convert.ToString(arguments[i]); + } + + _handlerMethodExecutingWithArguments(logger, handlerName, convertedArguments, null); + } } } From 070e85583b47e2cbeea0a862975a6e8a4072ee45 Mon Sep 17 00:00:00 2001 From: Pranav K Date: Thu, 11 Apr 2019 15:34:35 -0700 Subject: [PATCH 3/6] fixup --- src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs | 4 ++-- src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs | 5 ++--- 2 files changed, 4 insertions(+), 5 deletions(-) diff --git a/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs b/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs index fae92b3e639f..ad43b689819b 100644 --- a/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs +++ b/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs @@ -174,7 +174,7 @@ static MvcCoreLoggerExtensions() "Executing action method {ActionName} - Validation state: {ValidationState}"); _actionMethodExecutingWithArguments = LoggerMessage.Define( - LogLevel.Debug, + LogLevel.Trace, 3, "Executing action method {ActionName} with arguments ({Arguments})"); @@ -816,7 +816,7 @@ public static void ActionMethodExecuting(this ILogger logger, ControllerContext var validationState = context.ModelState.ValidationState; _actionMethodExecuting(logger, actionName, validationState, null); - if (arguments != null && logger.IsEnabled(LogLevel.Debug)) + if (arguments != null && logger.IsEnabled(LogLevel.Trace)) { var convertedArguments = new string[arguments.Length]; for (var i = 0; i < arguments.Length; i++) diff --git a/src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs b/src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs index 6c38409f7da9..fcca656b9d48 100644 --- a/src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs +++ b/src/Mvc/Mvc.RazorPages/src/Internal/PageLoggerExtensions.cs @@ -35,10 +35,9 @@ static PageLoggerExtensions() "Executing handler method {HandlerName} - ModelState is {ValidationState}"); _handlerMethodExecutingWithArguments = LoggerMessage.Define( - LogLevel.Debug, + LogLevel.Trace, 103, "Executing handler method {HandlerName} with arguments ({Arguments})"); - "Executing handler method {HandlerName} - ModelState is {ValidationState}"); _handlerMethodExecuted = LoggerMessage.Define( LogLevel.Debug, @@ -85,7 +84,7 @@ public static void ExecutingHandlerMethod(this ILogger logger, PageContext conte var validationState = context.ModelState.ValidationState; _handlerMethodExecuting(logger, handlerName, validationState, null); - if (arguments != null && logger.IsEnabled(LogLevel.Debug)) + if (arguments != null && logger.IsEnabled(LogLevel.Trace)) { var convertedArguments = new string[arguments.Length]; for (var i = 0; i < arguments.Length; i++) From ad391ae63291bac2d61f277c254e3f5b963ee34a Mon Sep 17 00:00:00 2001 From: Pranav K Date: Mon, 15 Apr 2019 09:57:21 -0700 Subject: [PATCH 4/6] Include details about the controller action being executed --- .../src/Internal/MvcCoreLoggerExtensions.cs | 23 ++++++++++++++++++- 1 file changed, 22 insertions(+), 1 deletion(-) diff --git a/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs b/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs index ad43b689819b..7ce747f03fc0 100644 --- a/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs +++ b/src/Mvc/Mvc.Core/src/Internal/MvcCoreLoggerExtensions.cs @@ -32,6 +32,7 @@ internal static class MvcCoreLoggerExtensions private static readonly double TimestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency; private static readonly Action _actionExecuting; + private static readonly Action _controllerActionExecuting; private static readonly Action _actionExecuted; private static readonly Action _challengeResultExecuting; @@ -153,6 +154,11 @@ static MvcCoreLoggerExtensions() 1, "Route matched with {RouteData}. Executing action {ActionName}"); + _controllerActionExecuting = LoggerMessage.Define( + LogLevel.Information, + 3, + "Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName})."); + _actionExecuted = LoggerMessage.Define( LogLevel.Information, 2, @@ -683,7 +689,22 @@ public static void ExecutingAction(this ILogger logger, ActionDescriptor action) } } - _actionExecuting(logger, stringBuilder.ToString(), action.DisplayName, null); + 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); + } } } From a20aa4d5c59302a3f5240a2402ebe3aa89546bd2 Mon Sep 17 00:00:00 2001 From: Pranav K Date: Mon, 15 Apr 2019 10:14:23 -0700 Subject: [PATCH 5/6] Add to patchconfig --- eng/PatchConfig.props | 1 + 1 file changed, 1 insertion(+) diff --git a/eng/PatchConfig.props b/eng/PatchConfig.props index 29e74d4f858b..d57cdabe9ed3 100644 --- a/eng/PatchConfig.props +++ b/eng/PatchConfig.props @@ -28,6 +28,7 @@ Later on, this will be checked using this condition: + Microsoft.AspNetCore.Mvc.Core; From 6777186b3b582ef9f83e6b24e4b1999a0c52a95c Mon Sep 17 00:00:00 2001 From: Pranav K Date: Mon, 15 Apr 2019 11:05:08 -0700 Subject: [PATCH 6/6] Also add RazorPages --- eng/PatchConfig.props | 1 + 1 file changed, 1 insertion(+) diff --git a/eng/PatchConfig.props b/eng/PatchConfig.props index d57cdabe9ed3..9afa0e2572f5 100644 --- a/eng/PatchConfig.props +++ b/eng/PatchConfig.props @@ -29,6 +29,7 @@ Later on, this will be checked using this condition: Microsoft.AspNetCore.Mvc.Core; + Microsoft.AspNetCore.Mvc.RazorPages;