From bdbe922b22f3af222289ea53a3790adc04479206 Mon Sep 17 00:00:00 2001 From: Jass Bagga Date: Thu, 12 Oct 2017 14:23:01 -0700 Subject: [PATCH] Add logging (#467) Addresses #439 --- .../DispatcherLoggerExtensions.cs | 44 ----- .../DispatcherMiddleware.cs | 8 +- .../EndpointMiddleware.cs | 5 +- .../HttpMethodEndpointSelector.cs | 44 +++++ .../LoggerExtensions.cs | 159 ++++++++++++++++++ .../MatcherBase.cs | 4 +- .../Dispatcher/TreeMatcher.cs | 1 + .../Logging/TreeRouterLoggerExtensions.cs | 13 ++ .../HttpMethodEndpointSelectorTest.cs | 6 + ...icrosoft.AspNetCore.Dispatcher.Test.csproj | 2 + 10 files changed, 236 insertions(+), 50 deletions(-) delete mode 100644 src/Microsoft.AspNetCore.Dispatcher/DispatcherLoggerExtensions.cs create mode 100644 src/Microsoft.AspNetCore.Dispatcher/LoggerExtensions.cs diff --git a/src/Microsoft.AspNetCore.Dispatcher/DispatcherLoggerExtensions.cs b/src/Microsoft.AspNetCore.Dispatcher/DispatcherLoggerExtensions.cs deleted file mode 100644 index 4f8dd9f631..0000000000 --- a/src/Microsoft.AspNetCore.Dispatcher/DispatcherLoggerExtensions.cs +++ /dev/null @@ -1,44 +0,0 @@ -// Copyright (c) .NET Foundation. All rights reserved. -// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. - -using System; -using Microsoft.AspNetCore.Http; -using Microsoft.Extensions.Logging; - -namespace Microsoft.AspNetCore.Dispatcher -{ - internal static class DispatcherLoggerExtensions - { - // Too many matches - private static readonly Action _ambiguousEndpoints = LoggerMessage.Define( - LogLevel.Error, - new EventId(1, "AmbiguousEndpoints"), - "Request matched multiple endpoints resulting in ambiguity. Matching endpoints: {AmbiguousEndpoints}"); - - // Unique match found - private static readonly Action _endpointMatched = LoggerMessage.Define( - LogLevel.Information, - new EventId(1, "EndpointMatched"), - "Request matched endpoint: {endpointName}"); - - private static readonly Action _noEndpointsMatched = LoggerMessage.Define( - LogLevel.Debug, - new EventId(2, "NoEndpointsMatched"), - "No endpoints matched the current request path: {PathString}"); - - public static void AmbiguousEndpoints(this ILogger logger, string ambiguousEndpoints) - { - _ambiguousEndpoints(logger, ambiguousEndpoints, null); - } - - public static void EndpointMatched(this ILogger logger, Endpoint endpoint) - { - _endpointMatched(logger, endpoint.DisplayName ?? "Unnamed endpoint", null); - } - - public static void NoEndpointsMatched(this ILogger logger, PathString pathString) - { - _noEndpointsMatched(logger, pathString, null); - } - } -} diff --git a/src/Microsoft.AspNetCore.Dispatcher/DispatcherMiddleware.cs b/src/Microsoft.AspNetCore.Dispatcher/DispatcherMiddleware.cs index c13ad2fefd..b93d908207 100644 --- a/src/Microsoft.AspNetCore.Dispatcher/DispatcherMiddleware.cs +++ b/src/Microsoft.AspNetCore.Dispatcher/DispatcherMiddleware.cs @@ -53,24 +53,28 @@ namespace Microsoft.AspNetCore.Dispatcher feature.Values = context.Values; await context.ShortCircuit(httpContext); + + _logger.RequestShortCircuitedDispatcherMiddleware(context); return; } if (context.Endpoint != null) { - _logger.LogInformation("Matched endpoint {Endpoint}", context.Endpoint.DisplayName); - + _logger.EndpointMatchedDispatcherMiddleware(context.Endpoint); feature.Endpoint = context.Endpoint; feature.Values = context.Values; feature.Handler = entry.HandlerFactory.CreateHandler(feature.Endpoint); if (feature.Handler == null) { + _logger.HandlerNotCreated(entry); throw new InvalidOperationException("Couldn't create a handler, that's bad."); } break; } + + _logger.NoEndpointsMatchedMatcher(entry.Matcher); } await _next(httpContext); diff --git a/src/Microsoft.AspNetCore.Dispatcher/EndpointMiddleware.cs b/src/Microsoft.AspNetCore.Dispatcher/EndpointMiddleware.cs index 48b5731475..b86c713210 100644 --- a/src/Microsoft.AspNetCore.Dispatcher/EndpointMiddleware.cs +++ b/src/Microsoft.AspNetCore.Dispatcher/EndpointMiddleware.cs @@ -42,14 +42,15 @@ namespace Microsoft.AspNetCore.Dispatcher var feature = httpContext.Features.Get(); if (feature.Handler != null) { - _logger.LogInformation("Executing endpoint {Endpoint}", feature.Endpoint.DisplayName); + _logger.ExecutingEndpoint(feature.Endpoint); + try { await feature.Handler(_next)(httpContext); } finally { - _logger.LogInformation("Executed endpoint {Endpoint}", feature.Endpoint.DisplayName); + _logger.ExecutedEndpoint(feature.Endpoint); } return; diff --git a/src/Microsoft.AspNetCore.Dispatcher/HttpMethodEndpointSelector.cs b/src/Microsoft.AspNetCore.Dispatcher/HttpMethodEndpointSelector.cs index 6045f1fb9a..f25e94d488 100644 --- a/src/Microsoft.AspNetCore.Dispatcher/HttpMethodEndpointSelector.cs +++ b/src/Microsoft.AspNetCore.Dispatcher/HttpMethodEndpointSelector.cs @@ -3,12 +3,25 @@ using System; using System.Collections.Generic; +using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.Dispatcher { public class HttpMethodEndpointSelector : EndpointSelector { + private object _lock; + private bool _servicesInitialized; + + public HttpMethodEndpointSelector() + { + _lock = new object(); + } + + protected ILogger Logger { get; private set; } + public override async Task SelectAsync(EndpointSelectorContext context) { if (context == null) @@ -16,6 +29,8 @@ namespace Microsoft.AspNetCore.Dispatcher throw new ArgumentNullException(nameof(context)); } + EnsureServicesInitialized(context); + var snapshot = context.CreateSnapshot(); var fallbackEndpoints = new List(); @@ -25,16 +40,20 @@ namespace Microsoft.AspNetCore.Dispatcher if (endpoint == null || endpoint.HttpMethod == null) { // No metadata. + Logger.NoHttpMethodFound(context.Endpoints[i]); + fallbackEndpoints.Add(context.Endpoints[i]); context.Endpoints.RemoveAt(i); } else if (string.Equals(endpoint.HttpMethod, context.HttpContext.Request.Method, StringComparison.OrdinalIgnoreCase)) { // The request method matches the endpoint's HTTP method. + Logger.RequestMethodMatchedEndpointMethod(endpoint.HttpMethod, context.Endpoints[i]); } else { // Not a match. + Logger.RequestMethodDidNotMatchEndpointMethod(context.HttpContext.Request.Method, endpoint.HttpMethod, context.Endpoints[i]); context.Endpoints.RemoveAt(i); } } @@ -45,8 +64,11 @@ namespace Microsoft.AspNetCore.Dispatcher if (context.Endpoints.Count == 0) { + Logger.NoEndpointMatchedRequestMethod(context.HttpContext.Request.Method); + // Nothing matched, do the fallback. context.RestoreSnapshot(snapshot); + context.Endpoints.Clear(); for (var i = 0; i < fallbackEndpoints.Count; i++) @@ -57,5 +79,27 @@ namespace Microsoft.AspNetCore.Dispatcher await context.InvokeNextAsync(); } } + + protected void EnsureServicesInitialized(EndpointSelectorContext context) + { + if (Volatile.Read(ref _servicesInitialized)) + { + return; + } + + EnsureServicesInitializedSlow(context); + } + + private void EnsureServicesInitializedSlow(EndpointSelectorContext context) + { + lock (_lock) + { + if (!Volatile.Read(ref _servicesInitialized)) + { + var services = context.HttpContext.RequestServices; + Logger = services.GetRequiredService().CreateLogger(GetType()); + } + } + } } } diff --git a/src/Microsoft.AspNetCore.Dispatcher/LoggerExtensions.cs b/src/Microsoft.AspNetCore.Dispatcher/LoggerExtensions.cs new file mode 100644 index 0000000000..b9d91cba8e --- /dev/null +++ b/src/Microsoft.AspNetCore.Dispatcher/LoggerExtensions.cs @@ -0,0 +1,159 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. + +using System; +using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.Logging; + +namespace Microsoft.AspNetCore.Dispatcher +{ + internal static class LoggerExtensions + { + // MatcherBase + private static readonly Action _ambiguousEndpoints = LoggerMessage.Define( + LogLevel.Error, + new EventId(0, "AmbiguousEndpoints"), + "Request matched multiple endpoints resulting in ambiguity. Matching endpoints: {AmbiguousEndpoints}"); + + private static readonly Action _noEndpointsMatched = LoggerMessage.Define( + LogLevel.Debug, + new EventId(1, "NoEndpointsMatched"), + "No endpoints matched the current request path '{PathString}'."); + + private static readonly Action _requestShortCircuitedMatcherBase = LoggerMessage.Define( + LogLevel.Information, + new EventId(2, "RequestShortCircuited_MatcherBase"), + "The current request '{RequestPath}' was short circuited."); + + private static readonly Action _endpointMatchedMatcherBase = LoggerMessage.Define( + LogLevel.Information, + new EventId(3, "EndpointMatched_MatcherBase"), + "Request matched endpoint '{endpointName}'."); + + // DispatcherMiddleware + private static readonly Action _handlerNotCreated = LoggerMessage.Define( + LogLevel.Error, + new EventId(0, "HandlerNotCreated"), + "A handler could not be created for '{MatcherType}'."); + + private static readonly Action _requestShortCircuitedDispatcherMiddleware = LoggerMessage.Define( + LogLevel.Information, + new EventId(1, "RequestShortCircuited_DispatcherMiddleware"), + "The current request '{RequestPath}' was short circuited."); + + private static readonly Action _endpointMatchedDispatcherMiddleware = LoggerMessage.Define( + LogLevel.Information, + new EventId(2, "EndpointMatched_DispatcherMiddleware"), + "Request matched endpoint '{endpointName}'."); + + private static readonly Action _noEndpointsMatchedMatcher = LoggerMessage.Define( + LogLevel.Debug, + new EventId(3, "NoEndpointsMatchedMatcher"), + "No endpoints matched matcher '{Matcher}'."); + + //EndpointMiddleware + private static readonly Action _executingEndpoint = LoggerMessage.Define( + LogLevel.Information, + new EventId(0, "ExecutingEndpoint"), + "Executing endpoint '{EndpointName}'."); + + private static readonly Action _executedEndpoint = LoggerMessage.Define( + LogLevel.Information, + new EventId(1, "ExecutedEndpoint"), + "Executed endpoint '{EndpointName}'."); + + // HttpMethodEndpointSelector + private static readonly Action _noHttpMethodFound = LoggerMessage.Define( + LogLevel.Information, + new EventId(0, "NoHttpMethodFound"), + "No HTTP method specified for endpoint '{EndpointName}'."); + + private static readonly Action _requestMethodMatchedEndpointMethod = LoggerMessage.Define( + LogLevel.Information, + new EventId(1, "RequestMethodMatchedEndpointMethod"), + "Request method matched HTTP method '{Method}' for endpoint '{EndpointName}'."); + + private static readonly Action _requestMethodDidNotMatchEndpointMethod = LoggerMessage.Define( + LogLevel.Information, + new EventId(2, "RequestMethodDidNotMatchEndpointMethod"), + "Request method '{RequestMethod}' did not match HTTP method '{EndpointMethod}' for endpoint '{EndpointName}'."); + + private static readonly Action _noEndpointMatchedRequestMethod = LoggerMessage.Define( + LogLevel.Information, + new EventId(3, "NoEndpointMatchedRequestMethod"), + "No endpoint matched request method '{Method}'."); + + public static void AmbiguousEndpoints(this ILogger logger, string ambiguousEndpoints) + { + _ambiguousEndpoints(logger, ambiguousEndpoints, null); + } + + public static void EndpointMatchedMatcherBase(this ILogger logger, Endpoint endpoint) + { + _endpointMatchedMatcherBase(logger, endpoint.DisplayName ?? "Unnamed endpoint", null); + } + + public static void NoEndpointsMatched(this ILogger logger, PathString pathString) + { + _noEndpointsMatched(logger, pathString, null); + } + + public static void RequestShortCircuitedMatcherBase(this ILogger logger, MatcherContext matcherContext) + { + var requestPath = matcherContext.HttpContext.Request.Path; + _requestShortCircuitedMatcherBase(logger, requestPath, null); + } + + public static void EndpointMatchedDispatcherMiddleware(this ILogger logger, Endpoint endpoint) + { + _endpointMatchedDispatcherMiddleware(logger, endpoint.DisplayName ?? "Unnamed endpoint", null); + } + + public static void RequestShortCircuitedDispatcherMiddleware(this ILogger logger, MatcherContext matcherContext) + { + var requestPath = matcherContext.HttpContext.Request.Path; + _requestShortCircuitedDispatcherMiddleware(logger, requestPath, null); + } + + public static void HandlerNotCreated(this ILogger logger, MatcherEntry matcher) + { + var matcherType = matcher.GetType(); + _handlerNotCreated(logger, matcherType, null); + } + + public static void NoEndpointsMatchedMatcher(this ILogger logger, IMatcher matcher) + { + _noEndpointsMatchedMatcher(logger, matcher, null); + } + + public static void ExecutingEndpoint(this ILogger logger, Endpoint endpoint) + { + _executingEndpoint(logger, endpoint.DisplayName ?? "Unnamed endpoint", null); + } + + public static void ExecutedEndpoint(this ILogger logger, Endpoint endpoint) + { + _executedEndpoint(logger, endpoint.DisplayName ?? "Unnamed endpoint", null); + } + + public static void NoHttpMethodFound(this ILogger logger, Endpoint endpoint) + { + _noHttpMethodFound(logger, endpoint.DisplayName ?? "Unnamed endpoint", null); + } + + public static void RequestMethodMatchedEndpointMethod(this ILogger logger, string httpMethod, Endpoint endpoint) + { + _requestMethodMatchedEndpointMethod(logger, httpMethod, endpoint.DisplayName ?? "Unnamed endpoint", null); + } + + public static void RequestMethodDidNotMatchEndpointMethod(this ILogger logger, string requestMethod, string endpointMethod, Endpoint endpoint) + { + _requestMethodDidNotMatchEndpointMethod(logger, requestMethod, endpointMethod, endpoint.DisplayName ?? "Unnamed endpoint", null); + } + + public static void NoEndpointMatchedRequestMethod(this ILogger logger, string requestMethod) + { + _noEndpointMatchedRequestMethod(logger, requestMethod, null); + } + } +} diff --git a/src/Microsoft.AspNetCore.Dispatcher/MatcherBase.cs b/src/Microsoft.AspNetCore.Dispatcher/MatcherBase.cs index 5f9edd8cfb..45228ca4e0 100644 --- a/src/Microsoft.AspNetCore.Dispatcher/MatcherBase.cs +++ b/src/Microsoft.AspNetCore.Dispatcher/MatcherBase.cs @@ -25,7 +25,6 @@ namespace Microsoft.AspNetCore.Dispatcher private bool _selectorsInitialized; private readonly Func _selectorInitializer; - public MatcherBase() { _lock = new object(); @@ -137,6 +136,7 @@ namespace Microsoft.AspNetCore.Dispatcher if (selectorContext.ShortCircuit != null) { context.ShortCircuit = selectorContext.ShortCircuit; + Logger.RequestShortCircuitedMatcherBase(context); return; } @@ -149,7 +149,7 @@ namespace Microsoft.AspNetCore.Dispatcher case 1: context.Endpoint = selectorContext.Endpoints[0]; - Logger.EndpointMatched(context.Endpoint); + Logger.EndpointMatchedMatcherBase(context.Endpoint); return; default: diff --git a/src/Microsoft.AspNetCore.Routing/Dispatcher/TreeMatcher.cs b/src/Microsoft.AspNetCore.Routing/Dispatcher/TreeMatcher.cs index 68e0c44515..3b87455ac9 100644 --- a/src/Microsoft.AspNetCore.Routing/Dispatcher/TreeMatcher.cs +++ b/src/Microsoft.AspNetCore.Routing/Dispatcher/TreeMatcher.cs @@ -76,6 +76,7 @@ namespace Microsoft.AspNetCore.Routing.Dispatcher await SelectEndpointAsync(context, (Endpoint[])entry.Tag); if (context.ShortCircuit != null) { + Logger.RequestShortCircuited(context); return; } diff --git a/src/Microsoft.AspNetCore.Routing/Logging/TreeRouterLoggerExtensions.cs b/src/Microsoft.AspNetCore.Routing/Logging/TreeRouterLoggerExtensions.cs index 3f6af8e5dc..c52635ec8c 100644 --- a/src/Microsoft.AspNetCore.Routing/Logging/TreeRouterLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Routing/Logging/TreeRouterLoggerExtensions.cs @@ -2,12 +2,19 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; +using Microsoft.AspNetCore.Dispatcher; using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.Routing.Logging { internal static class TreeRouterLoggerExtensions { + // TreeMatcher + private static readonly Action _requestShortCircuited = LoggerMessage.Define( + LogLevel.Information, + new EventId(3, "RequestShortCircuited"), + "The current request '{RequestPath}' was short circuited."); + private static readonly Action _matchedRoute; static TreeRouterLoggerExtensions() @@ -18,6 +25,12 @@ namespace Microsoft.AspNetCore.Routing.Logging "Request successfully matched the route with name '{RouteName}' and template '{RouteTemplate}'."); } + public static void RequestShortCircuited(this ILogger logger, MatcherContext matcherContext) + { + var requestPath = matcherContext.HttpContext.Request.Path; + _requestShortCircuited(logger, requestPath, null); + } + public static void MatchedRoute( this ILogger logger, string routeName, diff --git a/test/Microsoft.AspNetCore.Dispatcher.Test/HttpMethodEndpointSelectorTest.cs b/test/Microsoft.AspNetCore.Dispatcher.Test/HttpMethodEndpointSelectorTest.cs index 76e779d24c..19d1cd43ae 100644 --- a/test/Microsoft.AspNetCore.Dispatcher.Test/HttpMethodEndpointSelectorTest.cs +++ b/test/Microsoft.AspNetCore.Dispatcher.Test/HttpMethodEndpointSelectorTest.cs @@ -5,6 +5,7 @@ using System.Collections.Generic; using System.Linq; using System.Threading.Tasks; using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.DependencyInjection; using Xunit; namespace Microsoft.AspNetCore.Dispatcher @@ -82,8 +83,13 @@ namespace Microsoft.AspNetCore.Dispatcher private (EndpointSelectorContext, EndpointSelector) CreateContextAndSelector(string httpMethod, List endpoints) { + // Add services to the collection + var serviceCollection = new ServiceCollection(); + serviceCollection.AddLogging(); + var httpContext = new DefaultHttpContext(); httpContext.Request.Method = httpMethod; + httpContext.RequestServices = serviceCollection.BuildServiceProvider(); var selector = new HttpMethodEndpointSelector(); var selectors = new List() diff --git a/test/Microsoft.AspNetCore.Dispatcher.Test/Microsoft.AspNetCore.Dispatcher.Test.csproj b/test/Microsoft.AspNetCore.Dispatcher.Test/Microsoft.AspNetCore.Dispatcher.Test.csproj index b75aac40fa..876d17b915 100644 --- a/test/Microsoft.AspNetCore.Dispatcher.Test/Microsoft.AspNetCore.Dispatcher.Test.csproj +++ b/test/Microsoft.AspNetCore.Dispatcher.Test/Microsoft.AspNetCore.Dispatcher.Test.csproj @@ -11,6 +11,8 @@ + +