Change logging for various middleware

As part #35 logging is being checked. This commit changes the first four
middlewares within the pipeline to be more standardised.

Also added an extension method to easily print out the errors from a list
of errors.

src/Ocelot/Authentication/Middleware/AuthenticationMiddleware.cs

@@ -5,6 +5,7 @@ using Microsoft.AspNetCore.Http;
 using Ocelot.Authentication.Handler.Factory;
 using Ocelot.Configuration;
 using Ocelot.Errors;
+using Ocelot.Infrastructure.Extensions;
 using Ocelot.Infrastructure.RequestData;
 using Ocelot.Logging;
 using Ocelot.Middleware;
@@ -33,47 +34,57 @@ namespace Ocelot.Authentication.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogDebug("started authentication");
+            _logger.LogTrace($"entered {MiddlwareName}");
 
             if (IsAuthenticatedRoute(DownstreamRoute.ReRoute))
             {
+                _logger.LogDebug($"{context.Request.Path} is an authenticated route. {MiddlwareName} checking if client is authenticated");
+
                 var authenticationHandler = _authHandlerFactory.Get(_app, DownstreamRoute.ReRoute.AuthenticationOptions);
 
-                if (!authenticationHandler.IsError)
-                {
-                    _logger.LogDebug("calling authentication handler for ReRoute");
-
-                    await authenticationHandler.Data.Handler.Handle(context);
-                }
-                else
-                {
-                    _logger.LogDebug("there was an error getting authentication handler for ReRoute");
-
+                if (authenticationHandler.IsError)
+                {
+                    _logger.LogError($"Error getting authentication handler for {context.Request.Path}. {authenticationHandler.Errors.ToErrorString()}");
                     SetPipelineError(authenticationHandler.Errors);
-                }
+                    return;
+                }
+
+                await authenticationHandler.Data.Handler.Handle(context);
+
 
                 if (context.User.Identity.IsAuthenticated)
                 {
-                    _logger.LogDebug("the user was authenticated");
+                    _logger.LogDebug($"Client has been authenticated for {context.Request.Path}");
+                    _logger.LogTrace($"{MiddlwareName} invoking next middleware");
 
                     await _next.Invoke(context);
 
-                    _logger.LogDebug("succesfully called next middleware");
+                    _logger.LogTrace($"returned to {MiddlwareName} after next middleware completed");
+                    _logger.LogTrace($"completed {MiddlwareName}");
                 }
                 else
                 {
-                    _logger.LogDebug("the user was not authenticated");
+                    var error = new List<Error>
+                    {
+                        new UnauthenticatedError(
+                            $"Request for authenticated route {context.Request.Path} by {context.User.Identity.Name} was unauthenticated")
+                    };
 
-                    SetPipelineError(new List<Error> { new UnauthenticatedError($"Request for authenticated route {context.Request.Path} by {context.User.Identity.Name} was unauthenticated") });
+                    _logger.LogError($"Client has NOT been authenticated for {context.Request.Path} and pipeline error set. {error.ToErrorString()}");
+                    SetPipelineError(error);
+
+                    _logger.LogTrace($"completed {MiddlwareName}");
+                    return;
                 }
             }
             else
-            {
-                _logger.LogDebug("calling next middleware");
-
-                await _next.Invoke(context);
-
-                _logger.LogDebug("succesfully called next middleware");
+            {
+                _logger.LogTrace($"No authentication needed for {context.Request.Path}. Invoking next middleware from {MiddlwareName}");
+
+                await _next.Invoke(context);
+
+                _logger.LogTrace($"returned to {MiddlwareName} after next middleware completed");
+                _logger.LogTrace($"completed {MiddlwareName}");
             }
         }
 
@@ -83,3 +94,4 @@ namespace Ocelot.Authentication.Middleware
         }
     }
 }
+

src/Ocelot/DownstreamRouteFinder/Middleware/DownstreamRouteFinderMiddleware.cs

@@ -1,6 +1,9 @@
+using System.Linq;
+using System.Security.Cryptography.X509Certificates;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Http;
 using Ocelot.DownstreamRouteFinder.Finder;
+using Ocelot.Infrastructure.Extensions;
 using Ocelot.Infrastructure.RequestData;
 using Ocelot.Logging;
 using Ocelot.Middleware;
@@ -27,7 +30,7 @@ namespace Ocelot.DownstreamRouteFinder.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogDebug("started calling downstream route finder middleware");
+            _logger.LogTrace($"entered {MiddlwareName}");
 
             var upstreamUrlPath = context.Request.Path.ToString().SetLastCharacterAs('/');
 
@@ -37,7 +40,7 @@ namespace Ocelot.DownstreamRouteFinder.Middleware
 
             if (downstreamRoute.IsError)
             {
-                _logger.LogDebug("IDownstreamRouteFinder returned an error, setting pipeline error");
+                _logger.LogError($"{MiddlwareName} setting pipeline errors. IDownstreamRouteFinder returned {downstreamRoute.Errors.ToErrorString()}");
 
                 SetPipelineError(downstreamRoute.Errors);
                 return;
@@ -47,12 +50,12 @@ namespace Ocelot.DownstreamRouteFinder.Middleware
 
             SetDownstreamRouteForThisRequest(downstreamRoute.Data);
 
-            _logger.LogDebug("calling next middleware");
+            _logger.LogTrace($"invoking next middleware from {MiddlwareName}");
 
             await _next.Invoke(context);
 
-            _logger.LogDebug("succesfully called next middleware");
-
+            _logger.LogTrace($"returned to {MiddlwareName} after next middleware completed");
+            _logger.LogTrace($"completed {MiddlwareName}");
         }
     }
 }

src/Ocelot/Infrastructure/Extensions/ErrorListExtensions.cs

@@ -0,0 +1,18 @@
+using System;
+using System.Collections.Generic;
+using System.Linq;
+using System.Text;
+using Microsoft.Extensions.Primitives;
+using Ocelot.Errors;
+
+namespace Ocelot.Infrastructure.Extensions
+{
+    public static class ErrorListExtensions
+    {
+        public static string ToErrorString(this List<Error> errors)
+        {
+            var listOfErrorStrings = errors.Select(x => "Error Code: " + x.Code.ToString() + " Message: " + x.Message);
+            return string.Join(" ", listOfErrorStrings);
+        }
+     }
+}

src/Ocelot/RateLimit/Middleware/ClientRateLimitMiddleware.cs

@@ -30,12 +30,14 @@ namespace Ocelot.RateLimit.Middleware
         }
 
         public async Task Invoke(HttpContext context)
-        {
-            _logger.LogDebug("started calling RateLimit middleware");
+        {
+            _logger.LogTrace($"entered {MiddlwareName}");
+
             var options = DownstreamRoute.ReRoute.RateLimitOptions;
             // check if rate limiting is enabled
             if (!DownstreamRoute.ReRoute.EnableEndpointRateLimiting)
             {
+                _logger.LogDebug($"EndpointRateLimiting is not enabled for {DownstreamRoute.ReRoute.DownstreamPathTemplate}. Invoking next middleware from {MiddlwareName}.");
                 await _next.Invoke(context);
                 return;
             }
@@ -45,6 +47,7 @@ namespace Ocelot.RateLimit.Middleware
             // check white list
             if (IsWhitelisted(identity, options))
             {
+                _logger.LogDebug($"{DownstreamRoute.ReRoute.DownstreamPathTemplate} is white listed from rate limiting. Invoking next middleware from {MiddlwareName}.");
                 await _next.Invoke(context);
                 return;
             }
@@ -76,7 +79,12 @@ namespace Ocelot.RateLimit.Middleware
                 context.Response.OnStarting(SetRateLimitHeaders, state: headers);
             }
 
-            await _next.Invoke(context);
+            _logger.LogTrace($"invoking next middleware from {MiddlwareName}");
+
+            await _next.Invoke(context);
+
+            _logger.LogTrace($"returned to {MiddlwareName} after next middleware completed");
+            _logger.LogTrace($"completed {MiddlwareName}");
         }
 
         public virtual ClientRequestIdentity SetIdentity(HttpContext httpContext, RateLimitOptions option)

src/Ocelot/RequestId/Middleware/RequestIdMiddleware.cs

@@ -26,17 +26,18 @@ namespace Ocelot.RequestId.Middleware
 
         public async Task Invoke(HttpContext context)
         {         
-            _logger.LogDebug("started calling request id middleware");
+            _logger.LogTrace($"entered {MiddlwareName}");
 
             SetOcelotRequestId(context);
 
-            _logger.LogDebug("set request id");
+            _logger.LogDebug("set requestId");
 
-            _logger.LogDebug("calling next middleware");
+            _logger.LogTrace($"invoking next middleware from {MiddlwareName}");
 
             await _next.Invoke(context);
-            
-            _logger.LogDebug("succesfully called next middleware");
+
+            _logger.LogTrace($"returned to {MiddlwareName} after next middleware completed");
+            _logger.LogTrace($"completed {MiddlwareName}");
         }
 
         private void SetOcelotRequestId(HttpContext context)

src/Ocelot/Responder/ErrorsToHttpStatusCodeMapper.cs

@@ -27,6 +27,11 @@ namespace Ocelot.Responder
                 return new OkResponse<int>(503);
             }
 
+            if (errors.Any(e => e.Code == OcelotErrorCode.UnableToFindDownstreamRouteError))
+            {
+                return new OkResponse<int>(404);
+            }
+
             return new OkResponse<int>(404);
         }
     }