From 3227de8c0bfa7f60a03bde04163ba0f155b2651a Mon Sep 17 00:00:00 2001 From: Ryan Nowak Date: Thu, 27 Sep 2018 13:26:52 -0700 Subject: [PATCH] Fix #629 - Add logging to DfaMatcther Adds logging for the most common things that can prevent an endpoint from matching. Note that we already have good logging in other parts of the system, the stuff here completes the story by providing details at the debug level. --- .../DefaultLinkGenerator.cs | 4 +- .../EndpointMiddleware.cs | 4 +- .../EndpointRoutingMiddleware.cs | 4 +- .../RouteConstraintMatcherExtensions.cs | 2 +- .../RouterMiddlewareLoggerExtensions.cs | 2 +- .../Logging/TreeRouterLoggerExtensions.cs | 2 +- .../Matching/DfaMatcher.cs | 148 ++++++++++++- .../Matching/DfaMatcherBuilder.cs | 6 +- .../ConstraintMatcherTest.cs | 2 +- .../EndpointRoutingMiddlewareTest.cs | 2 +- .../Matching/CandidateSetTest.cs | 2 + .../Matching/DfaMatcherBuilderTest.cs | 2 + .../Matching/DfaMatcherTest.cs | 194 +++++++++++++++++- .../RouterMiddlewareTest.cs | 2 +- 14 files changed, 346 insertions(+), 30 deletions(-) diff --git a/src/Microsoft.AspNetCore.Routing/DefaultLinkGenerator.cs b/src/Microsoft.AspNetCore.Routing/DefaultLinkGenerator.cs index 7bd41daeaa..c652be90be 100644 --- a/src/Microsoft.AspNetCore.Routing/DefaultLinkGenerator.cs +++ b/src/Microsoft.AspNetCore.Routing/DefaultLinkGenerator.cs @@ -421,8 +421,8 @@ namespace Microsoft.AspNetCore.Routing LogLevel.Debug, EventIds.TemplateFailedExpansion, "Failed to process the template {Template} for {Endpoint}. " + - "The failure occured while expanding the template with values {Values}. " + - "This is usually due to a missing or empty value in a complex segment."); + "The failure occured while expanding the template with values {Values} " + + "This is usually due to a missing or empty value in a complex segment"); private static readonly Action, string, Exception> _linkGenerationSucceeded = LoggerMessage.Define, string>( LogLevel.Debug, diff --git a/src/Microsoft.AspNetCore.Routing/EndpointMiddleware.cs b/src/Microsoft.AspNetCore.Routing/EndpointMiddleware.cs index a9790e6ee1..7facd61bb0 100644 --- a/src/Microsoft.AspNetCore.Routing/EndpointMiddleware.cs +++ b/src/Microsoft.AspNetCore.Routing/EndpointMiddleware.cs @@ -57,12 +57,12 @@ namespace Microsoft.AspNetCore.Routing private static readonly Action _executingEndpoint = LoggerMessage.Define( LogLevel.Information, new EventId(0, "ExecutingEndpoint"), - "Executing endpoint '{EndpointName}'."); + "Executing endpoint '{EndpointName}'"); private static readonly Action _executedEndpoint = LoggerMessage.Define( LogLevel.Information, new EventId(1, "ExecutedEndpoint"), - "Executed endpoint '{EndpointName}'."); + "Executed endpoint '{EndpointName}'"); public static void ExecutingEndpoint(ILogger logger, Endpoint endpoint) { diff --git a/src/Microsoft.AspNetCore.Routing/EndpointRoutingMiddleware.cs b/src/Microsoft.AspNetCore.Routing/EndpointRoutingMiddleware.cs index b0d740b440..0b82dc3438 100644 --- a/src/Microsoft.AspNetCore.Routing/EndpointRoutingMiddleware.cs +++ b/src/Microsoft.AspNetCore.Routing/EndpointRoutingMiddleware.cs @@ -119,12 +119,12 @@ namespace Microsoft.AspNetCore.Routing private static readonly Action _matchSuccess = LoggerMessage.Define( LogLevel.Debug, new EventId(1, "MatchSuccess"), - "Request matched endpoint '{EndpointName}'."); + "Request matched endpoint '{EndpointName}'"); private static readonly Action _matchFailure = LoggerMessage.Define( LogLevel.Debug, new EventId(2, "MatchFailure"), - "Request did not match any endpoints."); + "Request did not match any endpoints"); public static void MatchSuccess(ILogger logger, EndpointSelectorContext context) { diff --git a/src/Microsoft.AspNetCore.Routing/Logging/RouteConstraintMatcherExtensions.cs b/src/Microsoft.AspNetCore.Routing/Logging/RouteConstraintMatcherExtensions.cs index 9a19250f30..3036d2b9b9 100644 --- a/src/Microsoft.AspNetCore.Routing/Logging/RouteConstraintMatcherExtensions.cs +++ b/src/Microsoft.AspNetCore.Routing/Logging/RouteConstraintMatcherExtensions.cs @@ -16,7 +16,7 @@ namespace Microsoft.AspNetCore.Routing.Logging LogLevel.Debug, 1, "Route value '{RouteValue}' with key '{RouteKey}' did not match " + - "the constraint '{RouteConstraint}'."); + "the constraint '{RouteConstraint}'"); } public static void RouteValueDoesNotMatchConstraint( diff --git a/src/Microsoft.AspNetCore.Routing/Logging/RouterMiddlewareLoggerExtensions.cs b/src/Microsoft.AspNetCore.Routing/Logging/RouterMiddlewareLoggerExtensions.cs index 35f05272cd..77fba27317 100644 --- a/src/Microsoft.AspNetCore.Routing/Logging/RouterMiddlewareLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Routing/Logging/RouterMiddlewareLoggerExtensions.cs @@ -15,7 +15,7 @@ namespace Microsoft.AspNetCore.Routing.Logging _requestDidNotMatchRoutes = LoggerMessage.Define( LogLevel.Debug, 1, - "Request did not match any routes."); + "Request did not match any routes"); } public static void RequestDidNotMatchRoutes(this ILogger logger) diff --git a/src/Microsoft.AspNetCore.Routing/Logging/TreeRouterLoggerExtensions.cs b/src/Microsoft.AspNetCore.Routing/Logging/TreeRouterLoggerExtensions.cs index 3f6af8e5dc..825e9ef888 100644 --- a/src/Microsoft.AspNetCore.Routing/Logging/TreeRouterLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Routing/Logging/TreeRouterLoggerExtensions.cs @@ -15,7 +15,7 @@ namespace Microsoft.AspNetCore.Routing.Logging _matchedRoute = LoggerMessage.Define( LogLevel.Debug, 1, - "Request successfully matched the route with name '{RouteName}' and template '{RouteTemplate}'."); + "Request successfully matched the route with name '{RouteName}' and template '{RouteTemplate}'"); } public static void MatchedRoute( diff --git a/src/Microsoft.AspNetCore.Routing/Matching/DfaMatcher.cs b/src/Microsoft.AspNetCore.Routing/Matching/DfaMatcher.cs index 212acaf1b5..da0f799129 100644 --- a/src/Microsoft.AspNetCore.Routing/Matching/DfaMatcher.cs +++ b/src/Microsoft.AspNetCore.Routing/Matching/DfaMatcher.cs @@ -6,17 +6,20 @@ using System.Collections.Generic; using System.Threading.Tasks; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Routing.Patterns; +using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.Routing.Matching { internal sealed class DfaMatcher : Matcher { + private readonly ILogger _logger; private readonly EndpointSelector _selector; private readonly DfaState[] _states; private readonly int _maxSegmentCount; - public DfaMatcher(EndpointSelector selector, DfaState[] states, int maxSegmentCount) + public DfaMatcher(ILogger logger, EndpointSelector selector, DfaState[] states, int maxSegmentCount) { + _logger = logger; _selector = selector; _states = states; _maxSegmentCount = maxSegmentCount; @@ -34,6 +37,9 @@ namespace Microsoft.AspNetCore.Routing.Matching throw new ArgumentNullException(nameof(context)); } + // All of the logging we do here is at level debug, so we can get away with doing a single check. + var log = _logger.IsEnabled(LogLevel.Debug); + // The sequence of actions we take is optimized to avoid doing expensive work // like creating substrings, creating route value dictionaries, and calling // into policies like versioning. @@ -49,9 +55,19 @@ namespace Microsoft.AspNetCore.Routing.Matching var candidates = FindCandidateSet(httpContext, path, segments); if (candidates.Length == 0) { + if (log) + { + Logger.CandidatesNotFound(_logger, path); + } + return Task.CompletedTask; } + if (log) + { + Logger.CandidatesFound(_logger, path, candidates); + } + // At this point we have a candidate set, defined as a list of endpoints in // priority order. // @@ -117,21 +133,34 @@ namespace Microsoft.AspNetCore.Routing.Matching // Now that we have the route values, we need to process complex segments. // Complex segments go through an old API that requires a fully-materialized // route value dictionary. + var isMatch = true; if ((flags & Candidate.CandidateFlags.HasComplexSegments) != 0) { - if (!ProcessComplexSegments(candidate.ComplexSegments, path, segments, values)) + if (!ProcessComplexSegments(candidate.Endpoint, candidate.ComplexSegments, path, segments, values)) { candidateSet.SetValidity(i, false); - continue; + isMatch = false; } } if ((flags & Candidate.CandidateFlags.HasConstraints) != 0) { - if (!ProcessConstraints(candidate.Constraints, httpContext, values)) + if (!ProcessConstraints(candidate.Endpoint, candidate.Constraints, httpContext, values)) { candidateSet.SetValidity(i, false); - continue; + isMatch = false; + } + } + + if (log) + { + if (isMatch) + { + Logger.CandidateValid(_logger, path, candidate.Endpoint); + } + else + { + Logger.CandidateNotValid(_logger, path, candidate.Endpoint); } } } @@ -202,6 +231,7 @@ namespace Microsoft.AspNetCore.Routing.Matching } private bool ProcessComplexSegments( + Endpoint endpoint, (RoutePatternPathSegment pathSegment, int segmentIndex)[] complexSegments, string path, ReadOnlySpan segments, @@ -209,10 +239,12 @@ namespace Microsoft.AspNetCore.Routing.Matching { for (var i = 0; i < complexSegments.Length; i++) { - var segment = segments[complexSegments[i].segmentIndex]; + (var complexSegment, var segmentIndex) = complexSegments[i]; + var segment = segments[segmentIndex]; var text = path.Substring(segment.Start, segment.Length); - if (!RoutePatternMatcher.MatchComplexSegment(complexSegments[i].pathSegment, text, values)) + if (!RoutePatternMatcher.MatchComplexSegment(complexSegment, text, values)) { + Logger.CandidateRejectedByComplexSegment(_logger, path, endpoint, complexSegment); return false; } } @@ -221,6 +253,7 @@ namespace Microsoft.AspNetCore.Routing.Matching } private bool ProcessConstraints( + Endpoint endpoint, KeyValuePair[] constraints, HttpContext httpContext, RouteValueDictionary values) @@ -230,11 +263,112 @@ namespace Microsoft.AspNetCore.Routing.Matching var constraint = constraints[i]; if (!constraint.Value.Match(httpContext, NullRouter.Instance, constraint.Key, values, RouteDirection.IncomingRequest)) { + Logger.CandidateRejectedByConstraint(_logger, httpContext.Request.Path, endpoint, constraint.Key, constraint.Value, values[constraint.Key]); return false; } } return true; } + + internal static class EventIds + { + public static readonly EventId CandidatesNotFound = new EventId(1000, "CandidatesNotFound"); + public static readonly EventId CandidatesFound = new EventId(1001, "CandidatesFound"); + + public static readonly EventId CandidateRejectedByComplexSegment = new EventId(1002, "CandidateRejectedByComplexSegment"); + public static readonly EventId CandidateRejectedByConstraint = new EventId(1003, "CandidateRejectedByConstraint"); + + public static readonly EventId CandidateNotValid = new EventId(1004, "CandiateNotValid"); + public static readonly EventId CandidateValid = new EventId(1005, "CandiateValid"); + } + + private static class Logger + { + private static readonly Action _candidatesNotFound = LoggerMessage.Define( + LogLevel.Debug, + EventIds.CandidatesNotFound, + "No candidates found for the request path '{Path}'"); + + private static readonly Action _candidatesFound = LoggerMessage.Define( + LogLevel.Debug, + EventIds.CandidatesFound, + "{CandidateCount} candidate(s) found for the request path '{Path}'"); + + private static readonly Action _candidateRejectedByComplexSegment = LoggerMessage.Define( + LogLevel.Debug, + EventIds.CandidateRejectedByComplexSegment, + "Endpoint '{Endpoint}' with route pattern '{RoutePattern}' was rejected by complex segment '{Segment}' for the request path '{Path}'"); + + private static readonly Action _candidateRejectedByConstraint = LoggerMessage.Define( + LogLevel.Debug, + EventIds.CandidateRejectedByConstraint, + "Endpoint '{Endpoint}' with route pattern '{RoutePattern}' was rejected by constraint '{ConstraintName}':'{Constraint}' with value '{RouteValue}' for the request path '{Path}'"); + + private static readonly Action _candidateNotValid = LoggerMessage.Define( + LogLevel.Debug, + EventIds.CandidateNotValid, + "Endpoint '{Endpoint}' with route pattern '{RoutePattern}' is not valid for the request path '{Path}'"); + + private static readonly Action _candidateValid = LoggerMessage.Define( + LogLevel.Debug, + EventIds.CandidateValid, + "Endpoint '{Endpoint}' with route pattern '{RoutePattern}' is valid for the request path '{Path}'"); + + public static void CandidatesNotFound(ILogger logger, string path) + { + _candidatesNotFound(logger, path, null); + } + + public static void CandidatesFound(ILogger logger, string path, Candidate[] candidates) + { + _candidatesFound(logger, candidates.Length, path, null); + } + + public static void CandidateRejectedByComplexSegment(ILogger logger, string path, Endpoint endpoint, RoutePatternPathSegment segment) + { + // This should return a real pattern since we're processing complex segments.... but just in case. + if (logger.IsEnabled(LogLevel.Debug)) + { + var routePattern = GetRoutePattern(endpoint); + _candidateRejectedByComplexSegment(logger, endpoint.DisplayName, routePattern, segment.DebuggerToString(), path, null); + } + } + + public static void CandidateRejectedByConstraint(ILogger logger, string path, Endpoint endpoint, string constraintName, IRouteConstraint constraint, object value) + { + // This should return a real pattern since we're processing constraints.... but just in case. + if (logger.IsEnabled(LogLevel.Debug)) + { + var routePattern = GetRoutePattern(endpoint); + _candidateRejectedByConstraint(logger, endpoint.DisplayName, routePattern, constraintName, constraint.ToString(), value, path, null); + } + } + + public static void CandidateNotValid(ILogger logger, string path, Endpoint endpoint) + { + // This can be the fallback value because it really might not be a route endpoint + if (logger.IsEnabled(LogLevel.Debug)) + { + var routePattern = GetRoutePattern(endpoint); + _candidateNotValid(logger, endpoint.DisplayName, routePattern, path, null); + } + } + + public static void CandidateValid(ILogger logger, string path, Endpoint endpoint) + { + // This can be the fallback value because it really might not be a route endpoint + if (logger.IsEnabled(LogLevel.Debug)) + { + var routePattern = GetRoutePattern(endpoint); + _candidateValid(logger, endpoint.DisplayName, routePattern, path, null); + } + } + + private static string GetRoutePattern(Endpoint endpoint) + { + return (endpoint as RouteEndpoint)?.RoutePattern?.RawText ?? "(none)"; + } + } } } diff --git a/src/Microsoft.AspNetCore.Routing/Matching/DfaMatcherBuilder.cs b/src/Microsoft.AspNetCore.Routing/Matching/DfaMatcherBuilder.cs index 28b5cdf353..bff708feea 100644 --- a/src/Microsoft.AspNetCore.Routing/Matching/DfaMatcherBuilder.cs +++ b/src/Microsoft.AspNetCore.Routing/Matching/DfaMatcherBuilder.cs @@ -6,6 +6,7 @@ using System.Collections.Generic; using System.Linq; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Routing.Patterns; +using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.Routing.Matching { @@ -13,6 +14,7 @@ namespace Microsoft.AspNetCore.Routing.Matching { private readonly List _endpoints = new List(); + private readonly ILoggerFactory _loggerFactory; private readonly ParameterPolicyFactory _parameterPolicyFactory; private readonly EndpointSelector _selector; private readonly MatcherPolicy[] _policies; @@ -29,10 +31,12 @@ namespace Microsoft.AspNetCore.Routing.Matching private int _stateIndex; public DfaMatcherBuilder( + ILoggerFactory loggerFactory, ParameterPolicyFactory parameterPolicyFactory, EndpointSelector selector, IEnumerable policies) { + _loggerFactory = loggerFactory; _parameterPolicyFactory = parameterPolicyFactory; _selector = selector; _policies = policies.OrderBy(p => p.Order).ToArray(); @@ -304,7 +308,7 @@ namespace Microsoft.AspNetCore.Routing.Matching JumpTableBuilder.Build(exitDestination, exitDestination, null), null); - return new DfaMatcher(_selector, states, maxSegmentCount); + return new DfaMatcher(_loggerFactory.CreateLogger(), _selector, states, maxSegmentCount); } private int AddNode( diff --git a/test/Microsoft.AspNetCore.Routing.Tests/ConstraintMatcherTest.cs b/test/Microsoft.AspNetCore.Routing.Tests/ConstraintMatcherTest.cs index 4d9b436e81..59194e3a0b 100644 --- a/test/Microsoft.AspNetCore.Routing.Tests/ConstraintMatcherTest.cs +++ b/test/Microsoft.AspNetCore.Routing.Tests/ConstraintMatcherTest.cs @@ -56,7 +56,7 @@ namespace Microsoft.AspNetCore.Routing }; var sink = SetUpMatch(constraints, loggerEnabled: true); var expectedMessage = "Route value 'value' with key 'b' did not match the constraint " + - $"'{typeof(FailConstraint).FullName}'."; + $"'{typeof(FailConstraint).FullName}'"; // Assert Assert.Empty(sink.Scopes); diff --git a/test/Microsoft.AspNetCore.Routing.Tests/EndpointRoutingMiddlewareTest.cs b/test/Microsoft.AspNetCore.Routing.Tests/EndpointRoutingMiddlewareTest.cs index a15d94e340..dad2fdf0ff 100644 --- a/test/Microsoft.AspNetCore.Routing.Tests/EndpointRoutingMiddlewareTest.cs +++ b/test/Microsoft.AspNetCore.Routing.Tests/EndpointRoutingMiddlewareTest.cs @@ -36,7 +36,7 @@ namespace Microsoft.AspNetCore.Routing public async Task Invoke_OnCall_WritesToConfiguredLogger() { // Arrange - var expectedMessage = "Request matched endpoint 'Test endpoint'."; + var expectedMessage = "Request matched endpoint 'Test endpoint'"; var sink = new TestSink( TestSink.EnableWithTypeName, diff --git a/test/Microsoft.AspNetCore.Routing.Tests/Matching/CandidateSetTest.cs b/test/Microsoft.AspNetCore.Routing.Tests/Matching/CandidateSetTest.cs index b94923df3c..470103e283 100644 --- a/test/Microsoft.AspNetCore.Routing.Tests/Matching/CandidateSetTest.cs +++ b/test/Microsoft.AspNetCore.Routing.Tests/Matching/CandidateSetTest.cs @@ -5,6 +5,7 @@ using System; using System.Linq; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Routing.Patterns; +using Microsoft.Extensions.Logging.Abstractions; using Moq; using Xunit; @@ -117,6 +118,7 @@ namespace Microsoft.AspNetCore.Routing.Matching { var dataSource = new CompositeEndpointDataSource(Array.Empty()); return new DfaMatcherBuilder( + NullLoggerFactory.Instance, Mock.Of(), Mock.Of(), policies); diff --git a/test/Microsoft.AspNetCore.Routing.Tests/Matching/DfaMatcherBuilderTest.cs b/test/Microsoft.AspNetCore.Routing.Tests/Matching/DfaMatcherBuilderTest.cs index 10c0aec62e..e2eec83cb0 100644 --- a/test/Microsoft.AspNetCore.Routing.Tests/Matching/DfaMatcherBuilderTest.cs +++ b/test/Microsoft.AspNetCore.Routing.Tests/Matching/DfaMatcherBuilderTest.cs @@ -7,6 +7,7 @@ using System.Linq; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Routing.Constraints; using Microsoft.AspNetCore.Routing.Patterns; +using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Options; using Moq; using Xunit; @@ -972,6 +973,7 @@ namespace Microsoft.AspNetCore.Routing.Matching { var dataSource = new CompositeEndpointDataSource(Array.Empty()); return new DfaMatcherBuilder( + NullLoggerFactory.Instance, new DefaultParameterPolicyFactory(Options.Create(new RouteOptions()), Mock.Of()), Mock.Of(), policies); diff --git a/test/Microsoft.AspNetCore.Routing.Tests/Matching/DfaMatcherTest.cs b/test/Microsoft.AspNetCore.Routing.Tests/Matching/DfaMatcherTest.cs index 924a11b733..08e3b76570 100644 --- a/test/Microsoft.AspNetCore.Routing.Tests/Matching/DfaMatcherTest.cs +++ b/test/Microsoft.AspNetCore.Routing.Tests/Matching/DfaMatcherTest.cs @@ -7,6 +7,8 @@ using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Http.Features; using Microsoft.AspNetCore.Routing.Patterns; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Testing; using Moq; using Xunit; @@ -26,7 +28,7 @@ namespace Microsoft.AspNetCore.Routing.Matching template); } - private Matcher CreateDfaMatcher(EndpointDataSource dataSource, EndpointSelector endpointSelector = null) + private Matcher CreateDfaMatcher(EndpointDataSource dataSource, EndpointSelector endpointSelector = null, ILoggerFactory loggerFactory = null) { var serviceCollection = new ServiceCollection() .AddLogging() @@ -38,6 +40,11 @@ namespace Microsoft.AspNetCore.Routing.Matching serviceCollection.AddSingleton(endpointSelector); } + if (loggerFactory != null) + { + serviceCollection.AddSingleton(loggerFactory); + } + var services = serviceCollection.BuildServiceProvider(); var factory = services.GetRequiredService(); @@ -76,14 +83,14 @@ namespace Microsoft.AspNetCore.Routing.Matching var matcher = CreateDfaMatcher(endpointDataSource); - var (httpContext, endpointFeature) = CreateContext(); + var (httpContext, context) = CreateContext(); httpContext.Request.Path = "/One"; // Act - await matcher.MatchAsync(httpContext, endpointFeature); + await matcher.MatchAsync(httpContext, context); // Assert - Assert.Null(endpointFeature.Endpoint); + Assert.Null(context.Endpoint); } [Fact] @@ -101,14 +108,14 @@ namespace Microsoft.AspNetCore.Routing.Matching var matcher = CreateDfaMatcher(endpointDataSource); - var (httpContext, endpointFeature) = CreateContext(); + var (httpContext, context) = CreateContext(); httpContext.Request.Path = "/Teams"; // Act - await matcher.MatchAsync(httpContext, endpointFeature); + await matcher.MatchAsync(httpContext, context); // Assert - Assert.Equal(lowerOrderEndpoint, endpointFeature.Endpoint); + Assert.Equal(lowerOrderEndpoint, context.Endpoint); } [Fact] @@ -147,14 +154,181 @@ namespace Microsoft.AspNetCore.Routing.Matching var matcher = CreateDfaMatcher(endpointDataSource, endpointSelector.Object); - var (httpContext, endpointFeature) = CreateContext(); + var (httpContext, context) = CreateContext(); httpContext.Request.Path = "/Teams"; // Act - await matcher.MatchAsync(httpContext, endpointFeature); + await matcher.MatchAsync(httpContext, context); // Assert - Assert.Equal(endpoint2, endpointFeature.Endpoint); + Assert.Equal(endpoint2, context.Endpoint); + } + + [Fact] + public async Task MatchAsync_NoCandidates_Logging() + { + // Arrange + var endpointDataSource = new DefaultEndpointDataSource(new List + { + CreateEndpoint("/{p:int}", 0) + }); + + var sink = new TestSink(); + var matcher = CreateDfaMatcher(endpointDataSource, loggerFactory: new TestLoggerFactory(sink, enabled: true)); + + var (httpContext, context) = CreateContext(); + httpContext.Request.Path = "/"; + + // Act + await matcher.MatchAsync(httpContext, context); + + // Assert + Assert.Null(context.Endpoint); + + Assert.Collection( + sink.Writes, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidatesNotFound, log.EventId); + Assert.Equal("No candidates found for the request path '/'", log.Message); + }); + } + + [Fact] + public async Task MatchAsync_ConstraintRejectsEndpoint_Logging() + { + // Arrange + var endpointDataSource = new DefaultEndpointDataSource(new List + { + CreateEndpoint("/{p:int}", 0) + }); + + var sink = new TestSink(); + var matcher = CreateDfaMatcher(endpointDataSource, loggerFactory: new TestLoggerFactory(sink, enabled: true)); + + var (httpContext, context) = CreateContext(); + httpContext.Request.Path = "/One"; + + // Act + await matcher.MatchAsync(httpContext, context); + + // Assert + Assert.Null(context.Endpoint); + + Assert.Collection( + sink.Writes, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidatesFound, log.EventId); + Assert.Equal("1 candidate(s) found for the request path '/One'", log.Message); + }, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidateRejectedByConstraint, log.EventId); + Assert.Equal("Endpoint '/{p:int}' with route pattern '/{p:int}' was rejected by constraint 'p':'Microsoft.AspNetCore.Routing.Constraints.IntRouteConstraint' with value 'One' for the request path '/One'", log.Message); + }, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidateNotValid, log.EventId); + Assert.Equal("Endpoint '/{p:int}' with route pattern '/{p:int}' is not valid for the request path '/One'", log.Message); + }); + } + + [Fact] + public async Task MatchAsync_ComplexSegmentRejectsEndpoint_Logging() + { + // Arrange + var endpointDataSource = new DefaultEndpointDataSource(new List + { + CreateEndpoint("/x-{id}-y", 0) + }); + + var sink = new TestSink(); + var matcher = CreateDfaMatcher(endpointDataSource, loggerFactory: new TestLoggerFactory(sink, enabled: true)); + + var (httpContext, context) = CreateContext(); + httpContext.Request.Path = "/One"; + + // Act + await matcher.MatchAsync(httpContext, context); + + // Assert + Assert.Null(context.Endpoint); + + Assert.Collection( + sink.Writes, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidatesFound, log.EventId); + Assert.Equal("1 candidate(s) found for the request path '/One'", log.Message); + }, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidateRejectedByComplexSegment, log.EventId); + Assert.Equal("Endpoint '/x-{id}-y' with route pattern '/x-{id}-y' was rejected by complex segment 'x-{id}-y' for the request path '/One'", log.Message); + }, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidateNotValid, log.EventId); + Assert.Equal("Endpoint '/x-{id}-y' with route pattern '/x-{id}-y' is not valid for the request path '/One'", log.Message); + }); + } + + [Fact] + public async Task MatchAsync_MultipleCandidates_Logging() + { + // Arrange + var endpointDataSource = new DefaultEndpointDataSource(new List + { + CreateEndpoint("/One", 0), + CreateEndpoint("/{p:int}", 0), + CreateEndpoint("/x-{id}-y", 0), + }); + + var sink = new TestSink(); + var matcher = CreateDfaMatcher(endpointDataSource, loggerFactory: new TestLoggerFactory(sink, enabled: true)); + + var (httpContext, context) = CreateContext(); + httpContext.Request.Path = "/One"; + + // Act + await matcher.MatchAsync(httpContext, context); + + // Assert + Assert.Same(endpointDataSource.Endpoints[0], context.Endpoint); + + Assert.Collection( + sink.Writes, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidatesFound, log.EventId); + Assert.Equal("3 candidate(s) found for the request path '/One'", log.Message); + }, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidateValid, log.EventId); + Assert.Equal("Endpoint '/One' with route pattern '/One' is valid for the request path '/One'", log.Message); + }, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidateRejectedByConstraint, log.EventId); + Assert.Equal("Endpoint '/{p:int}' with route pattern '/{p:int}' was rejected by constraint 'p':'Microsoft.AspNetCore.Routing.Constraints.IntRouteConstraint' with value 'One' for the request path '/One'", log.Message); + }, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidateNotValid, log.EventId); + Assert.Equal("Endpoint '/{p:int}' with route pattern '/{p:int}' is not valid for the request path '/One'", log.Message); + }, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidateRejectedByComplexSegment, log.EventId); + Assert.Equal("Endpoint '/x-{id}-y' with route pattern '/x-{id}-y' was rejected by complex segment 'x-{id}-y' for the request path '/One'", log.Message); + }, + (log) => + { + Assert.Equal(DfaMatcher.EventIds.CandidateNotValid, log.EventId); + Assert.Equal("Endpoint '/x-{id}-y' with route pattern '/x-{id}-y' is not valid for the request path '/One'", log.Message); + }); } private (HttpContext httpContext, EndpointSelectorContext context) CreateContext() diff --git a/test/Microsoft.AspNetCore.Routing.Tests/RouterMiddlewareTest.cs b/test/Microsoft.AspNetCore.Routing.Tests/RouterMiddlewareTest.cs index 7f6bd73963..3df8f6ad48 100644 --- a/test/Microsoft.AspNetCore.Routing.Tests/RouterMiddlewareTest.cs +++ b/test/Microsoft.AspNetCore.Routing.Tests/RouterMiddlewareTest.cs @@ -16,7 +16,7 @@ namespace Microsoft.AspNetCore.Routing public async Task Invoke_LogsCorrectValues_WhenNotHandled() { // Arrange - var expectedMessage = "Request did not match any routes."; + var expectedMessage = "Request did not match any routes"; var isHandled = false; var sink = new TestSink(