From 687ab258a192198bd3cf6e33cd46ad8a67cb2f45 Mon Sep 17 00:00:00 2001 From: Kiran Challa Date: Tue, 21 Apr 2015 15:45:45 -0700 Subject: [PATCH] Logging for filters --- .../ControllerActionInvoker.cs | 3 + .../ControllerActionInvokerProvider.cs | 7 ++- .../FilterActionInvoker.cs | 59 +++++++++++++++++++ .../ControllerActionInvokerTest.cs | 5 ++ 4 files changed, 73 insertions(+), 1 deletion(-) diff --git a/src/Microsoft.AspNet.Mvc.Core/ControllerActionInvoker.cs b/src/Microsoft.AspNet.Mvc.Core/ControllerActionInvoker.cs index c2555b1c5d..aea970cc16 100644 --- a/src/Microsoft.AspNet.Mvc.Core/ControllerActionInvoker.cs +++ b/src/Microsoft.AspNet.Mvc.Core/ControllerActionInvoker.cs @@ -8,6 +8,7 @@ using System.Threading.Tasks; using Microsoft.AspNet.Mvc.ModelBinding; using Microsoft.AspNet.Mvc.ModelBinding.Validation; using Microsoft.Framework.Internal; +using Microsoft.Framework.Logging; namespace Microsoft.AspNet.Mvc.Core { @@ -31,6 +32,7 @@ namespace Microsoft.AspNet.Mvc.Core [NotNull] IReadOnlyList valueProviderFactories, [NotNull] IScopedInstance actionBindingContextAccessor, [NotNull] ITempDataDictionary tempData, + [NotNull] ILoggerFactory loggerFactory, int maxModelValidationErrors) : base( actionContext, @@ -41,6 +43,7 @@ namespace Microsoft.AspNet.Mvc.Core modelValidatorProviders, valueProviderFactories, actionBindingContextAccessor, + loggerFactory, maxModelValidationErrors) { _descriptor = descriptor; diff --git a/src/Microsoft.AspNet.Mvc.Core/ControllerActionInvokerProvider.cs b/src/Microsoft.AspNet.Mvc.Core/ControllerActionInvokerProvider.cs index d183ab3c2c..7d4002f730 100644 --- a/src/Microsoft.AspNet.Mvc.Core/ControllerActionInvokerProvider.cs +++ b/src/Microsoft.AspNet.Mvc.Core/ControllerActionInvokerProvider.cs @@ -6,6 +6,7 @@ using System.Linq; using Microsoft.AspNet.Mvc.ModelBinding; using Microsoft.AspNet.Mvc.ModelBinding.Validation; using Microsoft.Framework.Internal; +using Microsoft.Framework.Logging; using Microsoft.Framework.OptionsModel; namespace Microsoft.AspNet.Mvc.Core @@ -23,6 +24,7 @@ namespace Microsoft.AspNet.Mvc.Core private readonly IScopedInstance _actionBindingContextAccessor; private readonly ITempDataDictionary _tempData; private readonly int _maxModelValidationErrors; + private readonly ILoggerFactory _loggerFactory; public ControllerActionInvokerProvider( IControllerFactory controllerFactory, @@ -30,7 +32,8 @@ namespace Microsoft.AspNet.Mvc.Core IControllerActionArgumentBinder argumentBinder, IOptions optionsAccessor, IScopedInstance actionBindingContextAccessor, - ITempDataDictionary tempData) + ITempDataDictionary tempData, + ILoggerFactory loggerFactory) { _controllerFactory = controllerFactory; _filterProviders = filterProviders.OrderBy(item => item.Order).ToArray(); @@ -43,6 +46,7 @@ namespace Microsoft.AspNet.Mvc.Core _actionBindingContextAccessor = actionBindingContextAccessor; _tempData = tempData; _maxModelValidationErrors = optionsAccessor.Options.MaxModelValidationErrors; + _loggerFactory = loggerFactory; } public int Order @@ -70,6 +74,7 @@ namespace Microsoft.AspNet.Mvc.Core _valueProviderFactories, _actionBindingContextAccessor, _tempData, + _loggerFactory, _maxModelValidationErrors); } } diff --git a/src/Microsoft.AspNet.Mvc.Core/FilterActionInvoker.cs b/src/Microsoft.AspNet.Mvc.Core/FilterActionInvoker.cs index 4b3882a10d..9a8fd93114 100644 --- a/src/Microsoft.AspNet.Mvc.Core/FilterActionInvoker.cs +++ b/src/Microsoft.AspNet.Mvc.Core/FilterActionInvoker.cs @@ -10,6 +10,7 @@ using System.Threading.Tasks; using Microsoft.AspNet.Mvc.ModelBinding; using Microsoft.AspNet.Mvc.ModelBinding.Validation; using Microsoft.Framework.Internal; +using Microsoft.Framework.Logging; namespace Microsoft.AspNet.Mvc.Core { @@ -22,6 +23,7 @@ namespace Microsoft.AspNet.Mvc.Core private readonly IReadOnlyList _modelValidatorProviders; private readonly IReadOnlyList _valueProviderFactories; private readonly IScopedInstance _actionBindingContextAccessor; + private readonly ILogger _logger; private readonly int _maxModelValidationErrors; private IFilter[] _filters; @@ -40,6 +42,17 @@ namespace Microsoft.AspNet.Mvc.Core private ResultExecutingContext _resultExecutingContext; private ResultExecutedContext _resultExecutedContext; + private const string AuthorizationFailureLogMessage = + "Authorization failed for the request at filter '{AuthorizationFilter}'."; + private const string ResourceFilterShortCircuitLogMessage = + "Request was short circuited at resource filter '{ResourceFilter}'."; + private const string ActionFilterShortCircuitLogMessage = + "Request was short circuited at action filter '{ActionFilter}'."; + private const string ExceptionFilterShortCircuitLogMessage = + "Request was short circuited at exception filter '{ExceptionFilter}'."; + private const string ResultFilterShortCircuitLogMessage = + "Request was short circuited at result filter '{ResultFilter}'."; + public FilterActionInvoker( [NotNull] ActionContext actionContext, [NotNull] IReadOnlyList filterProviders, @@ -49,6 +62,7 @@ namespace Microsoft.AspNet.Mvc.Core [NotNull] IReadOnlyList modelValidatorProviders, [NotNull] IReadOnlyList valueProviderFactories, [NotNull] IScopedInstance actionBindingContextAccessor, + [NotNull] ILoggerFactory loggerFactory, int maxModelValidationErrors) { ActionContext = actionContext; @@ -60,6 +74,7 @@ namespace Microsoft.AspNet.Mvc.Core _modelValidatorProviders = modelValidatorProviders; _valueProviderFactories = valueProviderFactories; _actionBindingContextAccessor = actionBindingContextAccessor; + _logger = loggerFactory.CreateLogger(); _maxModelValidationErrors = maxModelValidationErrors; } @@ -190,6 +205,10 @@ namespace Microsoft.AspNet.Mvc.Core // Only keep going if we don't have a result await InvokeAuthorizationFilterAsync(); } + else + { + _logger.LogWarning(AuthorizationFailureLogMessage, current.FilterAsync.GetType().FullName); + } } else if (current.Filter != null) { @@ -200,6 +219,10 @@ namespace Microsoft.AspNet.Mvc.Core // Only keep going if we don't have a result await InvokeAuthorizationFilterAsync(); } + else + { + _logger.LogWarning(AuthorizationFailureLogMessage, current.Filter.GetType().FullName); + } } else { @@ -254,6 +277,10 @@ namespace Microsoft.AspNet.Mvc.Core // If we get here then the filter didn't call 'next' indicating a short circuit if (_resourceExecutingContext.Result != null) { + _logger.LogVerbose( + ResourceFilterShortCircuitLogMessage, + item.FilterAsync.GetType().FullName); + await _resourceExecutingContext.Result.ExecuteResultAsync(ActionContext); } @@ -271,6 +298,9 @@ namespace Microsoft.AspNet.Mvc.Core if (_resourceExecutingContext.Result != null) { // Short-circuited by setting a result. + + _logger.LogVerbose(ResourceFilterShortCircuitLogMessage, item.Filter.GetType().FullName); + await _resourceExecutingContext.Result.ExecuteResultAsync(ActionContext); _resourceExecutedContext = new ResourceExecutedContext(_resourceExecutingContext, _filters) @@ -369,6 +399,13 @@ namespace Microsoft.AspNet.Mvc.Core // Exception filters only run when there's an exception - unsetting it will short-circuit // other exception filters. await current.FilterAsync.OnExceptionAsync(_exceptionContext); + + if (_exceptionContext.Exception == null) + { + _logger.LogVerbose( + ExceptionFilterShortCircuitLogMessage, + current.FilterAsync.GetType().FullName); + } } } else if (current.Filter != null) @@ -383,6 +420,13 @@ namespace Microsoft.AspNet.Mvc.Core // Exception filters only run when there's an exception - unsetting it will short-circuit // other exception filters. current.Filter.OnException(_exceptionContext); + + if (_exceptionContext.Exception == null) + { + _logger.LogVerbose( + ExceptionFilterShortCircuitLogMessage, + current.Filter.GetType().FullName); + } } } else @@ -476,6 +520,9 @@ namespace Microsoft.AspNet.Mvc.Core if (_actionExecutedContext == null) { // If we get here then the filter didn't call 'next' indicating a short circuit + + _logger.LogVerbose(ActionFilterShortCircuitLogMessage, item.FilterAsync.GetType().FullName); + _actionExecutedContext = new ActionExecutedContext( _actionExecutingContext, _filters, @@ -493,6 +540,9 @@ namespace Microsoft.AspNet.Mvc.Core if (_actionExecutingContext.Result != null) { // Short-circuited by setting a result. + + _logger.LogVerbose(ActionFilterShortCircuitLogMessage, item.Filter.GetType().FullName); + _actionExecutedContext = new ActionExecutedContext( _actionExecutingContext, _filters, @@ -581,6 +631,9 @@ namespace Microsoft.AspNet.Mvc.Core if (_resultExecutedContext == null) { // Short-circuited by not calling next + + _logger.LogVerbose(ResourceFilterShortCircuitLogMessage, item.FilterAsync.GetType().FullName); + _resultExecutedContext = new ResultExecutedContext( _resultExecutingContext, _filters, @@ -593,6 +646,9 @@ namespace Microsoft.AspNet.Mvc.Core else if (_resultExecutingContext.Cancel == true) { // Short-circuited by setting Cancel == true + + _logger.LogVerbose(ResourceFilterShortCircuitLogMessage, item.FilterAsync.GetType().FullName); + _resultExecutedContext = new ResultExecutedContext( _resultExecutingContext, _filters, @@ -610,6 +666,9 @@ namespace Microsoft.AspNet.Mvc.Core if (_resultExecutingContext.Cancel == true) { // Short-circuited by setting Cancel == true + + _logger.LogVerbose(ResourceFilterShortCircuitLogMessage, item.Filter.GetType().FullName); + _resultExecutedContext = new ResultExecutedContext( _resultExecutingContext, _filters, diff --git a/test/Microsoft.AspNet.Mvc.Core.Test/ControllerActionInvokerTest.cs b/test/Microsoft.AspNet.Mvc.Core.Test/ControllerActionInvokerTest.cs index 8ed3773e0b..2038b7bac5 100644 --- a/test/Microsoft.AspNet.Mvc.Core.Test/ControllerActionInvokerTest.cs +++ b/test/Microsoft.AspNet.Mvc.Core.Test/ControllerActionInvokerTest.cs @@ -2018,6 +2018,7 @@ namespace Microsoft.AspNet.Mvc .Returns(tempData); httpContext.Setup(o => o.RequestServices.GetService(typeof(ILogger))) .Returns(new Mock>().Object); + httpResponse.Body = new MemoryStream(); var options = new MvcOptions(); @@ -2065,6 +2066,7 @@ namespace Microsoft.AspNet.Mvc new IValueProviderFactory[0], new MockScopedInstance(), tempData, + new NullLoggerFactory(), maxAllowedErrorsInModelState); return invoker; @@ -2127,6 +2129,7 @@ namespace Microsoft.AspNet.Mvc new IValueProviderFactory[0], new MockScopedInstance(), Mock.Of(), + new NullLoggerFactory(), 200); // Act @@ -2227,6 +2230,7 @@ namespace Microsoft.AspNet.Mvc IReadOnlyList valueProviderFactories, IScopedInstance actionBindingContext, ITempDataDictionary tempData, + ILoggerFactory loggerFactory, int maxAllowedErrorsInModelState) : base( actionContext, @@ -2241,6 +2245,7 @@ namespace Microsoft.AspNet.Mvc valueProviderFactories, actionBindingContext, tempData, + loggerFactory, maxAllowedErrorsInModelState) { ControllerFactory = controllerFactory;