diff --git a/commercetools.Sdk/IntegrationTests/commercetools.Api.IntegrationTests/LoggingTest.cs b/commercetools.Sdk/IntegrationTests/commercetools.Api.IntegrationTests/LoggingTest.cs index 27d876d0358..8e45a0d76b3 100644 --- a/commercetools.Sdk/IntegrationTests/commercetools.Api.IntegrationTests/LoggingTest.cs +++ b/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(). + AddEnvironmentVariables("CTP_"). + Build(); + var clientConfiguration = configuration.GetSection("Client").Get(); + var loggerClientConf = new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary() + { + { "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(); + + 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; diff --git a/commercetools.Sdk/IntegrationTests/commercetools.Api.IntegrationTests/ServiceProviderFixture.cs b/commercetools.Sdk/IntegrationTests/commercetools.Api.IntegrationTests/ServiceProviderFixture.cs index 423808a4060..65087d5dcab 100644 --- a/commercetools.Sdk/IntegrationTests/commercetools.Api.IntegrationTests/ServiceProviderFixture.cs +++ b/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() + { + { "Logging:LogLevel:commercetoolsLoggerHandler", "Warning"}, + { "Logging:LogLevel:System.Net.Http.HttpClient", "Warning"}, + }). AddJsonFile("appsettings.test.Development.json", true). AddEnvironmentVariables(). AddUserSecrets(). @@ -28,12 +36,30 @@ public ServiceProviderFixture() var useStreamClient = Enum.Parse(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() ); + services.AddSingleton(new LoggerHandlerOptions() + { + ResponseLogEvent = LogLevel.Information, + DefaultExceptionLogEvent = LogLevel.Warning, + ExceptionLogEvents = new Dictionary() + { + { typeof(NotFoundException), LogLevel.Information }, + { typeof(ConcurrentModificationException), LogLevel.Information} + } + }); this.serviceProvider = services.BuildServiceProvider(); //set default ProjectKey diff --git a/commercetools.Sdk/commercetools.Base.Client/DefaultHttpLogger.cs b/commercetools.Sdk/commercetools.Base.Client/DefaultHttpLogger.cs new file mode 100644 index 00000000000..b0aa49e7b51 --- /dev/null +++ b/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") ?? "-"; + } + + } +} \ No newline at end of file diff --git a/commercetools.Sdk/commercetools.Base.Client/DependencyInjectionSetup.cs b/commercetools.Sdk/commercetools.Base.Client/DependencyInjectionSetup.cs index 114cb3d91da..757227eb346 100644 --- a/commercetools.Sdk/commercetools.Base.Client/DependencyInjectionSetup.cs +++ b/commercetools.Sdk/commercetools.Base.Client/DependencyInjectionSetup.cs @@ -105,6 +105,8 @@ public static IHttpClientBuilder SetupClient(this IServiceCollection services, s options ??= new ClientOptions(); services.AddSingleton(); services.AddSingleton(); + services.AddSingleton(); + services.AddSingleton(); var httpClientBuilder = services.AddHttpClient(clientName) .ConfigureHttpClient((provider, client) => { @@ -112,10 +114,12 @@ public static IHttpClientBuilder SetupClient(this IServiceCollection services, s { client.DefaultRequestHeaders.AcceptEncoding.ParseAdd("gzip"); } + if (options.DecompressionMethods.HasFlag(DecompressionMethods.Deflate)) { client.DefaultRequestHeaders.AcceptEncoding.ParseAdd("deflate"); } + var userAgentProvider = provider.GetService() ?? 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().Create()); + .AddHttpMessageHandler(c => c.GetService().Create()) + .AddHttpMessageHandler(c => new ErrorHandler(message => + serializerFactory(c).Deserialize(errorResponseTypeMapper(message), message.ExtractResponseBody()))); return httpClientBuilder; } diff --git a/commercetools.Sdk/commercetools.Base.Client/IHttpLogger.cs b/commercetools.Sdk/commercetools.Base.Client/IHttpLogger.cs new file mode 100644 index 00000000000..8a4297f3ebe --- /dev/null +++ b/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); + } +} \ No newline at end of file diff --git a/commercetools.Sdk/commercetools.Base.Client/ILoggerHandlerOptions.cs b/commercetools.Sdk/commercetools.Base.Client/ILoggerHandlerOptions.cs new file mode 100644 index 00000000000..778b351c5e9 --- /dev/null +++ b/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 ExceptionLogEvents { get; } + } +} \ No newline at end of file diff --git a/commercetools.Sdk/commercetools.Base.Client/LoggerHandler.cs b/commercetools.Sdk/commercetools.Base.Client/LoggerHandler.cs index 42dcaea4f98..3b3f0626fc1 100644 --- a/commercetools.Sdk/commercetools.Base.Client/LoggerHandler.cs +++ b/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 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; + } } } } \ No newline at end of file diff --git a/commercetools.Sdk/commercetools.Base.Client/LoggerHandlerFactory.cs b/commercetools.Sdk/commercetools.Base.Client/LoggerHandlerFactory.cs index aa0543190ab..c78e977813f 100644 --- a/commercetools.Sdk/commercetools.Base.Client/LoggerHandlerFactory.cs +++ b/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); } } } \ No newline at end of file diff --git a/commercetools.Sdk/commercetools.Base.Client/LoggerHandlerOptions.cs b/commercetools.Sdk/commercetools.Base.Client/LoggerHandlerOptions.cs new file mode 100644 index 00000000000..2d2488e13fc --- /dev/null +++ b/commercetools.Sdk/commercetools.Base.Client/LoggerHandlerOptions.cs @@ -0,0 +1,17 @@ +using System; +using System.Collections.Generic; +using commercetools.Base.Client.Error; +using Microsoft.Extensions.Logging; + +namespace commercetools.Base.Client +{ + public class LoggerHandlerOptions : ILoggerHandlerOptions + { + public LogLevel ResponseLogEvent { get; set; } = LogLevel.Information; + public LogLevel DefaultExceptionLogEvent { get; set; } = LogLevel.Error; + public Dictionary ExceptionLogEvents { get; set; } = new Dictionary() + { + { typeof(NotFoundException), LogLevel.Information } + }; + } +} \ No newline at end of file