Add logging (#467)

Addresses #439

src/Microsoft.AspNetCore.Dispatcher/DispatcherLoggerExtensions.cs

@@ -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<ILogger, string, Exception> _ambiguousEndpoints = LoggerMessage.Define<string>(
-            LogLevel.Error,
-            new EventId(1, "AmbiguousEndpoints"),
-            "Request matched multiple endpoints resulting in ambiguity. Matching endpoints: {AmbiguousEndpoints}");
-
-        // Unique match found
-        private static readonly Action<ILogger, string, Exception> _endpointMatched = LoggerMessage.Define<string>(
-            LogLevel.Information,
-            new EventId(1, "EndpointMatched"),
-            "Request matched endpoint: {endpointName}");
-
-        private static readonly Action<ILogger, PathString, Exception> _noEndpointsMatched = LoggerMessage.Define<PathString>(
-            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);
-        }
-    }
-}

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);

src/Microsoft.AspNetCore.Dispatcher/EndpointMiddleware.cs

@@ -42,14 +42,15 @@ namespace Microsoft.AspNetCore.Dispatcher
             var feature = httpContext.Features.Get<IDispatcherFeature>();
             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;

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<Endpoint>();
@@ -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<ILoggerFactory>().CreateLogger(GetType());
+                }
+            }
+        }
     }
 }

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<ILogger, string, Exception> _ambiguousEndpoints = LoggerMessage.Define<string>(
+            LogLevel.Error,
+            new EventId(0, "AmbiguousEndpoints"),
+            "Request matched multiple endpoints resulting in ambiguity. Matching endpoints: {AmbiguousEndpoints}");
+
+        private static readonly Action<ILogger, PathString, Exception> _noEndpointsMatched = LoggerMessage.Define<PathString>(
+            LogLevel.Debug,
+            new EventId(1, "NoEndpointsMatched"),
+            "No endpoints matched the current request path '{PathString}'.");
+
+        private static readonly Action<ILogger, string, Exception> _requestShortCircuitedMatcherBase = LoggerMessage.Define<string>(
+            LogLevel.Information,
+            new EventId(2, "RequestShortCircuited_MatcherBase"),
+            "The current request '{RequestPath}' was short circuited.");
+
+        private static readonly Action<ILogger, string, Exception> _endpointMatchedMatcherBase = LoggerMessage.Define<string>(
+            LogLevel.Information,
+            new EventId(3, "EndpointMatched_MatcherBase"),
+            "Request matched endpoint '{endpointName}'.");
+
+        // DispatcherMiddleware
+        private static readonly Action<ILogger, Type, Exception> _handlerNotCreated = LoggerMessage.Define<Type>(
+            LogLevel.Error,
+            new EventId(0, "HandlerNotCreated"),
+            "A handler could not be created for '{MatcherType}'.");
+
+        private static readonly Action<ILogger, string, Exception> _requestShortCircuitedDispatcherMiddleware = LoggerMessage.Define<string>(
+            LogLevel.Information,
+            new EventId(1, "RequestShortCircuited_DispatcherMiddleware"),
+            "The current request '{RequestPath}' was short circuited.");
+
+        private static readonly Action<ILogger, string, Exception> _endpointMatchedDispatcherMiddleware = LoggerMessage.Define<string>(
+            LogLevel.Information,
+            new EventId(2, "EndpointMatched_DispatcherMiddleware"),
+            "Request matched endpoint '{endpointName}'.");
+
+        private static readonly Action<ILogger, IMatcher, Exception> _noEndpointsMatchedMatcher = LoggerMessage.Define<IMatcher>(
+            LogLevel.Debug,
+            new EventId(3, "NoEndpointsMatchedMatcher"),
+            "No endpoints matched matcher '{Matcher}'.");
+
+        //EndpointMiddleware
+        private static readonly Action<ILogger, string, Exception> _executingEndpoint = LoggerMessage.Define<string>(
+            LogLevel.Information,
+            new EventId(0, "ExecutingEndpoint"),
+            "Executing endpoint '{EndpointName}'.");
+
+        private static readonly Action<ILogger, string, Exception> _executedEndpoint = LoggerMessage.Define<string>(
+            LogLevel.Information,
+            new EventId(1, "ExecutedEndpoint"),
+            "Executed endpoint '{EndpointName}'.");
+
+        // HttpMethodEndpointSelector
+        private static readonly Action<ILogger, string, Exception> _noHttpMethodFound = LoggerMessage.Define<string>(
+            LogLevel.Information,
+            new EventId(0, "NoHttpMethodFound"),
+            "No HTTP method specified for endpoint '{EndpointName}'.");
+
+        private static readonly Action<ILogger, string, string, Exception> _requestMethodMatchedEndpointMethod = LoggerMessage.Define<string, string>(
+            LogLevel.Information,
+            new EventId(1, "RequestMethodMatchedEndpointMethod"),
+            "Request method matched HTTP method '{Method}' for endpoint '{EndpointName}'.");
+
+        private static readonly Action<ILogger, string, string, string, Exception> _requestMethodDidNotMatchEndpointMethod = LoggerMessage.Define<string, string, string>(
+            LogLevel.Information,
+            new EventId(2, "RequestMethodDidNotMatchEndpointMethod"),
+            "Request method '{RequestMethod}' did not match HTTP method '{EndpointMethod}' for endpoint '{EndpointName}'.");
+
+        private static readonly Action<ILogger, string, Exception> _noEndpointMatchedRequestMethod = LoggerMessage.Define<string>(
+            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);
+        }
+    }
+}

src/Microsoft.AspNetCore.Dispatcher/MatcherBase.cs

@@ -25,7 +25,6 @@ namespace Microsoft.AspNetCore.Dispatcher
         private bool _selectorsInitialized;
         private readonly Func<object> _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:

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;
                         }
 

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<ILogger, string, Exception> _requestShortCircuited = LoggerMessage.Define<string>(
+            LogLevel.Information,
+            new EventId(3, "RequestShortCircuited"),
+            "The current request '{RequestPath}' was short circuited.");
+
         private static readonly Action<ILogger, string, string, Exception> _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,

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<Endpoint> 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<EndpointSelector>()

test/Microsoft.AspNetCore.Dispatcher.Test/Microsoft.AspNetCore.Dispatcher.Test.csproj

@@ -11,6 +11,8 @@
 
   <ItemGroup>
     <PackageReference Include="Microsoft.AspNetCore.Http" />
+    <PackageReference Include="Microsoft.Extensions.DependencyInjection" />
+    <PackageReference Include="Microsoft.Extensions.Logging" />
   </ItemGroup>
   
 </Project>