From 24b930fa7c9bd5e4219e861fec7282bb53182a2d Mon Sep 17 00:00:00 2001 From: Kiran Challa Date: Mon, 30 Mar 2015 14:14:04 -0700 Subject: [PATCH] Clean up logging. - Removing scopes as we want to limit the number of scopes being created. - Added new log statements using the new log format string. --- .../ActionDescriptor.cs | 6 + .../DefaultActionSelector.cs | 118 +++++++----------- .../Logging/AttributeRouteRouteAsyncValues.cs | 61 --------- .../DefaultActionSelectorSelectAsyncValues.cs | 81 ------------ .../MvcRouteHandlerRouteAsyncValues.cs | 66 ---------- .../MvcRouteHandler.cs | 75 +++++------ .../Routing/InnerAttributeRoute.cs | 48 +++---- .../ActionDescriptorValuesTest.cs | 23 ---- ...aultActionSelectorSelectAsyncValuesTest.cs | 30 ----- .../DefaultActionSelectorTests.cs | 111 +--------------- .../MvcRouteHandlerTests.cs | 88 ++++--------- .../Routing/InnerAttributeRouteTest.cs | 64 +--------- .../Logging/LoggingActionSelectionTest.cs | 102 --------------- 13 files changed, 131 insertions(+), 742 deletions(-) delete mode 100644 src/Microsoft.AspNet.Mvc.Core/Logging/AttributeRouteRouteAsyncValues.cs delete mode 100644 src/Microsoft.AspNet.Mvc.Core/Logging/DefaultActionSelectorSelectAsyncValues.cs delete mode 100644 src/Microsoft.AspNet.Mvc.Core/Logging/MvcRouteHandlerRouteAsyncValues.cs delete mode 100644 test/Microsoft.AspNet.Mvc.Core.Test/ActionDescriptorValuesTest.cs delete mode 100644 test/Microsoft.AspNet.Mvc.Core.Test/DefaultActionSelectorSelectAsyncValuesTest.cs delete mode 100644 test/Microsoft.AspNet.Mvc.FunctionalTests/Logging/LoggingActionSelectionTest.cs diff --git a/src/Microsoft.AspNet.Mvc.Core/ActionDescriptor.cs b/src/Microsoft.AspNet.Mvc.Core/ActionDescriptor.cs index 1e9a3ae008..25b3b2d6fe 100644 --- a/src/Microsoft.AspNet.Mvc.Core/ActionDescriptor.cs +++ b/src/Microsoft.AspNet.Mvc.Core/ActionDescriptor.cs @@ -13,8 +13,14 @@ namespace Microsoft.AspNet.Mvc { Properties = new Dictionary(); RouteValueDefaults = new Dictionary(StringComparer.OrdinalIgnoreCase); + Id = Guid.NewGuid().ToString(); } + /// + /// Gets an id which uniquely identifies the action. + /// + public string Id { get; } + public virtual string Name { get; set; } public IList RouteConstraints { get; set; } diff --git a/src/Microsoft.AspNet.Mvc.Core/DefaultActionSelector.cs b/src/Microsoft.AspNet.Mvc.Core/DefaultActionSelector.cs index cac43e706e..8c733a2aef 100644 --- a/src/Microsoft.AspNet.Mvc.Core/DefaultActionSelector.cs +++ b/src/Microsoft.AspNet.Mvc.Core/DefaultActionSelector.cs @@ -7,7 +7,6 @@ using System.Linq; using System.Threading.Tasks; using Microsoft.AspNet.Http; using Microsoft.AspNet.Mvc.ActionConstraints; -using Microsoft.AspNet.Mvc.Logging; using Microsoft.AspNet.Mvc.Routing; using Microsoft.AspNet.Routing; using Microsoft.Framework.Internal; @@ -36,86 +35,55 @@ namespace Microsoft.AspNet.Mvc.Core public Task SelectAsync([NotNull] RouteContext context) { - using (_logger.BeginScope("DefaultActionSelector.SelectAsync")) + var tree = _decisionTreeProvider.DecisionTree; + var matchingRouteConstraints = tree.Select(context.RouteData.Values); + + var candidates = new List(); + foreach (var action in matchingRouteConstraints) { - var tree = _decisionTreeProvider.DecisionTree; - var matchingRouteConstraints = tree.Select(context.RouteData.Values); + var constraints = GetConstraints(context.HttpContext, action); + candidates.Add(new ActionSelectorCandidate(action, constraints)); + } - var candidates = new List(); - foreach (var action in matchingRouteConstraints) + var matchingActionConstraints = + EvaluateActionConstraints(context, candidates, startingOrder: null); + + List matchingActions = null; + if (matchingActionConstraints != null) + { + matchingActions = new List(matchingActionConstraints.Count); + foreach (var candidate in matchingActionConstraints) { - var constraints = GetConstraints(context.HttpContext, action); - candidates.Add(new ActionSelectorCandidate(action, constraints)); + matchingActions.Add(candidate.Action); } + } - var matchingActionConstraints = - EvaluateActionConstraints(context, candidates, startingOrder: null); + var finalMatches = SelectBestActions(matchingActions); - List matchingActions = null; - if (matchingActionConstraints != null) - { - matchingActions = new List(matchingActionConstraints.Count); - foreach (var candidate in matchingActionConstraints) - { - matchingActions.Add(candidate.Action); - } - } + if (finalMatches == null || finalMatches.Count == 0) + { + return Task.FromResult(null); + } + else if (finalMatches.Count == 1) + { + var selectedAction = finalMatches[0]; - var finalMatches = SelectBestActions(matchingActions); + return Task.FromResult(selectedAction); + } + else + { + var actionNames = string.Join( + Environment.NewLine, + finalMatches.Select(a => a.DisplayName)); - if (finalMatches == null || finalMatches.Count == 0) - { - if (_logger.IsEnabled(LogLevel.Verbose)) - { - _logger.WriteValues(new DefaultActionSelectorSelectAsyncValues() - { - ActionsMatchingRouteConstraints = matchingRouteConstraints, - ActionsMatchingActionConstraints = matchingActions, - FinalMatches = finalMatches, - }); - } + _logger.LogError("Request matched multiple actions resulting in ambiguity. " + + "Matching actions: {AmbiguousActions}", actionNames); - return Task.FromResult(null); - } - else if (finalMatches.Count == 1) - { - var selectedAction = finalMatches[0]; + var message = Resources.FormatDefaultActionSelector_AmbiguousActions( + Environment.NewLine, + actionNames); - if (_logger.IsEnabled(LogLevel.Verbose)) - { - _logger.WriteValues(new DefaultActionSelectorSelectAsyncValues() - { - ActionsMatchingRouteConstraints = matchingRouteConstraints, - ActionsMatchingActionConstraints = matchingActions, - FinalMatches = finalMatches, - SelectedAction = selectedAction - }); - } - - return Task.FromResult(selectedAction); - } - else - { - if (_logger.IsEnabled(LogLevel.Verbose)) - { - _logger.WriteValues(new DefaultActionSelectorSelectAsyncValues() - { - ActionsMatchingRouteConstraints = matchingRouteConstraints, - ActionsMatchingActionConstraints = matchingActions, - FinalMatches = finalMatches, - }); - } - - var actionNames = string.Join( - Environment.NewLine, - finalMatches.Select(a => a.DisplayName)); - - var message = Resources.FormatDefaultActionSelector_AmbiguousActions( - Environment.NewLine, - actionNames); - - throw new AmbiguousActionException(message); - } + throw new AmbiguousActionException(message); } } @@ -184,6 +152,14 @@ namespace Microsoft.AspNet.Mvc.Core if (!constraint.Accept(constraintContext)) { isMatch = false; + + _logger.LogVerbose( + "Action '{ActionDisplayName}' with id '{ActionId}' did not match the " + + "constraint '{ActionConstraint}'", + candidate.Action.DisplayName, + candidate.Action.Id, + constraint); + break; } } diff --git a/src/Microsoft.AspNet.Mvc.Core/Logging/AttributeRouteRouteAsyncValues.cs b/src/Microsoft.AspNet.Mvc.Core/Logging/AttributeRouteRouteAsyncValues.cs deleted file mode 100644 index 3952f04e00..0000000000 --- a/src/Microsoft.AspNet.Mvc.Core/Logging/AttributeRouteRouteAsyncValues.cs +++ /dev/null @@ -1,61 +0,0 @@ -// Copyright (c) Microsoft Open Technologies, Inc. All rights reserved. -// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. - -using System.Collections.Generic; -using System.Text; -using Microsoft.AspNet.Routing.Template; - -namespace Microsoft.AspNet.Mvc.Logging -{ - /// - /// Represents the state of . - /// - public class AttributeRouteRouteAsyncValues - { - /// - /// The name of the state. - /// - public string Name - { - get - { - return "AttributeRoute.RouteAsync"; - } - } - - /// - /// The matching routes. - /// - public IList MatchingRoutes { get; set; } - - /// - /// True if the request is handled. - /// - public bool Handled { get; set; } - - /// - /// A summary of the data for display. - /// - public string Summary - { - get - { - var builder = new StringBuilder(); - builder.AppendLine(Name); - builder.Append("\tMatching routes: "); - StringBuilderHelpers.Append(builder, MatchingRoutes); - builder.AppendLine(); - builder.Append("\tHandled? "); - builder.Append(Handled); - return builder.ToString(); - } - } - - /// - public override string ToString() - { - return Summary; - } - } -} \ No newline at end of file diff --git a/src/Microsoft.AspNet.Mvc.Core/Logging/DefaultActionSelectorSelectAsyncValues.cs b/src/Microsoft.AspNet.Mvc.Core/Logging/DefaultActionSelectorSelectAsyncValues.cs deleted file mode 100644 index 2341a4c0c5..0000000000 --- a/src/Microsoft.AspNet.Mvc.Core/Logging/DefaultActionSelectorSelectAsyncValues.cs +++ /dev/null @@ -1,81 +0,0 @@ -// Copyright (c) Microsoft Open Technologies, Inc. All rights reserved. -// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. - -using System.Collections.Generic; -using System.Text; - -namespace Microsoft.AspNet.Mvc.Logging -{ - /// - /// Represents the state of . - /// - public class DefaultActionSelectorSelectAsyncValues - { - /// - /// The name of the state. - /// - public string Name - { - get - { - return "DefaultActionSelector.SelectAsync"; - } - } - - /// - /// The list of actions that matched all their route constraints, if any. - /// - public IReadOnlyList ActionsMatchingRouteConstraints { get; set; } - - /// - /// The list of actions that matched all their route constraints, and action constraints, if any. - /// - public IReadOnlyList ActionsMatchingActionConstraints { get; set; } - - /// - /// The list of actions that are the best matches. These match all constraints and any additional criteria - /// for disambiguation. - /// - public IReadOnlyList FinalMatches { get; set; } - - /// - /// The selected action. Will be null if no matches are found or more than one match is found. - /// - public ActionDescriptor SelectedAction { get; set; } - - /// - /// A summary of the data for display. - /// - public string Summary - { - get - { - var builder = new StringBuilder(); - builder.AppendLine(Name); - builder.Append("\tActions matching route constraints: "); - StringBuilderHelpers.Append(builder, ActionsMatchingRouteConstraints, Formatter); - builder.AppendLine(); - builder.Append("\tActions matching action constraints: "); - StringBuilderHelpers.Append(builder, ActionsMatchingActionConstraints, Formatter); - builder.AppendLine(); - builder.Append("\tFinal Matches: "); - StringBuilderHelpers.Append(builder, FinalMatches, Formatter); - builder.AppendLine(); - builder.Append("\tSelected action: "); - builder.Append(Formatter(SelectedAction)); - return builder.ToString(); - } - } - - /// - public override string ToString() - { - return Summary; - } - - private string Formatter(ActionDescriptor descriptor) - { - return descriptor != null ? descriptor.DisplayName : "No action selected"; - } - } -} \ No newline at end of file diff --git a/src/Microsoft.AspNet.Mvc.Core/Logging/MvcRouteHandlerRouteAsyncValues.cs b/src/Microsoft.AspNet.Mvc.Core/Logging/MvcRouteHandlerRouteAsyncValues.cs deleted file mode 100644 index 6b135739b6..0000000000 --- a/src/Microsoft.AspNet.Mvc.Core/Logging/MvcRouteHandlerRouteAsyncValues.cs +++ /dev/null @@ -1,66 +0,0 @@ -// Copyright (c) Microsoft Open Technologies, Inc. All rights reserved. -// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. - -using System.Text; - -namespace Microsoft.AspNet.Mvc.Logging -{ - /// - /// Represents the state of . - /// - public class MvcRouteHandlerRouteAsyncValues - { - /// - /// The name of the state. - /// - public string Name - { - get - { - return "MvcRouteHandler.RouteAsync"; - } - } - - /// - /// True if an action was selected. - /// - public bool ActionSelected { get; set; } - - /// - /// True if the selected action was invoked. - /// - public bool ActionInvoked { get; set; } - - /// - /// True if the request is handled. - /// - public bool Handled { get; set; } - - /// - /// A summary of the data for display. - /// - public string Summary - { - get - { - var builder = new StringBuilder(); - builder.AppendLine(Name); - builder.Append("\tAction selected? "); - builder.Append(ActionSelected); - builder.AppendLine(); - builder.Append("\tAction invoked? "); - builder.Append(ActionInvoked); - builder.AppendLine(); - builder.Append("\tHandled? "); - builder.Append(Handled); - return builder.ToString(); - } - } - - /// - public override string ToString() - { - return Summary; - } - } -} \ No newline at end of file diff --git a/src/Microsoft.AspNet.Mvc.Core/MvcRouteHandler.cs b/src/Microsoft.AspNet.Mvc.Core/MvcRouteHandler.cs index b49149bf4b..522d5fa94d 100644 --- a/src/Microsoft.AspNet.Mvc.Core/MvcRouteHandler.cs +++ b/src/Microsoft.AspNet.Mvc.Core/MvcRouteHandler.cs @@ -2,12 +2,12 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; +using System.Linq; using System.Diagnostics; using System.Threading.Tasks; using Microsoft.AspNet.Http; using Microsoft.AspNet.Mvc.Core; using Microsoft.AspNet.Mvc.Internal; -using Microsoft.AspNet.Mvc.Logging; using Microsoft.AspNet.Routing; using Microsoft.Framework.DependencyInjection; using Microsoft.Framework.Internal; @@ -40,49 +40,49 @@ namespace Microsoft.AspNet.Mvc MvcServicesHelper.ThrowIfMvcNotRegistered(services); EnsureLogger(context.HttpContext); - using (_logger.BeginScope("MvcRouteHandler.RouteAsync")) + var actionSelector = services.GetRequiredService(); + var actionDescriptor = await actionSelector.SelectAsync(context); + + if (actionDescriptor == null) { - var actionSelector = services.GetRequiredService(); - var actionDescriptor = await actionSelector.SelectAsync(context); + _logger.LogVerbose("No actions matched the current request."); + return; + } - if (actionDescriptor == null) + // Replacing the route data allows any code running here to dirty the route values or data-tokens + // without affecting something upstream. + var oldRouteData = context.RouteData; + var newRouteData = new RouteData(oldRouteData); + + if (actionDescriptor.RouteValueDefaults != null) + { + foreach (var kvp in actionDescriptor.RouteValueDefaults) { - LogActionSelection(actionSelected: false, actionInvoked: false, handled: context.IsHandled); - return; - } - - // Replacing the route data allows any code running here to dirty the route values or data-tokens - // without affecting something upstream. - var oldRouteData = context.RouteData; - var newRouteData = new RouteData(oldRouteData); - - if (actionDescriptor.RouteValueDefaults != null) - { - foreach (var kvp in actionDescriptor.RouteValueDefaults) + if (!newRouteData.Values.ContainsKey(kvp.Key)) { - if (!newRouteData.Values.ContainsKey(kvp.Key)) - { - newRouteData.Values.Add(kvp.Key, kvp.Value); - } + newRouteData.Values.Add(kvp.Key, kvp.Value); } } + } - try + try + { + context.RouteData = newRouteData; + + using (_logger.BeginScope("ActionId: {ActionId}", actionDescriptor.Id)) { - context.RouteData = newRouteData; + _logger.LogVerbose("Executing action {ActionDisplayName}", actionDescriptor.DisplayName); await InvokeActionAsync(context, actionDescriptor); context.IsHandled = true; } - finally + } + finally + { + if (!context.IsHandled) { - if (!context.IsHandled) - { - context.RouteData = oldRouteData; - } + context.RouteData = oldRouteData; } - - LogActionSelection(actionSelected: true, actionInvoked: true, handled: context.IsHandled); } } @@ -102,8 +102,6 @@ namespace Microsoft.AspNet.Mvc var invoker = invokerFactory.CreateInvoker(actionContext); if (invoker == null) { - LogActionSelection(actionSelected: true, actionInvoked: false, handled: context.IsHandled); - throw new InvalidOperationException( Resources.FormatActionInvokerFactory_CouldNotCreateInvoker( actionDescriptor.DisplayName)); @@ -120,18 +118,5 @@ namespace Microsoft.AspNet.Mvc _logger = factory.CreateLogger(); } } - - private void LogActionSelection(bool actionSelected, bool actionInvoked, bool handled) - { - if (_logger.IsEnabled(LogLevel.Verbose)) - { - _logger.WriteValues(new MvcRouteHandlerRouteAsyncValues() - { - ActionSelected = actionSelected, - ActionInvoked = actionInvoked, - Handled = handled, - }); - } - } } } diff --git a/src/Microsoft.AspNet.Mvc.Core/Routing/InnerAttributeRoute.cs b/src/Microsoft.AspNet.Mvc.Core/Routing/InnerAttributeRoute.cs index f0b3212631..1506c30923 100644 --- a/src/Microsoft.AspNet.Mvc.Core/Routing/InnerAttributeRoute.cs +++ b/src/Microsoft.AspNet.Mvc.Core/Routing/InnerAttributeRoute.cs @@ -7,7 +7,6 @@ using System.Linq; using System.Threading.Tasks; using Microsoft.AspNet.Mvc.Core; using Microsoft.AspNet.Mvc.Internal.Routing; -using Microsoft.AspNet.Mvc.Logging; using Microsoft.AspNet.Routing; using Microsoft.AspNet.Routing.Template; using Microsoft.Framework.Internal; @@ -102,42 +101,35 @@ namespace Microsoft.AspNet.Mvc.Routing /// public async Task RouteAsync([NotNull] RouteContext context) { - using (_logger.BeginScope("AttributeRoute.RouteAsync")) + foreach (var route in _matchingRoutes) { - foreach (var route in _matchingRoutes) + var oldRouteData = context.RouteData; + + var newRouteData = new RouteData(oldRouteData); + newRouteData.Routers.Add(route); + + try { - var oldRouteData = context.RouteData; - - var newRouteData = new RouteData(oldRouteData); - newRouteData.Routers.Add(route); - - try + context.RouteData = newRouteData; + await route.RouteAsync(context); + } + finally + { + if (!context.IsHandled) { - context.RouteData = newRouteData; - await route.RouteAsync(context); - } - finally - { - if (!context.IsHandled) - { - context.RouteData = oldRouteData; - } + context.RouteData = oldRouteData; } + } - if (context.IsHandled) - { - break; - } + if (context.IsHandled) + { + break; } } - if (_logger.IsEnabled(LogLevel.Verbose)) + if (!context.IsHandled) { - _logger.WriteValues(new AttributeRouteRouteAsyncValues() - { - MatchingRoutes = _matchingRoutes, - Handled = context.IsHandled - }); + _logger.LogVerbose("Request did not match any attribute route."); } } diff --git a/test/Microsoft.AspNet.Mvc.Core.Test/ActionDescriptorValuesTest.cs b/test/Microsoft.AspNet.Mvc.Core.Test/ActionDescriptorValuesTest.cs deleted file mode 100644 index 9ad84e2a34..0000000000 --- a/test/Microsoft.AspNet.Mvc.Core.Test/ActionDescriptorValuesTest.cs +++ /dev/null @@ -1,23 +0,0 @@ -// Copyright (c) Microsoft Open Technologies, Inc. All rights reserved. -// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. - -using Xunit; - -namespace Microsoft.AspNet.Mvc.Logging -{ - public class ActionDescriptorValuesTest - { - [Fact] - public void ActionDescriptorValues_IncludesAllProperties() - { - // Arrange - var include = new[] { "HttpMethods" }; - - // Assert - PropertiesAssert.PropertiesAreTheSame( - typeof(ControllerActionDescriptor), - typeof(ActionDescriptorValues), - include: include); - } - } -} \ No newline at end of file diff --git a/test/Microsoft.AspNet.Mvc.Core.Test/DefaultActionSelectorSelectAsyncValuesTest.cs b/test/Microsoft.AspNet.Mvc.Core.Test/DefaultActionSelectorSelectAsyncValuesTest.cs deleted file mode 100644 index 954f211949..0000000000 --- a/test/Microsoft.AspNet.Mvc.Core.Test/DefaultActionSelectorSelectAsyncValuesTest.cs +++ /dev/null @@ -1,30 +0,0 @@ -// Copyright (c) Microsoft Open Technologies, Inc. All rights reserved. -// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. - -using System; -using Xunit; - -namespace Microsoft.AspNet.Mvc.Logging -{ - public class DefaultActionSelectorSelectAsyncValuesTest - { - [Fact] - public void EmptyDefaultActionSelectorSelectAsyncValues_ReturnValue() - { - // Arrange - var logObject = new DefaultActionSelectorSelectAsyncValues(); - - // Act - var result = logObject.ToString(); - - var expected = "DefaultActionSelector.SelectAsync" + Environment.NewLine + - "\tActions matching route constraints: " + Environment.NewLine + - "\tActions matching action constraints: " + Environment.NewLine + - "\tFinal Matches: " + Environment.NewLine + - "\tSelected action: No action selected"; - - // Assert - Assert.Equal(expected, result); - } - } -} diff --git a/test/Microsoft.AspNet.Mvc.Core.Test/DefaultActionSelectorTests.cs b/test/Microsoft.AspNet.Mvc.Core.Test/DefaultActionSelectorTests.cs index 98924d7b67..f87a3bb813 100644 --- a/test/Microsoft.AspNet.Mvc.Core.Test/DefaultActionSelectorTests.cs +++ b/test/Microsoft.AspNet.Mvc.Core.Test/DefaultActionSelectorTests.cs @@ -25,91 +25,6 @@ namespace Microsoft.AspNet.Mvc { public class DefaultActionSelectorTests { - [Fact] - public async void SelectAsync_NoMatchedActions_LogIsCorrect() - { - // Arrange - var sink = new TestSink(); - var loggerFactory = new TestLoggerFactory(sink); - - var routeContext = CreateRouteContext("POST"); - - var actions = new ActionDescriptor[0]; - var selector = CreateSelector(actions, loggerFactory); - - // Act - var action = await selector.SelectAsync(routeContext); - - // Assert - Assert.Equal(1, sink.Scopes.Count); - var scope = sink.Scopes[0]; - Assert.Equal(typeof(DefaultActionSelector).FullName, scope.LoggerName); - Assert.Equal("DefaultActionSelector.SelectAsync", scope.Scope.ToString()); - - Assert.Equal(1, sink.Writes.Count); - - var write = sink.Writes[0]; - Assert.Equal(typeof(DefaultActionSelector).FullName, write.LoggerName); - Assert.Equal("DefaultActionSelector.SelectAsync", write.Scope.ToString()); - var values = Assert.IsType(write.State); - Assert.Equal("DefaultActionSelector.SelectAsync", values.Name); - Assert.Empty(values.ActionsMatchingRouteConstraints); - Assert.Empty(values.ActionsMatchingActionConstraints); - Assert.Empty(values.FinalMatches); - Assert.Null(values.SelectedAction); - - // (does not throw) - Assert.NotEmpty(values.Summary); - } - - [Fact] - public async void SelectAsync_MatchedActions_LogIsCorrect() - { - // Arrange - var sink = new TestSink(); - var loggerFactory = new TestLoggerFactory(sink); - - var matched = new ActionDescriptor() - { - ActionConstraints = new List() - { - new HttpMethodConstraint(new string[] { "POST" }), - }, - Parameters = new List(), - }; - - var notMatched = new ActionDescriptor() - { - Parameters = new List(), - }; - - var actions = new ActionDescriptor[] { matched, notMatched }; - var selector = CreateSelector(actions, loggerFactory); - - var routeContext = CreateRouteContext("POST"); - - // Act - var action = await selector.SelectAsync(routeContext); - - // Assert - Assert.Equal(1, sink.Scopes.Count); - var scope = sink.Scopes[0]; - Assert.Equal(typeof(DefaultActionSelector).FullName, scope.LoggerName); - Assert.Equal("DefaultActionSelector.SelectAsync", scope.Scope.ToString()); - - Assert.Equal(1, sink.Writes.Count); - - var write = sink.Writes[0]; - Assert.Equal(typeof(DefaultActionSelector).FullName, write.LoggerName); - Assert.Equal("DefaultActionSelector.SelectAsync", write.Scope.ToString()); - var values = Assert.IsType(write.State); - Assert.Equal("DefaultActionSelector.SelectAsync", values.Name); - Assert.Equal(actions, values.ActionsMatchingRouteConstraints); - Assert.Equal(new[] { matched }, values.ActionsMatchingActionConstraints); - Assert.Equal(matched, Assert.Single(values.FinalMatches)); - Assert.Equal(matched, values.SelectedAction); - } - [Fact] public async void SelectAsync_AmbiguousActions_LogIsCorrect() { @@ -122,10 +37,12 @@ namespace Microsoft.AspNet.Mvc new ActionDescriptor() { DisplayName = "A1" }, new ActionDescriptor() { DisplayName = "A2" }, }; - var selector = CreateSelector(actions, loggerFactory); var routeContext = CreateRouteContext("POST"); + var actionNames = string.Join(Environment.NewLine, actions.Select(action => action.DisplayName)); + var expectedMessage = "Request matched multiple actions resulting in " + + $"ambiguity. Matching actions: {actionNames}"; // Act await Assert.ThrowsAsync(async () => @@ -134,25 +51,9 @@ namespace Microsoft.AspNet.Mvc }); // Assert - Assert.Equal(1, sink.Scopes.Count); - var scope = sink.Scopes[0]; - Assert.Equal(typeof(DefaultActionSelector).FullName, scope.LoggerName); - Assert.Equal("DefaultActionSelector.SelectAsync", scope.Scope.ToString()); - - Assert.Equal(1, sink.Writes.Count); - - var write = sink.Writes[0]; - Assert.Equal(typeof(DefaultActionSelector).FullName, write.LoggerName); - Assert.Equal("DefaultActionSelector.SelectAsync", write.Scope.ToString()); - var values = Assert.IsType(write.State); - Assert.Equal("DefaultActionSelector.SelectAsync", values.Name); - Assert.Equal(actions, values.ActionsMatchingRouteConstraints); - Assert.Equal(actions, values.ActionsMatchingActionConstraints); - Assert.Equal(actions, values.FinalMatches); - Assert.Null(values.SelectedAction); - - // (does not throw) - Assert.NotEmpty(values.Summary); + Assert.Empty(sink.Scopes); + Assert.Single(sink.Writes); + Assert.Equal(expectedMessage, sink.Writes[0].State?.ToString()); } [Fact] diff --git a/test/Microsoft.AspNet.Mvc.Core.Test/MvcRouteHandlerTests.cs b/test/Microsoft.AspNet.Mvc.Core.Test/MvcRouteHandlerTests.cs index efd5199f35..eea8c825ea 100644 --- a/test/Microsoft.AspNet.Mvc.Core.Test/MvcRouteHandlerTests.cs +++ b/test/Microsoft.AspNet.Mvc.Core.Test/MvcRouteHandlerTests.cs @@ -23,27 +23,22 @@ namespace Microsoft.AspNet.Mvc // Arrange var sink = new TestSink(); var loggerFactory = new TestLoggerFactory(sink); - - var context = CreateRouteContext(loggerFactory: loggerFactory); - + var displayName = "A.B.C"; + var actionDescriptor = new Mock(); + actionDescriptor.SetupGet(ad => ad.DisplayName) + .Returns(displayName); + var context = CreateRouteContext(actionDescriptor: actionDescriptor.Object, loggerFactory: loggerFactory); var handler = new MvcRouteHandler(); + var expectedMessage = $"Executing action {displayName}"; // Act await handler.RouteAsync(context); // Assert - var scope = Assert.Single(sink.Scopes); - Assert.Equal(typeof(MvcRouteHandler).FullName, scope.LoggerName); - Assert.Equal("MvcRouteHandler.RouteAsync", scope.Scope.ToString()); - - var write = Assert.Single(sink.Writes); - Assert.Equal(typeof(MvcRouteHandler).FullName, write.LoggerName); - Assert.Equal("MvcRouteHandler.RouteAsync", write.Scope.ToString()); - var values = Assert.IsType(write.State); - Assert.Equal("MvcRouteHandler.RouteAsync", values.Name); - Assert.True(values.ActionSelected); - Assert.True(values.ActionInvoked); - Assert.True(values.Handled); + Assert.Single(sink.Scopes); + Assert.StartsWith("ActionId: ", sink.Scopes[0].Scope?.ToString()); + Assert.Single(sink.Writes); + Assert.Equal(expectedMessage, sink.Writes[0].State?.ToString()); } [Fact] @@ -62,61 +57,15 @@ namespace Microsoft.AspNet.Mvc loggerFactory: loggerFactory); var handler = new MvcRouteHandler(); + var expectedMessage = "No actions matched the current request."; // Act await handler.RouteAsync(context); // Assert - var scope = Assert.Single(sink.Scopes); - Assert.Equal(typeof(MvcRouteHandler).FullName, scope.LoggerName); - Assert.Equal("MvcRouteHandler.RouteAsync", scope.Scope.ToString()); - - var write = Assert.Single(sink.Writes); - Assert.Equal(typeof(MvcRouteHandler).FullName, write.LoggerName); - Assert.Equal("MvcRouteHandler.RouteAsync", write.Scope.ToString()); - var values = Assert.IsType(write.State); - Assert.Equal("MvcRouteHandler.RouteAsync", values.Name); - Assert.False(values.ActionSelected); - Assert.False(values.ActionInvoked); - Assert.False(values.Handled); - } - - [Fact] - public async Task RouteAsync_FailOnNoInvoker_LogsCorrectValues() - { - // Arrange - var sink = new TestSink(); - var loggerFactory = new TestLoggerFactory(sink); - - var mockInvokerFactory = new Mock(); - mockInvokerFactory.Setup(f => f.CreateInvoker(It.IsAny())) - .Returns(null); - - var context = CreateRouteContext( - invokerFactory: mockInvokerFactory.Object, - loggerFactory: loggerFactory); - - var handler = new MvcRouteHandler(); - - // Act - await Assert.ThrowsAsync(async () => - await handler.RouteAsync(context)); - - // Assert - var scope = Assert.Single(sink.Scopes); - Assert.Equal(typeof(MvcRouteHandler).FullName, scope.LoggerName); - Assert.Equal("MvcRouteHandler.RouteAsync", scope.Scope.ToString()); - - Assert.Equal(1, sink.Writes.Count); - - var write = sink.Writes[0]; - Assert.Equal(typeof(MvcRouteHandler).FullName, write.LoggerName); - Assert.Equal("MvcRouteHandler.RouteAsync", write.Scope.ToString()); - var values = Assert.IsType(write.State); - Assert.Equal("MvcRouteHandler.RouteAsync", values.Name); - Assert.True(values.ActionSelected); - Assert.False(values.ActionInvoked); - Assert.False(values.Handled); + Assert.Empty(sink.Scopes); + Assert.Single(sink.Writes); + Assert.Equal(expectedMessage, sink.Writes[0].State?.ToString()); } [Fact] @@ -241,6 +190,7 @@ namespace Microsoft.AspNet.Mvc } private RouteContext CreateRouteContext( + ActionDescriptor actionDescriptor = null, IActionSelector actionSelector = null, IActionInvokerFactory invokerFactory = null, ILoggerFactory loggerFactory = null, @@ -248,13 +198,17 @@ namespace Microsoft.AspNet.Mvc { var mockContextAccessor = new Mock>(); - if (actionSelector == null) + if (actionDescriptor == null) { var mockAction = new Mock(); + actionDescriptor = mockAction.Object; + } + if (actionSelector == null) + { var mockActionSelector = new Mock(); mockActionSelector.Setup(a => a.SelectAsync(It.IsAny())) - .Returns(Task.FromResult(mockAction.Object)); + .Returns(Task.FromResult(actionDescriptor)); actionSelector = mockActionSelector.Object; } diff --git a/test/Microsoft.AspNet.Mvc.Core.Test/Routing/InnerAttributeRouteTest.cs b/test/Microsoft.AspNet.Mvc.Core.Test/Routing/InnerAttributeRouteTest.cs index 3bf33bf61d..574a964b46 100644 --- a/test/Microsoft.AspNet.Mvc.Core.Test/Routing/InnerAttributeRouteTest.cs +++ b/test/Microsoft.AspNet.Mvc.Core.Test/Routing/InnerAttributeRouteTest.cs @@ -907,69 +907,7 @@ namespace Microsoft.AspNet.Mvc.Routing Assert.Equal(string.Format("1&{0}", template), selectedGroup); } - [Fact] - public async void AttributeRoute_RouteAsyncHandled_LogsCorrectValues() - { - // Arrange - var sink = new TestSink(); - var loggerFactory = new TestLoggerFactory(sink); - - var entry = CreateMatchingEntry("api/Store"); - var route = CreateRoutingAttributeRoute(loggerFactory, entry); - - var context = CreateRouteContext("/api/Store"); - - // Act - await route.RouteAsync(context); - - // Assert - Assert.Equal(1, sink.Scopes.Count); - var scope = sink.Scopes[0]; - Assert.Equal(typeof(AttributeRoute).FullName, scope.LoggerName); - Assert.Equal("AttributeRoute.RouteAsync", scope.Scope.ToString()); - - Assert.Equal(1, sink.Writes.Count); - - var write = sink.Writes[0]; - Assert.Equal(typeof(AttributeRoute).FullName, write.LoggerName); - Assert.Equal("AttributeRoute.RouteAsync", write.Scope.ToString()); - var values = Assert.IsType(write.State); - Assert.Equal("AttributeRoute.RouteAsync", values.Name); - Assert.True(values.Handled); - } - - [Fact] - public async void AttributeRoute_RouteAsyncNotHandled_LogsCorrectValues() - { - // Arrange - var sink = new TestSink(); - var loggerFactory = new TestLoggerFactory(sink); - - var entry = CreateMatchingEntry("api/Store"); - var route = CreateRoutingAttributeRoute(loggerFactory, entry); - - var context = CreateRouteContext("/"); - - // Act - await route.RouteAsync(context); - - // Assert - Assert.Equal(1, sink.Scopes.Count); - var scope = sink.Scopes[0]; - Assert.Equal(typeof(AttributeRoute).FullName, scope.LoggerName); - Assert.Equal("AttributeRoute.RouteAsync", scope.Scope.ToString()); - - Assert.Equal(1, sink.Writes.Count); - - var write = sink.Writes[0]; - Assert.Equal(typeof(AttributeRoute).FullName, write.LoggerName); - Assert.Equal("AttributeRoute.RouteAsync", write.Scope.ToString()); - var values = Assert.IsType(write.State); - Assert.Equal("AttributeRoute.RouteAsync", values.Name); - Assert.False(values.Handled); - } - - [Fact] + [Fact] public void AttributeRoute_GenerateLink_NoRequiredValues() { // Arrange diff --git a/test/Microsoft.AspNet.Mvc.FunctionalTests/Logging/LoggingActionSelectionTest.cs b/test/Microsoft.AspNet.Mvc.FunctionalTests/Logging/LoggingActionSelectionTest.cs deleted file mode 100644 index 464326708f..0000000000 --- a/test/Microsoft.AspNet.Mvc.FunctionalTests/Logging/LoggingActionSelectionTest.cs +++ /dev/null @@ -1,102 +0,0 @@ -// Copyright (c) Microsoft Open Technologies, Inc. All rights reserved. -// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. - -#if DNX451 // Since Json.net serialization fails in CoreCLR -using System; -using System.Collections.Generic; -using System.Linq; -using System.Net; -using System.Net.Http; -using System.Threading.Tasks; -using LoggingWebSite; -using Microsoft.AspNet.Builder; -using Microsoft.AspNet.Mvc.Logging; -using Microsoft.Framework.DependencyInjection; -using Newtonsoft.Json; -using Xunit; - -namespace Microsoft.AspNet.Mvc.FunctionalTests -{ - public class LoggingActionSelectionTest - { - private const string SiteName = nameof(LoggingWebSite); - private readonly Action _app = new Startup().Configure; - private readonly Action _configureServices = new Startup().ConfigureServices; - - [Fact] - public async Task Successful_ActionSelection_Logged() - { - // Arrange - var server = TestHelper.CreateServer(_app, SiteName, _configureServices); - var client = server.CreateClient(); - var requestTraceId = Guid.NewGuid().ToString(); - - // Act - var response = await client.GetAsync(string.Format( - "http://localhost/home/index?{0}={1}", - LoggingExtensions.RequestTraceIdQueryKey, - requestTraceId)); - - // Assert - Assert.Equal(HttpStatusCode.OK, response.StatusCode); - var responseData = await response.Content.ReadAsStringAsync(); - Assert.Equal("Home.Index", responseData); - - var logs = await GetLogsAsync(client, requestTraceId); - var scopeNode = logs.FindScope(nameof(MvcRouteHandler) + ".RouteAsync"); - - Assert.NotNull(scopeNode); - var logInfo = scopeNode.Messages.OfDataType() - .FirstOrDefault(); - - Assert.NotNull(logInfo); - Assert.NotNull(logInfo.State); - - dynamic actionSelection = logInfo.State; - Assert.True((bool)actionSelection.ActionSelected); - Assert.True((bool)actionSelection.ActionInvoked); - Assert.True((bool)actionSelection.Handled); - } - - [Fact] - public async Task Failed_ActionSelection_Logged() - { - // Arrange - var server = TestHelper.CreateServer(_app, SiteName, _configureServices); - var client = server.CreateClient(); - var requestTraceId = Guid.NewGuid().ToString(); - - // Act - var response = await client.GetAsync(string.Format( - "http://localhost/InvalidController/InvalidAction?{0}={1}", - LoggingExtensions.RequestTraceIdQueryKey, - requestTraceId)); - - // Assert - Assert.Equal(HttpStatusCode.NotFound, response.StatusCode); - - - var logs = await GetLogsAsync(client, requestTraceId); - var scopeNode = logs.FindScope(nameof(MvcRouteHandler) + ".RouteAsync"); - - Assert.NotNull(scopeNode); - var logInfo = scopeNode.Messages.OfDataType() - .FirstOrDefault(); - Assert.NotNull(logInfo); - - dynamic actionSelection = logInfo.State; - Assert.False((bool)actionSelection.ActionSelected); - Assert.False((bool)actionSelection.ActionInvoked); - Assert.False((bool)actionSelection.Handled); - } - - private async Task> GetLogsAsync(HttpClient client, - string requestTraceId) - { - var responseData = await client.GetStringAsync("http://localhost/logs"); - var logActivities = JsonConvert.DeserializeObject>(responseData); - return logActivities.FilterByRequestTraceId(requestTraceId); - } - } -} -#endif