Logging for filters

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<IValueProviderFactory> valueProviderFactories,
             [NotNull] IScopedInstance<ActionBindingContext> 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;

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<ActionBindingContext> _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<MvcOptions> optionsAccessor,
             IScopedInstance<ActionBindingContext> 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);
             }
         }

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<IModelValidatorProvider> _modelValidatorProviders;
         private readonly IReadOnlyList<IValueProviderFactory> _valueProviderFactories;
         private readonly IScopedInstance<ActionBindingContext> _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<IFilterProvider> filterProviders,
@@ -49,6 +62,7 @@ namespace Microsoft.AspNet.Mvc.Core
             [NotNull] IReadOnlyList<IModelValidatorProvider> modelValidatorProviders,
             [NotNull] IReadOnlyList<IValueProviderFactory> valueProviderFactories,
             [NotNull] IScopedInstance<ActionBindingContext> 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<FilterActionInvoker>();
             _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,

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<ObjectResult>)))
                        .Returns(new Mock<ILogger<ObjectResult>>().Object);
+
             httpResponse.Body = new MemoryStream();
 
             var options = new MvcOptions();
@@ -2065,6 +2066,7 @@ namespace Microsoft.AspNet.Mvc
                 new IValueProviderFactory[0],
                 new MockScopedInstance<ActionBindingContext>(),
                 tempData,
+                new NullLoggerFactory(),
                 maxAllowedErrorsInModelState);
 
             return invoker;
@@ -2127,6 +2129,7 @@ namespace Microsoft.AspNet.Mvc
                 new IValueProviderFactory[0],
                 new MockScopedInstance<ActionBindingContext>(),
                 Mock.Of<ITempDataDictionary>(),
+                new NullLoggerFactory(),
                 200);
 
             // Act
@@ -2227,6 +2230,7 @@ namespace Microsoft.AspNet.Mvc
                 IReadOnlyList<IValueProviderFactory> valueProviderFactories,
                 IScopedInstance<ActionBindingContext> actionBindingContext,
                 ITempDataDictionary tempData,
+                ILoggerFactory loggerFactory,
                 int maxAllowedErrorsInModelState)
                 : base(
                       actionContext,
@@ -2241,6 +2245,7 @@ namespace Microsoft.AspNet.Mvc
                       valueProviderFactories,
                       actionBindingContext,
                       tempData,
+                      loggerFactory,
                       maxAllowedErrorsInModelState)
             {
                 ControllerFactory = controllerFactory;