Improving logging and request id (#189)

* hacking around to work out why logging and request id isnt working

* pass request id into logger so it can be structured, removed a bunch of debug logging we dont need because diagnostic trace gets it

* changed config dependency

* always have tracing available

* made it so we dont need to pass config into services.AddOcelot anymore with .net core 2.0

* add test

* lots of changes relating to logging and request ids, also updated documentation

* fixed failing test i missed

src/Ocelot/Configuration/Creator/FileOcelotConfigurationCreator.cs

@@ -97,7 +97,7 @@ namespace Ocelot.Configuration.Creator
 
             var serviceProviderConfiguration = _serviceProviderConfigCreator.Create(fileConfiguration.GlobalConfiguration);
             
-            var config = new OcelotConfiguration(reRoutes, _adminPath.Path, serviceProviderConfiguration);
+            var config = new OcelotConfiguration(reRoutes, _adminPath.Path, serviceProviderConfiguration, fileConfiguration.GlobalConfiguration.RequestIdKey);
 
             return new OkResponse<IOcelotConfiguration>(config);
         }

src/Ocelot/Configuration/Creator/RequestIdKeyCreator.cs

@@ -6,11 +6,11 @@ namespace Ocelot.Configuration.Creator
     {
         public string Create(FileReRoute fileReRoute, FileGlobalConfiguration globalConfiguration)
         {
-            var globalRequestIdConfiguration = !string.IsNullOrEmpty(globalConfiguration?.RequestIdKey);
+            var reRouteId = !string.IsNullOrEmpty(fileReRoute.RequestIdKey);
 
-             var requestIdKey = globalRequestIdConfiguration
-                ? globalConfiguration.RequestIdKey
-                : fileReRoute.RequestIdKey;
+             var requestIdKey = reRouteId
+                ? fileReRoute.RequestIdKey
+                : globalConfiguration.RequestIdKey;
 
                 return requestIdKey;
         }

src/Ocelot/Configuration/IOcelotConfiguration.cs

@@ -7,5 +7,6 @@ namespace Ocelot.Configuration
         List<ReRoute> ReRoutes { get; }
         string AdministrationPath {get;}
         ServiceProviderConfiguration ServiceProviderConfiguration {get;}
+        string RequestId {get;}
     }
 }

src/Ocelot/Configuration/OcelotConfiguration.cs

@@ -4,15 +4,17 @@ namespace Ocelot.Configuration
 {
     public class OcelotConfiguration : IOcelotConfiguration
     {
-        public OcelotConfiguration(List<ReRoute> reRoutes, string administrationPath, ServiceProviderConfiguration serviceProviderConfiguration)
+        public OcelotConfiguration(List<ReRoute> reRoutes, string administrationPath, ServiceProviderConfiguration serviceProviderConfiguration, string requestId)
         {
             ReRoutes = reRoutes;
             AdministrationPath = administrationPath;
             ServiceProviderConfiguration = serviceProviderConfiguration;
+            RequestId = requestId;
         }
 
         public List<ReRoute> ReRoutes { get; }
         public string AdministrationPath {get;}
         public ServiceProviderConfiguration ServiceProviderConfiguration {get;}
+        public string RequestId {get;}
     }
 }

src/Ocelot/DependencyInjection/OcelotBuilder.cs

@@ -58,9 +58,9 @@ namespace Ocelot.DependencyInjection
     public class OcelotBuilder : IOcelotBuilder
     {
         private IServiceCollection _services;
-        private IConfigurationRoot _configurationRoot;
+        private IConfiguration _configurationRoot;
         
-        public OcelotBuilder(IServiceCollection services, IConfigurationRoot configurationRoot)
+        public OcelotBuilder(IServiceCollection services, IConfiguration configurationRoot)
         {
             _configurationRoot = configurationRoot;
             _services = services;    
@@ -280,9 +280,9 @@ namespace Ocelot.DependencyInjection
     public class OcelotAdministrationBuilder : IOcelotAdministrationBuilder
     {
         private IServiceCollection _services;
-        private IConfigurationRoot _configurationRoot;
+        private IConfiguration _configurationRoot;
         
-        public OcelotAdministrationBuilder(IServiceCollection services, IConfigurationRoot configurationRoot)
+        public OcelotAdministrationBuilder(IServiceCollection services, IConfiguration configurationRoot)
         {
             _configurationRoot = configurationRoot;
             _services = services;    

src/Ocelot/DependencyInjection/ServiceCollectionExtensions.cs

@@ -7,10 +7,16 @@ namespace Ocelot.DependencyInjection
 {
     public static class ServiceCollectionExtensions
     {
-        public static IOcelotBuilder AddOcelot(this IServiceCollection services,
-            IConfigurationRoot configurationRoot)
+        public static IOcelotBuilder AddOcelot(this IServiceCollection services)
         {
-            return new OcelotBuilder(services, configurationRoot);
+            var service = services.First(x => x.ServiceType == typeof(IConfiguration));
+            var configuration = (IConfiguration)service.ImplementationInstance;
+            return new OcelotBuilder(services, configuration);
+        }
+
+        public static IOcelotBuilder AddOcelot(this IServiceCollection services, IConfiguration configuration)
+        {
+            return new OcelotBuilder(services, configuration);
         }
     }
 }

src/Ocelot/DownstreamRouteFinder/Middleware/DownstreamRouteFinderMiddleware.cs

@@ -36,7 +36,6 @@ namespace Ocelot.DownstreamRouteFinder.Middleware
         {
             var upstreamUrlPath = context.Request.Path.ToString();
 
-            //todo make this getting config its own middleware one day?
             var configuration = await _configProvider.Get(); 
             
             if(configuration.IsError)

src/Ocelot/Errors/Middleware/ExceptionHandlerMiddleware.cs

@@ -1,24 +1,34 @@
 using System;
+using System.Linq;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Http;
+using Microsoft.Extensions.Primitives;
+using Ocelot.Configuration.Provider;
+using Ocelot.Infrastructure.Extensions;
 using Ocelot.Infrastructure.RequestData;
 using Ocelot.Logging;
+using Ocelot.Middleware;
 
 namespace Ocelot.Errors.Middleware
 {
     /// <summary>
     /// Catches all unhandled exceptions thrown by middleware, logs and returns a 500
     /// </summary>
-    public class ExceptionHandlerMiddleware 
+    public class ExceptionHandlerMiddleware : OcelotMiddleware
     {
         private readonly RequestDelegate _next;
         private readonly IOcelotLogger _logger;
         private readonly IRequestScopedDataRepository _requestScopedDataRepository;
+        private readonly IOcelotConfigurationProvider _configProvider;
+
 
         public ExceptionHandlerMiddleware(RequestDelegate next,
             IOcelotLoggerFactory loggerFactory, 
-            IRequestScopedDataRepository requestScopedDataRepository)
+            IRequestScopedDataRepository requestScopedDataRepository,
+            IOcelotConfigurationProvider configProvider)
+            :base(requestScopedDataRepository)
         {
+            _configProvider = configProvider;
             _next = next;
             _requestScopedDataRepository = requestScopedDataRepository;
             _logger = loggerFactory.CreateLogger<ExceptionHandlerMiddleware>();
@@ -28,26 +38,51 @@ namespace Ocelot.Errors.Middleware
         {
             try
             {
-                _logger.LogDebug("ocelot pipeline started");
+                await TrySetGlobalRequestId(context);
 
-                _logger.LogDebug("calling next middleware");
+                _logger.LogDebug("ocelot pipeline started");
 
                 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);
+                
                 SetInternalServerErrorOnResponse(context);
             }
 
             _logger.LogDebug("ocelot pipeline finished");
         }
 
+        private async Task TrySetGlobalRequestId(HttpContext context)
+        {
+                //try and get the global request id and set it for logs...
+                //shoudl this basically be immutable per request...i guess it should!
+                //first thing is get config
+                 var configuration = await _configProvider.Get(); 
+            
+                //if error throw to catch below..
+                if(configuration.IsError)
+                {
+                    throw new Exception($"{MiddlewareName} setting pipeline errors. IOcelotConfigurationProvider returned {configuration.Errors.ToErrorString()}");
+                }
+
+                //else set the request id?
+                var key = configuration.Data.RequestId;
+
+                StringValues upstreamRequestIds;
+                if (!string.IsNullOrEmpty(key) && context.Request.Headers.TryGetValue(key, out upstreamRequestIds))
+                {
+                    context.TraceIdentifier = upstreamRequestIds.First();
+                    _requestScopedDataRepository.Add<string>("RequestId", context.TraceIdentifier);
+                }
+        }
+
         private void SetInternalServerErrorOnResponse(HttpContext context)
         {
             context.Response.StatusCode = 500;

src/Ocelot/Infrastructure/RequestData/HttpDataRepository.cs

@@ -31,6 +31,22 @@ namespace Ocelot.Infrastructure.RequestData
             }
         }
 
+        public Response Update<T>(string key, T value)
+        {
+            try
+            {
+                _httpContextAccessor.HttpContext.Items[key] = value;
+                return new OkResponse();
+            }
+            catch (Exception exception)
+            {
+                return new ErrorResponse(new List<Error>
+                {
+                    new CannotAddDataError(string.Format($"Unable to update data for key: {key}, exception: {exception.Message}"))
+                });
+            }
+        }
+
         public Response<T> Get<T>(string key)
         {
             object obj;

src/Ocelot/Infrastructure/RequestData/IRequestScopedDataRepository.cs

@@ -5,6 +5,7 @@ namespace Ocelot.Infrastructure.RequestData
     public interface IRequestScopedDataRepository
     {
         Response Add<T>(string key, T value);
+        Response Update<T>(string key, T value);
         Response<T> Get<T>(string key);
     }
 }

src/Ocelot/Logging/AspDotNetLogger.cs

@@ -19,34 +19,69 @@ namespace Ocelot.Logging
         }
 
         public void LogTrace(string message, params object[] args)
-        {
-            _logger.LogTrace(GetMessageWithOcelotRequestId(message), args);
+        {            
+            var requestId = GetOcelotRequestId();
+            var previousRequestId = GetOcelotPreviousRequestId();
+            _logger.LogTrace("requestId: {requestId}, previousRequestId: {previousRequestId}, message: {message},", requestId, previousRequestId, message, args);
         }
 
         public void LogDebug(string message, params object[] args)
-        {
-            _logger.LogDebug(GetMessageWithOcelotRequestId(message), args);
+        {            
+            var requestId = GetOcelotRequestId();
+            var previousRequestId = GetOcelotPreviousRequestId();
+            _logger.LogDebug("requestId: {requestId}, previousRequestId: {previousRequestId}, message: {message},", requestId, previousRequestId, message, args);
         }
+
+        public void LogInformation(string message, params object[] args)
+        {            
+            var requestId = GetOcelotRequestId();
+            var previousRequestId = GetOcelotPreviousRequestId();
+            _logger.LogInformation("requestId: {requestId}, previousRequestId: {previousRequestId}, message: {message},", requestId, previousRequestId, message, args);
+        }
+
         public void LogError(string message, Exception exception)
         {
-            _logger.LogError(GetMessageWithOcelotRequestId(message), exception);
+            var requestId = GetOcelotRequestId();
+            var previousRequestId = GetOcelotPreviousRequestId();
+            _logger.LogError("requestId: {requestId}, previousRequestId: {previousRequestId}, message: {message}, exception: {exception}", requestId, previousRequestId, message, exception);
         }
 
         public void LogError(string message, params object[] args)
         {
-            _logger.LogError(GetMessageWithOcelotRequestId(message), args);
+            var requestId = GetOcelotRequestId();
+            var previousRequestId = GetOcelotPreviousRequestId();
+            _logger.LogError("requestId: {requestId}, previousRequestId: {previousRequestId}, message: {message}", requestId, previousRequestId, message, args);
         }
 
-        private string GetMessageWithOcelotRequestId(string message)
+        public void LogCritical(string message, Exception exception)
+        {
+            var requestId = GetOcelotRequestId();
+            var previousRequestId = GetOcelotPreviousRequestId();
+            _logger.LogError("requestId: {requestId}, previousRequestId: {previousRequestId}, message: {message}", requestId, previousRequestId, message);
+        }
+
+        private string GetOcelotRequestId()
         {
             var requestId = _scopedDataRepository.Get<string>("RequestId");
 
             if (requestId == null || requestId.IsError)
             {
-                return $"{message} : OcelotRequestId - not set";
+                return $"no request id";
             }
 
-            return $"{message} : OcelotRequestId - {requestId.Data}";
+            return requestId.Data;
+        }
+
+        private string GetOcelotPreviousRequestId()
+        {
+            var requestId = _scopedDataRepository.Get<string>("PreviousRequestId");
+
+            if (requestId == null || requestId.IsError)
+            {
+                return $"no previous request id";
+            }
+
+            return requestId.Data;
         }
     }
 }

src/Ocelot/Logging/IOcelotLoggerFactory.cs

@@ -6,18 +6,20 @@ namespace Ocelot.Logging
     {
         IOcelotLogger CreateLogger<T>();
     }
-    /// <summary>
-    /// Thin wrapper around the DotNet core logging framework, used to allow the scopedDataRepository to be injected giving access to the Ocelot RequestId
+    /// <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 LogInformation(string message, params object[] args);
         void LogError(string message, Exception exception);
         void LogError(string message, params object[] args);
+        void LogCritical(string message, Exception exception);
 
-        /// <summary>
-        /// The name of the type the logger has been built for.
+        /// <summary>
+        /// The name of the type the logger has been built for.
         /// </summary>
         string Name { get; }
     }

src/Ocelot/Middleware/OcelotMiddlewareExtensions.cs

@@ -77,6 +77,7 @@ namespace Ocelot.Middleware
             ConfigureDiagnosticListener(builder);
 
             // This is registered to catch any global exceptions that are not handled
+            // It also sets the Request Id if anything is set globally
             builder.UseExceptionHandlerMiddleware();
 
             // Allow the user to respond with absolutely anything they want.
@@ -94,7 +95,9 @@ namespace Ocelot.Middleware
             // We check whether the request is ratelimit, and if there is no continue processing
             builder.UseRateLimiting();
 
-            // Now we can look for the requestId
+            // This adds or updates the request id (initally we try and set this based on global config in the error handling middleware)
+            // If anything was set at global level and we have a different setting at re route level the global stuff will be overwritten
+            // This means you can get a scenario where you have a different request id from the first piece of middleware to the request id middleware.
             builder.UseRequestIdMiddleware();
 
             // Allow pre authentication logic. The idea being people might want to run something custom before what is built in.
@@ -313,15 +316,10 @@ namespace Ocelot.Middleware
          /// <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);
-             }
+            var env = (IHostingEnvironment)builder.ApplicationServices.GetService(typeof(IHostingEnvironment));
+            var listener = (OcelotDiagnosticListener)builder.ApplicationServices.GetService(typeof(OcelotDiagnosticListener));
+            var diagnosticListener = (DiagnosticListener)builder.ApplicationServices.GetService(typeof(DiagnosticListener));
+            diagnosticListener.SubscribeWithAdapter(listener);
          }
         
         private static void OnShutdown(IApplicationBuilder app)

src/Ocelot/Request/Middleware/DownstreamRequestInitialiserMiddleware.cs

@@ -26,8 +26,6 @@ namespace Ocelot.Request.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogDebug("started calling request builder middleware");
-
             var downstreamRequest = await _requestMapper.Map(context.Request);
             if (downstreamRequest.IsError)
             {
@@ -37,11 +35,7 @@ namespace Ocelot.Request.Middleware
 
             SetDownstreamRequest(downstreamRequest.Data);
 
-            _logger.LogDebug("calling next middleware");
-
             await _next.Invoke(context);
-
-            _logger.LogDebug("succesfully called next middleware");
         }
     }
 }

src/Ocelot/Request/Middleware/HttpRequestBuilderMiddleware.cs

@@ -30,8 +30,6 @@ namespace Ocelot.Request.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogDebug("started calling request builder middleware");
-
             var qosProvider = _qosProviderHouse.Get(DownstreamRoute.ReRoute);
 
             if (qosProvider.IsError)
@@ -62,11 +60,7 @@ namespace Ocelot.Request.Middleware
 
             SetUpstreamRequestForThisRequest(buildResult.Data);
 
-            _logger.LogDebug("calling next middleware");
-
             await _next.Invoke(context);
-
-            _logger.LogDebug("succesfully called next middleware");
         }
     }
 }

src/Ocelot/RequestId/Middleware/ReRouteRequestIdMiddleware.cs

@@ -11,19 +11,19 @@ using System.Collections.Generic;
 
 namespace Ocelot.RequestId.Middleware
 {
-    public class RequestIdMiddleware : OcelotMiddleware
+    public class ReRouteRequestIdMiddleware : OcelotMiddleware
     {
         private readonly RequestDelegate _next;
         private readonly IOcelotLogger _logger;
         private readonly IRequestScopedDataRepository _requestScopedDataRepository;
 
-        public RequestIdMiddleware(RequestDelegate next,
+        public ReRouteRequestIdMiddleware(RequestDelegate next,
             IOcelotLoggerFactory loggerFactory,
             IRequestScopedDataRepository requestScopedDataRepository)
             : base(requestScopedDataRepository)
         {
             _next = next;
-            _logger = loggerFactory.CreateLogger<RequestIdMiddleware>();
+            _logger = loggerFactory.CreateLogger<ReRouteRequestIdMiddleware>();
             _requestScopedDataRepository = requestScopedDataRepository;
         }
 
@@ -41,7 +41,22 @@ namespace Ocelot.RequestId.Middleware
             StringValues upstreamRequestIds;
             if (context.Request.Headers.TryGetValue(key, out upstreamRequestIds))
             {
+                //set the traceidentifier
                 context.TraceIdentifier = upstreamRequestIds.First();
+
+                //check if we have previous id
+                var previousRequestId = _requestScopedDataRepository.Get<string>("RequestId");
+                if(!previousRequestId.IsError && !string.IsNullOrEmpty(previousRequestId.Data))
+                {
+                    //we have a previous request id lets store it and update request id
+                    _requestScopedDataRepository.Add<string>("PreviousRequestId", previousRequestId.Data);
+                    _requestScopedDataRepository.Update<string>("RequestId", context.TraceIdentifier);
+                }
+                else
+                {
+                    //else just add request id
+                    _requestScopedDataRepository.Add<string>("RequestId", context.TraceIdentifier);
+                }
             }
 
             // set request ID on downstream request, if required

src/Ocelot/RequestId/Middleware/RequestIdMiddlewareExtensions.cs

@@ -6,7 +6,7 @@ namespace Ocelot.RequestId.Middleware
     {
         public static IApplicationBuilder UseRequestIdMiddleware(this IApplicationBuilder builder)
         {
-            return builder.UseMiddleware<RequestIdMiddleware>();
+            return builder.UseMiddleware<ReRouteRequestIdMiddleware>();
         }
     }
 }

src/Ocelot/Requester/Middleware/HttpRequesterMiddleware.cs

@@ -26,8 +26,6 @@ namespace Ocelot.Requester.Middleware
 
         public async Task Invoke(HttpContext context)
         {
-            _logger.LogDebug("started calling requester middleware");
-
             var response = await _requester.GetResponse(Request);
 
             if (response.IsError)
@@ -41,8 +39,6 @@ namespace Ocelot.Requester.Middleware
             _logger.LogDebug("setting http response message");
 
             SetHttpResponseMessageThisRequest(response.Data);
-
-            _logger.LogDebug("returning to calling middleware");
         }
     }
 }