Merge branch 'MarcDenman-feature/logging' into develop

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}");
-
+                    await _next.Invoke(context);
-                    _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);
-                    await _next.Invoke(context);
-                _logger.TraceInvokeNextCompleted();
-                _logger.TraceMiddlewareCompleted();
             }
         }
 

src/Ocelot/Authorisation/Middleware/AuthorisationMiddleware.cs

@@ -33,8 +33,6 @@ namespace Ocelot.Authorisation.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogDebug("started authorisation");
-
             if (IsAuthenticatedRoute(DownstreamRoute.ReRoute))
             {
                 _logger.LogDebug("route is authenticated scopes must be checked");
@@ -73,7 +71,7 @@ namespace Ocelot.Authorisation.Middleware
 
                 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;
@@ -81,30 +79,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

@@ -183,6 +183,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

@@ -30,8 +30,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);
 
@@ -53,11 +51,7 @@ namespace Ocelot.DownstreamUrlCreator.Middleware
 
             _logger.LogDebug("downstream url is {downstreamUrl.Data.Value}", DownstreamRequest.RequestUri);
 
-            _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.SetHeadersOnDownstreamRequest(DownstreamRoute.ReRoute.ClaimsToHeaders, context.User.Claims, DownstreamRequest);
 
                 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,6 +39,7 @@ 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;
             }
@@ -52,23 +52,19 @@ namespace Ocelot.LoadBalancer.Middleware
             }
             DownstreamRequest.RequestUri = uriBuilder.Uri;
 
-            _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,34 @@
+using System;
+using Microsoft.AspNetCore.Http;
+using Microsoft.Extensions.DiagnosticAdapter;
+
+namespace Ocelot.Logging
+{
+    public class OcelotDiagnosticListener
+    {
+        private IOcelotLogger _logger;
+
+        public OcelotDiagnosticListener(IOcelotLoggerFactory factory)
+        {
+            _logger = factory.CreateLogger<OcelotDiagnosticListener>();
+        }
+
+        [DiagnosticName("Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareStarting")]
+        public virtual void OnMiddlewareStarting(HttpContext httpContext, string name)
+        {
+            _logger.LogTrace($"MiddlewareStarting: {name}; {httpContext.Request.Path}");
+        }
+
+        [DiagnosticName("Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareException")]
+        public virtual void OnMiddlewareException(Exception exception, string name)
+        {
+            _logger.LogTrace($"MiddlewareException: {name}; {exception.Message}");
+        }
+
+        [DiagnosticName("Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareFinished")]
+        public virtual void OnMiddlewareFinished(HttpContext httpContext, string name)
+        {
+            _logger.LogTrace($"MiddlewareFinished: {name}; {httpContext.Response.StatusCode}");
+        }
+    }
+}

src/Ocelot/Logging/OcelotLoggerExtensions.cs

@@ -1,29 +0,0 @@
-using System;
-using System.Collections.Generic;
-using System.Text;
-
-namespace Ocelot.Logging
-{
-    public static class OcelotLoggerExtensions
-    {
-        public static void TraceMiddlewareEntry(this IOcelotLogger logger)
-        {
-            logger.LogTrace($"entered {logger.Name}");
-        }
-
-        public static void TraceInvokeNext(this IOcelotLogger logger)
-        {
-            logger.LogTrace($"invoking next middleware from {logger.Name}");
-        }
-
-        public static void TraceInvokeNextCompleted(this IOcelotLogger logger)
-        {
-            logger.LogTrace($"returned to {logger.Name} after next middleware completed");
-        }
-
-        public static void TraceMiddlewareCompleted(this IOcelotLogger logger)
-        {
-            logger.LogTrace($"completed {logger.Name}");
-        }
-    }
-}

src/Ocelot/Middleware/OcelotMiddlewareExtensions.cs

@@ -1,4 +1,5 @@
 using System.Collections.Generic;
+using System.Diagnostics;
 using IdentityServer4.AccessTokenValidation;
 using Microsoft.AspNetCore.Builder;
 using Ocelot.Authentication.Middleware;
@@ -8,6 +9,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 +55,8 @@ namespace Ocelot.Middleware
         {
             await CreateAdministrationArea(builder);
 
+            ConfigureDiagnosticListener(builder);
+
             // This is registered to catch any global exceptions that are not handled
             builder.UseExceptionHandlerMiddleware();
 
@@ -205,5 +209,22 @@ namespace Ocelot.Middleware
                 builder.Use(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 = (IHostingEnvironment)builder.ApplicationServices.GetService(typeof(IHostingEnvironment));
+
+            //https://github.com/TomPallister/Ocelot/pull/87 not sure why only for dev envs and marc disapeered so just merging and maybe change one day?
+            if (!env.IsProduction())
+             {
+                 var listener = (OcelotDiagnosticListener)builder.ApplicationServices.GetService(typeof(OcelotDiagnosticListener));
+                 var diagnosticListener = (DiagnosticListener)builder.ApplicationServices.GetService(typeof(DiagnosticListener));
+                 diagnosticListener.SubscribeWithAdapter(listener);
+             }
+         }
     }
 }

src/Ocelot/Ocelot.csproj

@@ -26,10 +26,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.SetQueriesOnDownstreamRequest(DownstreamRoute.ReRoute.ClaimsToQueries, context.User.Claims, DownstreamRequest);
 
@@ -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,14 @@ 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();
+                await _next.Invoke(context);
                 return;
             }
             // compute identity from request
@@ -52,11 +48,9 @@ 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();
+                await _next.Invoke(context);
                 return;
             }
 
@@ -78,7 +72,6 @@ namespace Ocelot.RateLimit.Middleware
                     var retrystring = retryAfter.ToString(System.Globalization.CultureInfo.InvariantCulture);
                     // break execution
                     await ReturnQuotaExceededResponse(context, options, retrystring);
-                    _logger.TraceMiddlewareCompleted();
 
                     return;
                 }
@@ -91,10 +84,7 @@ namespace Ocelot.RateLimit.Middleware
                 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

@@ -20,7 +20,7 @@ namespace Ocelot.RequestId.Middleware
         public RequestIdMiddleware(RequestDelegate next,
             IOcelotLoggerFactory loggerFactory,
             IRequestScopedDataRepository requestScopedDataRepository)
-            :base(requestScopedDataRepository)
+            : base(requestScopedDataRepository)
         {
             _next = next;
             _logger = loggerFactory.CreateLogger<RequestIdMiddleware>();
@@ -29,14 +29,8 @@ namespace Ocelot.RequestId.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.TraceMiddlewareEntry();
-
             SetOcelotRequestId(context);
-
+            await _next.Invoke(context);
-            _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();
+            await _next.Invoke(context);
-            _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)

test/Ocelot.ManualTest/appsettings.json

@@ -2,7 +2,7 @@
   "Logging": {
     "IncludeScopes": true,
     "LogLevel": {
-      "Default": "Trace",
+      "Default": "Information",
       "System": "Information",
       "Microsoft": "Information"
     }