Test ControllerActionInvoker logs and fix log for empty RouteValues

src/Mvc/Mvc.Core/src/MvcCoreLoggerExtensions.cs

@@ -724,13 +724,14 @@ namespace Microsoft.AspNetCore.Mvc
                 {
                     if (i == routeValues.Length - 1)
                     {
-                        stringBuilder.Append($"{routeKeys[i]} = \"{routeValues[i]}\"}}");
+                        stringBuilder.Append($"{routeKeys[i]} = \"{routeValues[i]}\"");
                     }
                     else
                     {
                         stringBuilder.Append($"{routeKeys[i]} = \"{routeValues[i]}\", ");
                     }
                 }
+                stringBuilder.Append("}");
 
                 if (action.RouteValues.TryGetValue("page", out var page) && page != null)
                 {

src/Mvc/Mvc.Core/test/Infrastructure/ControllerActionInvokerTest.cs

@@ -1457,7 +1457,7 @@ namespace Microsoft.AspNetCore.Mvc.Infrastructure
         #region Logs
 
         [Fact]
-        public async Task InvokeAsync_LogsControllerFactory()
+        public async Task InvokeAsync_Logs()
         {
             // Arrange
             var testSink = new TestSink();
@@ -1485,8 +1485,22 @@ namespace Microsoft.AspNetCore.Mvc.Infrastructure
             // Assert
             var messages = testSink.Writes.Select(write => write.State.ToString()).ToList();
             var controllerName = $"{typeof(ControllerActionInvokerTest).FullName}+{nameof(TestController)} ({typeof(ControllerActionInvokerTest).Assembly.GetName().Name})";
+            var actionName = $"{typeof(ControllerActionInvokerTest).FullName}+{nameof(TestController)}.{nameof(TestController.ActionMethod)} ({typeof(ControllerActionInvokerTest).Assembly.GetName().Name})";
+            var actionResultName = $"{typeof(CommonResourceInvokerTest).FullName}+{nameof(TestResult)}";
+            Assert.Equal(13, messages.Count);
+            Assert.Contains($"Route matched with {{}}. Executing controller action with signature {typeof(IActionResult).FullName} {nameof(TestController.ActionMethod)}() on controller {controllerName}.", messages);
+            Assert.Contains("Execution plan of authorization filters (in the following order): None", messages);
+            Assert.Contains("Execution plan of resource filters (in the following order): None", messages);
+            Assert.Contains("Execution plan of action filters (in the following order): None", messages);
+            Assert.Contains("Execution plan of exception filters (in the following order): None", messages);
+            Assert.Contains("Execution plan of result filters (in the following order): None", messages);
             Assert.Contains($"Executing controller factory for controller {controllerName}", messages);
             Assert.Contains($"Executed controller factory for controller {controllerName}", messages);
+            Assert.Contains($"Executing action method {actionName} - Validation state: Valid", messages);
+            Assert.Contains(messages, m => m.Contains($"Executed action method {actionName}, returned result {actionResultName} in "));
+            Assert.Contains($"Before executing action result {actionResultName}.", messages);
+            Assert.Contains($"After executing action result {actionResultName}.", messages);
+            Assert.Contains(messages, m => m.Contains($"Executed action {actionName} in "));
         }
 
         #endregion

src/Mvc/Mvc.Core/test/MvcCoreLoggerExtensionsTest.cs

@@ -2,6 +2,7 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.Generic;
 using System.Reflection;
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Mvc.Filters;
@@ -14,6 +15,47 @@ namespace Microsoft.AspNetCore.Mvc
 {
     public class MvcCoreLoggerExtensionsTest
     {
+        public static object[][] RouteValuesTestData { get; } = new object[][]
+        {
+            new object[]{ "{}" },
+            new object[]{ "{foo = \"bar\"}", new KeyValuePair<string, string>("foo", "bar") },
+            new object[]{ "{foo = \"bar\", other = \"value\"}",
+                new KeyValuePair<string, string>("foo", "bar"),
+                new KeyValuePair<string, string>("other", "value") },
+        };
+
+        [Theory]
+        [MemberData(nameof(RouteValuesTestData))]
+        public void ExecutingAction_WithGivenRouteValues_LogsActionAndRouteData(string expectedRouteValuesLogMessage, params KeyValuePair<string, string>[] routeValues)
+        {
+            // Arrange
+            var testSink = new TestSink();
+            var loggerFactory = new TestLoggerFactory(testSink, enabled: true);
+            var logger = loggerFactory.CreateLogger("test");
+
+            var action = new Controllers.ControllerActionDescriptor
+            {
+                // Using a generic type to verify the use of a clean name
+                ControllerTypeInfo = typeof(ValueTuple<int, string>).GetTypeInfo(),
+                MethodInfo = typeof(object).GetMethod(nameof(ToString)),
+            };
+
+            foreach (var routeValue in routeValues)
+            {
+                action.RouteValues.Add(routeValue);
+            }
+
+            // Act
+            logger.ExecutingAction(action);
+
+            // Assert
+            var write = Assert.Single(testSink.Writes);
+            Assert.Equal(
+                $"Route matched with {expectedRouteValuesLogMessage}. " +
+                "Executing controller action with signature System.String ToString() on controller System.ValueTuple<int, string> (System.Private.CoreLib).",
+                write.State.ToString());
+        }
+
         [Fact]
         public void LogsFilters_OnlyWhenLogger_IsEnabled()
         {