Use DiagnosticListner for middleware logging

Instead of each middleware having to log that it has started and ended,
the DianosticListner package allows for capturing of these events in a
lightwieght manner.

This commit implements this and removes unncessary logging from most
middleware.

src/Ocelot/Authentication/Middleware/AuthenticationMiddleware.cs

@@ -34,8 +34,6 @@ namespace Ocelot.Authentication.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.TraceMiddlewareEntry();
-
             if (IsAuthenticatedRoute(DownstreamRoute.ReRoute))
             {
                 _logger.LogDebug($"{context.Request.Path} is an authenticated route. {MiddlwareName} checking if client is authenticated");
@@ -46,7 +44,6 @@ namespace Ocelot.Authentication.Middleware
                 {
                     _logger.LogError($"Error getting authentication handler for {context.Request.Path}. {authenticationHandler.Errors.ToErrorString()}");
                     SetPipelineError(authenticationHandler.Errors);
-                    _logger.TraceMiddlewareCompleted();
                     return;
                 }
 
@@ -56,11 +53,7 @@ namespace Ocelot.Authentication.Middleware
                 if (context.User.Identity.IsAuthenticated)
                 {
                     _logger.LogDebug($"Client has been authenticated for {context.Request.Path}");
-
-                    _logger.TraceInvokeNext();
                     await _next.Invoke(context);
-                    _logger.TraceInvokeNextCompleted();
-                    _logger.TraceMiddlewareCompleted();
                 }
                 else
                 {
@@ -72,8 +65,6 @@ namespace Ocelot.Authentication.Middleware
 
                     _logger.LogError($"Client has NOT been authenticated for {context.Request.Path} and pipeline error set. {error.ToErrorString()}");
                     SetPipelineError(error);
-
-                    _logger.TraceMiddlewareCompleted();
                     return;
                 }
             }
@@ -81,10 +72,7 @@ namespace Ocelot.Authentication.Middleware
             {
                 _logger.LogTrace($"No authentication needed for {context.Request.Path}");
 
-                _logger.TraceInvokeNext();
                 await _next.Invoke(context);
-                _logger.TraceInvokeNextCompleted();
-                _logger.TraceMiddlewareCompleted();
             }
         }
 

src/Ocelot/Authorisation/Middleware/AuthorisationMiddleware.cs

@@ -29,17 +29,15 @@ namespace Ocelot.Authorisation.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogDebug("started authorisation");
-
             if (DownstreamRoute.ReRoute.IsAuthorised)
             {
-                _logger.LogDebug("route is authorised");
+                _logger.LogDebug($"{DownstreamRoute.ReRoute.DownstreamPathTemplate.Value} route requires user to be authorised");
 
                 var authorised = _authoriser.Authorise(context.User, DownstreamRoute.ReRoute.RouteClaimsRequirement);
 
                 if (authorised.IsError)
                 {
-                    _logger.LogDebug("error authorising user");
+                    _logger.LogDebug($"Error whilst authorising {context.User.Identity.Name} for {context.User.Identity.Name}. Setting pipeline error");
 
                     SetPipelineError(authorised.Errors);
                     return;
@@ -47,30 +45,23 @@ namespace Ocelot.Authorisation.Middleware
 
                 if (IsAuthorised(authorised))
                 {
-                    _logger.LogDebug("user is authorised calling next middleware");
+                    _logger.LogDebug($"{context.User.Identity.Name} has succesfully been authorised for {DownstreamRoute.ReRoute.UpstreamPathTemplate.Value}. Calling next middleware");
-
                     await _next.Invoke(context);
-
-                    _logger.LogDebug("succesfully called next middleware");
                 }
                 else
                 {
-                    _logger.LogDebug("user is not authorised setting pipeline error");
+                    _logger.LogDebug($"{context.User.Identity.Name} is not authorised to access {DownstreamRoute.ReRoute.UpstreamPathTemplate.Value}. Setting pipeline error");
 
                     SetPipelineError(new List<Error>
                     {
-                        new UnauthorisedError(
+                        new UnauthorisedError($"{context.User.Identity.Name} is not authorised to access {DownstreamRoute.ReRoute.UpstreamPathTemplate.Value}")
-                            $"{context.User.Identity.Name} unable to access {DownstreamRoute.ReRoute.UpstreamPathTemplate.Value}")
                     });
                 }
             }
             else
             {
-                _logger.LogDebug("AuthorisationMiddleware.Invoke route is not authorised calling next middleware");
+                _logger.LogDebug($"{DownstreamRoute.ReRoute.DownstreamPathTemplate.Value} route does not require user to be authorised");
-
                 await _next.Invoke(context);
-
-                _logger.LogDebug("succesfully called next middleware");
             }
         }
 

src/Ocelot/Cache/Middleware/OutputCacheMiddleware.cs

@@ -54,8 +54,6 @@ namespace Ocelot.Cache.Middleware
 
             await _next.Invoke(context);
 
-            _logger.LogDebug("succesfully called next middleware");
-
             if (PipelineError)
             {
                 _logger.LogDebug("there was a pipeline error for {downstreamUrlKey}", downstreamUrlKey);

src/Ocelot/Claims/Middleware/ClaimsBuilderMiddleware.cs

@@ -26,8 +26,6 @@ namespace Ocelot.Claims.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogDebug("started claims middleware");
-
             if (DownstreamRoute.ReRoute.ClaimsToClaims.Any())
             {
                 _logger.LogDebug("this route has instructions to convert claims to other claims");
@@ -42,12 +40,7 @@ namespace Ocelot.Claims.Middleware
                     return;
                 }
             }
-
-            _logger.LogDebug("calling next middleware");
-
             await _next.Invoke(context);
-
-            _logger.LogDebug("succesfully called next middleware");
         }
     }
 }

src/Ocelot/DependencyInjection/ServiceCollectionExtensions.cs

@@ -166,6 +166,11 @@ namespace Ocelot.DependencyInjection
             services.TryAddSingleton<IHttpContextAccessor, HttpContextAccessor>();
             services.TryAddScoped<IRequestScopedDataRepository, HttpDataRepository>();
             services.AddMemoryCache();
+
+            //Used to log the the start and ending of middleware
+            services.TryAddSingleton<OcelotDiagnosticListener>();
+            services.AddMiddlewareAnalysis();
+
             return services;
         }
     }

src/Ocelot/DownstreamRouteFinder/Middleware/DownstreamRouteFinderMiddleware.cs

@@ -30,8 +30,6 @@ namespace Ocelot.DownstreamRouteFinder.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.TraceMiddlewareEntry();
-
             var upstreamUrlPath = context.Request.Path.ToString().SetLastCharacterAs('/');
 
             _logger.LogDebug("upstream url path is {upstreamUrlPath}", upstreamUrlPath);
@@ -43,8 +41,6 @@ namespace Ocelot.DownstreamRouteFinder.Middleware
                 _logger.LogError($"{MiddlwareName} setting pipeline errors. IDownstreamRouteFinder returned {downstreamRoute.Errors.ToErrorString()}");
 
                 SetPipelineError(downstreamRoute.Errors);
-
-                _logger.TraceMiddlewareCompleted();
                 return;
             }
 
@@ -52,12 +48,7 @@ namespace Ocelot.DownstreamRouteFinder.Middleware
 
             SetDownstreamRouteForThisRequest(downstreamRoute.Data);
 
-            _logger.TraceInvokeNext();
-
             await _next.Invoke(context);
-
-            _logger.TraceInvokeNextCompleted();
-            _logger.TraceMiddlewareCompleted();
         }
     }
 }

src/Ocelot/DownstreamUrlCreator/Middleware/DownstreamUrlCreatorMiddleware.cs

@@ -29,8 +29,6 @@ namespace Ocelot.DownstreamUrlCreator.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogDebug("started calling downstream url creator middleware");
-
             var dsPath = _replacer
                 .Replace(DownstreamRoute.ReRoute.DownstreamPathTemplate, DownstreamRoute.TemplatePlaceholderNameAndValues);
 
@@ -60,11 +58,7 @@ namespace Ocelot.DownstreamUrlCreator.Middleware
 
             SetDownstreamUrlForThisRequest(dsUrl.Data.Value);
 
-            _logger.LogDebug("calling next middleware");
-
             await _next.Invoke(context);
-
-            _logger.LogDebug("succesfully called next middleware");
         }
     }
 }

src/Ocelot/Headers/Middleware/HttpRequestHeadersBuilderMiddleware.cs

@@ -26,17 +26,15 @@ namespace Ocelot.Headers.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogDebug("started calling headers builder middleware");
-
             if (DownstreamRoute.ReRoute.ClaimsToHeaders.Any())
             {
-                _logger.LogDebug("this route has instructions to convert claims to headers");
+                _logger.LogDebug($"{ DownstreamRoute.ReRoute.DownstreamPathTemplate.Value} has instructions to convert claims to headers");
 
                 var response = _addHeadersToRequest.SetHeadersOnContext(DownstreamRoute.ReRoute.ClaimsToHeaders, context);
 
                 if (response.IsError)
                 {
-                    _logger.LogDebug("there was an error setting headers on context, setting pipeline error");
+                    _logger.LogDebug("Error setting headers on context, setting pipeline error");
 
                     SetPipelineError(response.Errors);
                     return;
@@ -45,11 +43,7 @@ namespace Ocelot.Headers.Middleware
                 _logger.LogDebug("headers have been set on context");
             }
 
-            _logger.LogDebug("calling next middleware");
-
             await _next.Invoke(context);
-
-            _logger.LogDebug("succesfully called next middleware");
         }
     }
 }

src/Ocelot/LoadBalancer/Middleware/LoadBalancingMiddleware.cs

@@ -28,11 +28,10 @@ namespace Ocelot.LoadBalancer.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogDebug("started calling load balancing middleware");
-
             var loadBalancer = _loadBalancerHouse.Get(DownstreamRoute.ReRoute.ReRouteKey);
             if(loadBalancer.IsError)
             {
+                _logger.LogDebug("there was an error retriving the loadbalancer, setting pipeline error");
                 SetPipelineError(loadBalancer.Errors);
                 return;
             }
@@ -40,29 +39,26 @@ namespace Ocelot.LoadBalancer.Middleware
             var hostAndPort = await loadBalancer.Data.Lease();
             if(hostAndPort.IsError)
             {
+                _logger.LogDebug("there was an error leasing the loadbalancer, setting pipeline error");
                 SetPipelineError(hostAndPort.Errors);
                 return;
             }
 
             SetHostAndPortForThisRequest(hostAndPort.Data);
 
-            _logger.LogDebug("calling next middleware");
-
             try
             {
                 await _next.Invoke(context);
-
-                loadBalancer.Data.Release(hostAndPort.Data);
             }
             catch (Exception)
             {
-                loadBalancer.Data.Release(hostAndPort.Data);
+                _logger.LogDebug("Exception calling next middleware, exception will be thrown to global handler");
-                 
-                 _logger.LogDebug("error calling next middleware, exception will be thrown to global handler");
                 throw;
             }
-
+            finally
-            _logger.LogDebug("succesfully called next middleware");
+            {
+                loadBalancer.Data.Release(hostAndPort.Data);
+            }
         }
     }
 }

src/Ocelot/Logging/OcelotDiagnosticListener.cs

@@ -0,0 +1,27 @@
+using System;
+using Microsoft.AspNetCore.Http;
+using Microsoft.Extensions.DiagnosticAdapter;
+
+namespace Ocelot.Logging
+{
+    public class OcelotDiagnosticListener
+    {
+        [DiagnosticName("Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareStarting")]
+        public virtual void OnMiddlewareStarting(HttpContext httpContext, string name)
+        {
+            Console.WriteLine($"MiddlewareStarting: {name}; {httpContext.Request.Path}");
+        }
+
+        [DiagnosticName("Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareException")]
+        public virtual void OnMiddlewareException(Exception exception, string name)
+        {
+            Console.WriteLine($"MiddlewareException: {name}; {exception.Message}");
+        }
+
+        [DiagnosticName("Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareFinished")]
+        public virtual void OnMiddlewareFinished(HttpContext httpContext, string name)
+        {
+            Console.WriteLine($"MiddlewareFinished: {name}; {httpContext.Response.StatusCode}");
+        }
+    }
+}

src/Ocelot/Middleware/OcelotMiddlewareExtensions.cs

@@ -1,6 +1,8 @@
 using System.Collections.Generic;
+using System.Diagnostics;
 using IdentityServer4.AccessTokenValidation;
 using Microsoft.AspNetCore.Builder;
+using Microsoft.Extensions.DependencyInjection;
 using Ocelot.Authentication.Middleware;
 using Ocelot.Cache.Middleware;
 using Ocelot.Claims.Middleware;
@@ -8,6 +10,7 @@ using Ocelot.DownstreamRouteFinder.Middleware;
 using Ocelot.DownstreamUrlCreator.Middleware;
 using Ocelot.Errors.Middleware;
 using Ocelot.Headers.Middleware;
+using Ocelot.Logging;
 using Ocelot.QueryStrings.Middleware;
 using Ocelot.Request.Middleware;
 using Ocelot.Requester.Middleware;
@@ -53,6 +56,8 @@ namespace Ocelot.Middleware
         {
             await CreateAdministrationArea(builder);
 
+            ConfigureDiagnosticListener(builder);
+
             // This is registered to catch any global exceptions that are not handled
             builder.UseExceptionHandlerMiddleware();
 
@@ -155,7 +160,7 @@ namespace Ocelot.Middleware
 
             ocelotConfiguration = await configProvider.Get();
 
-            if(ocelotConfiguration == null || ocelotConfiguration.Data == null || ocelotConfiguration.IsError)
+            if (ocelotConfiguration == null || ocelotConfiguration.Data == null || ocelotConfiguration.IsError)
             {
                 throw new Exception("Unable to start Ocelot: ocelot configuration was not returned by provider.");
             }
@@ -169,7 +174,7 @@ namespace Ocelot.Middleware
 
             var identityServerConfiguration = (IIdentityServerConfiguration)builder.ApplicationServices.GetService(typeof(IIdentityServerConfiguration));
 
-            if(!string.IsNullOrEmpty(configuration.AdministrationPath) && identityServerConfiguration != null)
+            if (!string.IsNullOrEmpty(configuration.AdministrationPath) && identityServerConfiguration != null)
             {
                 var urlFinder = (IBaseUrlFinder)builder.ApplicationServices.GetService(typeof(IBaseUrlFinder));
 
@@ -177,7 +182,7 @@ namespace Ocelot.Middleware
 
                 builder.Map(configuration.AdministrationPath, app =>
                 {
-                    var identityServerUrl = $"{baseSchemeUrlAndPort}/{configuration.AdministrationPath.Remove(0,1)}";
+                    var identityServerUrl = $"{baseSchemeUrlAndPort}/{configuration.AdministrationPath.Remove(0, 1)}";
 
                     app.UseIdentityServerAuthentication(new IdentityServerAuthenticationOptions
                     {
@@ -196,6 +201,22 @@ namespace Ocelot.Middleware
             }
         }
 
+        /// <summary>
+        /// Configure a DiagnosticListener to listen for diagnostic events when the middleware starts and ends
+        /// </summary>
+        /// <param name="builder"></param>
+        private static void ConfigureDiagnosticListener(IApplicationBuilder builder)
+        {
+            
+            var env = builder.ApplicationServices.GetService<IHostingEnvironment>();
+            if (!env.IsProduction())
+            {
+                var listener = builder.ApplicationServices.GetService<OcelotDiagnosticListener>();
+                var diagnosticListener = builder.ApplicationServices.GetService<DiagnosticListener>();
+                diagnosticListener.SubscribeWithAdapter(listener);
+            }
+        }
+
         private static void UseIfNotNull(this IApplicationBuilder builder, Func<HttpContext, Func<Task>, Task> middleware)
         {
             if (middleware != null)

src/Ocelot/Ocelot.csproj

@@ -21,10 +21,12 @@
   </PropertyGroup>
 
   <ItemGroup>
+    <PackageReference Include="Microsoft.AspNetCore.MiddlewareAnalysis" Version="1.1.1" />
     <PackageReference Include="Microsoft.AspNetCore.Server.IISIntegration" Version="1.1.1" />
     <PackageReference Include="Microsoft.Extensions.Configuration.EnvironmentVariables" Version="1.1.1" />
     <PackageReference Include="Microsoft.Extensions.Configuration.FileExtensions" Version="1.1.1" />
     <PackageReference Include="Microsoft.Extensions.Configuration.Json" Version="1.1.1" />
+    <PackageReference Include="Microsoft.Extensions.DiagnosticAdapter" Version="1.1.0" />
     <PackageReference Include="Microsoft.Extensions.Logging" Version="1.1.1" />
     <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="1.1.1" />
     <PackageReference Include="Microsoft.Extensions.Logging.Debug" Version="1.1.1" />

src/Ocelot/QueryStrings/Middleware/QueryStringBuilderMiddleware.cs

@@ -26,11 +26,9 @@ namespace Ocelot.QueryStrings.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogDebug("started calling query string builder middleware");
-
             if (DownstreamRoute.ReRoute.ClaimsToQueries.Any())
             {
-                _logger.LogDebug("this route has instructions to convert claims to queries");
+                _logger.LogDebug($"{DownstreamRoute.ReRoute.DownstreamPathTemplate.Value} has instructions to convert claims to queries");
 
                 var response = _addQueriesToRequest.SetQueriesOnContext(DownstreamRoute.ReRoute.ClaimsToQueries, context);
 
@@ -43,11 +41,7 @@ namespace Ocelot.QueryStrings.Middleware
                 }
             }
 
-            _logger.LogDebug("calling next middleware");
-
             await _next.Invoke(context);
-
-            _logger.LogDebug("succesfully called next middleware");
         }
     }
 }

src/Ocelot/RateLimit/Middleware/ClientRateLimitMiddleware.cs

@@ -31,18 +31,13 @@ namespace Ocelot.RateLimit.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.TraceMiddlewareEntry();
-
             var options = DownstreamRoute.ReRoute.RateLimitOptions;
             // check if rate limiting is enabled
             if (!DownstreamRoute.ReRoute.EnableEndpointEndpointRateLimiting)
             {
                 _logger.LogDebug($"EndpointRateLimiting is not enabled for {DownstreamRoute.ReRoute.DownstreamPathTemplate}");
-
-                _logger.TraceInvokeNext();
                 await _next.Invoke(context);
-                _logger.TraceInvokeNextCompleted();
+
-                _logger.TraceMiddlewareCompleted();
                 return;
             }
             // compute identity from request
@@ -52,11 +47,8 @@ namespace Ocelot.RateLimit.Middleware
             if (IsWhitelisted(identity, options))
             {
                 _logger.LogDebug($"{DownstreamRoute.ReRoute.DownstreamPathTemplate} is white listed from rate limiting");
-
-                _logger.TraceInvokeNext();
                 await _next.Invoke(context);
-                _logger.TraceInvokeNextCompleted();
+
-                _logger.TraceMiddlewareCompleted();
                 return;
             }
 
@@ -77,21 +69,18 @@ namespace Ocelot.RateLimit.Middleware
 
                     // break execution
                     await ReturnQuotaExceededResponse(context, options, retryAfter);
-                    _logger.TraceMiddlewareCompleted();
                     return;
                 }
             }
             //set X-Rate-Limit headers for the longest period
             if (!options.DisableRateLimitHeaders)
             {
-                var headers = _processor.GetRateLimitHeaders( context,identity, options);
+                var headers = _processor.GetRateLimitHeaders(context, identity, options);
                 context.Response.OnStarting(SetRateLimitHeaders, state: headers);
             }
 
-            _logger.TraceInvokeNext();
             await _next.Invoke(context);
-            _logger.TraceInvokeNextCompleted();
+
-            _logger.TraceMiddlewareCompleted();
         }
 
         public virtual ClientRequestIdentity SetIdentity(HttpContext httpContext, RateLimitOptions option)

src/Ocelot/RequestId/Middleware/RequestIdMiddleware.cs

@@ -17,7 +17,7 @@ namespace Ocelot.RequestId.Middleware
         public RequestIdMiddleware(RequestDelegate next,
             IOcelotLoggerFactory loggerFactory,
             IRequestScopedDataRepository requestScopedDataRepository)
-            :base(requestScopedDataRepository)
+            : base(requestScopedDataRepository)
         {
             _next = next;
             _logger = loggerFactory.CreateLogger<RequestIdMiddleware>();
@@ -26,16 +26,10 @@ namespace Ocelot.RequestId.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.TraceMiddlewareEntry();
-
             SetOcelotRequestId(context);
 
             _logger.LogDebug("set requestId");
-
-            _logger.TraceInvokeNext();
             await _next.Invoke(context);
-            _logger.TraceInvokeNextCompleted();
-            _logger.TraceMiddlewareCompleted();
         }
 
         private void SetOcelotRequestId(HttpContext context)

src/Ocelot/Responder/Middleware/ResponderMiddleware.cs

@@ -34,10 +34,7 @@ namespace Ocelot.Responder.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.TraceMiddlewareEntry();
-            _logger.TraceInvokeNext();
             await _next.Invoke(context);
-            _logger.TraceInvokeNextCompleted();
 
             if (PipelineError)
             {
@@ -51,7 +48,6 @@ namespace Ocelot.Responder.Middleware
                 _logger.LogDebug("no pipeline errors, setting and returning completed response");
                 await _responder.SetResponseOnHttpContext(context, HttpResponseMessage);
             }
-            _logger.TraceMiddlewareCompleted();
         }
 
         private void SetErrorResponse(HttpContext context, List<Error> errors)