Added some logging at last!

src/Ocelot/Authentication/Middleware/AuthenticationMiddleware.cs

@@ -2,10 +2,12 @@
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Builder;
 using Microsoft.AspNetCore.Http;
+using Microsoft.Extensions.Logging;
 using Ocelot.Authentication.Handler.Factory;
 using Ocelot.Configuration;
 using Ocelot.Errors;
 using Ocelot.Infrastructure.RequestData;
+using Ocelot.Logging;
 using Ocelot.Middleware;
 
 namespace Ocelot.Authentication.Middleware
@@ -15,45 +17,64 @@ namespace Ocelot.Authentication.Middleware
         private readonly RequestDelegate _next;
         private readonly IApplicationBuilder _app;
         private readonly IAuthenticationHandlerFactory _authHandlerFactory;
+        private readonly IOcelotLogger _logger;
 
-        public AuthenticationMiddleware(RequestDelegate next, 
+        public AuthenticationMiddleware(RequestDelegate next,
             IApplicationBuilder app,
-            IRequestScopedDataRepository requestScopedDataRepository, 
-            IAuthenticationHandlerFactory authHandlerFactory) 
+            IRequestScopedDataRepository requestScopedDataRepository,
+            IAuthenticationHandlerFactory authHandlerFactory,
+            IOcelotLoggerFactory loggerFactory)
             : base(requestScopedDataRepository)
         {
             _next = next;
             _authHandlerFactory = authHandlerFactory;
             _app = app;
+            _logger = loggerFactory.CreateLogger<AuthenticationMiddleware>();
         }
 
         public async Task Invoke(HttpContext context)
         {
+            _logger.LogDebug("started authentication");
+
             if (IsAuthenticatedRoute(DownstreamRoute.ReRoute))
             {
                 var authenticationHandler = _authHandlerFactory.Get(_app, DownstreamRoute.ReRoute.AuthenticationOptions);
 
                 if (!authenticationHandler.IsError)
                 {
+                    _logger.LogDebug("calling authentication handler for ReRoute");
+
                     await authenticationHandler.Data.Handler.Invoke(context);
                 }
                 else
                 {
+                    _logger.LogDebug("there was an error getting authentication handler for ReRoute");
+
                     SetPipelineError(authenticationHandler.Errors);
                 }
 
                 if (context.User.Identity.IsAuthenticated)
                 {
+                    _logger.LogDebug("the user was authenticated");
+
                     await _next.Invoke(context);
+
+                    _logger.LogDebug("succesfully called next middleware");
                 }
                 else
-                {   
-                    SetPipelineError(new List<Error> {new UnauthenticatedError($"Request for authenticated route {context.Request.Path} by {context.User.Identity.Name} was unauthenticated")});
-                }      
+                {
+                    _logger.LogDebug("the user was not authenticated");
+
+                    SetPipelineError(new List<Error> { new UnauthenticatedError($"Request for authenticated route {context.Request.Path} by {context.User.Identity.Name} was unauthenticated") });
+                }
             }
             else
             {
+                _logger.LogDebug("calling next middleware");
+
                 await _next.Invoke(context);
+
+                _logger.LogDebug("succesfully called next middleware");
             }
         }
 

src/Ocelot/Authorisation/Middleware/AuthorisationMiddleware.cs

@@ -1,4 +1,6 @@
-using Ocelot.Infrastructure.RequestData;
+using Microsoft.Extensions.Logging;
+using Ocelot.Infrastructure.RequestData;
+using Ocelot.Logging;
 using Ocelot.Responses;
 
 namespace Ocelot.Authorisation.Middleware
@@ -13,34 +15,49 @@ namespace Ocelot.Authorisation.Middleware
     {
         private readonly RequestDelegate _next;
         private readonly IAuthoriser _authoriser;
+        private readonly IOcelotLogger _logger;
 
         public AuthorisationMiddleware(RequestDelegate next,
             IRequestScopedDataRepository requestScopedDataRepository,
-            IAuthoriser authoriser)
+            IAuthoriser authoriser,
+            IOcelotLoggerFactory loggerFactory)
             : base(requestScopedDataRepository)
         {
             _next = next;
             _authoriser = authoriser;
+            _logger = loggerFactory.CreateLogger<AuthorisationMiddleware>();
         }
 
         public async Task Invoke(HttpContext context)
         {
+            _logger.LogDebug("started authorisation");
+
             if (DownstreamRoute.ReRoute.IsAuthorised)
             {
+                _logger.LogDebug("route is authorised");
+
                 var authorised = _authoriser.Authorise(context.User, DownstreamRoute.ReRoute.RouteClaimsRequirement);
 
                 if (authorised.IsError)
                 {
+                    _logger.LogDebug("error authorising user");
+
                     SetPipelineError(authorised.Errors);
                     return;
                 }
 
                 if (IsAuthorised(authorised))
                 {
+                    _logger.LogDebug("user is authorised calling next middleware");
+
                     await _next.Invoke(context);
+
+                    _logger.LogDebug("succesfully called next middleware");
                 }
                 else
                 {
+                    _logger.LogDebug("user is not authorised setting pipeline error");
+
                     SetPipelineError(new List<Error>
                     {
                         new UnauthorisedError(
@@ -50,7 +67,11 @@ namespace Ocelot.Authorisation.Middleware
             }
             else
             {
+                _logger.LogDebug("AuthorisationMiddleware.Invoke route is not authorised calling next middleware");
+
                 await _next.Invoke(context);
+
+                _logger.LogDebug("succesfully called next middleware");
             }
         }
 

src/Ocelot/Cache/Middleware/OutputCacheMiddleware.cs

@@ -4,6 +4,7 @@ using System.Threading.Tasks;
 using Microsoft.AspNetCore.Http;
 using Microsoft.Extensions.Logging;
 using Ocelot.Infrastructure.RequestData;
+using Ocelot.Logging;
 using Ocelot.Middleware;
 
 namespace Ocelot.Cache.Middleware
@@ -11,11 +12,11 @@ namespace Ocelot.Cache.Middleware
     public class OutputCacheMiddleware : OcelotMiddleware
     {
         private readonly RequestDelegate _next;
-        private readonly ILogger _logger;
+        private readonly IOcelotLogger _logger;
         private readonly IOcelotCache<HttpResponseMessage> _outputCache;
 
-        public OutputCacheMiddleware(RequestDelegate next, 
-            ILoggerFactory loggerFactory,
+        public OutputCacheMiddleware(RequestDelegate next,
+            IOcelotLoggerFactory loggerFactory,
             IRequestScopedDataRepository scopedDataRepository,
             IOcelotCache<HttpResponseMessage> outputCache)
             :base(scopedDataRepository)
@@ -35,26 +36,30 @@ namespace Ocelot.Cache.Middleware
                 return;
             }
 
-            _logger.LogDebug("OutputCacheMiddleware.Invoke stared checking cache for downstreamUrlKey", downstreamUrlKey);
+            _logger.LogDebug("started checking cache for {downstreamUrlKey}", downstreamUrlKey);
   
             var cached = _outputCache.Get(downstreamUrlKey);
 
             if (cached != null)
             {
+                _logger.LogDebug("cache entry exists for {downstreamUrlKey}", downstreamUrlKey);
+
                 SetHttpResponseMessageThisRequest(cached);
 
-                _logger.LogDebug("OutputCacheMiddleware.Invoke finished returned cached response for downstreamUrlKey", downstreamUrlKey);
+                _logger.LogDebug("finished returned cached response for {downstreamUrlKey}", downstreamUrlKey);
 
                 return;
             }
 
-            _logger.LogDebug("OutputCacheMiddleware.Invoke no resonse cached for downstreamUrlKey", downstreamUrlKey);
+            _logger.LogDebug("no resonse cached for {downstreamUrlKey}", downstreamUrlKey);
 
             await _next.Invoke(context);
 
+            _logger.LogDebug("succesfully called next middleware");
+
             if (PipelineError())
             {
-                _logger.LogDebug("OutputCacheMiddleware.Invoke there was a pipeline error for downstreamUrlKey", downstreamUrlKey);
+                _logger.LogDebug("there was a pipeline error for {downstreamUrlKey}", downstreamUrlKey);
 
                 return;
             }
@@ -63,7 +68,7 @@ namespace Ocelot.Cache.Middleware
 
             _outputCache.Add(downstreamUrlKey, response, TimeSpan.FromSeconds(DownstreamRoute.ReRoute.FileCacheOptions.TtlSeconds));
 
-            _logger.LogDebug("OutputCacheMiddleware.Invoke finished response added to cache for downstreamUrlKey", downstreamUrlKey);
+            _logger.LogDebug("finished response added to cache for {downstreamUrlKey}", downstreamUrlKey);
         }
     }
 }

src/Ocelot/Claims/Middleware/ClaimsBuilderMiddleware.cs

@@ -2,6 +2,7 @@
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Http;
 using Ocelot.Infrastructure.RequestData;
+using Ocelot.Logging;
 using Ocelot.Middleware;
 
 namespace Ocelot.Claims.Middleware
@@ -10,30 +11,43 @@ namespace Ocelot.Claims.Middleware
     {
         private readonly RequestDelegate _next;
         private readonly IAddClaimsToRequest _addClaimsToRequest;
+        private readonly IOcelotLogger _logger;
 
         public ClaimsBuilderMiddleware(RequestDelegate next, 
             IRequestScopedDataRepository requestScopedDataRepository,
+            IOcelotLoggerFactory loggerFactory,
             IAddClaimsToRequest addClaimsToRequest) 
             : base(requestScopedDataRepository)
         {
             _next = next;
             _addClaimsToRequest = addClaimsToRequest;
+            _logger = loggerFactory.CreateLogger<ClaimsBuilderMiddleware>();
         }
 
         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");
+
                 var result = _addClaimsToRequest.SetClaimsOnContext(DownstreamRoute.ReRoute.ClaimsToClaims, context);
 
                 if (result.IsError)
                 {
+                    _logger.LogDebug("error converting claims to other claims, setting pipeline error");
+
                     SetPipelineError(result.Errors);
                     return;
                 }
             }
-            
+
+            _logger.LogDebug("calling next middleware");
+
             await _next.Invoke(context);
+
+            _logger.LogDebug("succesfully called next middleware");
         }
     }
 }

src/Ocelot/DependencyInjection/ServiceCollectionExtensions.cs

@@ -22,6 +22,7 @@ using Ocelot.DownstreamUrlCreator.UrlTemplateReplacer;
 using Ocelot.Headers;
 using Ocelot.Infrastructure.Claims.Parser;
 using Ocelot.Infrastructure.RequestData;
+using Ocelot.Logging;
 using Ocelot.QueryStrings;
 using Ocelot.Request.Builder;
 using Ocelot.Requester;
@@ -57,7 +58,7 @@ namespace Ocelot.DependencyInjection
         {
             services.AddMvcCore().AddJsonFormatters();
             services.AddLogging();
-
+            services.AddSingleton<IOcelotLoggerFactory, AspDotNetLoggerFactory>();
             services.AddSingleton<IRemoveOutputHeaders, RemoveOutputHeaders>();
             services.AddSingleton<IOcelotConfigurationProvider, OcelotConfigurationProvider>();
             services.AddSingleton<IClaimToThingConfigurationParser, ClaimToThingConfigurationParser>();

src/Ocelot/DownstreamRouteFinder/Middleware/DownstreamRouteFinderMiddleware.cs

@@ -2,6 +2,7 @@ using System.Threading.Tasks;
 using Microsoft.AspNetCore.Http;
 using Ocelot.DownstreamRouteFinder.Finder;
 using Ocelot.Infrastructure.RequestData;
+using Ocelot.Logging;
 using Ocelot.Middleware;
 
 namespace Ocelot.DownstreamRouteFinder.Middleware
@@ -10,31 +11,47 @@ namespace Ocelot.DownstreamRouteFinder.Middleware
     {
         private readonly RequestDelegate _next;
         private readonly IDownstreamRouteFinder _downstreamRouteFinder;
+        private readonly IOcelotLogger _logger;
 
-        public DownstreamRouteFinderMiddleware(RequestDelegate next, 
+        public DownstreamRouteFinderMiddleware(RequestDelegate next,
+            IOcelotLoggerFactory loggerFactory,
             IDownstreamRouteFinder downstreamRouteFinder, 
             IRequestScopedDataRepository requestScopedDataRepository)
             :base(requestScopedDataRepository)
         {
             _next = next;
             _downstreamRouteFinder = downstreamRouteFinder;
+            _logger = loggerFactory.CreateLogger<DownstreamRouteFinderMiddleware>();
         }
 
         public async Task Invoke(HttpContext context)
         {
+            _logger.LogDebug("started calling downstream route finder middleware");
+
             var upstreamUrlPath = context.Request.Path.ToString();
 
+            _logger.LogDebug("upstream url path is {upstreamUrlPath}", upstreamUrlPath);
+
             var downstreamRoute = _downstreamRouteFinder.FindDownstreamRoute(upstreamUrlPath, context.Request.Method);
 
             if (downstreamRoute.IsError)
             {
+                _logger.LogDebug("IDownstreamRouteFinder returned an error, setting pipeline error");
+
                 SetPipelineError(downstreamRoute.Errors);
                 return;
             }
 
+            _logger.LogDebug("downstream template is {downstreamRoute.Data.ReRoute.DownstreamTemplate}", downstreamRoute.Data.ReRoute.DownstreamTemplate);
+
             SetDownstreamRouteForThisRequest(downstreamRoute.Data);
 
+            _logger.LogDebug("calling next middleware");
+
             await _next.Invoke(context);
+
+            _logger.LogDebug("succesfully called next middleware");
+
         }
     }
 }

src/Ocelot/DownstreamUrlCreator/Middleware/DownstreamUrlCreatorMiddleware.cs

@@ -3,6 +3,7 @@ using Microsoft.AspNetCore.Http;
 using Ocelot.DownstreamRouteFinder;
 using Ocelot.DownstreamUrlCreator.UrlTemplateReplacer;
 using Ocelot.Infrastructure.RequestData;
+using Ocelot.Logging;
 using Ocelot.Middleware;
 
 namespace Ocelot.DownstreamUrlCreator.Middleware
@@ -11,29 +12,42 @@ namespace Ocelot.DownstreamUrlCreator.Middleware
     {
         private readonly RequestDelegate _next;
         private readonly IDownstreamUrlPathPlaceholderReplacer _urlReplacer;
+        private readonly IOcelotLogger _logger;
 
-        public DownstreamUrlCreatorMiddleware(RequestDelegate next, 
+        public DownstreamUrlCreatorMiddleware(RequestDelegate next,
+            IOcelotLoggerFactory loggerFactory,
             IDownstreamUrlPathPlaceholderReplacer urlReplacer,
             IRequestScopedDataRepository requestScopedDataRepository)
             :base(requestScopedDataRepository)
         {
             _next = next;
             _urlReplacer = urlReplacer;
+            _logger = loggerFactory.CreateLogger<DownstreamUrlCreatorMiddleware>();
         }
 
         public async Task Invoke(HttpContext context)
         {
+            _logger.LogDebug("started calling downstream url creator middleware");
+
             var downstreamUrl = _urlReplacer.Replace(DownstreamRoute.ReRoute.DownstreamTemplate, DownstreamRoute.TemplatePlaceholderNameAndValues);
 
             if (downstreamUrl.IsError)
             {
+                _logger.LogDebug("IDownstreamUrlPathPlaceholderReplacer returned an error, setting pipeline error");
+
                 SetPipelineError(downstreamUrl.Errors);
                 return;
             }
 
+            _logger.LogDebug("downstream url is {downstreamUrl.Data.Value}", downstreamUrl.Data.Value);
+
             SetDownstreamUrlForThisRequest(downstreamUrl.Data.Value);
 
+            _logger.LogDebug("calling next middleware");
+
             await _next.Invoke(context);
+
+            _logger.LogDebug("succesfully called next middleware");
         }
     }
 }

src/Ocelot/Errors/Middleware/ExceptionHandlerMiddleware.cs

@@ -0,0 +1,67 @@
+using System;
+using System.Threading.Tasks;
+using Microsoft.AspNetCore.Http;
+using Microsoft.Extensions.Logging;
+using Ocelot.Infrastructure.RequestData;
+using Ocelot.Logging;
+
+namespace Ocelot.Errors.Middleware
+{
+    public class ExceptionHandlerMiddleware 
+    {
+        private readonly RequestDelegate _next;
+        private readonly IOcelotLogger _logger;
+        private readonly IRequestScopedDataRepository _requestScopedDataRepository;
+
+        public ExceptionHandlerMiddleware(RequestDelegate next,
+            IOcelotLoggerFactory loggerFactory, 
+            IRequestScopedDataRepository requestScopedDataRepository)
+        {
+            _next = next;
+            _requestScopedDataRepository = requestScopedDataRepository;
+            _logger = loggerFactory.CreateLogger<ExceptionHandlerMiddleware>();
+        }
+
+        public async Task Invoke(HttpContext context)
+        {
+            try
+            {   
+                _logger.LogDebug("calling middleware");
+
+                _requestScopedDataRepository.Add("RequestId", context.TraceIdentifier);
+
+                await _next.Invoke(context);
+
+                _logger.LogDebug("succesfully called middleware");
+            }
+            catch (Exception e)
+            {
+                _logger.LogDebug("error calling middleware");
+
+                var message = CreateMessage(context, e);
+                _logger.LogError(message, e);
+                await SetInternalServerErrorOnResponse(context);
+            }
+        }
+
+        private static async Task SetInternalServerErrorOnResponse(HttpContext context)
+        {
+            context.Response.StatusCode = 500;
+            context.Response.ContentType = "application/json";
+            await context.Response.WriteAsync("Internal Server Error");
+        }
+
+        private static string CreateMessage(HttpContext context, Exception e)
+        {
+            var message =
+                $"Exception caught in global error handler, exception message: {e.Message}, exception stack: {e.StackTrace}";
+
+            if (e.InnerException != null)
+            {
+                message =
+                    $"{message}, inner exception message {e.InnerException.Message}, inner exception stack {e.InnerException.StackTrace}";
+            }
+            return $"{message} RequestId: {context.TraceIdentifier}";
+        }
+    }
+}

src/Ocelot/Errors/Middleware/ExceptionHandlerMiddlewareExtensions.cs

@@ -1,6 +1,6 @@
 using Microsoft.AspNetCore.Builder;
 
-namespace Ocelot.Middleware
+namespace Ocelot.Errors.Middleware
 {
     public static class ExceptionHandlerMiddlewareExtensions
     {

src/Ocelot/Logging/IOcelotLoggerFactory.cs

@@ -0,0 +1,66 @@
+using System;
+using Microsoft.Extensions.Logging;
+using Ocelot.Infrastructure.RequestData;
+
+namespace Ocelot.Logging
+{
+    public interface IOcelotLoggerFactory
+    {
+        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);
+        }
+    }
+
+    public interface IOcelotLogger
+    {
+        void LogDebug(string message, params object[] args);
+        void LogError(string message, Exception exception);
+    }
+
+    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(GetMessageWithRequestId(message), args);
+        }
+
+        public void LogError(string message, Exception exception)
+        {
+            _logger.LogError(GetMessageWithRequestId(message), exception);
+        }
+
+        private string GetMessageWithRequestId(string message)
+        {
+            var requestId = _scopedDataRepository.Get<string>("RequestId");
+
+            return requestId.IsError 
+                ? $"{message} : RequestId: Error" 
+                : $"{message} : RequestId: {requestId.Data}";
+        }
+    }
+}

src/Ocelot/Middleware/ExceptionHandlerMiddleware.cs

@@ -1,49 +0,0 @@
-using System;
-using System.Threading.Tasks;
-using Microsoft.AspNetCore.Http;
-using Microsoft.Extensions.Logging;
-
-namespace Ocelot.Middleware
-{
-    public class ExceptionHandlerMiddleware 
-    {
-        private readonly RequestDelegate _next;
-        private readonly ILogger _logger;
-
-        public ExceptionHandlerMiddleware(RequestDelegate next, 
-            ILoggerFactory loggerFactory)
-        {
-            _next = next;
-            _logger = loggerFactory.CreateLogger<ExceptionHandlerMiddleware>();
-        }
-
-        public async Task Invoke(HttpContext context)
-        {
-            try
-            {
-                await _next.Invoke(context);
-            }
-            catch (Exception e)
-            {
-                var message = CreateMessage(context, e);
-                _logger.LogError(new EventId(1, "Ocelot Global Error"), message, e);
-                context.Response.StatusCode = 500;
-                context.Response.ContentType = "application/json";
-                await context.Response.WriteAsync("Internal Server Error");
-            }
-        }
-
-        private static string CreateMessage(HttpContext context, Exception e)
-        {
-            var message =
-                $"RequestId: {context.TraceIdentifier}, Exception caught in global error handler, exception message: {e.Message}, exception stack: {e.StackTrace}";
-
-            if (e.InnerException != null)
-            {
-                message =
-                    $"{message}, inner exception message {e.InnerException.Message}, inner exception stack {e.InnerException.StackTrace}";
-            }
-            return message;
-        }
-    }
-}

src/Ocelot/Middleware/OcelotMiddlewareExtensions.cs

@@ -4,6 +4,7 @@ using Ocelot.Cache.Middleware;
 using Ocelot.Claims.Middleware;
 using Ocelot.DownstreamRouteFinder.Middleware;
 using Ocelot.DownstreamUrlCreator.Middleware;
+using Ocelot.Errors.Middleware;
 using Ocelot.Headers.Middleware;
 using Ocelot.QueryStrings.Middleware;
 using Ocelot.Request.Middleware;