[Fixes #4291] Simplified MvcRouteHandler code

src/Microsoft.AspNetCore.Mvc.Core/Internal/ControllerActionInvoker.cs

@@ -112,6 +112,19 @@ namespace Microsoft.AspNetCore.Mvc.Internal
 
         public virtual async Task InvokeAsync()
         {
+            try
+            {
+                _diagnosticSource.BeforeAction(
+                    _controllerContext.ActionDescriptor,
+                    _controllerContext.HttpContext,
+                    _controllerContext.RouteData);
+
+                using (_logger.ActionScope(_controllerContext.ActionDescriptor))
+                {
+                    _logger.ExecutingAction(_controllerContext.ActionDescriptor);
+
+                    var startTimestamp = _logger.IsEnabled(LogLevel.Information) ? Stopwatch.GetTimestamp() : 0;
+
                     await InvokeAllAuthorizationFiltersAsync();
 
                     // If Authorization Filters return a result, it's a short circuit because
@@ -152,6 +165,17 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                             _resourceExecutedContext.ExceptionDispatchInfo.Throw();
                         }
                     }
+
+                    _logger.ExecutedAction(_controllerContext.ActionDescriptor, startTimestamp);
+                }
+            }
+            finally
+            {
+                _diagnosticSource.AfterAction(
+                    _controllerContext.ActionDescriptor,
+                    _controllerContext.HttpContext,
+                    _controllerContext.RouteData);
+            }
         }
 
         private Task InvokeAllAuthorizationFiltersAsync()

src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs

@@ -87,12 +87,12 @@ namespace Microsoft.AspNetCore.Mvc.Internal
             _actionMethodExecuting = LoggerMessage.Define<string, string[], ModelValidationState>(
                 LogLevel.Information,
                 1,
-                "Executing action method {ActionName} with arguments ({Arguments}) - ModelState is {ValidationState}'");
+                "Executing action method {ActionName} with arguments ({Arguments}) - ModelState is {ValidationState}");
 
             _actionMethodExecuted = LoggerMessage.Define<string, string>(
                 LogLevel.Debug,
                 2,
-                "Executed action method {ActionName}, returned result {ActionResult}.'");
+                "Executed action method {ActionName}, returned result {ActionResult}.");
 
             _ambiguousActions = LoggerMessage.Define<string>(
                 LogLevel.Error,

src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcRouteHandler.cs

@@ -4,8 +4,6 @@
 using System;
 using System.Diagnostics;
 using System.Threading.Tasks;
-using Microsoft.AspNetCore.Http;
-using Microsoft.AspNetCore.Mvc.Abstractions;
 using Microsoft.AspNetCore.Mvc.Core;
 using Microsoft.AspNetCore.Mvc.Infrastructure;
 using Microsoft.AspNetCore.Routing;
@@ -87,24 +85,11 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                 context.RouteData.Values.Remove(TreeRouter.RouteGroupKey);
             }
 
-            context.Handler = (c) => InvokeActionAsync(c, actionDescriptor);
+            context.Handler = async (c) =>
-            return TaskCache.CompletedTask;
-        }
-
-        private async Task InvokeActionAsync(HttpContext httpContext, ActionDescriptor actionDescriptor)
             {
-            var routeData = httpContext.GetRouteData();
+                var routeData = c.GetRouteData();
-            try
-            {
-                _diagnosticSource.BeforeAction(actionDescriptor, httpContext, routeData);
 
-                using (_logger.ActionScope(actionDescriptor))
+                var actionContext = new ActionContext(context.HttpContext, routeData, actionDescriptor);
-                {
-                    _logger.ExecutingAction(actionDescriptor);
-
-                    var startTimestamp = _logger.IsEnabled(LogLevel.Information) ? Stopwatch.GetTimestamp() : 0;
-
-                    var actionContext = new ActionContext(httpContext, routeData, actionDescriptor);
                 if (_actionContextAccessor != null)
                 {
                     _actionContextAccessor.ActionContext = actionContext;
@@ -119,14 +104,9 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                 }
 
                 await invoker.InvokeAsync();
+            };
 
-                    _logger.ExecutedAction(actionDescriptor, startTimestamp);
+            return TaskCache.CompletedTask;
-                }
-            }
-            finally
-            {
-                _diagnosticSource.AfterAction(actionDescriptor, httpContext, routeData);
-            }
         }
     }
 }

test/Microsoft.AspNetCore.Mvc.Core.Test/Infrastructure/MvcRouteHandlerTests.cs

@@ -19,37 +19,6 @@ namespace Microsoft.AspNetCore.Mvc.Infrastructure
 {
     public class MvcRouteHandlerTests
     {
-        [Fact]
-        public async Task RouteHandler_Success_LogsCorrectValues()
-        {
-            // Arrange
-            var sink = new TestSink();
-            var loggerFactory = new TestLoggerFactory(sink, enabled: true);
-
-            var displayName = "A.B.C";
-            var actionDescriptor = new Mock<ActionDescriptor>();
-            actionDescriptor
-                .SetupGet(ad => ad.DisplayName)
-                .Returns(displayName);
-
-            var context = CreateRouteContext();
-
-            var handler = CreateMvcRouteHandler(actionDescriptor: actionDescriptor.Object, loggerFactory: loggerFactory);
-            await handler.RouteAsync(context);
-
-            // Act
-            await context.Handler(context.HttpContext);
-
-            // Assert
-            Assert.Single(sink.Scopes);
-            Assert.Equal(displayName, sink.Scopes[0].Scope?.ToString());
-
-            Assert.Equal(2, sink.Writes.Count);
-            Assert.Equal($"Executing action {displayName}", sink.Writes[0].State?.ToString());
-            // This message has the execution time embedded, which we don't want to verify.
-            Assert.StartsWith($"Executed action {displayName} ", sink.Writes[1].State?.ToString());
-        }
-
         [Fact]
         public async Task RouteAsync_FailOnNoAction_LogsCorrectValues()
         {
@@ -112,51 +81,6 @@ namespace Microsoft.AspNetCore.Mvc.Infrastructure
             Assert.False(context.RouteData.Values.ContainsKey(TreeRouter.RouteGroupKey));
         }
 
-        [Fact]
-        public async Task RouteHandler_WritesDiagnostic_ActionSelected()
-        {
-            // Arrange
-            var listener = new TestDiagnosticListener();
-
-            var context = CreateRouteContext();
-            context.RouteData.Values.Add("tag", "value");
-
-            var handler = CreateMvcRouteHandler(diagnosticListener: listener);
-            await handler.RouteAsync(context);
-
-            // Act
-            await context.Handler(context.HttpContext);
-
-            // Assert
-            Assert.NotNull(listener.BeforeAction?.ActionDescriptor);
-            Assert.NotNull(listener.BeforeAction?.HttpContext);
-
-            var routeValues = listener.BeforeAction?.RouteData?.Values;
-            Assert.NotNull(routeValues);
-
-            Assert.Equal(1, routeValues.Count);
-            Assert.Contains(routeValues, kvp => kvp.Key == "tag" && string.Equals(kvp.Value, "value"));
-        }
-
-        [Fact]
-        public async Task RouteHandler_WritesDiagnostic_ActionInvoked()
-        {
-            // Arrange
-            var listener = new TestDiagnosticListener();
-
-            var context = CreateRouteContext();
-
-            var handler = CreateMvcRouteHandler(diagnosticListener: listener);
-            await handler.RouteAsync(context);
-
-            // Act
-            await context.Handler(context.HttpContext);
-
-            // Assert
-            Assert.NotNull(listener.AfterAction?.ActionDescriptor);
-            Assert.NotNull(listener.AfterAction?.HttpContext);
-        }
-
         private MvcRouteHandler CreateMvcRouteHandler(
             ActionDescriptor actionDescriptor = null,
             IActionSelector actionSelector = null,

test/Microsoft.AspNetCore.Mvc.Core.Test/Internal/ControllerActionInvokerTest.cs

@@ -2480,6 +2480,123 @@ namespace Microsoft.AspNetCore.Mvc.Internal
             Assert.Equal(5, context.Object.Items["Result"]);
         }
 
+        [Fact]
+        public async Task Invoke_Success_LogsCorrectValues()
+        {
+            // Arrange
+            var sink = new TestSink();
+            var loggerFactory = new TestLoggerFactory(sink, enabled: true);
+            var logger = loggerFactory.CreateLogger<ControllerActionInvoker>();
+
+            var displayName = "A.B.C";
+            var mockActionDescriptor = new Mock<ControllerActionDescriptor>();
+            mockActionDescriptor
+                .SetupGet(ad => ad.DisplayName)
+                .Returns(displayName);
+            var actionDescriptor = mockActionDescriptor.Object;
+            actionDescriptor.MethodInfo = typeof(ControllerActionInvokerTest).GetMethod(
+                    nameof(ControllerActionInvokerTest.ActionMethod));
+            actionDescriptor.ControllerTypeInfo = typeof(ControllerActionInvokerTest).GetTypeInfo();
+            actionDescriptor.FilterDescriptors = new List<FilterDescriptor>();
+            actionDescriptor.Parameters = new List<ParameterDescriptor>();
+
+            var filter = Mock.Of<IFilterMetadata>();
+            var invoker = CreateInvoker(
+                new[] { filter },
+                actionDescriptor,
+                controllerArgumentBinder: null,
+                controller: null,
+                logger: logger);
+
+            // Act
+            await invoker.InvokeAsync();
+
+            // Assert
+            Assert.Single(sink.Scopes);
+            Assert.Equal(displayName, sink.Scopes[0].Scope?.ToString());
+
+            Assert.Equal(4, sink.Writes.Count);
+            Assert.Equal($"Executing action {displayName}", sink.Writes[0].State?.ToString());
+            Assert.Equal($"Executing action method {displayName} with arguments () - ModelState is Valid", sink.Writes[1].State?.ToString());
+            Assert.Equal($"Executed action method {displayName}, returned result Microsoft.AspNetCore.Mvc.ContentResult.", sink.Writes[2].State?.ToString());
+            // This message has the execution time embedded, which we don't want to verify.
+            Assert.StartsWith($"Executed action {displayName} ", sink.Writes[3].State?.ToString());
+        }
+
+        [Fact]
+        public async Task Invoke_WritesDiagnostic_ActionSelected()
+        {
+            // Arrange
+            var actionDescriptor = new ControllerActionDescriptor()
+            {
+                FilterDescriptors = new List<FilterDescriptor>(),
+                Parameters = new List<ParameterDescriptor>(),
+            };
+
+            actionDescriptor.MethodInfo = typeof(ControllerActionInvokerTest).GetMethod(
+                    nameof(ControllerActionInvokerTest.ActionMethod));
+            actionDescriptor.ControllerTypeInfo = typeof(ControllerActionInvokerTest).GetTypeInfo();
+
+            var listener = new TestDiagnosticListener();
+
+            var routeData = new RouteData();
+            routeData.Values.Add("tag", "value");
+
+            var filter = Mock.Of<IFilterMetadata>();
+            var invoker = CreateInvoker(
+                new[] { filter },
+                actionDescriptor,
+                controllerArgumentBinder: null,
+                controller: null,
+                diagnosticListener: listener,
+                routeData: routeData);
+
+            // Act
+            await invoker.InvokeAsync();
+
+            // Assert
+            Assert.NotNull(listener.BeforeAction?.ActionDescriptor);
+            Assert.NotNull(listener.BeforeAction?.HttpContext);
+
+            var routeValues = listener.BeforeAction?.RouteData?.Values;
+            Assert.NotNull(routeValues);
+
+            Assert.Equal(1, routeValues.Count);
+            Assert.Contains(routeValues, kvp => kvp.Key == "tag" && string.Equals(kvp.Value, "value"));
+        }
+
+        [Fact]
+        public async Task Invoke_WritesDiagnostic_ActionInvoked()
+        {
+            // Arrange
+            var actionDescriptor = new ControllerActionDescriptor()
+            {
+                FilterDescriptors = new List<FilterDescriptor>(),
+                Parameters = new List<ParameterDescriptor>(),
+            };
+
+            actionDescriptor.MethodInfo = typeof(ControllerActionInvokerTest).GetMethod(
+                    nameof(ControllerActionInvokerTest.ActionMethod));
+            actionDescriptor.ControllerTypeInfo = typeof(ControllerActionInvokerTest).GetTypeInfo();
+
+            var listener = new TestDiagnosticListener();
+
+            var filter = Mock.Of<IFilterMetadata>();
+            var invoker = CreateInvoker(
+                new[] { filter },
+                actionDescriptor,
+                controllerArgumentBinder: null,
+                controller: null,
+                diagnosticListener: listener);
+
+            // Act
+            await invoker.InvokeAsync();
+
+            // Assert
+            Assert.NotNull(listener.AfterAction?.ActionDescriptor);
+            Assert.NotNull(listener.AfterAction?.HttpContext);
+        }
+
         private TestControllerActionInvoker CreateInvoker(
             IFilterMetadata filter,
             bool actionThrows = false,
@@ -2543,7 +2660,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal
             IControllerArgumentBinder controllerArgumentBinder,
             object controller,
             int maxAllowedErrorsInModelState = 200,
-            List<IValueProviderFactory> valueProviderFactories = null)
+            List<IValueProviderFactory> valueProviderFactories = null,
+            RouteData routeData = null,
+            ILogger logger = null,
+            object diagnosticListener = null)
         {
             var httpContext = new Mock<HttpContext>(MockBehavior.Loose);
 
@@ -2593,9 +2713,14 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                     new TestHttpResponseStreamWriterFactory(),
                     NullLoggerFactory.Instance));
 
+            if (routeData == null)
+            {
+                routeData = new RouteData();
+            }
+
             var actionContext = new ActionContext(
                 httpContext: httpContext.Object,
-                routeData: new RouteData(),
+                routeData: routeData,
                 actionDescriptor: actionDescriptor);
 
             var filterProvider = new Mock<IFilterProvider>(MockBehavior.Strict);
@@ -2643,12 +2768,23 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                 valueProviderFactories = new List<IValueProviderFactory>();
             }
 
+            if (logger == null)
+            {
+                logger = new NullLoggerFactory().CreateLogger<ControllerActionInvoker>();
+            }
+
+            var diagnosticSource = new DiagnosticListener("Microsoft.AspNetCore");
+            if (diagnosticListener != null)
+            {
+                diagnosticSource.SubscribeWithAdapter(diagnosticListener);
+            }
+
             var invoker = new TestControllerActionInvoker(
                 new[] { filterProvider.Object },
                 new MockControllerFactory(controller ?? this),
                 argumentBinder,
-                new NullLoggerFactory().CreateLogger<ControllerActionInvoker>(),
+                logger,
-                new DiagnosticListener("Microsoft.AspNetCore"),
+                diagnosticSource,
                 actionContext,
                 valueProviderFactories.AsReadOnly(),
                 maxAllowedErrorsInModelState);