refactor loggerhandler (#273)

* refactor loggerhandler

* support multipe loglevel for exceptions

* better logger format in CI

* add test for logging

* add test for default logging output

commercetools.Sdk/IntegrationTests/commercetools.Api.IntegrationTests/LoggingTest.cs

@@ -17,6 +17,45 @@ namespace commercetools.Api.IntegrationTests;
 
 public class LoggingTest
 {
+    [Fact]
+    public async void DefaultLogger()
+    {
+        var configuration = new ConfigurationBuilder().
+            AddJsonFile("appsettings.test.Development.json", true).
+            AddEnvironmentVariables().
+            AddUserSecrets<ServiceProviderFixture>().
+            AddEnvironmentVariables("CTP_").
+            Build();
+        var clientConfiguration = configuration.GetSection("Client").Get<ClientConfiguration>();
+        var loggerClientConf = new ConfigurationBuilder()
+            .AddInMemoryCollection(new Dictionary<string, string>()
+            {
+                { "LoggerClient:ClientId", clientConfiguration.ClientId},
+                { "LoggerClient:ClientSecret", clientConfiguration.ClientSecret},
+                { "LoggerClient:ProjectKey", clientConfiguration.ProjectKey},
+            })
+            .Build();
+        var logger = new TestLogger();
+        var loggerFactory = LoggerFactory.Create(builder =>
+        {
+            builder
+                .AddFilter("System.Net.Http.HttpClient", LogLevel.None) // disable HTTP client default logging
+                .AddProvider(new TestLoggerProvider(logger));
+        });
+        var s = new ServiceCollection();
+        s.AddSingleton(loggerFactory);
+        s.UseCommercetoolsApi(loggerClientConf, "LoggerClient");
+        var p = s.BuildServiceProvider();
+
+        var apiRoot = p.GetService<ProjectApiRoot>();
+
+        await apiRoot.Get().ExecuteAsync();
+
+        var messages = logger.GetLogMessages();
+        Assert.StartsWith("GET https://api.europe-west1.gcp.commercetools.com/" + clientConfiguration.ProjectKey, messages.TrimEnd());
+    }
+
+
     [Fact]
     public async void CustomLogger()
     {
@@ -55,7 +94,7 @@ public async void CustomLogger()
         var messages = logger.GetLogMessages();
         Assert.Equal("GET https://api.europe-west1.gcp.commercetools.com/" + clientConfiguration.ProjectKey, messages.TrimEnd());
     }
-
+    
     public class CustomLoggerHandler : DelegatingHandler
     {
         private readonly ILogger logger;

commercetools.Sdk/IntegrationTests/commercetools.Api.IntegrationTests/ServiceProviderFixture.cs

@@ -1,6 +1,8 @@
 using System;
+using System.Collections.Generic;
 using commercetools.Sdk.Api.Models.Errors;
 using commercetools.Base.Client;
+using commercetools.Base.Client.Error;
 using commercetools.Sdk.Api;
 using commercetools.Sdk.Api.Serialization;
 using Microsoft.Extensions.Configuration;
@@ -20,6 +22,12 @@ public ServiceProviderFixture()
 
             //services.AddLogging(configure => configure.AddConsole());
             this.configuration = new ConfigurationBuilder().
+                AddInMemoryCollection(
+                    new Dictionary<string, string>()
+                    {
+                        { "Logging:LogLevel:commercetoolsLoggerHandler", "Warning"},
+                        { "Logging:LogLevel:System.Net.Http.HttpClient", "Warning"},
+                    }).
                 AddJsonFile("appsettings.test.Development.json", true).
                 AddEnvironmentVariables().
                 AddUserSecrets<ServiceProviderFixture>().
@@ -28,12 +36,30 @@ public ServiceProviderFixture()
 
             var useStreamClient = Enum.Parse<ClientType>(configuration.GetValue("ClientType", "String")) != ClientType.String;
             services.UseCommercetoolsApi(configuration, "Client", options: new ClientOptions { ReadResponseAsStream = useStreamClient });
+            services.AddLogging(c => c.AddConfiguration(configuration.GetSection("Logging")));
             services.AddLogging(c => c.AddProvider(new InMemoryLoggerProvider()));
+            services.AddLogging(c => c.AddSimpleConsole(o =>
+            {
+                o.UseUtcTimestamp = true;
+                o.IncludeScopes = true;
+                o.TimestampFormat = "yyyy'-'MM'-'dd'T'HH':'mm':'ss.FFFFFFK ";
+                o.SingleLine = true;
+            }));
             services.SetupClient(
                 "MeClient",
                 errorTypeMapper => typeof(ErrorResponse),
                 s => s.GetService<IApiSerializerService>()
             );
+            services.AddSingleton<ILoggerHandlerOptions>(new LoggerHandlerOptions()
+            {
+                ResponseLogEvent = LogLevel.Information,
+                DefaultExceptionLogEvent = LogLevel.Warning,
+                ExceptionLogEvents = new Dictionary<System.Type, LogLevel>()
+                {
+                    { typeof(NotFoundException), LogLevel.Information },
+                    { typeof(ConcurrentModificationException), LogLevel.Information}
+                }
+            });
             this.serviceProvider = services.BuildServiceProvider();
 
             //set default ProjectKey

commercetools.Sdk/commercetools.Base.Client/DefaultHttpLogger.cs

@@ -0,0 +1,111 @@
+using System;
+using System.Linq;
+using System.Net.Http;
+using System.Net.Http.Headers;
+using System.Text.RegularExpressions;
+using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
+
+namespace commercetools.Base.Client
+{
+    public class DefaultHttpLogger : IHttpLogger
+    {
+        public async Task LogRequestBody(ILogger logger, LogLevel logLevel, HttpRequestMessage request)
+        {
+            if (logger.IsEnabled(logLevel))
+            {
+                var body = await (request.Content?.ReadAsStringAsync() ?? Task.FromResult(""));
+                logger.Log(logLevel, "{HttpMethod} {Uri} {Headers} {Body}", request.Method.Method,
+                    request.RequestUri.AbsoluteUri, RedactAuthorizationHeader(request.Headers), SecuredBody(body));
+            }
+        }
+
+        public async Task LogResponseBody(ILogger logger, LogLevel logLevel, HttpRequestMessage request, HttpResponseMessage response, long elapsed)
+        {
+            if (logger.IsEnabled(logLevel))
+            {
+                var body = await (response.Content?.ReadAsStringAsync() ?? Task.FromResult(""));
+                logger.Log(logLevel, "{HttpMethod} {Uri} {StatusCode} {Timing} {Headers} {Body}", request.Method.Method,
+                    request.RequestUri.AbsoluteUri, (int)response.StatusCode, elapsed, RedactAuthorizationHeader(request.Headers), SecuredBody(body));
+            }
+        }
+
+        public void Log(ILogger logger, LogLevel logLevel, HttpRequestMessage request)
+        {
+            if (logger.IsEnabled(logLevel))
+            {
+                logger.Log(logLevel, "{HttpMethod} {Uri} {Headers}", request.Method.Method,
+                    request.RequestUri.AbsoluteUri, RedactAuthorizationHeader(request.Headers));
+            }
+        }
+
+        public void Log(ILogger logger, LogLevel level, HttpRequestMessage request, HttpResponseMessage response, long elapsed)
+        {
+            if (logger.IsEnabled(level))
+            {
+                logger.Log(level, "{HttpMethod} {Uri} {StatusCode} {Timing} {CorrelationId} {ServerTiming}", request.Method.Method,
+                    request.RequestUri.AbsoluteUri, (int)response.StatusCode, elapsed, GetCorrelationId(response.Headers), GetServerTiming(response.Headers));
+            }
+        }
+
+        public void Log(ILogger logger, LogLevel logLevel, HttpRequestMessage request, ApiHttpException exception, long elapsed)
+        {
+            if (logger.IsEnabled(logLevel))
+            {
+                logger.Log(logLevel, "{HttpMethod} {Uri} {StatusCode} {Timing} {CorrelationId} {ServerTiming}", request.Method.Method,
+                    request.RequestUri.AbsoluteUri, exception.StatusCode, elapsed, GetCorrelationId(exception.Headers), GetServerTiming(exception.Headers));
+            }
+        }
+
+
+        private static string RedactAuthorizationHeader(HttpRequestHeaders headers)
+        {
+            var headString = from header in headers
+                where header.Key.ToLower() != "authorization"
+                select header.Key + ": " + string.Join(", ", header.Value);
+
+            return "[" + string.Join(", ", headString) + "]";
+        }
+
+        private static string SecuredBody(string body)
+        {
+            if (body != null)
+                return Regex.Replace(body, "(\"\\w*([Pp]ass|access_token|refresh_token)\\w*\"):\\W*\"[^\"]*\"",
+                "$1:\"**removed from output**\"");
+            return null;
+        }
+
+        private static string GetCorrelationId(ApiHttpHeaders headers)
+        {
+            return headers.GetFirst("X-Correlation-Id") ?? "-";
+        }
+
+        private static string GetCorrelationId(HttpResponseHeaders headers)
+        {
+            return GetHeader(headers, "X-Correlation-ID");
+        }
+
+        private static string GetHeader(HttpResponseHeaders headers, string headerName)
+        {
+            var headerValue = "-";
+
+            if (headers.TryGetValues(headerName, out var values))
+            {
+                headerValue = values.First();
+            }
+
+            return headerValue;
+        }
+
+        private static string GetServerTiming(HttpResponseHeaders headers)
+        {
+            return GetHeader(headers, "Server-Timing");
+        }
+
+        private static string GetServerTiming(ApiHttpHeaders headers)
+        {
+            return headers.GetFirst("Server-Timing") ?? "-";
+        }
+
+    }
+}

commercetools.Sdk/commercetools.Base.Client/DependencyInjectionSetup.cs

@@ -105,17 +105,21 @@ public static IHttpClientBuilder SetupClient(this IServiceCollection services, s
             options ??= new ClientOptions();
             services.AddSingleton<IUserAgentProvider, UserAgentProvider>();
             services.AddSingleton<ILoggerHandlerFactory, LoggerHandlerFactory>();
+            services.AddSingleton<IHttpLogger, DefaultHttpLogger>();
+            services.AddSingleton<ILoggerHandlerOptions, LoggerHandlerOptions>();
             var httpClientBuilder = services.AddHttpClient(clientName)
                 .ConfigureHttpClient((provider, client) =>
                 {
                     if (options.DecompressionMethods.HasFlag(DecompressionMethods.GZip))
                     {
                         client.DefaultRequestHeaders.AcceptEncoding.ParseAdd("gzip");
                     }
+
                     if (options.DecompressionMethods.HasFlag(DecompressionMethods.Deflate))
                     {
                         client.DefaultRequestHeaders.AcceptEncoding.ParseAdd("deflate");
                     }
+
                     var userAgentProvider = provider.GetService<IUserAgentProvider>() ?? new UserAgentProvider();
                     client.DefaultRequestHeaders.UserAgent.ParseAdd(userAgentProvider.UserAgent);
                 })
@@ -126,8 +130,9 @@ public static IHttpClientBuilder SetupClient(this IServiceCollection services, s
                         AutomaticDecompression = options.DecompressionMethods
                     };
                 })
-                .AddHttpMessageHandler(c => new ErrorHandler(message => serializerFactory(c).Deserialize(errorResponseTypeMapper(message), message.ExtractResponseBody())))
-                .AddHttpMessageHandler(c => c.GetService<ILoggerHandlerFactory>().Create());
+                .AddHttpMessageHandler(c => c.GetService<ILoggerHandlerFactory>().Create())
+                .AddHttpMessageHandler(c => new ErrorHandler(message =>
+                    serializerFactory(c).Deserialize(errorResponseTypeMapper(message), message.ExtractResponseBody())));
 
             return httpClientBuilder;
         }

commercetools.Sdk/commercetools.Base.Client/IHttpLogger.cs

@@ -0,0 +1,18 @@
+using System.Net.Http;
+using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
+
+namespace commercetools.Base.Client
+{
+    public interface IHttpLogger
+    {
+        void Log(ILogger logger, LogLevel level, HttpRequestMessage request);
+        void Log(ILogger logger, LogLevel level, HttpRequestMessage request, HttpResponseMessage response, long elapsed);
+        void Log(ILogger logger, LogLevel logLevel, HttpRequestMessage request, ApiHttpException exception, long elapsed);
+
+        Task LogRequestBody(ILogger logger, LogLevel logLevel, HttpRequestMessage request);
+
+        Task LogResponseBody(ILogger logger, LogLevel logLevel, HttpRequestMessage request,
+            HttpResponseMessage response, long elapsed);
+    }
+}

commercetools.Sdk/commercetools.Base.Client/ILoggerHandlerOptions.cs

@@ -0,0 +1,13 @@
+using System;
+using System.Collections.Generic;
+using Microsoft.Extensions.Logging;
+
+namespace commercetools.Base.Client
+{
+    public interface ILoggerHandlerOptions
+    {
+        LogLevel ResponseLogEvent { get; }
+        LogLevel DefaultExceptionLogEvent { get; }
+        Dictionary<Type, LogLevel> ExceptionLogEvents { get; }
+    }
+}

commercetools.Sdk/commercetools.Base.Client/LoggerHandler.cs

@@ -1,4 +1,6 @@
 using System;
+using System.Diagnostics;
+using System.Linq;
 using System.Net.Http;
 using System.Threading;
 using System.Threading.Tasks;
@@ -8,32 +10,54 @@ namespace commercetools.Base.Client
 {
     public class LoggerHandler : DelegatingHandler
     {
-        private readonly ILoggerFactory loggerFactory;
+        private readonly ILoggerFactory _loggerFactory;
 
-        public LoggerHandler(ILoggerFactory loggerFactory)
+        private readonly IHttpLogger _httpLogger;
+
+        private readonly ILoggerHandlerOptions _loggerHandlerOptions;
+
+        public LoggerHandler(ILoggerFactory loggerFactory, IHttpLogger httpLogger = null, ILoggerHandlerOptions options = null)
         {
-            this.loggerFactory = loggerFactory;
+            _loggerFactory = loggerFactory;
+            _httpLogger = httpLogger ?? new DefaultHttpLogger();
+            _loggerHandlerOptions = options ?? new LoggerHandlerOptions();
         }
 
         protected override async Task<HttpResponseMessage> SendAsync(
             HttpRequestMessage request,
             CancellationToken cancellationToken)
         {
-            var logger = this.loggerFactory.CreateLogger("commercetoolsLoggerHandler");
+            var logger = _loggerFactory.CreateLogger("commercetoolsLoggerHandler");
 
             if (request == null)
             {
                 throw new ArgumentNullException(nameof(request));
             }
 
-            using (Log.BeginRequestPipelineScope(logger, request))
+            _httpLogger.Log(logger, LogLevel.Debug, request);
+            await _httpLogger.LogRequestBody(logger, LogLevel.Trace, request).ConfigureAwait(false);
+            var watch = Stopwatch.StartNew();
+            try
             {
-                Log.RequestPipelineStart(logger, request);
                 var response = await base.SendAsync(request, cancellationToken).ConfigureAwait(false);
-                Log.RequestPipelineEnd(logger, response);
-
+                watch.Stop();
+
+                _httpLogger.Log(logger, (int)response.StatusCode < 400 ? _loggerHandlerOptions.ResponseLogEvent : _loggerHandlerOptions.DefaultExceptionLogEvent, request, response, watch.ElapsedMilliseconds);
+                await _httpLogger.LogResponseBody(logger, LogLevel.Trace, request, response, watch.ElapsedMilliseconds);
+
                 return response;
             }
+            catch (ApiHttpException e)
+            {
+                watch.Stop();
+                var defaultLevel = _loggerHandlerOptions.DefaultExceptionLogEvent;
+                var exceptionLevel = _loggerHandlerOptions.ExceptionLogEvents
+                    .Where(pair => pair.Key.IsInstanceOfType(e))
+                    .Select(pair => pair.Value)
+                    .ToArray();
+                _httpLogger.Log(logger, exceptionLevel.Any() ? exceptionLevel.First() : defaultLevel, request, e, watch.ElapsedMilliseconds);
+                throw;
+            }
         }
     }
 }

commercetools.Sdk/commercetools.Base.Client/LoggerHandlerFactory.cs

@@ -5,16 +5,22 @@ namespace commercetools.Base.Client
 {
     public class LoggerHandlerFactory : ILoggerHandlerFactory
     {
-        private readonly ILoggerFactory loggerFactory;
+        private readonly ILoggerFactory _loggerFactory;
 
-        public LoggerHandlerFactory(ILoggerFactory loggerFactory)
+        private readonly IHttpLogger _httpLogger;
+
+        private readonly ILoggerHandlerOptions _handlerOptions;
+
+        public LoggerHandlerFactory(ILoggerFactory loggerFactory, IHttpLogger httpLogger = null, ILoggerHandlerOptions options = null)
         {
-            this.loggerFactory = loggerFactory;
+            _loggerFactory = loggerFactory;
+            _httpLogger = httpLogger;
+            _handlerOptions = options;
         }
 
         public DelegatingHandler Create()
         {
-            return new LoggerHandler(loggerFactory);
+            return new LoggerHandler(_loggerFactory, _httpLogger, _handlerOptions);
         }
     }
 }