Merge pull request #70 from MarcDenman/feature/updateLogging

Update logging

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.TraceMiddlewareEntry();
 
             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);
-                }
+                    _logger.TraceMiddlewareCompleted();
+                    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}");
 
-                    await _next.Invoke(context);
-
-                    _logger.LogDebug("succesfully called next middleware");
+                    _logger.TraceInvokeNext();
+                        await _next.Invoke(context);
+                    _logger.TraceInvokeNextCompleted();
+                    _logger.TraceMiddlewareCompleted();
                 }
                 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.TraceMiddlewareCompleted();
+                    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}");
+
+                _logger.TraceInvokeNext();
+                    await _next.Invoke(context);
+                _logger.TraceInvokeNextCompleted();
+                _logger.TraceMiddlewareCompleted();
             }
         }
 
@@ -83,3 +94,4 @@ namespace Ocelot.Authentication.Middleware
         }
     }
 }
+

src/Ocelot/Configuration/Creator/FileOcelotConfigurationCreator.cs

@@ -9,6 +9,7 @@ using Ocelot.Configuration.File;
 using Ocelot.Configuration.Parser;
 using Ocelot.Configuration.Validator;
 using Ocelot.LoadBalancer.LoadBalancers;
+using Ocelot.Logging;
 using Ocelot.Requester.QoS;
 using Ocelot.Responses;
 using Ocelot.Utilities;
@@ -22,7 +23,7 @@ namespace Ocelot.Configuration.Creator
     {
         private readonly IOptions<FileConfiguration> _options;
         private readonly IConfigurationValidator _configurationValidator;
-        private readonly ILogger<FileOcelotConfigurationCreator> _logger;
+        private readonly IOcelotLogger _logger;
         private readonly ILoadBalancerFactory _loadBalanceFactory;
         private readonly ILoadBalancerHouse _loadBalancerHouse;
         private readonly IQoSProviderFactory _qoSProviderFactory;
@@ -38,8 +39,8 @@ namespace Ocelot.Configuration.Creator
 
         public FileOcelotConfigurationCreator(
             IOptions<FileConfiguration> options, 
-            IConfigurationValidator configurationValidator, 
-            ILogger<FileOcelotConfigurationCreator> logger,
+            IConfigurationValidator configurationValidator,
+            IOcelotLoggerFactory loggerFactory,
             ILoadBalancerFactory loadBalancerFactory,
             ILoadBalancerHouse loadBalancerHouse, 
             IQoSProviderFactory qoSProviderFactory, 
@@ -64,7 +65,7 @@ namespace Ocelot.Configuration.Creator
             _qosProviderHouse = qosProviderHouse;
             _options = options;
             _configurationValidator = configurationValidator;
-            _logger = logger;
+            _logger = loggerFactory.CreateLogger<FileOcelotConfigurationCreator>();
             _claimsToThingCreator = claimsToThingCreator;
             _serviceProviderConfigCreator = serviceProviderConfigCreator;
             _qosOptionsCreator = qosOptionsCreator;

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.TraceMiddlewareEntry();
 
             var upstreamUrlPath = context.Request.Path.ToString().SetLastCharacterAs('/');
 
@@ -37,9 +40,11 @@ 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);
+
+                _logger.TraceMiddlewareCompleted();
                 return;
             }
 
@@ -47,12 +52,12 @@ namespace Ocelot.DownstreamRouteFinder.Middleware
 
             SetDownstreamRouteForThisRequest(downstreamRoute.Data);
 
-            _logger.LogDebug("calling next middleware");
+            _logger.TraceInvokeNext();
 
             await _next.Invoke(context);
 
-            _logger.LogDebug("succesfully called next middleware");
-
+            _logger.TraceInvokeNextCompleted();
+            _logger.TraceMiddlewareCompleted();
         }
     }
 }

src/Ocelot/Errors/Middleware/ExceptionHandlerMiddleware.cs

@@ -6,6 +6,9 @@ using Ocelot.Logging;
 
 namespace Ocelot.Errors.Middleware
 {
+    /// <summary>
+    /// Catches all unhandled exceptions thrown by middleware, logs and returns a 500
+    /// </summary>
     public class ExceptionHandlerMiddleware 
     {
         private readonly RequestDelegate _next;

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/Logging/AspDotNetLogger.cs

@@ -0,0 +1,52 @@
+using System;
+using Microsoft.Extensions.Logging;
+using Ocelot.Infrastructure.RequestData;
+
+namespace Ocelot.Logging
+{
+    public class AspDotNetLogger : IOcelotLogger
+    {
+        private readonly ILogger _logger;
+        private readonly IRequestScopedDataRepository _scopedDataRepository;
+
+        public string Name { get; }
+
+        public AspDotNetLogger(ILogger logger, IRequestScopedDataRepository scopedDataRepository, string typeName)
+        {
+            Name = typeName;
+            _logger = logger;
+            _scopedDataRepository = scopedDataRepository;
+        }
+
+        public void LogTrace(string message, params object[] args)
+        {
+            _logger.LogTrace(GetMessageWithOcelotRequestId(message), args);
+        }
+
+        public void LogDebug(string message, params object[] args)
+        {
+            _logger.LogDebug(GetMessageWithOcelotRequestId(message), args);
+        }
+        public void LogError(string message, Exception exception)
+        {
+            _logger.LogError(GetMessageWithOcelotRequestId(message), exception);
+        }
+
+        public void LogError(string message, params object[] args)
+        {
+            _logger.LogError(GetMessageWithOcelotRequestId(message), args);
+        }
+
+        private string GetMessageWithOcelotRequestId(string message)
+        {
+            var requestId = _scopedDataRepository.Get<string>("RequestId");
+
+            if (requestId == null || requestId.IsError)
+            {
+                return $"{message} : OcelotRequestId - not set";
+            }
+
+            return $"{message} : OcelotRequestId - {requestId.Data}";
+        }
+    }
+}

src/Ocelot/Logging/AspDotNetLoggerFactory.cs

@@ -0,0 +1,23 @@
+using Microsoft.Extensions.Logging;
+using Ocelot.Infrastructure.RequestData;
+
+namespace Ocelot.Logging
+{
+    public class AspDotNetLoggerFactory : IOcelotLoggerFactory
+    {
+        private readonly ILoggerFactory _loggerFactory;
+        private readonly IRequestScopedDataRepository _scopedDataRepository;
+
+        public AspDotNetLoggerFactory(ILoggerFactory loggerFactory, IRequestScopedDataRepository scopedDataRepository)
+        {
+            _loggerFactory = loggerFactory;
+            _scopedDataRepository = scopedDataRepository;
+        }
+
+        public IOcelotLogger CreateLogger<T>()
+        {
+            var logger = _loggerFactory.CreateLogger<T>();
+            return new AspDotNetLogger(logger, _scopedDataRepository, typeof(T).Name);
+        }
+    }
+}

src/Ocelot/Logging/IOcelotLoggerFactory.cs

@@ -1,6 +1,4 @@
 using System;
-using Microsoft.Extensions.Logging;
-using Ocelot.Infrastructure.RequestData;
 
 namespace Ocelot.Logging
 {
@@ -8,62 +6,19 @@ namespace Ocelot.Logging
     {
         IOcelotLogger CreateLogger<T>();
     }
-
-    public class AspDotNetLoggerFactory : IOcelotLoggerFactory
-    {
-        private readonly ILoggerFactory _loggerFactory;
-        private readonly IRequestScopedDataRepository _scopedDataRepository;
-
-        public AspDotNetLoggerFactory(ILoggerFactory loggerFactory, IRequestScopedDataRepository scopedDataRepository)
-        {
-            _loggerFactory = loggerFactory;
-            _scopedDataRepository = scopedDataRepository;
-        }
-
-        public IOcelotLogger CreateLogger<T>()
-        {
-            var logger = _loggerFactory.CreateLogger<T>();
-            return new AspDotNetLogger(logger, _scopedDataRepository);
-        }
-    }
-
+    /// <summary>
+    /// Thin wrapper around the DotNet core logging framework, used to allow the scopedDataRepository to be injected giving access to the Ocelot RequestId
+    /// </summary>
     public interface IOcelotLogger
     {
+        void LogTrace(string message, params object[] args);
         void LogDebug(string message, params object[] args);
         void LogError(string message, Exception exception);
-    }
+        void LogError(string message, params object[] args);
 
-    public class AspDotNetLogger : IOcelotLogger
-    {
-        private readonly ILogger _logger;
-        private readonly IRequestScopedDataRepository _scopedDataRepository;
-
-        public AspDotNetLogger(ILogger logger, IRequestScopedDataRepository scopedDataRepository)
-        {
-            _logger = logger;
-            _scopedDataRepository = scopedDataRepository;
-        }
-
-        public void LogDebug(string message, params object[] args)
-        {
-            _logger.LogDebug(GetMessageWithOcelotRequestId(message), args);
-        }
-
-        public void LogError(string message, Exception exception)
-        {
-            _logger.LogError(GetMessageWithOcelotRequestId(message), exception);
-        }
-
-        private string GetMessageWithOcelotRequestId(string message)
-        {
-            var requestId = _scopedDataRepository.Get<string>("RequestId");
-
-            if (requestId != null && !requestId.IsError)
-            {
-                return $"{message} : OcelotRequestId - {requestId.Data}";
-                
-            }
-            return $"{message} : OcelotRequestId - not set";
-        }
+        /// <summary>
+        /// The name of the type the logger has been built for.
+        /// </summary>
+        string Name { get; }
     }
 }

src/Ocelot/Logging/OcelotLoggerExtensions.cs

@@ -0,0 +1,29 @@
+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/OcelotMiddleware.cs

@@ -14,8 +14,11 @@ namespace Ocelot.Middleware
         protected OcelotMiddleware(IRequestScopedDataRepository requestScopedDataRepository)
         {
             _requestScopedDataRepository = requestScopedDataRepository;
+            MiddlwareName = this.GetType().Name;
         }
 
+        public string MiddlwareName { get; } 
+
         public bool PipelineError
         {
             get

src/Ocelot/RateLimit/Middleware/ClientRateLimitMiddleware.cs

@@ -30,13 +30,19 @@ namespace Ocelot.RateLimit.Middleware
         }
 
         public async Task Invoke(HttpContext context)
-        {
-            _logger.LogDebug("started calling RateLimit middleware");
+        {
+            _logger.TraceMiddlewareEntry();
+
             var options = DownstreamRoute.ReRoute.RateLimitOptions;
             // check if rate limiting is enabled
             if (!DownstreamRoute.ReRoute.EnableEndpointRateLimiting)
             {
-                await _next.Invoke(context);
+                _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
@@ -45,7 +51,12 @@ namespace Ocelot.RateLimit.Middleware
             // check white list
             if (IsWhitelisted(identity, options))
             {
-                await _next.Invoke(context);
+                _logger.LogDebug($"{DownstreamRoute.ReRoute.DownstreamPathTemplate} is white listed from rate limiting");
+
+                _logger.TraceInvokeNext();
+                    await _next.Invoke(context);
+                _logger.TraceInvokeNextCompleted();
+                _logger.TraceMiddlewareCompleted();
                 return;
             }
 
@@ -66,6 +77,7 @@ namespace Ocelot.RateLimit.Middleware
 
                     // break execution
                     await ReturnQuotaExceededResponse(context, options, retryAfter);
+                    _logger.TraceMiddlewareCompleted();
                     return;
                 }
             }
@@ -74,9 +86,12 @@ namespace Ocelot.RateLimit.Middleware
             {
                 var headers = _processor.GetRateLimitHeaders( context,identity, options);
                 context.Response.OnStarting(SetRateLimitHeaders, state: headers);
-            }
-
-            await _next.Invoke(context);
+            }
+
+            _logger.TraceInvokeNext();
+                await _next.Invoke(context);
+            _logger.TraceInvokeNextCompleted();
+            _logger.TraceMiddlewareCompleted();
         }
 
         public virtual ClientRequestIdentity SetIdentity(HttpContext httpContext, RateLimitOptions option)

src/Ocelot/RequestId/Middleware/RequestIdMiddleware.cs

@@ -26,17 +26,16 @@ namespace Ocelot.RequestId.Middleware
 
         public async Task Invoke(HttpContext context)
         {         
-            _logger.LogDebug("started calling request id middleware");
+            _logger.TraceMiddlewareEntry();
 
             SetOcelotRequestId(context);
 
-            _logger.LogDebug("set request id");
+            _logger.LogDebug("set requestId");
 
-            _logger.LogDebug("calling next middleware");
-
-            await _next.Invoke(context);
-            
-            _logger.LogDebug("succesfully called next middleware");
+            _logger.TraceInvokeNext();
+                await _next.Invoke(context);
+            _logger.TraceInvokeNextCompleted();
+            _logger.TraceMiddlewareCompleted();
         }
 
         private void SetOcelotRequestId(HttpContext context)

src/Ocelot/Responder/ErrorsToHttpStatusCodeMapper.cs

@@ -24,9 +24,14 @@ namespace Ocelot.Responder
             if (errors.Any(e => e.Code == OcelotErrorCode.RequestTimedOutError))
             {
                 return 503;
+            }
+
+            if (errors.Any(e => e.Code == OcelotErrorCode.UnableToFindDownstreamRouteError))
+            {
+                return 404;
             }
 
-            return 404;
+            return 404;
         }
     }
 }

src/Ocelot/Responder/Middleware/ResponderMiddleware.cs

@@ -1,66 +1,64 @@
-using System.Collections.Generic;
-using System.Threading.Tasks;
-using Microsoft.AspNetCore.Http;
-using Microsoft.Extensions.Logging;
-using Ocelot.Errors;
-using Ocelot.Infrastructure.RequestData;
-using Ocelot.Logging;
-using Ocelot.Middleware;
-
-namespace Ocelot.Responder.Middleware
-{
-    public class ResponderMiddleware : OcelotMiddleware
-    {
-        private readonly RequestDelegate _next;
-        private readonly IHttpResponder _responder;
-        private readonly IErrorsToHttpStatusCodeMapper _codeMapper;
-        private readonly IOcelotLogger _logger;
-
-        public ResponderMiddleware(RequestDelegate next,
-            IHttpResponder responder,
-            IOcelotLoggerFactory loggerFactory,
-            IRequestScopedDataRepository requestScopedDataRepository,
-            IErrorsToHttpStatusCodeMapper codeMapper)
-            : base(requestScopedDataRepository)
-        {
-            _next = next;
-            _responder = responder;
-            _codeMapper = codeMapper;
-            _logger = loggerFactory.CreateLogger<ResponderMiddleware>();
-
-        }
-
-        public async Task Invoke(HttpContext context)
-        {
-            _logger.LogDebug("started error responder middleware");
-
-            await _next.Invoke(context);
-
-            _logger.LogDebug("calling next middleware");
-
-            if (PipelineError)
-            {
-                _logger.LogDebug("there is a pipeline error, getting errors");
-
-                var errors = PipelineErrors;
-
-                _logger.LogDebug("received errors setting error response");
-
-                SetErrorResponse(context, errors);
-            }
-            else
-            {
-                _logger.LogDebug("no pipeline error, setting response");
-
-                await _responder.SetResponseOnHttpContext(context, HttpResponseMessage);
-            }
-        }
-
+using System.Collections.Generic;
+using System.Threading.Tasks;
+using Microsoft.AspNetCore.Http;
+using Ocelot.Errors;
+using Ocelot.Infrastructure.RequestData;
+using Ocelot.Logging;
+using Ocelot.Middleware;
+
+namespace Ocelot.Responder.Middleware
+{
+    /// <summary>
+    /// Completes and returns the request and request body, if any pipeline errors occured then sets the appropriate HTTP status code instead.
+    /// </summary>
+    public class ResponderMiddleware : OcelotMiddleware
+    {
+        private readonly RequestDelegate _next;
+        private readonly IHttpResponder _responder;
+        private readonly IErrorsToHttpStatusCodeMapper _codeMapper;
+        private readonly IOcelotLogger _logger;
+
+        public ResponderMiddleware(RequestDelegate next, 
+            IHttpResponder responder,
+            IOcelotLoggerFactory loggerFactory,
+            IRequestScopedDataRepository requestScopedDataRepository, 
+            IErrorsToHttpStatusCodeMapper codeMapper)
+            :base(requestScopedDataRepository)
+        {
+            _next = next;
+            _responder = responder;
+            _codeMapper = codeMapper;
+            _logger = loggerFactory.CreateLogger<ResponderMiddleware>();
+
+        }
+
+        public async Task Invoke(HttpContext context)
+        {
+            _logger.TraceMiddlewareEntry();
+            _logger.TraceInvokeNext();
+                await _next.Invoke(context);
+            _logger.TraceInvokeNextCompleted();
+
+            if (PipelineError)
+            {
+                var errors = PipelineErrors;
+                _logger.LogError($"{errors.Count} pipeline errors found in {MiddlwareName}. Setting error response status code");
+
+                SetErrorResponse(context, errors);
+            }
+            else
+            {
+                _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)
         {
             var statusCode = _codeMapper.Map(errors);
 
             _responder.SetErrorResponseOnContext(context, statusCode);
-        }
-    }
+        }
+    }
 }