From a3b01e2a07ff65fac821a20b790b4cd0736d33db Mon Sep 17 00:00:00 2001 From: Nikita Balabaev Date: Mon, 21 Aug 2023 11:11:55 +0200 Subject: [PATCH] HttpClient logging based on new .NET 8 runtime APIs (#4224) * use new .NET 8 runtime APIs in HttpClient logging * Leverage KeyedServices feature in HttpClient logging (#4253) Co-authored-by: Nikita Balabaev --- .../BenchEnricher.cs | 4 +- eng/common/tools.ps1 | 2 +- .../TaskWaitAsync/TaskExtensions.cs | 2 +- .../Internal/HttpClientLatencyLogEnricher.cs | 5 +- .../Logging/HttpClientLoggingExtensions.cs | 228 ++---- .../Logging/HttpClientLoggingTagNames.cs | 8 +- .../Logging/IHttpClientLogEnricher.cs | 4 +- .../Logging/Internal/HttpClientLogger.cs | 242 ++++++ .../Logging/Internal/HttpHeadersReader.cs | 10 +- .../Logging/Internal/HttpLoggingHandler.cs | 173 ----- .../Logging/Internal/HttpRequestBodyReader.cs | 5 +- .../Logging/Internal/HttpRequestReader.cs | 47 +- .../Internal/HttpResponseBodyReader.cs | 8 +- .../Logging/Internal/Log.cs | 138 +++- .../Logging/Internal/LogRecord.cs | 24 +- .../Internal/LogRecordPooledObjectPolicy.cs | 26 - .../Internal/LoggerMessageStateExtensions.cs | 54 ++ .../Logging/Internal/OptionsExtensions.cs | 27 + .../Internal/ServiceProviderExtensions.cs | 26 + .../Internal/TagCollectorExtensions.cs | 44 -- .../Microsoft.Extensions.Http.Telemetry.json | 6 +- .../Http/RequestMetadata.cs | 2 +- .../Logging/LogMethodHelper.cs | 1 - .../HttpClientLatencyLogEnricherTest.cs | 6 +- .../Logging/AcceptanceTests.cs | 629 +++++++++++++++ ...HandlerTest.cs => HttpClientLoggerTest.cs} | 726 ++++++++---------- .../HttpClientLoggingAcceptanceTest.cs | 74 -- .../HttpClientLoggingExtensionsTest.cs | 537 +------------ ...st.cs => HttpClientLoggingTagNamesTest.cs} | 6 +- .../Logging/HttpHeadersReaderTest.cs | 24 +- .../Logging/HttpRequestBodyReaderTest.cs | 59 +- .../Logging/HttpRequestReaderTest.cs | 124 ++- .../Logging/HttpResponseBodyReaderTest.cs | 45 +- .../Logging/Internal/EmptyEnricher.cs | 3 +- .../Logging/Internal/EnricherWithCounter.cs | 6 +- .../Logging/Internal/HelperExtensions.cs | 22 + .../Logging/Internal/LogRecordExtensions.cs | 17 +- .../Logging/Internal/MockedLogger.cs | 30 - .../Logging/Internal/TestEnricher.cs | 26 +- .../Logging/Internal/TestLoggingHandler.cs | 35 + ...tPolicyTest.cs => LogRecordPoolingTest.cs} | 12 +- .../HttpClientTracingExtensionsTests.cs | 4 +- 42 files changed, 1849 insertions(+), 1622 deletions(-) create mode 100644 src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpClientLogger.cs delete mode 100644 src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpLoggingHandler.cs delete mode 100644 src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/LogRecordPooledObjectPolicy.cs create mode 100644 src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/LoggerMessageStateExtensions.cs create mode 100644 src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/OptionsExtensions.cs create mode 100644 src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/ServiceProviderExtensions.cs delete mode 100644 src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/TagCollectorExtensions.cs create mode 100644 test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/AcceptanceTests.cs rename test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/{HttpLoggingHandlerTest.cs => HttpClientLoggerTest.cs} (61%) delete mode 100644 test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingAcceptanceTest.cs rename test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/{HttpClientLoggingDimensionsTest.cs => HttpClientLoggingTagNamesTest.cs} (81%) delete mode 100644 test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/MockedLogger.cs create mode 100644 test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/TestLoggingHandler.cs rename test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/{LogRecordPooledObjectPolicyTest.cs => LogRecordPoolingTest.cs} (82%) diff --git a/bench/Libraries/Microsoft.Extensions.Http.Telemetry.PerformanceTests/BenchEnricher.cs b/bench/Libraries/Microsoft.Extensions.Http.Telemetry.PerformanceTests/BenchEnricher.cs index 0b3e43f245c..67613a87af5 100644 --- a/bench/Libraries/Microsoft.Extensions.Http.Telemetry.PerformanceTests/BenchEnricher.cs +++ b/bench/Libraries/Microsoft.Extensions.Http.Telemetry.PerformanceTests/BenchEnricher.cs @@ -1,6 +1,7 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System; using System.Net.Http; using Microsoft.Extensions.Telemetry.Enrichment; @@ -11,8 +12,7 @@ internal sealed class BenchEnricher : IHttpClientLogEnricher private const string Key = "Performance in .NET Extensions"; private const string Value = "is paramount."; - public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage? request = null, - HttpResponseMessage? response = null) + public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage request, HttpResponseMessage? response = null, Exception? exception = null) { if (request is not null) { diff --git a/eng/common/tools.ps1 b/eng/common/tools.ps1 index c9eced9f7df..f87bc9423c8 100644 --- a/eng/common/tools.ps1 +++ b/eng/common/tools.ps1 @@ -296,7 +296,7 @@ function InstallDotNet([string] $dotnetRoot, if ($runtime -eq "aspnetcore") { $runtimePath = $runtimePath + "\Microsoft.AspNetCore.App" } if ($runtime -eq "windowsdesktop") { $runtimePath = $runtimePath + "\Microsoft.WindowsDesktop.App" } $runtimePath = $runtimePath + "\" + $version - + $dotnetVersionLabel = "runtime toolset '$runtime/$architecture v$version'" if (Test-Path $runtimePath) { diff --git a/src/LegacySupport/TaskWaitAsync/TaskExtensions.cs b/src/LegacySupport/TaskWaitAsync/TaskExtensions.cs index 271bf7da6b2..07545710797 100644 --- a/src/LegacySupport/TaskWaitAsync/TaskExtensions.cs +++ b/src/LegacySupport/TaskWaitAsync/TaskExtensions.cs @@ -38,7 +38,7 @@ private static async Task WaitTaskAsync(Task task, Ca { var tcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); using (cancellationToken.Register( - static o => ((TaskCompletionSource)o!).SetCanceled(), tcs, false)) + static state => ((TaskCompletionSource)state!).SetCanceled(), tcs, false)) { var t = await Task.WhenAny(task, tcs.Task).ConfigureAwait(false); #pragma warning disable VSTHRD103 // Call async methods when in an async method diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Latency/Internal/HttpClientLatencyLogEnricher.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Latency/Internal/HttpClientLatencyLogEnricher.cs index 4325057bf73..03f9662a287 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Latency/Internal/HttpClientLatencyLogEnricher.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Latency/Internal/HttpClientLatencyLogEnricher.cs @@ -1,6 +1,7 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System; using System.Linq; using System.Net.Http; using System.Net.Http.Headers; @@ -14,7 +15,7 @@ namespace Microsoft.Extensions.Http.Telemetry.Latency.Internal; /// -/// The enrciher appends checkpoints for the outgoing http request. +/// The enricher appends checkpoints for the outgoing http request. /// It also logs the server name from the response header to correlate logs between client and server. /// internal sealed class HttpClientLatencyLogEnricher : IHttpClientLogEnricher @@ -30,7 +31,7 @@ public HttpClientLatencyLogEnricher(HttpClientLatencyContext latencyContext, ILa _enricherInvoked = tokenIssuer.GetCheckpointToken(HttpCheckpoints.EnricherInvoked); } - public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage? request = null, HttpResponseMessage? response = null) + public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage request, HttpResponseMessage? response = null, Exception? exception = null) { if (response != null) { diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/HttpClientLoggingExtensions.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/HttpClientLoggingExtensions.cs index a9e9650e890..bb4dc002060 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/HttpClientLoggingExtensions.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/HttpClientLoggingExtensions.cs @@ -2,15 +2,13 @@ // The .NET Foundation licenses this file to you under the MIT license. using System; -using System.Collections.Generic; using System.Diagnostics.CodeAnalysis; -using System.Linq; using System.Net.Http; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.DependencyInjection.Extensions; using Microsoft.Extensions.Http.Logging; using Microsoft.Extensions.Http.Telemetry.Logging.Internal; -using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; using Microsoft.Extensions.Telemetry.Internal; using Microsoft.Shared.Diagnostics; @@ -22,21 +20,17 @@ namespace Microsoft.Extensions.Http.Telemetry.Logging; /// public static class HttpClientLoggingExtensions { - internal static readonly string HandlerAddedTwiceExceptionMessage = - $"{typeof(HttpLoggingHandler)} was already added either to all HttpClientBuilder's or to the current instance of {typeof(IHttpClientBuilder)}."; - - private static readonly ServiceDescriptor _removeDefaultLoggingFilterDescriptor = ServiceDescriptor.Singleton(); - /// - /// Adds a to collect and emit logs for outgoing requests for all http clients. + /// Adds an to emit logs for outgoing requests for all HTTP clients created with . /// - /// - /// This extension configures outgoing request logs auto collection globally for all http clients. - /// /// The . /// /// instance for chaining. /// + /// + /// All other loggers are removed - including the default one, registered via . + /// + /// Argument is . public static IServiceCollection AddDefaultHttpClientLogging(this IServiceCollection services) { _ = Throw.IfNull(services); @@ -46,49 +40,36 @@ public static IServiceCollection AddDefaultHttpClientLogging(this IServiceCollec .AddHttpHeadersRedactor() .AddOutgoingRequestContext(); - AddBuiltInLoggingRemoverFilter(services, name: null); - + services.TryAddSingleton(); services.TryAddActivatedSingleton(); services.TryAddActivatedSingleton(); - return services.ConfigureAll( - httpClientOptions => - { - httpClientOptions - .HttpMessageHandlerBuilderActions.Add(httpMessageHandlerBuilder => - { - var logger = httpMessageHandlerBuilder.Services.GetRequiredService>(); - var httpRequestReader = httpMessageHandlerBuilder.Services.GetRequiredService(); - var enrichers = httpMessageHandlerBuilder.Services.GetServices(); - var loggingOptions = httpMessageHandlerBuilder.Services.GetRequiredService>(); - - if (httpMessageHandlerBuilder.AdditionalHandlers.Any(handler => handler is HttpLoggingHandler)) - { - Throw.InvalidOperationException(HandlerAddedTwiceExceptionMessage); - } - - httpMessageHandlerBuilder.AdditionalHandlers.Add(new HttpLoggingHandler(logger, httpRequestReader, enrichers, loggingOptions)); - }); - }); + return services.ConfigureHttpClientDefaults( + static httpClientBuilder => + httpClientBuilder + .RemoveAllLoggers() + .AddLogger(wrapHandlersPipeline: true)); } /// - /// Adds a to collect and emit logs for outgoing requests for all http clients. + /// Adds an to emit logs for outgoing requests for all HTTP clients created with . /// - /// - /// This extension configures outgoing request logs auto collection globally for all http clients. - /// /// The . /// The to use for configuring . /// /// instance for chaining. /// + /// + /// All other loggers are removed - including the default one, registered via . + /// + /// Any of the arguments is . [DynamicDependency(DynamicallyAccessedMemberTypes.PublicProperties | DynamicallyAccessedMemberTypes.PublicParameterlessConstructor, typeof(LoggingOptions))] [UnconditionalSuppressMessage("Trimming", "IL2026:Members annotated with 'RequiresUnreferencedCodeAttribute' require dynamic access otherwise can break functionality when trimming application code", Justification = "Addressed with [DynamicDependency]")] public static IServiceCollection AddDefaultHttpClientLogging(this IServiceCollection services, IConfigurationSection section) { + _ = Throw.IfNull(services); _ = Throw.IfNull(section); _ = services @@ -99,18 +80,20 @@ public static IServiceCollection AddDefaultHttpClientLogging(this IServiceCollec } /// - /// Adds a to collect and emit logs for outgoing requests for all http clients. + /// Adds an to emit logs for outgoing requests for all HTTP clients created with . /// - /// - /// This extension configures outgoing request logs auto collection globally for all http clients. - /// /// The . /// The delegate to configure with. /// /// instance for chaining. /// + /// + /// All other loggers are removed - including the default one, registered via . + /// + /// Any of the arguments is . public static IServiceCollection AddDefaultHttpClientLogging(this IServiceCollection services, Action configure) { + _ = Throw.IfNull(services); _ = Throw.IfNull(configure); _ = services @@ -121,49 +104,34 @@ public static IServiceCollection AddDefaultHttpClientLogging(this IServiceCollec } /// - /// Registers HTTP client logging components into . + /// Adds an to emit logs for outgoing requests for a named . /// /// The . /// /// An that can be used to configure the client. /// + /// + /// All other loggers are removed - including the default one, registered via . + /// /// Argument is . public static IHttpClientBuilder AddHttpClientLogging(this IHttpClientBuilder builder) { _ = Throw.IfNull(builder); - _ = builder.Services - .AddOptionsWithValidateOnStart(builder.Name); - - _ = builder.Services - .AddHttpRouteProcessor() - .AddHttpHeadersRedactor() - .AddOutgoingRequestContext(); - - AddBuiltInLoggingRemoverFilter(builder.Services, builder.Name); - - builder.Services.TryAddActivatedSingleton(); - builder.Services.TryAddActivatedSingleton(); - - _ = builder.ConfigureAdditionalHttpMessageHandlers((handlers, _) => - { - if (handlers.Any(handler => handler is HttpLoggingHandler)) - { - Throw.InvalidOperationException(HandlerAddedTwiceExceptionMessage); - } - }); - - return builder.AddHttpMessageHandler(ConfigureHandler(builder)); + return AddNamedClientLoggingInternal(builder); } /// - /// Registers HTTP client logging components into . + /// Adds an to emit logs for outgoing requests for a named . /// /// The . /// The to use for configuring . /// /// An that can be used to configure the client. /// + /// + /// All other loggers are removed - including the default one, registered via . + /// /// Any of the arguments is . [DynamicDependency(DynamicallyAccessedMemberTypes.PublicProperties | DynamicallyAccessedMemberTypes.PublicParameterlessConstructor, typeof(LoggingOptions))] [UnconditionalSuppressMessage("Trimming", @@ -174,31 +142,20 @@ public static IHttpClientBuilder AddHttpClientLogging(this IHttpClientBuilder bu _ = Throw.IfNull(builder); _ = Throw.IfNull(section); - _ = builder.Services - .AddOptionsWithValidateOnStart(builder.Name) - .Bind(section); - - _ = builder.Services - .AddHttpRouteProcessor() - .AddHttpHeadersRedactor() - .AddOutgoingRequestContext(); - - AddBuiltInLoggingRemoverFilter(builder.Services, builder.Name); - - builder.Services.TryAddActivatedSingleton(); - builder.Services.TryAddActivatedSingleton(); - - return builder.AddHttpMessageHandler(ConfigureHandler(builder)); + return AddNamedClientLoggingInternal(builder, options => options.Bind(section)); } /// - /// Registers HTTP client logging components into . + /// Adds an to emit logs for outgoing requests for a named . /// /// The . /// The delegate to configure with. /// /// An that can be used to configure the client. /// + /// + /// All other loggers are removed - including the default one, registered via . + /// /// Any of the arguments is . [DynamicDependency(DynamicallyAccessedMemberTypes.PublicProperties | DynamicallyAccessedMemberTypes.PublicParameterlessConstructor, typeof(LoggingOptions))] [UnconditionalSuppressMessage("Trimming", @@ -209,25 +166,11 @@ public static IHttpClientBuilder AddHttpClientLogging(this IHttpClientBuilder bu _ = Throw.IfNull(builder); _ = Throw.IfNull(configure); - _ = builder.Services - .AddOptionsWithValidateOnStart(builder.Name) - .Configure(configure); - - _ = builder.Services - .AddHttpRouteProcessor() - .AddHttpHeadersRedactor() - .AddOutgoingRequestContext(); - - AddBuiltInLoggingRemoverFilter(builder.Services, builder.Name); - - builder.Services.TryAddActivatedSingleton(); - builder.Services.TryAddActivatedSingleton(); - - return builder.AddHttpMessageHandler(ConfigureHandler(builder)); + return AddNamedClientLoggingInternal(builder, options => options.Configure(configure)); } /// - /// Adds an enricher instance of to the to enrich HTTP client logs. + /// Adds an enricher instance of to the to enrich logs. /// /// Type of enricher. /// The to add the instance of to. @@ -242,85 +185,26 @@ public static IServiceCollection AddHttpClientLogEnricher(this IServiceCollec return services; } - /// - /// Configures DI registration so that a named instance of gets injected into . - /// - /// The . - /// - /// An that can be used to configure the client. - /// - private static Func ConfigureHandler(IHttpClientBuilder builder) - { - return serviceProvider => - { - var loggingOptions = Microsoft.Extensions.Options.Options.Create(serviceProvider - .GetRequiredService>().Get(builder.Name)); - - return ActivatorUtilities.CreateInstance( - serviceProvider, - ActivatorUtilities.CreateInstance( - serviceProvider, - ActivatorUtilities.CreateInstance( - serviceProvider, - loggingOptions), - loggingOptions), - loggingOptions); - }; - } - - private static void AddBuiltInLoggingRemoverFilter(IServiceCollection services, string? name) + private static IHttpClientBuilder AddNamedClientLoggingInternal(IHttpClientBuilder builder, Action>? configureOptionsBuilder = null) { - // We want to remove default logging. To do that we need to modify the builder after the filter that adds logging runs. - // To do that we use another filter that runs after LoggingHttpMessageHandlerBuilderFilter. This is done by inserting - // our filter to the service collection as the first item. That ensures it is in the right position when resolving - // IHttpMessageHandlerBuilderFilter instances. It doesn't matter if AddHttpClient is called before or after. - if (!services.Contains(_removeDefaultLoggingFilterDescriptor)) - { - services.Insert(0, _removeDefaultLoggingFilterDescriptor); - } - - _ = services.Configure(o => o.ClientNames.Add(name)); - } - - private sealed class BuiltInLoggerRemoverFilterOptions - { - // Names of clients to remove built-in logging from. - // A null value means built-in logging is removed globally from clients. - public HashSet ClientNames { get; } = new HashSet(); - } + var optionsBuilder = builder.Services + .AddOptionsWithValidateOnStart(builder.Name); - private sealed class BuiltInLoggingRemoverFilter : IHttpMessageHandlerBuilderFilter - { - private readonly BuiltInLoggerRemoverFilterOptions _options; - private readonly bool _global; + configureOptionsBuilder?.Invoke(optionsBuilder); - [SuppressMessage("Major Code Smell", "S1144:Unused private types or members should be removed", Justification = "This constructor is used by dependency injection.")] - public BuiltInLoggingRemoverFilter(IOptions options) - { - _options = options.Value; - _global = _options.ClientNames.Contains(null); - } + _ = builder.Services + .AddHttpRouteProcessor() + .AddHttpHeadersRedactor() + .AddOutgoingRequestContext(); - public Action Configure(Action next) - { - return (builder) => - { - // Run other configuration first, we want to decorate. - next(builder); + builder.Services.TryAddKeyedSingleton(builder.Name); + builder.Services.TryAddKeyedSingleton(builder.Name); + builder.Services.TryAddKeyedSingleton(builder.Name); - if (_global || _options.ClientNames.Contains(builder.Name)) - { - // Remove the logger handlers added by the filter. Fortunately, they're both public, so it is a simple test on the type. - for (var i = builder.AdditionalHandlers.Count - 1; i >= 0; i--) - { - var handlerType = builder.AdditionalHandlers[i].GetType(); - if (handlerType == typeof(LoggingScopeHttpMessageHandler) || handlerType == typeof(LoggingHttpMessageHandler)) - { - builder.AdditionalHandlers.RemoveAt(i); - } - } - } - }; - } + return builder + .RemoveAllLoggers() + .AddLogger( + serviceProvider => serviceProvider.GetRequiredKeyedService(builder.Name), + wrapHandlersPipeline: true); } } diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/HttpClientLoggingTagNames.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/HttpClientLoggingTagNames.cs index ca2e5534766..83ebcdfa027 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/HttpClientLoggingTagNames.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/HttpClientLoggingTagNames.cs @@ -7,7 +7,7 @@ namespace Microsoft.Extensions.Http.Telemetry.Logging; /// -/// Constants used for HTTP client logging dimensions. +/// Constants used for HTTP client logging tags. /// public static class HttpClientLoggingTagNames { @@ -57,10 +57,10 @@ public static class HttpClientLoggingTagNames public const string StatusCode = "httpStatusCode"; /// - /// Gets a list of all dimension names. + /// Gets a list of all tag names. /// - /// A read-only of all dimension names. - public static IReadOnlyList DimensionNames { get; } = + /// A read-only of all tag names. + public static IReadOnlyList TagNames { get; } = Array.AsReadOnly(new[] { Duration, diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/IHttpClientLogEnricher.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/IHttpClientLogEnricher.cs index da1492e2a93..8f6efd688c8 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/IHttpClientLogEnricher.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/IHttpClientLogEnricher.cs @@ -1,6 +1,7 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System; using System.Net.Http; using Microsoft.Extensions.Telemetry.Enrichment; @@ -17,5 +18,6 @@ public interface IHttpClientLogEnricher /// Tag collector to add tags to. /// object associated with the outgoing HTTP request. /// object associated with the outgoing HTTP request. - void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage? request = null, HttpResponseMessage? response = null); + /// An optional that was thrown within the outgoing HTTP request processing. + void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage request, HttpResponseMessage? response = null, Exception? exception = null); } diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpClientLogger.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpClientLogger.cs new file mode 100644 index 00000000000..a64fc22f1b1 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpClientLogger.cs @@ -0,0 +1,242 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Generic; +using System.Diagnostics.CodeAnalysis; +using System.Linq; +using System.Net.Http; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Http.Logging; +using Microsoft.Extensions.Http.Telemetry.Logging.Internal; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.ObjectPool; +using Microsoft.Extensions.Options; +using Microsoft.Extensions.Telemetry.Logging; +using Microsoft.Shared.Pools; + +namespace Microsoft.Extensions.Http.Telemetry.Logging; + +internal sealed class HttpClientLogger : IHttpClientAsyncLogger +{ + private const string SyncLoggingExceptionMessage = "Synchronous logging is not supported"; + + private readonly ObjectPool>> _headersPool = + PoolFactory.CreateListPool>(); + + private readonly ObjectPool _logRecordPool = + PoolFactory.CreateResettingPool(); + + private readonly bool _logRequestStart; + private readonly bool _logResponseHeaders; + private readonly bool _logRequestHeaders; + private readonly bool _pathParametersRedactionSkipped; + private ILogger _logger; + private IHttpRequestReader _httpRequestReader; + private IHttpClientLogEnricher[] _enrichers; + + public HttpClientLogger( + IServiceProvider serviceProvider, + ILogger logger, + IEnumerable enrichers, + IOptionsMonitor optionsMonitor, + [ServiceKey] string? serviceKey = null) + : this( + logger, + serviceProvider.GetRequiredOrKeyedRequiredService(serviceKey), + enrichers, + optionsMonitor.GetKeyedOrCurrent(serviceKey)) + { + } + + internal HttpClientLogger( + ILogger logger, + IHttpRequestReader httpRequestReader, + IEnumerable enrichers, + LoggingOptions options) + { + _logger = logger; + _httpRequestReader = httpRequestReader; + _enrichers = enrichers.Where(static x => x is not null).ToArray(); + _logRequestStart = options.LogRequestStart; + _logResponseHeaders = options.ResponseHeadersDataClasses.Count > 0; + _logRequestHeaders = options.RequestHeadersDataClasses.Count > 0; + _pathParametersRedactionSkipped = options.RequestPathParameterRedactionMode == HttpRouteParameterRedactionMode.None; + } + + [SuppressMessage("Design", "CA1031:Do not catch general exception types", Justification = "The logger shouldn't throw")] + public async ValueTask LogRequestStartAsync(HttpRequestMessage request, CancellationToken cancellationToken = default) + { + var logRecord = _logRecordPool.Get(); + + List>? requestHeadersBuffer = null; + if (_logRequestHeaders) + { + requestHeadersBuffer = _headersPool.Get(); + } + + try + { + await _httpRequestReader.ReadRequestAsync(logRecord, request, requestHeadersBuffer, cancellationToken).ConfigureAwait(false); + + if (_logRequestStart) + { + Log.OutgoingRequest(_logger, LogLevel.Information, logRecord); + } + + return logRecord; + } + catch (Exception ex) + { + // If redaction is skipped, we can log unredacted request path; otherwise use "logRecord.Path" (even though it might not be set): + var pathToLog = _pathParametersRedactionSkipped + ? request.RequestUri?.AbsolutePath + : logRecord.Path; + + Log.RequestReadError(_logger, ex, request.Method, request.RequestUri?.Host, pathToLog); + + // Return back pooled objects (since the logRecord wasn't fully prepared): + _logRecordPool.Return(logRecord); + + if (requestHeadersBuffer is not null) + { + _headersPool.Return(requestHeadersBuffer); + } + + // Recommendation is to swallow the exception (logger shouldn't throw), so we don't re-throw here: + return null; + } + } + + public async ValueTask LogRequestStopAsync( + object? context, + HttpRequestMessage request, + HttpResponseMessage response, + TimeSpan elapsed, + CancellationToken cancellationToken = default) + => await LogResponseAsync(context, request, response, null, elapsed, cancellationToken).ConfigureAwait(false); + + public async ValueTask LogRequestFailedAsync( + object? context, + HttpRequestMessage request, + HttpResponseMessage? response, + Exception exception, + TimeSpan elapsed, + CancellationToken cancellationToken = default) + => await LogResponseAsync(context, request, response, exception, elapsed, cancellationToken).ConfigureAwait(false); + + public object? LogRequestStart(HttpRequestMessage request) + => throw new NotSupportedException(SyncLoggingExceptionMessage); + + public void LogRequestStop(object? context, HttpRequestMessage request, HttpResponseMessage response, TimeSpan elapsed) + => throw new NotSupportedException(SyncLoggingExceptionMessage); + + public void LogRequestFailed(object? context, HttpRequestMessage request, HttpResponseMessage? response, Exception exception, TimeSpan elapsed) + => throw new NotSupportedException(SyncLoggingExceptionMessage); + + private static LogLevel GetLogLevel(LogRecord logRecord) + { + const int HttpErrorsRangeStart = 400; + const int HttpErrorsRangeEnd = 599; + int statusCode = logRecord.StatusCode!.Value; + + if (statusCode >= HttpErrorsRangeStart && statusCode <= HttpErrorsRangeEnd) + { + return LogLevel.Error; + } + + return LogLevel.Information; + } + + [SuppressMessage("Design", "CA1031:Do not catch general exception types", Justification = "The logger shouldn't throw")] + private async ValueTask LogResponseAsync( + object? context, + HttpRequestMessage request, + HttpResponseMessage? response, + Exception? exception, + TimeSpan elapsed, + CancellationToken cancellationToken) + { + if (context is not LogRecord logRecord) + { + var requestState = response is null + ? "failed" + : "completed"; + + Log.LoggerContextMissing(_logger, exception, requestState, request.Method, request.RequestUri?.Host); + return; + } + + LoggerMessageState? loggerMessageState = null; + List>? responseHeadersBuffer = null; + try + { + if (response is not null) + { + if (_logResponseHeaders) + { + responseHeadersBuffer = _headersPool.Get(); + } + + await _httpRequestReader.ReadResponseAsync(logRecord, response, responseHeadersBuffer, cancellationToken).ConfigureAwait(false); + } + + loggerMessageState = LoggerMessageHelper.ThreadLocalState; + FillLogRecord(logRecord, loggerMessageState, in elapsed, request, response, exception); + + if (exception is null) + { + Log.OutgoingRequest(_logger, GetLogLevel(logRecord), logRecord); + } + else + { + Log.OutgoingRequestError(_logger, logRecord, exception); + } + } + catch (Exception ex) + { + // Logger shouldn't throw, so we just log the exception and don't re-throw it: + Log.ResponseReadError(_logger, ex, request.Method, logRecord.Host, logRecord.Path); + } + finally + { + var requestHeadersBuffer = logRecord.RequestHeaders; // Store the value first, and then return logRecord to the pool. + _logRecordPool.Return(logRecord); + loggerMessageState?.Clear(); + + if (responseHeadersBuffer is not null) + { + _headersPool.Return(responseHeadersBuffer); + } + + if (requestHeadersBuffer is not null) + { + _headersPool.Return(requestHeadersBuffer); + } + } + } + + [SuppressMessage("Design", "CA1031:Do not catch general exception types", + Justification = "We intentionally catch all exception types to make Telemetry code resilient to failures.")] + private void FillLogRecord( + LogRecord logRecord, LoggerMessageState loggerMessageState, in TimeSpan elapsed, + HttpRequestMessage request, HttpResponseMessage? response, Exception? exception) + { + foreach (var enricher in _enrichers) + { + try + { + enricher.Enrich(loggerMessageState, request, response, exception); + } + catch (Exception e) + { + Log.EnrichmentError(_logger, e, enricher.GetType().FullName, request.Method, logRecord.Host, logRecord.Path); + } + } + + logRecord.EnrichmentTags = loggerMessageState; + logRecord.Duration = (long)elapsed.TotalMilliseconds; + } +} diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpHeadersReader.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpHeadersReader.cs index 4af0cb03e5d..d9914a9d0c7 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpHeadersReader.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpHeadersReader.cs @@ -7,9 +7,9 @@ using System.Net.Http; using System.Net.Http.Headers; using Microsoft.Extensions.Compliance.Classification; +using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Options; using Microsoft.Extensions.Telemetry.Internal; -using Microsoft.Shared.Diagnostics; namespace Microsoft.Extensions.Http.Telemetry.Logging.Internal; @@ -19,14 +19,14 @@ internal sealed class HttpHeadersReader : IHttpHeadersReader private readonly FrozenDictionary _responseHeaders; private readonly IHttpHeadersRedactor _redactor; - public HttpHeadersReader(IOptions options, IHttpHeadersRedactor redactor) + public HttpHeadersReader(IOptionsMonitor optionsMonitor, IHttpHeadersRedactor redactor, [ServiceKey] string? serviceKey = null) { - _ = Throw.IfMemberNull(options, options.Value); + var options = optionsMonitor.GetKeyedOrCurrent(serviceKey); _redactor = redactor; - _requestHeaders = options.Value.RequestHeadersDataClasses.ToFrozenDictionary(StringComparer.OrdinalIgnoreCase); - _responseHeaders = options.Value.ResponseHeadersDataClasses.ToFrozenDictionary(StringComparer.OrdinalIgnoreCase); + _requestHeaders = options.RequestHeadersDataClasses.ToFrozenDictionary(StringComparer.OrdinalIgnoreCase); + _responseHeaders = options.ResponseHeadersDataClasses.ToFrozenDictionary(StringComparer.OrdinalIgnoreCase); } public void ReadRequestHeaders(HttpRequestMessage request, List>? destination) diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpLoggingHandler.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpLoggingHandler.cs deleted file mode 100644 index 8331ad288c1..00000000000 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpLoggingHandler.cs +++ /dev/null @@ -1,173 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using System; -using System.Collections.Generic; -using System.Diagnostics.CodeAnalysis; -using System.Linq; -using System.Net.Http; -using System.Threading; -using System.Threading.Tasks; -using Microsoft.Extensions.Logging; -using Microsoft.Extensions.ObjectPool; -using Microsoft.Extensions.Options; -using Microsoft.Extensions.Telemetry.Logging; -using Microsoft.Shared.Diagnostics; -using Microsoft.Shared.Pools; - -namespace Microsoft.Extensions.Http.Telemetry.Logging.Internal; - -/// -/// Handler that logs HTTP client requests./>. -/// -internal sealed class HttpLoggingHandler : DelegatingHandler -{ - internal TimeProvider TimeProvider = TimeProvider.System; - - private readonly IHttpClientLogEnricher[] _enrichers; - private readonly ILogger _logger; - private readonly IHttpRequestReader _httpRequestReader; - - private readonly ObjectPool>> _headersPool = - PoolFactory.CreateListPool>(); - - private readonly ObjectPool _logRecordPool = - PoolFactory.CreatePool(new LogRecordPooledObjectPolicy()); - - private readonly bool _logRequestStart; - private readonly bool _logRequestHeaders; - private readonly bool _logResponseHeaders; - - /// - /// Initializes a new instance of the class. - /// - /// The logger. - /// Handler for reading an HTTP request message. - /// HTTP client log enrichers to enrich log records by. - /// An instance of representing HTTP logging options. - public HttpLoggingHandler( - ILogger logger, - IHttpRequestReader httpRequestReader, - IEnumerable enrichers, - IOptions options) - { - _logger = logger; - _httpRequestReader = httpRequestReader; - _enrichers = enrichers.ToArray(); - _ = Throw.IfMemberNull(options, options.Value); - - _logRequestStart = options.Value.LogRequestStart; - _logResponseHeaders = options.Value.ResponseHeadersDataClasses.Count > 0; - _logRequestHeaders = options.Value.RequestHeadersDataClasses.Count > 0; - } - - /// - /// Sends an HTTP request to the inner handler to send to the server as an asynchronous operation. - /// - /// The HTTP request message to send to the server. - /// A cancellation token to cancel operation. - /// - /// The task object representing the asynchronous operation. - /// - protected override async Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) - { - _ = Throw.IfNull(request); - - var timestamp = TimeProvider.GetTimestamp(); - - var logRecord = _logRecordPool.Get(); - var propertyBag = LogMethodHelper.GetHelper(); - - List>? requestHeadersBuffer = null; - List>? responseHeadersBuffer = null; - - HttpResponseMessage? response = null; - - if (_logRequestHeaders) - { - requestHeadersBuffer = _headersPool.Get(); - } - - try - { - await _httpRequestReader.ReadRequestAsync(logRecord, request, requestHeadersBuffer, cancellationToken).ConfigureAwait(false); - - if (_logRequestStart) - { - Log.OutgoingRequest(_logger, LogLevel.Information, logRecord); - } - - response = await base.SendAsync(request, cancellationToken).ConfigureAwait(false); - - if (_logResponseHeaders) - { - responseHeadersBuffer = _headersPool.Get(); - } - - await _httpRequestReader.ReadResponseAsync(logRecord, response, responseHeadersBuffer, cancellationToken).ConfigureAwait(false); - - FillLogRecord(logRecord, propertyBag, timestamp, request, response); - Log.OutgoingRequest(_logger, GetLogLevel(logRecord), logRecord); - - return response; - } - catch (Exception exception) - { - FillLogRecord(logRecord, propertyBag, timestamp, request, response); - Log.OutgoingRequestError(_logger, logRecord, exception); - - throw; - } - finally - { - _logRecordPool.Return(logRecord); - LogMethodHelper.ReturnHelper(propertyBag); - - if (responseHeadersBuffer is not null) - { - _headersPool.Return(responseHeadersBuffer); - } - - if (requestHeadersBuffer is not null) - { - _headersPool.Return(requestHeadersBuffer); - } - } - } - - private static LogLevel GetLogLevel(LogRecord logRecord) - { - const int HttpErrorsRangeStart = 400; - const int HttpErrorsRangeEnd = 599; - int statusCode = logRecord.StatusCode!.Value; - - if (statusCode >= HttpErrorsRangeStart && statusCode <= HttpErrorsRangeEnd) - { - return LogLevel.Error; - } - - return LogLevel.Information; - } - - [SuppressMessage("Design", "CA1031:Do not catch general exception types", - Justification = "We intentionally catch all exception types to make Telemetry code resilient to failures.")] - private void FillLogRecord( - LogRecord logRecord, LogMethodHelper propertyBag, long timestamp, - HttpRequestMessage request, HttpResponseMessage? response) - { - foreach (var enricher in _enrichers) - { - try - { - enricher.Enrich(propertyBag, request, response); - } - catch (Exception e) - { - Log.EnrichmentError(_logger, e); - } - } - - logRecord.EnrichmentTags = propertyBag; - logRecord.Duration = (long)TimeProvider.GetElapsedTime(timestamp, TimeProvider.GetTimestamp()).TotalMilliseconds; - } -} diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpRequestBodyReader.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpRequestBodyReader.cs index 95048c81bc6..a411ce20beb 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpRequestBodyReader.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpRequestBodyReader.cs @@ -11,7 +11,6 @@ #if NETCOREAPP3_1_OR_GREATER using Microsoft.Extensions.ObjectPool; #endif -using Microsoft.Extensions.Options; using Microsoft.Shared.Diagnostics; #if NETCOREAPP3_1_OR_GREATER using Microsoft.Shared.Pools; @@ -34,10 +33,8 @@ internal sealed class HttpRequestBodyReader private readonly FrozenSet _readableRequestContentTypes; private readonly int _requestReadLimit; - public HttpRequestBodyReader(IOptions options, IDebuggerState? debugger = null) + public HttpRequestBodyReader(LoggingOptions requestOptions, IDebuggerState? debugger = null) { - var requestOptions = Throw.IfMemberNull(options, options.Value); - _readableRequestContentTypes = requestOptions.RequestBodyContentTypes.ToFrozenSet(StringComparer.OrdinalIgnoreCase); debugger ??= DebuggerState.System; _requestReadLimit = requestOptions.BodySizeLimit; diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpRequestReader.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpRequestReader.cs index f1e2b14cfa0..42b929abbb7 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpRequestReader.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpRequestReader.cs @@ -8,6 +8,7 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.Compliance.Classification; +using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Options; using Microsoft.Extensions.Telemetry; using Microsoft.Extensions.Telemetry.Internal; @@ -40,39 +41,59 @@ internal sealed class HttpRequestReader : IHttpRequestReader private readonly IDownstreamDependencyMetadataManager? _downstreamDependencyMetadataManager; public HttpRequestReader( - IOptions options, + IServiceProvider serviceProvider, + IOptionsMonitor optionsMonitor, + IHttpRouteFormatter routeFormatter, + IOutgoingRequestContext requestMetadataContext, + IDownstreamDependencyMetadataManager? downstreamDependencyMetadataManager = null, + [ServiceKey] string? serviceKey = null) + : this( + optionsMonitor.GetKeyedOrCurrent(serviceKey), + routeFormatter, + serviceProvider.GetRequiredOrKeyedRequiredService(serviceKey), + requestMetadataContext, + downstreamDependencyMetadataManager) + { + } + + internal HttpRequestReader( + LoggingOptions options, IHttpRouteFormatter routeFormatter, IHttpHeadersReader httpHeadersReader, IOutgoingRequestContext requestMetadataContext, IDownstreamDependencyMetadataManager? downstreamDependencyMetadataManager = null) { - var optionsValue = Throw.IfMemberNull(options, options.Value); - _routeFormatter = routeFormatter; - _outgoingPathLogMode = Throw.IfOutOfRange(optionsValue.RequestPathLoggingMode); + _outgoingPathLogMode = Throw.IfOutOfRange(options.RequestPathLoggingMode); _httpHeadersReader = httpHeadersReader; + + _routeFormatter = routeFormatter; _requestMetadataContext = requestMetadataContext; _downstreamDependencyMetadataManager = downstreamDependencyMetadataManager; - _defaultSensitiveParameters = optionsValue.RouteParameterDataClasses.ToFrozenDictionary(StringComparer.Ordinal); + _defaultSensitiveParameters = options.RouteParameterDataClasses.ToFrozenDictionary(StringComparer.Ordinal); - if (optionsValue.LogBody) + if (options.LogBody) { - _logRequestBody = optionsValue.RequestBodyContentTypes.Count > 0; - _logResponseBody = optionsValue.ResponseBodyContentTypes.Count > 0; + _logRequestBody = options.RequestBodyContentTypes.Count > 0; + _logResponseBody = options.ResponseBodyContentTypes.Count > 0; } - _logRequestHeaders = optionsValue.RequestHeadersDataClasses.Count > 0; - _logResponseHeaders = optionsValue.ResponseHeadersDataClasses.Count > 0; + _logRequestHeaders = options.RequestHeadersDataClasses.Count > 0; + _logResponseHeaders = options.ResponseHeadersDataClasses.Count > 0; _httpRequestBodyReader = new HttpRequestBodyReader(options); _httpResponseBodyReader = new HttpResponseBodyReader(options); - _routeParameterRedactionMode = optionsValue.RequestPathParameterRedactionMode; + _routeParameterRedactionMode = options.RequestPathParameterRedactionMode; } public async Task ReadRequestAsync(LogRecord logRecord, HttpRequestMessage request, List>? requestHeadersBuffer, CancellationToken cancellationToken) { + logRecord.Host = request.RequestUri?.Host ?? TelemetryConstants.Unknown; + logRecord.Method = request.Method; + logRecord.Path = GetRedactedPath(request); + if (_logRequestHeaders) { _httpHeadersReader.ReadRequestHeaders(request, requestHeadersBuffer); @@ -84,10 +105,6 @@ public async Task ReadRequestAsync(LogRecord logRecord, HttpRequestMessage reque logRecord.RequestBody = await _httpRequestBodyReader.ReadAsync(request, cancellationToken) .ConfigureAwait(false); } - - logRecord.Host = request.RequestUri?.Host ?? TelemetryConstants.Unknown; - logRecord.Method = request.Method; - logRecord.Path = GetRedactedPath(request); } public async Task ReadResponseAsync(LogRecord logRecord, HttpResponseMessage response, diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpResponseBodyReader.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpResponseBodyReader.cs index 9f8ff281fc3..3175303c509 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpResponseBodyReader.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpResponseBodyReader.cs @@ -9,7 +9,6 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.ObjectPool; -using Microsoft.Extensions.Options; using Microsoft.IO; using Microsoft.Shared.Diagnostics; using Microsoft.Shared.Pools; @@ -29,11 +28,8 @@ internal sealed class HttpResponseBodyReader private readonly RecyclableMemoryStreamManager _streamManager; - public HttpResponseBodyReader(IOptions options, IDebuggerState? debugger = null) + public HttpResponseBodyReader(LoggingOptions responseOptions, IDebuggerState? debugger = null) { - _ = Throw.IfMemberNull(options, options.Value); - - var responseOptions = options.Value; _streamManager = new RecyclableMemoryStreamManager(); _readableResponseContentTypes = responseOptions.ResponseBodyContentTypes.ToFrozenSet(StringComparer.OrdinalIgnoreCase); _responseReadLimit = responseOptions.BodySizeLimit; @@ -66,7 +62,7 @@ private static async ValueTask ReadFromStreamAsync(HttpResponseMessage r RecyclableMemoryStreamManager streamManager, CancellationToken cancellationToken) { #if NET5_0_OR_GREATER - var streamToReadFrom = await response.Content!.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false); + var streamToReadFrom = await response.Content.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false); #else var streamToReadFrom = await response.Content.ReadAsStreamAsync().WaitAsync(cancellationToken).ConfigureAwait(false); #endif diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/Log.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/Log.cs index b3050aa3f25..a7024d39bab 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/Log.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/Log.cs @@ -2,6 +2,7 @@ // The .NET Foundation licenses this file to you under the MIT license. using System; +using System.Collections.Generic; using System.Diagnostics.CodeAnalysis; using System.Net.Http; using Microsoft.Extensions.Logging; @@ -12,10 +13,31 @@ namespace Microsoft.Extensions.Http.Telemetry.Logging.Internal; /// /// Logs , and the exceptions due to errors of request/response. /// -[SuppressMessage("Major Code Smell", "S107:Methods should not have too many parameters", Justification = "Workaround because Complex object logging does not support this.")] [SuppressMessage("Major Code Smell", "S109:Magic numbers should not be used", Justification = "Event ID's.")] internal static partial class Log { + internal const string OriginalFormat = "{OriginalFormat}"; + internal const string OriginalFormatValue = "{httpMethod} {httpHost}/{httpPath}"; + + private const int MinimalPropertyCount = 4; + + private const string RequestReadErrorMessage = + "An error occurred while reading the request data to fill the logger context for request: " + + $"{{{HttpClientLoggingTagNames.Method}}} {{{HttpClientLoggingTagNames.Host}}}/{{{HttpClientLoggingTagNames.Path}}}"; + + private const string ResponseReadErrorMessage = + "An error occurred while reading the response data to fill the logger context for request: " + + $"{{{HttpClientLoggingTagNames.Method}}} {{{HttpClientLoggingTagNames.Host}}}/{{{HttpClientLoggingTagNames.Path}}}"; + + private const string LoggerContextMissingMessage = + $"The logger couldn't read its context for {{requestState}} request: {{{HttpClientLoggingTagNames.Method}}} {{{HttpClientLoggingTagNames.Host}}}"; + + private const string EnrichmentErrorMessage = + "An error occurred in enricher '{enricherType}' while enriching the logger context for request: " + + $"{{{HttpClientLoggingTagNames.Method}}} {{{HttpClientLoggingTagNames.Host}}}/{{{HttpClientLoggingTagNames.Path}}}"; + + private static readonly Func _originalFormatValueFMTFunc = OriginalFormatValueFMT; + public static void OutgoingRequest(ILogger logger, LogLevel level, LogRecord record) { OutgoingRequest(logger, level, 1, nameof(OutgoingRequest), record); @@ -26,51 +48,101 @@ public static void OutgoingRequestError(ILogger logger, LogRecord record, Except OutgoingRequest(logger, LogLevel.Error, 2, nameof(OutgoingRequestError), record, exception); } - [LoggerMessage(3, LogLevel.Error, "An error occurred while enriching the log record.")] - public static partial void EnrichmentError(ILogger logger, Exception exception); + [LoggerMessage(LogLevel.Error, RequestReadErrorMessage)] + public static partial void RequestReadError(ILogger logger, Exception exception, HttpMethod httpMethod, string? httpHost, string? httpPath); + + [LoggerMessage(LogLevel.Error, ResponseReadErrorMessage)] + public static partial void ResponseReadError(ILogger logger, Exception exception, HttpMethod httpMethod, string httpHost, string httpPath); + + [LoggerMessage(LogLevel.Error, LoggerContextMissingMessage)] + public static partial void LoggerContextMissing(ILogger logger, Exception? exception, string requestState, HttpMethod httpMethod, string? httpHost); - // Using the code below to avoid every item in ILogger's logRecord State being prefixed with parameter name. + [LoggerMessage(LogLevel.Error, EnrichmentErrorMessage)] + public static partial void EnrichmentError(ILogger logger, Exception exception, string? enricherType, HttpMethod httpMethod, string httpHost, string httpPath); + + // Using the code below instead of generated logging method because we have a custom formatter and custom tag keys for headers. private static void OutgoingRequest( ILogger logger, LogLevel level, int eventId, string eventName, LogRecord record, Exception? exception = null) { - if (logger.IsEnabled(level)) + if (!logger.IsEnabled(level)) { - var collector = record.EnrichmentTags ?? LogMethodHelper.GetHelper(); + return; + } - collector.AddRequestHeaders(record.RequestHeaders); - collector.AddResponseHeaders(record.ResponseHeaders); - collector.Add(HttpClientLoggingTagNames.Host, record.Host); - collector.Add(HttpClientLoggingTagNames.Method, record.Method); - collector.Add(HttpClientLoggingTagNames.Path, record.Path); - collector.Add(HttpClientLoggingTagNames.Duration, record.Duration); + // EnrichmentTags is null when we log request's start: + var loggerMessageState = record.EnrichmentTags ?? LoggerMessageHelper.ThreadLocalState; - if (record.StatusCode is not null) - { - collector.Add(HttpClientLoggingTagNames.StatusCode, record.StatusCode); - } + var statusCodePropertyCount = record.StatusCode.HasValue ? 1 : 0; + var requestHeadersCount = record.RequestHeaders?.Count ?? 0; + var responseHeadersCount = record.ResponseHeaders?.Count ?? 0; - if (!string.IsNullOrEmpty(record.RequestBody)) - { - collector.Add(HttpClientLoggingTagNames.RequestBody, record.RequestBody); - } + var index = loggerMessageState.ReserveTagSpace(MinimalPropertyCount + statusCodePropertyCount + requestHeadersCount + responseHeadersCount); + loggerMessageState.TagArray[index++] = new(HttpClientLoggingTagNames.Method, record.Method); + loggerMessageState.TagArray[index++] = new(HttpClientLoggingTagNames.Host, record.Host); + loggerMessageState.TagArray[index++] = new(HttpClientLoggingTagNames.Path, record.Path); + loggerMessageState.TagArray[index++] = new(HttpClientLoggingTagNames.Duration, record.Duration); - if (!string.IsNullOrEmpty(record.ResponseBody)) - { - collector.Add(HttpClientLoggingTagNames.ResponseBody, record.ResponseBody); - } + if (record.StatusCode.HasValue) + { + loggerMessageState.TagArray[index++] = new(HttpClientLoggingTagNames.StatusCode, record.StatusCode.Value); + } - logger.Log( - level, - new(eventId, eventName), - collector, - exception, - static (_, _) => string.Empty); + if (requestHeadersCount > 0) + { + loggerMessageState.AddRequestHeaders(record.RequestHeaders!, ref index); + } - // Stryker disable once all - if (collector != record.EnrichmentTags) + if (responseHeadersCount > 0) + { + loggerMessageState.AddResponseHeaders(record.ResponseHeaders!, ref index); + } + + if (record.RequestBody is not null) + { + loggerMessageState.AddTag(HttpClientLoggingTagNames.RequestBody, record.RequestBody); + } + + if (record.ResponseBody is not null) + { + loggerMessageState.AddTag(HttpClientLoggingTagNames.ResponseBody, record.ResponseBody); + } + + logger.Log( + level, + new(eventId, eventName), + loggerMessageState, + exception, + _originalFormatValueFMTFunc); + + if (record.EnrichmentTags is null) + { + loggerMessageState.Clear(); + } + } + + private static string OriginalFormatValueFMT(LoggerMessageState request, Exception? _) + { + int startIndex = FindStartIndex(request); + var httpMethod = request[startIndex].Value; + var httpHost = request[startIndex + 1].Value; + var httpPath = request[startIndex + 2].Value; + return FormattableString.Invariant($"{httpMethod} {httpHost}/{httpPath}"); + } + + private static int FindStartIndex(LoggerMessageState request) + { + int startIndex = 0; + + foreach (var kvp in request) + { + if (kvp.Key == HttpClientLoggingTagNames.Method) { - LogMethodHelper.ReturnHelper(collector); + break; } + + startIndex++; } + + return startIndex; } } diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/LogRecord.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/LogRecord.cs index fa615df7f4d..7bee2bec71a 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/LogRecord.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/LogRecord.cs @@ -3,6 +3,7 @@ using System.Collections.Generic; using System.Net.Http; +using Microsoft.Extensions.ObjectPool; using Microsoft.Extensions.Telemetry.Logging; namespace Microsoft.Extensions.Http.Telemetry.Logging.Internal; @@ -10,7 +11,7 @@ namespace Microsoft.Extensions.Http.Telemetry.Logging.Internal; /// /// Parsed HTTP information. /// -internal sealed class LogRecord +internal sealed class LogRecord : IResettable { /// /// Gets or sets HTTP host. @@ -50,15 +51,30 @@ internal sealed class LogRecord /// /// Gets or sets parsed request body. /// - public string RequestBody { get; set; } = string.Empty; + public string? RequestBody { get; set; } /// /// Gets or sets parsed response body. /// - public string ResponseBody { get; set; } = string.Empty; + public string? ResponseBody { get; set; } /// /// Gets or sets enrichment properties. /// - public LogMethodHelper? EnrichmentTags { get; set; } + public LoggerMessageState? EnrichmentTags { get; set; } + + public bool TryReset() + { + Host = string.Empty; + Method = null; + Path = string.Empty; + Duration = 0; + StatusCode = null; + RequestBody = null; + ResponseBody = null; + EnrichmentTags = null; + RequestHeaders = null; + ResponseHeaders = null; + return true; + } } diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/LogRecordPooledObjectPolicy.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/LogRecordPooledObjectPolicy.cs deleted file mode 100644 index b09907f2bd8..00000000000 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/LogRecordPooledObjectPolicy.cs +++ /dev/null @@ -1,26 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using Microsoft.Extensions.ObjectPool; - -namespace Microsoft.Extensions.Http.Telemetry.Logging.Internal; - -internal sealed class LogRecordPooledObjectPolicy : PooledObjectPolicy -{ - public override LogRecord Create() => new(); - - public override bool Return(LogRecord record) - { - record.Host = string.Empty; - record.Method = null; - record.Path = string.Empty; - record.Duration = 0; - record.StatusCode = null; - record.RequestBody = string.Empty; - record.ResponseBody = string.Empty; - record.EnrichmentTags = null; - record.RequestHeaders = null; - record.ResponseHeaders = null; - return true; - } -} diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/LoggerMessageStateExtensions.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/LoggerMessageStateExtensions.cs new file mode 100644 index 00000000000..0b138908d48 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/LoggerMessageStateExtensions.cs @@ -0,0 +1,54 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Collections.Concurrent; +using System.Collections.Generic; +using Microsoft.Extensions.Telemetry.Logging; + +namespace Microsoft.Extensions.Http.Telemetry.Logging.Internal; + +internal static class LoggerMessageStateExtensions +{ + private static readonly ConcurrentDictionary _requestPrefixedNamesCache = new(); + private static readonly ConcurrentDictionary _responsePrefixedNamesCache = new(); + + /// + /// Adds request headers to . + /// + /// A to be filled. + /// A list with request headers. + /// Represents an index to be used when writing tags into . + /// will be mutated to point to the next item. + public static void AddRequestHeaders(this LoggerMessageState state, List> items, ref int index) + { + for (var i = 0; i < items.Count; i++) + { + var key = _requestPrefixedNamesCache.GetOrAdd( + items[i].Key, + static (x, p) => p + x, + HttpClientLoggingTagNames.RequestHeaderPrefix); + + state.TagArray[index++] = new(key, items[i].Value); + } + } + + /// + /// Adds response headers to . + /// + /// A to be filled. + /// A list with response headers. + /// Represents an index to be used when writing tags into . + /// will be mutated to point to the next item. + public static void AddResponseHeaders(this LoggerMessageState state, List> items, ref int index) + { + for (var i = 0; i < items.Count; i++) + { + var key = _responsePrefixedNamesCache.GetOrAdd( + items[i].Key, + static (x, p) => p + x, + HttpClientLoggingTagNames.ResponseHeaderPrefix); + + state.TagArray[index++] = new(key, items[i].Value); + } + } +} diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/OptionsExtensions.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/OptionsExtensions.cs new file mode 100644 index 00000000000..b9868c8b0f7 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/OptionsExtensions.cs @@ -0,0 +1,27 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using Microsoft.Extensions.Options; + +namespace Microsoft.Extensions.Http.Telemetry.Logging.Internal; + +internal static class OptionsExtensions +{ + /// + /// Gets the options for the given service key, or the current value if the service key is . + /// + /// The options type. + /// The to load the options object from. + /// An optional string that specifies the name of the options object to get. + /// The instance. + public static TOptions GetKeyedOrCurrent(this IOptionsMonitor optionsMonitor, string? serviceKey) + where TOptions : class + { + if (serviceKey is null) + { + return optionsMonitor.CurrentValue; + } + + return optionsMonitor.Get(serviceKey); + } +} diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/ServiceProviderExtensions.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/ServiceProviderExtensions.cs new file mode 100644 index 00000000000..838eb62aca9 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/ServiceProviderExtensions.cs @@ -0,0 +1,26 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using Microsoft.Extensions.DependencyInjection; + +namespace Microsoft.Extensions.Http.Telemetry.Logging.Internal; + +internal static class ServiceProviderExtensions +{ + /// + /// Gets a keyed service from the , or a non-keyed service if the key is . + /// + /// The type of service object to get. + /// The to retrieve the service object from. + /// An optional string that specifies the key of service object to get. + /// A service object of type . + /// There is no service of type registered. + public static T GetRequiredOrKeyedRequiredService(this IServiceProvider provider, string? serviceKey) + where T : notnull + { + return serviceKey is null + ? provider.GetRequiredService() + : provider.GetRequiredKeyedService(serviceKey); + } +} diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/TagCollectorExtensions.cs b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/TagCollectorExtensions.cs deleted file mode 100644 index 9a46d544aaa..00000000000 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/TagCollectorExtensions.cs +++ /dev/null @@ -1,44 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using System.Collections.Concurrent; -using System.Collections.Generic; -using Microsoft.Extensions.Telemetry.Logging; - -namespace Microsoft.Extensions.Http.Telemetry.Logging.Internal; - -internal static class TagCollectorExtensions -{ - private static readonly ConcurrentDictionary _requestPrefixedNamesCache = new(); - private static readonly ConcurrentDictionary _responsePrefixedNamesCache = new(); - - public static void AddRequestHeaders(this ITagCollector tags, List>? items) - { - if (items is not null) - { - for (var i = 0; i < items.Count; i++) - { - var key = _requestPrefixedNamesCache.GetOrAdd( - items[i].Key, - static (x, p) => p + x, - HttpClientLoggingTagNames.RequestHeaderPrefix); - tags.Add(key, items[i].Value); - } - } - } - - public static void AddResponseHeaders(this ITagCollector collector, List>? items) - { - if (items is not null) - { - for (var i = 0; i < items.Count; i++) - { - var key = _responsePrefixedNamesCache.GetOrAdd( - items[i].Key, - static (x, p) => p + x, - HttpClientLoggingTagNames.ResponseHeaderPrefix); - collector.Add(key, items[i].Value); - } - } - } -} diff --git a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Microsoft.Extensions.Http.Telemetry.json b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Microsoft.Extensions.Http.Telemetry.json index fb6e9b27efb..9b9d15b7b5b 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Telemetry/Microsoft.Extensions.Http.Telemetry.json +++ b/src/Libraries/Microsoft.Extensions.Http.Telemetry/Microsoft.Extensions.Http.Telemetry.json @@ -121,7 +121,7 @@ ], "Properties": [ { - "Member": "static System.Collections.Generic.IReadOnlyList Microsoft.Extensions.Http.Telemetry.Logging.HttpClientLoggingTagNames.DimensionNames { get; }", + "Member": "static System.Collections.Generic.IReadOnlyList Microsoft.Extensions.Http.Telemetry.Logging.HttpClientLoggingTagNames.TagNames { get; }", "Stage": "Stable" } ] @@ -185,7 +185,7 @@ "Stage": "Stable", "Methods": [ { - "Member": "void Microsoft.Extensions.Http.Telemetry.Logging.IHttpClientLogEnricher.Enrich(Microsoft.Extensions.Telemetry.Enrichment.IEnrichmentTagCollector collector, System.Net.Http.HttpRequestMessage? request = null, System.Net.Http.HttpResponseMessage? response = null);", + "Member": "void Microsoft.Extensions.Http.Telemetry.Logging.IHttpClientLogEnricher.Enrich(Microsoft.Extensions.Telemetry.Enrichment.IEnrichmentTagCollector collector, System.Net.Http.HttpRequestMessage request, System.Net.Http.HttpResponseMessage? response = null, System.Exception? exception = null);", "Stage": "Stable" } ] @@ -289,4 +289,4 @@ ] } ] -} \ No newline at end of file +} diff --git a/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Http/RequestMetadata.cs b/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Http/RequestMetadata.cs index 4a5f14fbd46..f20bd77bff6 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Http/RequestMetadata.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Http/RequestMetadata.cs @@ -59,7 +59,7 @@ public RequestMetadata(string methodType, string requestRoute, string requestNam /// - For outgoing request metrics: RequestName is used as the request name dimension if present, if not provided RequestRoute value would be used instead. /// - For outgoing request traces: It is used as the Display name for the activity i.e. When looking at the E2E trace flow this name is used in the Tree view of traces. /// if not provided RequestRoute value would be used instead. - /// - For outgoing request logs: When present it would be added as an additional dimension to logs. + /// - For outgoing request logs: When present it would be added as an additional tag to logs. /// public string RequestName { get; set; } = TelemetryConstants.Unknown; diff --git a/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Logging/LogMethodHelper.cs b/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Logging/LogMethodHelper.cs index e33b3563b4e..6319fcac9fa 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Logging/LogMethodHelper.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Logging/LogMethodHelper.cs @@ -162,7 +162,6 @@ public static string Stringify(IEnumerable /// A usable instance. - [SuppressMessage("Minor Code Smell", "S4049:Properties should be preferred", Justification = "Not appropriate")] public static LogMethodHelper GetHelper() => _helpers.Get(); /// diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Latency/Internal/HttpClientLatencyLogEnricherTest.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Latency/Internal/HttpClientLatencyLogEnricherTest.cs index 85d7c31c538..f75cf0da6fb 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Latency/Internal/HttpClientLatencyLogEnricherTest.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Latency/Internal/HttpClientLatencyLogEnricherTest.cs @@ -26,7 +26,7 @@ public void HttpClientLatencyLogEnricher_NoOp_OnRequest() var enricher = new HttpClientLatencyLogEnricher(context, lcti.Object); Mock mockEnrichmentPropertyBag = new Mock(); - enricher.Enrich(mockEnrichmentPropertyBag.Object, null, null); + enricher.Enrich(mockEnrichmentPropertyBag.Object, null!, null); mockEnrichmentPropertyBag.Verify(m => m.Add(It.IsAny(), It.IsAny()), Times.Never); } @@ -46,7 +46,7 @@ public void HttpClientLatencyLogEnricher_Enriches_OnResponseWithoutHeader() var enricher = new HttpClientLatencyLogEnricher(context, lcti.Object); Mock mockEnrichmentPropertyBag = new Mock(); - enricher.Enrich(mockEnrichmentPropertyBag.Object, null, httpResponseMessage); + enricher.Enrich(mockEnrichmentPropertyBag.Object, null!, httpResponseMessage); mockEnrichmentPropertyBag.Verify(m => m.Add(It.Is(s => s.Equals("latencyInfo")), It.Is(s => s.Contains("a/b"))), Times.Once); } @@ -68,7 +68,7 @@ public void HttpClientLatencyLogEnricher_Enriches_OnResponseWithHeader() var enricher = new HttpClientLatencyLogEnricher(context, lcti.Object); Mock mockEnrichmentPropertyBag = new Mock(); - enricher.Enrich(mockEnrichmentPropertyBag.Object, null, httpResponseMessage); + enricher.Enrich(mockEnrichmentPropertyBag.Object, null!, httpResponseMessage); mockEnrichmentPropertyBag.Verify(m => m.Add(It.Is(s => s.Equals("latencyInfo")), It.Is(s => s.Contains("a/b") && s.Contains(serverName))), Times.Once); } } diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/AcceptanceTests.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/AcceptanceTests.cs new file mode 100644 index 00000000000..325037b8125 --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/AcceptanceTests.cs @@ -0,0 +1,629 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Generic; +using System.Linq; +using System.Net.Http; +using System.Text; +using System.Threading.Tasks; +using FluentAssertions; +using Microsoft.Extensions.Compliance.Classification; +using Microsoft.Extensions.Compliance.Testing; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Http.Telemetry.Logging.Test.Internal; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Microsoft.Extensions.Telemetry.Testing.Logging; +using Xunit; + +namespace Microsoft.Extensions.Http.Telemetry.Logging.Test; + +public class AcceptanceTests +{ + private const string LoggingCategory = "Microsoft.Extensions.Http.Telemetry.Logging.HttpClientLogger"; + private static readonly Uri _unreachableRequestUri = new("https://we.wont.hit.this.doman.anyway"); + + [Fact] + public async Task AddHttpClientLogEnricher_WhenNullEnricherRegistered_SkipsNullEnrichers() + { + await using var sp = new ServiceCollection() + .AddFakeLogging() + .AddFakeRedaction() + .AddDefaultHttpClientLogging() + .AddHttpClientLogEnricher() + .AddSingleton(static _ => null!) + .BlockRemoteCall() + .BuildServiceProvider(); + + using var httpClient = sp.GetRequiredService().CreateClient(); + using var _ = await httpClient.GetAsync(_unreachableRequestUri).ConfigureAwait(false); + var collector = sp.GetFakeLogCollector(); + var logRecord = Assert.Single(collector.GetSnapshot()); + + // No error should be logged: + Assert.Equal(LogLevel.Information, logRecord.Level); + Assert.Equal(LoggingCategory, logRecord.Category); + Assert.Equal($"{HttpMethod.Get} {_unreachableRequestUri.Host}/{TelemetryConstants.Redacted}", logRecord.Message); + Assert.Null(logRecord.Exception); + + var enrichers = sp.GetServices().ToList(); + var nullEnricher = Assert.Single(enrichers, x => x is null); + Assert.Null(nullEnricher); + + var enricher = Assert.Single(enrichers, x => x is not null); + var testEnricher = Assert.IsType(enricher); + Assert.Equal(1, testEnricher.TimesCalled); + } + + [Fact] + public async Task HttpClientLogger_WhenEnricherThrows_EmitsErrorAndKeepsExecution() + { + await using var sp = new ServiceCollection() + .AddFakeLogging() + .AddFakeRedaction() + .AddDefaultHttpClientLogging() + .AddSingleton(static _ => new TestEnricher(throwOnEnrich: true)) + .BlockRemoteCall() + .BuildServiceProvider(); + + using var httpClient = sp.GetRequiredService().CreateClient(); + using var _ = await httpClient.GetAsync(_unreachableRequestUri).ConfigureAwait(false); + var collector = sp.GetFakeLogCollector(); + Assert.Collection( + collector.GetSnapshot(), + static firstLogRecord => + { + Assert.Equal(LogLevel.Error, firstLogRecord.Level); + Assert.Equal(LoggingCategory, firstLogRecord.Category); + Assert.StartsWith($"An error occurred in enricher '{typeof(TestEnricher).FullName}'", firstLogRecord.Message); + Assert.EndsWith($"{HttpMethod.Get} {_unreachableRequestUri.Host}/{TelemetryConstants.Redacted}", firstLogRecord.Message); + Assert.IsType(firstLogRecord.Exception); + }, + static secondLogRecord => + { + // No error should be logged: + Assert.Equal(LogLevel.Information, secondLogRecord.Level); + Assert.Equal(LoggingCategory, secondLogRecord.Category); + Assert.Equal($"{HttpMethod.Get} {_unreachableRequestUri.Host}/{TelemetryConstants.Redacted}", secondLogRecord.Message); + Assert.Null(secondLogRecord.Exception); + }); + } + + [Fact] + public async Task AddHttpClientLogging_ServiceCollectionAndEnrichers_EnrichesLogsWithAllEnrichers() + { + await using var sp = new ServiceCollection() + .AddFakeLogging() + .AddFakeRedaction() + .AddDefaultHttpClientLogging() + .AddHttpClientLogEnricher() + .AddHttpClientLogEnricher() + .AddHttpClient("testClient").Services + .BlockRemoteCall() + .BuildServiceProvider(); + + using var httpClient = sp.GetRequiredService().CreateClient("testClient"); + using var httpRequestMessage = new HttpRequestMessage + { + Method = HttpMethod.Get, + RequestUri = _unreachableRequestUri, + }; + + _ = await httpClient.SendAsync(httpRequestMessage).ConfigureAwait(false); + var collector = sp.GetFakeLogCollector(); + var logRecord = collector.GetSnapshot().Single(logRecord => logRecord.Category == LoggingCategory); + + Assert.Equal($"{httpRequestMessage.Method} {httpRequestMessage.RequestUri.Host}/{TelemetryConstants.Redacted}", logRecord.Message); + var state = logRecord.StructuredState; + var enricher1 = sp.GetServices().SingleOrDefault(enn => enn is EnricherWithCounter) as EnricherWithCounter; + var enricher2 = sp.GetServices().SingleOrDefault(enn => enn is TestEnricher) as TestEnricher; + + enricher1.Should().NotBeNull(); + enricher2.Should().NotBeNull(); + + enricher1!.TimesCalled.Should().Be(1); + state!.Single(kvp => kvp.Key == enricher2!.KvpRequest.Key).Value.Should().Be(enricher2!.KvpRequest.Value!.ToString()); + } + + [Fact] + public async Task AddHttpClientLogging_WithNamedHttpClients_WorksCorrectly() + { + await using var provider = new ServiceCollection() + .AddFakeLogging() + .AddFakeRedaction() + .AddHttpClient("namedClient1") + .AddHttpClientLogging(o => + { + o.ResponseHeadersDataClasses.Add("ResponseHeader", SimpleClassifications.PrivateData); + o.RequestHeadersDataClasses.Add("RequestHeader", SimpleClassifications.PrivateData); + o.RequestHeadersDataClasses.Add("RequestHeaderFirst", SimpleClassifications.PrivateData); + o.RequestBodyContentTypes.Add("application/json"); + o.ResponseBodyContentTypes.Add("application/json"); + o.LogBody = true; + }).Services + .AddHttpClient("namedClient2") + .AddHttpClientLogging(o => + { + o.ResponseHeadersDataClasses.Add("ResponseHeader", SimpleClassifications.PrivateData); + o.RequestHeadersDataClasses.Add("RequestHeader", SimpleClassifications.PrivateData); + o.RequestHeadersDataClasses.Add("RequestHeaderSecond", SimpleClassifications.PrivateData); + o.RequestBodyContentTypes.Add("application/json"); + o.ResponseBodyContentTypes.Add("application/json"); + o.LogBody = true; + }).Services + .BlockRemoteCall() + .BuildServiceProvider(); + + using var namedClient1 = provider.GetRequiredService().CreateClient("namedClient1"); + using var namedClient2 = provider.GetRequiredService().CreateClient("namedClient2"); + + using var httpRequestMessage = new HttpRequestMessage + { + Method = HttpMethod.Get, + RequestUri = _unreachableRequestUri, + }; + + httpRequestMessage.Headers.Add("requestHeader", "Request Value"); + httpRequestMessage.Headers.Add("ReQuEStHeAdErFirst", new List { "Request Value 2", "Request Value 3" }); + var responseString = await SendRequest(namedClient1, httpRequestMessage); + var collector = provider.GetFakeLogCollector(); + var logRecord = collector.GetSnapshot().Single(l => l.Category == LoggingCategory); + var state = logRecord.State as List>; + state.Should().Contain(kvp => kvp.Value == responseString); + state.Should().Contain(kvp => kvp.Value == "Request Value"); + state.Should().Contain(kvp => kvp.Value == "Request Value 2,Request Value 3"); + + using var httpRequestMessage2 = new HttpRequestMessage + { + Method = HttpMethod.Get, + RequestUri = _unreachableRequestUri, + }; + + httpRequestMessage2.Headers.Add("requestHeader", "Request Value"); + httpRequestMessage2.Headers.Add("ReQuEStHeAdErSecond", new List { "Request Value 2", "Request Value 3" }); + collector.Clear(); + responseString = await SendRequest(namedClient2, httpRequestMessage2); + logRecord = collector.GetSnapshot().Single(l => l.Category == LoggingCategory); + state = logRecord.State as List>; + state.Should().Contain(kvp => kvp.Value == responseString); + state.Should().Contain(kvp => kvp.Value == "Request Value"); + state.Should().Contain(kvp => kvp.Value == "Request Value 2,Request Value 3"); + } + + private static async Task SendRequest(HttpClient httpClient, HttpRequestMessage httpRequestMessage) + { + using var content = await httpClient + .SendAsync(httpRequestMessage, HttpCompletionOption.ResponseHeadersRead) + .ConfigureAwait(false); + + var responseStream = await content.Content.ReadAsStreamAsync(); + var buffer = new byte[32768]; + _ = await responseStream.ReadAsync(buffer, 0, 32768); + return Encoding.UTF8.GetString(buffer); + } + + [Fact] + public async Task AddHttpClientLogging_WithTypedHttpClients_WorksCorrectly() + { + await using var provider = new ServiceCollection() + .AddFakeLogging() + .AddFakeRedaction() + .AddSingleton() + .AddSingleton() + .AddHttpClient() + .AddHttpClientLogging(x => + { + x.ResponseHeadersDataClasses.Add("ResponseHeader", SimpleClassifications.PrivateData); + x.RequestHeadersDataClasses.Add("RequestHeader", SimpleClassifications.PrivateData); + x.RequestHeadersDataClasses.Add("RequestHeader2", SimpleClassifications.PrivateData); + x.RequestBodyContentTypes.Add("application/json"); + x.ResponseBodyContentTypes.Add("application/json"); + x.BodySizeLimit = 10000; + x.LogBody = true; + }).Services + .AddHttpClient() + .AddHttpClientLogging(x => + { + x.ResponseHeadersDataClasses.Add("ResponseHeader", SimpleClassifications.PrivateData); + x.RequestHeadersDataClasses.Add("RequestHeader", SimpleClassifications.PrivateData); + x.RequestHeadersDataClasses.Add("RequestHeader2", SimpleClassifications.PrivateData); + x.RequestBodyContentTypes.Add("application/json"); + x.ResponseBodyContentTypes.Add("application/json"); + x.BodySizeLimit = 20000; + x.LogBody = true; + }).Services + .BlockRemoteCall() + .BuildServiceProvider(); + + var firstClient = provider.GetService() as TestHttpClient1; + var secondClient = provider.GetService() as TestHttpClient2; + + using var httpRequestMessage = new HttpRequestMessage + { + Method = HttpMethod.Get, + RequestUri = _unreachableRequestUri, + }; + + httpRequestMessage.Headers.Add("requestHeader", "Request Value"); + httpRequestMessage.Headers.Add("ReQuEStHeAdEr2", new List { "Request Value 2", "Request Value 3" }); + var content = await firstClient!.SendRequest(httpRequestMessage).ConfigureAwait(false); + var collector = provider.GetFakeLogCollector(); + var responseStream = await content.Content.ReadAsStreamAsync(); + var buffer = new byte[10000]; + _ = await responseStream.ReadAsync(buffer, 0, 10000); + var responseString = Encoding.UTF8.GetString(buffer); + + var logRecord = collector.GetSnapshot().Single(l => l.Category == LoggingCategory); + var state = logRecord.State as List>; + state.Should().Contain(kvp => kvp.Value == responseString); + state.Should().Contain(kvp => kvp.Value == "Request Value"); + state.Should().Contain(kvp => kvp.Value == "Request Value 2,Request Value 3"); + + using var httpRequestMessage2 = new HttpRequestMessage + { + Method = HttpMethod.Get, + RequestUri = _unreachableRequestUri, + }; + + httpRequestMessage2.Headers.Add("requestHeader", "Request Value"); + httpRequestMessage2.Headers.Add("ReQuEStHeAdEr2", new List { "Request Value 2", "Request Value 3" }); + collector.Clear(); + content = await secondClient!.SendRequest(httpRequestMessage2).ConfigureAwait(false); + responseStream = await content.Content.ReadAsStreamAsync(); + buffer = new byte[20000]; + _ = await responseStream.ReadAsync(buffer, 0, 20000); + responseString = Encoding.UTF8.GetString(buffer); + + logRecord = collector.GetSnapshot().Single(l => l.Category == LoggingCategory); + state = logRecord.State as List>; + state.Should().Contain(kvp => kvp.Value == responseString); + state.Should().Contain(kvp => kvp.Value == "Request Value"); + state.Should().Contain(kvp => kvp.Value == "Request Value 2,Request Value 3"); + } + + [Theory] + [InlineData(HttpRouteParameterRedactionMode.Strict, "v1/unit/REDACTED/users/REDACTED:123")] + [InlineData(HttpRouteParameterRedactionMode.Loose, "v1/unit/999/users/REDACTED:123")] + [InlineData(HttpRouteParameterRedactionMode.None, "/v1/unit/999/users/123")] + public async Task AddHttpClientLogging_RedactSensitivePrams(HttpRouteParameterRedactionMode parameterRedactionMode, string redactedPath) + { + const string RequestPath = "https://fake.com/v1/unit/999/users/123"; + + await using var sp = new ServiceCollection() + .AddFakeLogging() + .AddFakeRedaction(o => o.RedactionFormat = "REDACTED:{0}") + .AddHttpClient() + .AddDefaultHttpClientLogging(o => + { + o.RouteParameterDataClasses.Add("userId", SimpleClassifications.PrivateData); + o.RequestPathParameterRedactionMode = parameterRedactionMode; + }) + .BlockRemoteCall() + .BuildServiceProvider(); + + using var httpClient = sp.GetRequiredService().CreateClient(); + using var httpRequestMessage = new HttpRequestMessage + { + Method = HttpMethod.Get, + RequestUri = new Uri(RequestPath), + }; + + var requestContext = sp.GetRequiredService(); + requestContext.SetRequestMetadata(new RequestMetadata + { + RequestRoute = "/v1/unit/{unitId}/users/{userId}" + }); + + _ = await httpClient.SendAsync(httpRequestMessage).ConfigureAwait(false); + + var collector = sp.GetFakeLogCollector(); + var logRecord = collector.GetSnapshot().Single(logRecord => logRecord.Category == LoggingCategory); + var state = logRecord.State as List>; + state!.Single(kvp => kvp.Key == "httpPath").Value.Should().Be(redactedPath); + } + + [Theory] + [InlineData(HttpRouteParameterRedactionMode.Strict, "v1/unit/REDACTED/users/REDACTED:123")] + [InlineData(HttpRouteParameterRedactionMode.Loose, "v1/unit/999/users/REDACTED:123")] + public async Task AddHttpClientLogging_NamedHttpClient_RedactSensitivePrams(HttpRouteParameterRedactionMode parameterRedactionMode, string redactedPath) + { + const string RequestPath = "https://fake.com/v1/unit/999/users/123"; + + await using var sp = new ServiceCollection() + .AddFakeLogging() + .AddFakeRedaction(o => o.RedactionFormat = "REDACTED:{0}") + .AddHttpClient("test") + .AddHttpClientLogging(o => + { + o.RouteParameterDataClasses.Add("userId", SimpleClassifications.PrivateData); + o.RequestPathParameterRedactionMode = parameterRedactionMode; + }) + .Services + .BlockRemoteCall() + .BuildServiceProvider(); + + using var httpClient = sp.GetRequiredService().CreateClient("test"); + using var httpRequestMessage = new HttpRequestMessage + { + Method = HttpMethod.Get, + RequestUri = new Uri(RequestPath), + }; + + var requestContext = sp.GetRequiredService(); + requestContext.SetRequestMetadata(new RequestMetadata + { + RequestRoute = "/v1/unit/{unitId}/users/{userId}" + }); + + using var _ = await httpClient.SendAsync(httpRequestMessage).ConfigureAwait(false); + + var collector = sp.GetFakeLogCollector(); + var logRecord = collector.GetSnapshot().Single(logRecord => logRecord.Category == LoggingCategory); + var state = logRecord.State as List>; + state!.Single(kvp => kvp.Key == "httpPath").Value.Should().Be(redactedPath); + } + + [Fact] + public void AddHttpClientLogging_WithNamedClients_RegistersNamedOptions() + { + const string FirstClientName = "1"; + const string SecondClientName = "2"; + + using var provider = new ServiceCollection() + .AddFakeRedaction() + .AddHttpClient(FirstClientName) + .AddHttpClientLogging(options => + { + options.LogRequestStart = true; + options.ResponseHeadersDataClasses = new Dictionary { { "test1", SimpleClassifications.PrivateData } }; + }) + .Services + .AddHttpClient(SecondClientName) + .AddHttpClientLogging(options => + { + options.LogRequestStart = false; + options.ResponseHeadersDataClasses = new Dictionary { { "test2", SimpleClassifications.PrivateData } }; + }) + .Services + .BuildServiceProvider(); + + var factory = provider.GetRequiredService(); + + var firstClient = factory.CreateClient(FirstClientName); + var secondClient = factory.CreateClient(SecondClientName); + firstClient.Should().NotBe(secondClient); + + var optionsFirst = provider.GetRequiredService>().Get(FirstClientName); + var optionsSecond = provider.GetRequiredService>().Get(SecondClientName); + optionsFirst.Should().NotBeNull(); + optionsSecond.Should().NotBeNull(); + optionsFirst.Should().NotBeEquivalentTo(optionsSecond); + } + + [Fact] + public void AddHttpClientLogging_WithTypedClients_RegistersNamedOptions() + { + using var provider = new ServiceCollection() + .AddFakeRedaction() + .AddSingleton() + .AddSingleton() + .AddHttpClient() + .AddHttpClientLogging(options => + { + options.LogRequestStart = true; + options.ResponseHeadersDataClasses = new Dictionary { { "test1", SimpleClassifications.PrivateData } }; + }) + .Services + .AddHttpClient() + .AddHttpClientLogging(options => + { + options.LogRequestStart = false; + options.ResponseHeadersDataClasses = new Dictionary { { "test2", SimpleClassifications.PrivateData } }; + }) + .Services + .BuildServiceProvider(); + + var firstClient = provider.GetService() as TestHttpClient1; + var secondClient = provider.GetService() as TestHttpClient2; + + firstClient.Should().NotBe(secondClient); + + var optionsFirst = provider.GetRequiredService>().Get(nameof(ITestHttpClient1)); + var optionsSecond = provider.GetRequiredService>().Get(nameof(ITestHttpClient2)); + optionsFirst.Should().NotBeNull(); + optionsSecond.Should().NotBeNull(); + optionsFirst.Should().NotBeEquivalentTo(optionsSecond); + } + + [Fact] + public void AddHttpClientLogging_WithTypedAndNamedClients_RegistersNamedOptions() + { + using var provider = new ServiceCollection() + .AddFakeRedaction() + .AddSingleton() + .AddSingleton() + .AddHttpClient() + .AddHttpClientLogging(options => + { + options.ResponseHeadersDataClasses = new Dictionary { { "test1", SimpleClassifications.PrivateData } }; + }) + .Services + .AddHttpClient() + .AddHttpClientLogging(options => + { + options.ResponseHeadersDataClasses = new Dictionary { { "test2", SimpleClassifications.PrivateData } }; + }) + .Services + .AddHttpClient("testClient3") + .AddHttpClientLogging(options => + { + options.ResponseHeadersDataClasses = new Dictionary { { "test3", SimpleClassifications.PrivateData } }; + }) + .Services + .AddHttpClient("testClient4") + .AddHttpClientLogging(options => + { + options.ResponseHeadersDataClasses = new Dictionary { { "test4", SimpleClassifications.PrivateData } }; + }) + .Services + .AddHttpClient("testClient5") + .AddHttpClientLogging(options => + { + options.ResponseHeadersDataClasses = new Dictionary { { "test5", SimpleClassifications.PrivateData } }; + }) + .Services + .AddDefaultHttpClientLogging(options => + { + options.ResponseHeadersDataClasses = new Dictionary { { "test6", SimpleClassifications.PrivateData } }; + }) + .BuildServiceProvider(); + + var optionsFirst = provider.GetRequiredService>().Get(nameof(ITestHttpClient1)); + var optionsSecond = provider.GetRequiredService>().Get(nameof(ITestHttpClient2)); + var optionsThird = provider.GetRequiredService>().Get("testClient3"); + var optionsFourth = provider.GetRequiredService>().Get("testClient4"); + var optionsFifth = provider.GetRequiredService>().Get("testClient5"); + var optionsSixth = provider.GetRequiredService>().Value; + + optionsFirst.Should().NotBeNull(); + optionsSecond.Should().NotBeNull(); + optionsFirst.Should().NotBeEquivalentTo(optionsSecond); + + optionsThird.Should().NotBeNull(); + optionsFourth.Should().NotBeNull(); + optionsThird.Should().NotBeEquivalentTo(optionsFourth); + + optionsFifth.Should().NotBeNull(); + optionsFifth.Should().NotBeEquivalentTo(optionsFourth); + + optionsSixth.Should().NotBeNull(); + optionsSixth.Should().NotBeEquivalentTo(optionsFifth); + } + + [Fact] + public async Task AddHttpClientLogging_DisablesNetScope() + { + await using var provider = new ServiceCollection() + .AddFakeLogging() + .AddFakeRedaction() + .AddHttpClient("test") + .AddHttpClientLogging() + .Services + .BlockRemoteCall() + .BuildServiceProvider(); + + var options = provider.GetRequiredService>().Get("test"); + var client = provider.GetRequiredService().CreateClient("test"); + using var httpRequestMessage = new HttpRequestMessage(HttpMethod.Get, _unreachableRequestUri); + + _ = await client.SendAsync(httpRequestMessage, HttpCompletionOption.ResponseHeadersRead).ConfigureAwait(false); + var collector = provider.GetFakeLogCollector(); + var logRecord = collector.GetSnapshot().Single(l => l.Category == LoggingCategory); + + logRecord.Scopes.Should().HaveCount(0); + } + + [Fact] + public async Task AddHttpClientLogging_CallFromOtherClient_HasBuiltInLogging() + { + await using var provider = new ServiceCollection() + .AddFakeLogging() + .AddFakeRedaction() + .AddHttpClient("test") + .AddHttpClientLogging() + .Services + .AddHttpClient("normal") + .Services + .BlockRemoteCall() + .BuildServiceProvider(); + + // The test client has AddHttpClientLogging. The normal client doesn't. + // The normal client should still log via the built-in HTTP logging. + var client = provider.GetRequiredService().CreateClient("normal"); + using var httpRequestMessage = new HttpRequestMessage(HttpMethod.Get, _unreachableRequestUri); + + _ = await client.SendAsync(httpRequestMessage, HttpCompletionOption.ResponseHeadersRead).ConfigureAwait(false); + var collector = provider.GetFakeLogCollector(); + var logRecords = collector.GetSnapshot().Where(l => l.Category == "System.Net.Http.HttpClient.normal.LogicalHandler").ToList(); + + Assert.Collection(logRecords, + r => Assert.Equal("RequestPipelineStart", r.Id.Name), + r => Assert.Equal("RequestPipelineEnd", r.Id.Name)); + } + + [Fact] + public async Task AddDefaultHttpClientLogging_DisablesNetScope() + { + await using var provider = new ServiceCollection() + .AddFakeLogging() + .AddFakeRedaction() + .AddHttpClient() + .AddDefaultHttpClientLogging() + .BlockRemoteCall() + .BuildServiceProvider(); + var options = provider.GetRequiredService>().Get("test"); + var client = provider.GetRequiredService().CreateClient("test"); + using var httpRequestMessage = new HttpRequestMessage(HttpMethod.Get, _unreachableRequestUri); + + _ = await client.SendAsync(httpRequestMessage, HttpCompletionOption.ResponseHeadersRead).ConfigureAwait(false); + var collector = provider.GetFakeLogCollector(); + var logRecord = collector.GetSnapshot().Single(l => l.Category == LoggingCategory); + + logRecord.Scopes.Should().HaveCount(0); + } + + [Theory] + [InlineData(4_096)] + [InlineData(8_192)] + [InlineData(16_384)] + [InlineData(32_768)] + [InlineData(315_883)] + public async Task HttpClientLoggingHandler_LogsBodyDataUpToSpecifiedLimit(int limit) + { + await using var provider = new ServiceCollection() + .AddFakeLogging() + .AddFakeRedaction() + .AddHttpClient(nameof(HttpClientLoggingHandler_LogsBodyDataUpToSpecifiedLimit)) + .AddHttpClientLogging(x => + { + x.ResponseHeadersDataClasses.Add("ResponseHeader", SimpleClassifications.PrivateData); + x.RequestHeadersDataClasses.Add("RequestHeader", SimpleClassifications.PrivateData); + x.RequestHeadersDataClasses.Add("RequestHeader2", SimpleClassifications.PrivateData); + x.RequestBodyContentTypes.Add("application/json"); + x.ResponseBodyContentTypes.Add("application/json"); + x.BodySizeLimit = limit; + x.LogBody = true; + }) + .Services + .BlockRemoteCall() + .BuildServiceProvider(); + + var client = provider + .GetRequiredService() + .CreateClient(nameof(HttpClientLoggingHandler_LogsBodyDataUpToSpecifiedLimit)); + + using var httpRequestMessage = new HttpRequestMessage + { + Method = HttpMethod.Get, + RequestUri = _unreachableRequestUri, + }; + + httpRequestMessage.Headers.Add("requestHeader", "Request Value"); + httpRequestMessage.Headers.Add("ReQuEStHeAdEr2", new List { "Request Value 2", "Request Value 3" }); + + var content = await client.SendAsync(httpRequestMessage, HttpCompletionOption.ResponseHeadersRead).ConfigureAwait(false); + var responseStream = await content.Content.ReadAsStreamAsync(); + var length = (int)responseStream.Length > limit ? limit : (int)responseStream.Length; + var buffer = new byte[length]; + _ = await responseStream.ReadAsync(buffer, 0, length); + var responseString = Encoding.UTF8.GetString(buffer); + + var collector = provider.GetFakeLogCollector(); + var logRecord = collector.GetSnapshot().Single(l => l.Category == LoggingCategory); + var state = logRecord.StructuredState; + state.Should().Contain(kvp => kvp.Value == responseString); + state.Should().Contain(kvp => kvp.Value == "Request Value"); + state.Should().Contain(kvp => kvp.Value == "Request Value 2,Request Value 3"); + } +} diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpLoggingHandlerTest.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggerTest.cs similarity index 61% rename from test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpLoggingHandlerTest.cs rename to test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggerTest.cs index 1a5271a3f33..ce43ca284b7 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpLoggingHandlerTest.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggerTest.cs @@ -11,12 +11,12 @@ using System.Threading; using System.Threading.Tasks; using AutoFixture; -using FluentAssertions; using Microsoft.Extensions.Compliance.Classification; using Microsoft.Extensions.Compliance.Testing; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Http.Telemetry.Logging.Internal; using Microsoft.Extensions.Http.Telemetry.Logging.Test.Internal; +using Microsoft.Extensions.Http.Telemetry.Test.Logging.Internal; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Telemetry.Enrichment; @@ -25,12 +25,11 @@ using Microsoft.Extensions.Time.Testing; using Microsoft.Shared.Collections; using Moq; -using Moq.Protected; using Xunit; namespace Microsoft.Extensions.Http.Telemetry.Logging.Test; -public class HttpLoggingHandlerTest +public class HttpClientLoggerTest { private const string TestRequestHeader = "RequestHeader"; private const string TestResponseHeader = "ResponseHeader"; @@ -43,35 +42,36 @@ public class HttpLoggingHandlerTest private readonly Fixture _fixture; - public HttpLoggingHandlerTest() + public HttpClientLoggerTest() { _fixture = new(); } - [Fact] - public void HttpLoggingHandler_NullOptions_Throws() - { - var options = Microsoft.Extensions.Options.Options.Create(null!); - var act = () => new HttpLoggingHandler( - NullLogger.Instance, - Mock.Of(), - Empty.Enumerable(), - options); - - act.Should().Throw(); - } - [Fact] public async Task SendAsync_NullRequest_ThrowsException() { var responseCode = _fixture.Create(); using var httpResponseMessage = new HttpResponseMessage { StatusCode = responseCode }; - using var client = HttpLoggingHandlerTest.CreateClient(httpResponseMessage); + + var options = new LoggingOptions + { + BodyReadTimeout = TimeSpan.FromMinutes(5) + }; + + using var handler = new TestLoggingHandler( + new HttpClientLogger( + NullLogger.Instance, + Mock.Of(), + Empty.Enumerable(), + options), + new TestingHandlerStub((_, _) => Task.FromResult(httpResponseMessage))); + + using var client = new HttpClient(handler); var act = async () => await client.SendAsync(null!, It.IsAny()).ConfigureAwait(false); - await act.Should().ThrowAsync().ConfigureAwait(false); + await Assert.ThrowsAsync(act); } [Fact] @@ -86,16 +86,32 @@ public async Task SendAsync_HttpRequestException_ThrowsException() Content = new StringContent(input, Encoding.UTF8, TextPlain) }; - using var client = HttpLoggingHandlerTest.CreateClientWithException(exception, isLoggingEnabled: false); + var options = new LoggingOptions(); + + var mockHeadersRedactor = new Mock(); + mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) + .Returns(Redacted); + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), mockHeadersRedactor.Object); + + using var handler = new TestLoggingHandler( + new HttpClientLogger( + NullLogger.Instance, + new HttpRequestReader(options, GetHttpRouteFormatter(), headersReader, RequestMetadataContext), + Enumerable.Empty(), + options), + new TestingHandlerStub((_, _) => throw exception)); + + using var client = new HttpClient(handler); var act = async () => await client.SendAsync(httpRequestMessage, It.IsAny()).ConfigureAwait(false); - await act.Should().ThrowAsync().Where(e => e == exception); + var actualException = await Assert.ThrowsAsync(act); + Assert.Same(exception, actualException); } [Fact] - public async Task SendAsync_ReadRequestAsyncThrowsOperationCancelled_ThrowsOperationCancelled() + public async Task Logger_WhenReadRequestAsyncThrows_DoesntThrow() { using var cancellationTokenSource = new CancellationTokenSource(); @@ -107,12 +123,34 @@ public async Task SendAsync_ReadRequestAsyncThrowsOperationCancelled_ThrowsOpera RequestUri = new("http://default-uri.com"), Content = new StringContent(input, Encoding.UTF8, TextPlain) }; - using var httpClient = HttpLoggingHandlerTest.CreateClientWithOperationCanceledException(operationCanceledException); + + var requestReaderMock = new Mock(MockBehavior.Strict); + requestReaderMock.Setup(e => + e.ReadRequestAsync(It.IsAny(), + It.IsAny(), + It.IsAny>>(), + It.IsAny())) + .Throws(operationCanceledException); + + var mockedRequestReader = new MockedRequestReader(requestReaderMock); + + var options = new LoggingOptions(); + + using var handler = new TestLoggingHandler( + new HttpClientLogger( + NullLogger.Instance, + mockedRequestReader, + Enumerable.Empty(), + options), + new TestingHandlerStub((_, _) => Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK)))); + + using var httpClient = new HttpClient(handler); var act = async () => await httpClient.SendAsync(httpRequestMessage, It.IsAny()).ConfigureAwait(false); - await act.Should().ThrowAsync(); + var exception = await Record.ExceptionAsync(act); + Assert.Null(exception); } [Fact] @@ -123,8 +161,6 @@ public async Task HttpLoggingHandler_AllOptions_LogsOutgoingRequest() var testRequestHeaderValue = _fixture.Create(); var testResponseHeaderValue = _fixture.Create(); - var fakeTimeProvider = new FakeTimeProvider(DateTimeOffset.UtcNow); - var testEnricher = new TestEnricher(); var testSharedRequestHeaderKey = $"{HttpClientLoggingTagNames.RequestHeaderPrefix}Header3"; @@ -135,13 +171,12 @@ public async Task HttpLoggingHandler_AllOptions_LogsOutgoingRequest() Host = "default-uri.com", Method = HttpMethod.Post, Path = "foo/bar", - Duration = 1000, StatusCode = 200, ResponseHeaders = new() { new(TestExpectedResponseHeaderKey, Redacted), new(testSharedResponseHeaderKey, Redacted) }, RequestHeaders = new() { new(TestExpectedRequestHeaderKey, Redacted), new(testSharedRequestHeaderKey, Redacted) }, RequestBody = requestContent, ResponseBody = responseContent, - EnrichmentTags = testEnricher.EnrichmentCollector + EnrichmentTags = testEnricher.EnrichmentBag }; using var httpRequestMessage = new HttpRequestMessage @@ -150,6 +185,7 @@ public async Task HttpLoggingHandler_AllOptions_LogsOutgoingRequest() RequestUri = new($"http://{expectedLogRecord.Host}/{expectedLogRecord.Path}"), Content = new StringContent(requestContent, Encoding.UTF8, TextPlain) }; + httpRequestMessage.Headers.Add(TestRequestHeader, testRequestHeaderValue); httpRequestMessage.Headers.Add("Header3", testRequestHeaderValue); @@ -158,10 +194,11 @@ public async Task HttpLoggingHandler_AllOptions_LogsOutgoingRequest() StatusCode = HttpStatusCode.OK, Content = new StringContent(responseContent, Encoding.UTF8, TextPlain), }; + httpResponseMessage.Headers.Add(TestResponseHeader, testResponseHeaderValue); httpResponseMessage.Headers.Add("Header3", testRequestHeaderValue); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions + var options = new LoggingOptions { ResponseHeadersDataClasses = new Dictionary { { TestResponseHeader, SimpleClassifications.PrivateData }, { "Header3", SimpleClassifications.PrivateData } }, RequestHeadersDataClasses = new Dictionary { { TestRequestHeader, SimpleClassifications.PrivateData }, { "Header3", SimpleClassifications.PrivateData } }, @@ -173,51 +210,46 @@ public async Task HttpLoggingHandler_AllOptions_LogsOutgoingRequest() LogRequestStart = false, LogBody = true, RouteParameterDataClasses = { { "userId", SimpleClassifications.PrivateData } }, - }); + }; var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(options, mockHeadersRedactor.Object); + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), mockHeadersRedactor.Object); - var fakeLogger = new FakeLogger(new FakeLogCollector(Microsoft.Extensions.Options.Options.Create(new FakeLogCollectorOptions()))); + var fakeLogger = new FakeLogger(new FakeLogCollector(Options.Options.Create(new FakeLogCollectorOptions()))); - using var handler = new HttpLoggingHandler( + var logger = new HttpClientLogger( fakeLogger, new HttpRequestReader( options, GetHttpRouteFormatter(), headersReader, RequestMetadataContext), new List { testEnricher }, - options) - { - InnerHandler = new TestingHandlerStub((_, _) => - { - fakeTimeProvider.Advance(TimeSpan.FromMilliseconds(1000)); - return Task.FromResult(httpResponseMessage); - }) - }; - handler.TimeProvider = fakeTimeProvider; + options); + + using var handler = new TestLoggingHandler( + logger, + new TestingHandlerStub((_, _) => Task.FromResult(httpResponseMessage))); - using var client = new System.Net.Http.HttpClient(handler); + using var client = new HttpClient(handler); await client.SendAsync(httpRequestMessage, It.IsAny()).ConfigureAwait(false); var logRecords = fakeLogger.Collector.GetSnapshot(); - logRecords.Count.Should().Be(1); - - var logRecord = logRecords[0].GetStructuredState(); - logRecord.Contains(HttpClientLoggingTagNames.Host, expectedLogRecord.Host); - logRecord.Contains(HttpClientLoggingTagNames.Method, expectedLogRecord.Method.ToString()); - logRecord.Contains(HttpClientLoggingTagNames.Path, TelemetryConstants.Redacted); - logRecord.Contains(HttpClientLoggingTagNames.Duration, expectedLogRecord.Duration.ToString(CultureInfo.InvariantCulture)); - logRecord.Contains(HttpClientLoggingTagNames.StatusCode, expectedLogRecord.StatusCode.Value.ToString(CultureInfo.InvariantCulture)); - logRecord.Contains(HttpClientLoggingTagNames.RequestBody, expectedLogRecord.RequestBody); - logRecord.Contains(HttpClientLoggingTagNames.ResponseBody, expectedLogRecord.ResponseBody); - logRecord.Contains(TestExpectedRequestHeaderKey, expectedLogRecord.RequestHeaders[0].Value); - logRecord.Contains(TestExpectedResponseHeaderKey, expectedLogRecord.ResponseHeaders[0].Value); - logRecord.Contains(testSharedResponseHeaderKey, expectedLogRecord.ResponseHeaders[1].Value); - logRecord.Contains(testSharedRequestHeaderKey, expectedLogRecord.RequestHeaders[1].Value); - logRecord.Contains(testEnricher.KvpRequest.Key, expectedLogRecord.GetEnrichmentProperty(testEnricher.KvpRequest.Key)); + var logRecord = Assert.Single(logRecords); + var logRecordState = logRecord.GetStructuredState(); + logRecordState.Contains(HttpClientLoggingTagNames.Host, expectedLogRecord.Host); + logRecordState.Contains(HttpClientLoggingTagNames.Method, expectedLogRecord.Method.ToString()); + logRecordState.Contains(HttpClientLoggingTagNames.Path, TelemetryConstants.Redacted); + logRecordState.Contains(HttpClientLoggingTagNames.Duration, EnsureLogRecordDuration); + logRecordState.Contains(HttpClientLoggingTagNames.StatusCode, expectedLogRecord.StatusCode.Value.ToString(CultureInfo.InvariantCulture)); + logRecordState.Contains(HttpClientLoggingTagNames.RequestBody, expectedLogRecord.RequestBody); + logRecordState.Contains(HttpClientLoggingTagNames.ResponseBody, expectedLogRecord.ResponseBody); + logRecordState.Contains(TestExpectedRequestHeaderKey, expectedLogRecord.RequestHeaders[0].Value); + logRecordState.Contains(TestExpectedResponseHeaderKey, expectedLogRecord.ResponseHeaders[0].Value); + logRecordState.Contains(testSharedResponseHeaderKey, expectedLogRecord.ResponseHeaders[1].Value); + logRecordState.Contains(testSharedRequestHeaderKey, expectedLogRecord.RequestHeaders[1].Value); + logRecordState.Contains(testEnricher.KvpRequest.Key, expectedLogRecord.GetEnrichmentProperty(testEnricher.KvpRequest.Key)); } [Fact] @@ -227,7 +259,6 @@ public async Task HttpLoggingHandler_AllOptionsWithLogRequestStart_LogsOutgoingR var responseContent = _fixture.Create(); var requestHeaderValue = _fixture.Create(); var responseHeaderValue = _fixture.Create(); - var fakeTimeProvider = new FakeTimeProvider(DateTimeOffset.UtcNow); var testEnricher = new TestEnricher(); var expectedLogRecord = new LogRecord @@ -235,13 +266,12 @@ public async Task HttpLoggingHandler_AllOptionsWithLogRequestStart_LogsOutgoingR Host = "default-uri.com", Method = HttpMethod.Post, Path = "foo/bar", - Duration = 1000, StatusCode = 200, ResponseHeaders = new() { new(TestResponseHeader, Redacted) }, RequestHeaders = new() { new(TestRequestHeader, Redacted) }, RequestBody = requestContent, ResponseBody = responseContent, - EnrichmentTags = testEnricher.EnrichmentCollector + EnrichmentTags = testEnricher.EnrichmentBag }; using var httpRequestMessage = new HttpRequestMessage @@ -259,7 +289,7 @@ public async Task HttpLoggingHandler_AllOptionsWithLogRequestStart_LogsOutgoingR }; httpResponseMessage.Headers.Add(TestResponseHeader, responseHeaderValue); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions + var options = new LoggingOptions { ResponseHeadersDataClasses = new Dictionary { { TestResponseHeader, SimpleClassifications.PrivateData } }, RequestHeadersDataClasses = new Dictionary { { TestRequestHeader, SimpleClassifications.PrivateData } }, @@ -271,11 +301,11 @@ public async Task HttpLoggingHandler_AllOptionsWithLogRequestStart_LogsOutgoingR LogRequestStart = true, LogBody = true, RouteParameterDataClasses = { { "userId", SimpleClassifications.PrivateData } }, - }); + }; - var fakeLogger = new FakeLogger( + var fakeLogger = new FakeLogger( new FakeLogCollector( - Microsoft.Extensions.Options.Options.Create( + Options.Options.Create( new FakeLogCollectorOptions()))); var mockHeadersRedactor = new Mock(); @@ -283,30 +313,26 @@ public async Task HttpLoggingHandler_AllOptionsWithLogRequestStart_LogsOutgoingR .Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(options, mockHeadersRedactor.Object); + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), mockHeadersRedactor.Object); - using var handler = new HttpLoggingHandler( + var logger = new HttpClientLogger( fakeLogger, new HttpRequestReader( options, GetHttpRouteFormatter(), headersReader, RequestMetadataContext), new List { testEnricher }, - options) - { - InnerHandler = new TestingHandlerStub((_, _) => - { - fakeTimeProvider.Advance(TimeSpan.FromMilliseconds(1000)); - return Task.FromResult(httpResponseMessage); - }) - }; - handler.TimeProvider = fakeTimeProvider; + options); - using var client = new System.Net.Http.HttpClient(handler); + using var handler = new TestLoggingHandler( + logger, + new TestingHandlerStub((_, _) => Task.FromResult(httpResponseMessage))); + + using var client = new HttpClient(handler); await client.SendAsync(httpRequestMessage, It.IsAny()).ConfigureAwait(false); var logRecords = fakeLogger.Collector.GetSnapshot(); - logRecords.Count.Should().Be(2); + Assert.Equal(2, logRecords.Count); var logRecordRequest = logRecords[0].GetStructuredState(); logRecordRequest.Contains(HttpClientLoggingTagNames.Host, expectedLogRecord.Host); @@ -321,7 +347,7 @@ public async Task HttpLoggingHandler_AllOptionsWithLogRequestStart_LogsOutgoingR logRecordFull.Contains(HttpClientLoggingTagNames.Host, expectedLogRecord.Host); logRecordFull.Contains(HttpClientLoggingTagNames.Method, expectedLogRecord.Method.ToString()); logRecordFull.Contains(HttpClientLoggingTagNames.Path, TelemetryConstants.Redacted); - logRecordFull.Contains(HttpClientLoggingTagNames.Duration, expectedLogRecord.Duration.ToString(CultureInfo.InvariantCulture)); + logRecordFull.Contains(HttpClientLoggingTagNames.Duration, EnsureLogRecordDuration); logRecordFull.Contains(HttpClientLoggingTagNames.StatusCode, expectedLogRecord.StatusCode.Value.ToString(CultureInfo.InvariantCulture)); logRecordFull.Contains(HttpClientLoggingTagNames.RequestBody, expectedLogRecord.RequestBody); logRecordFull.Contains(HttpClientLoggingTagNames.ResponseBody, expectedLogRecord.ResponseBody); @@ -338,7 +364,6 @@ public async Task HttpLoggingHandler_AllOptionsSendAsyncFailed_LogsRequestInform var responseContent = _fixture.Create(); var requestHeaderValue = _fixture.Create(); var responseHeaderValue = _fixture.Create(); - var fakeTimeProvider = new FakeTimeProvider(DateTimeOffset.UtcNow); var testEnricher = new TestEnricher(); var expectedLogRecord = new LogRecord @@ -346,13 +371,12 @@ public async Task HttpLoggingHandler_AllOptionsSendAsyncFailed_LogsRequestInform Host = "default-uri.com", Method = HttpMethod.Post, Path = "foo/bar", - Duration = 1000, StatusCode = 200, ResponseHeaders = new() { new(TestResponseHeader, Redacted) }, RequestHeaders = new() { new(TestRequestHeader, Redacted) }, RequestBody = requestContent, ResponseBody = responseContent, - EnrichmentTags = testEnricher.EnrichmentCollector + EnrichmentTags = testEnricher.EnrichmentBag }; using var httpRequestMessage = new HttpRequestMessage @@ -361,6 +385,7 @@ public async Task HttpLoggingHandler_AllOptionsSendAsyncFailed_LogsRequestInform RequestUri = new($"http://{expectedLogRecord.Host}/{expectedLogRecord.Path}"), Content = new StringContent(requestContent, Encoding.UTF8, TextPlain) }; + httpRequestMessage.Headers.Add(TestRequestHeader, requestHeaderValue); using var httpResponseMessage = new HttpResponseMessage @@ -368,9 +393,10 @@ public async Task HttpLoggingHandler_AllOptionsSendAsyncFailed_LogsRequestInform StatusCode = HttpStatusCode.OK, Content = new StringContent(responseContent, Encoding.UTF8, TextPlain), }; + httpResponseMessage.Headers.Add(TestResponseHeader, responseHeaderValue); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions + var options = new LoggingOptions { ResponseHeadersDataClasses = new Dictionary { { TestResponseHeader, SimpleClassifications.PrivateData } }, RequestHeadersDataClasses = new Dictionary { { TestRequestHeader, SimpleClassifications.PrivateData } }, @@ -382,55 +408,49 @@ public async Task HttpLoggingHandler_AllOptionsSendAsyncFailed_LogsRequestInform LogRequestStart = false, LogBody = true, RouteParameterDataClasses = { { "userId", SimpleClassifications.PrivateData } }, - }); + }; - var fakeLogger = new FakeLogger(new FakeLogCollector(Microsoft.Extensions.Options.Options.Create(new FakeLogCollectorOptions()))); + var fakeLogger = new FakeLogger(new FakeLogCollector(Options.Options.Create(new FakeLogCollectorOptions()))); - var exception = new OperationCanceledException(); + var exception = new TaskCanceledException(); var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(options, mockHeadersRedactor.Object); - - using var handler = new HttpLoggingHandler( - fakeLogger, - new HttpRequestReader( - options, - GetHttpRouteFormatter(), - headersReader, RequestMetadataContext), - new List { testEnricher }, - options) - { - InnerHandler = new TestingHandlerStub((_, _) => - { - fakeTimeProvider.Advance(TimeSpan.FromMilliseconds(expectedLogRecord.Duration)); - throw exception; - }), - TimeProvider = fakeTimeProvider - }; - - using var client = new System.Net.Http.HttpClient(handler); - var act = async () => await client.SendAsync(httpRequestMessage, It.IsAny()).ConfigureAwait(false); - await act.Should().ThrowAsync().ConfigureAwait(false); + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), mockHeadersRedactor.Object); + + using var handler = new TestLoggingHandler( + new HttpClientLogger( + fakeLogger, + new HttpRequestReader( + options, + GetHttpRouteFormatter(), + headersReader, RequestMetadataContext), + new List { testEnricher }, + options), + new TestingHandlerStub((_, _) => throw exception)); + + using var client = new HttpClient(handler); + var act = () => client.SendAsync(httpRequestMessage, CancellationToken.None); + await Assert.ThrowsAsync(act); var logRecords = fakeLogger.Collector.GetSnapshot(); - logRecords.Count.Should().Be(1); - logRecords[0].Message.Should().BeEmpty(); - logRecords[0].Exception.Should().Be(exception); - - var logRecord = logRecords[0].GetStructuredState(); - logRecord.Contains(HttpClientLoggingTagNames.Host, expectedLogRecord.Host); - logRecord.Contains(HttpClientLoggingTagNames.Method, expectedLogRecord.Method.ToString()); - logRecord.Contains(HttpClientLoggingTagNames.Path, TelemetryConstants.Redacted); - logRecord.Contains(HttpClientLoggingTagNames.RequestBody, expectedLogRecord.RequestBody); - logRecord.NotContains(HttpClientLoggingTagNames.ResponseBody); - logRecord.NotContains(HttpClientLoggingTagNames.StatusCode); - logRecord.Contains(TestExpectedRequestHeaderKey, expectedLogRecord.RequestHeaders.FirstOrDefault().Value); - logRecord.Should().NotContain(kvp => kvp.Key.StartsWith(HttpClientLoggingTagNames.ResponseHeaderPrefix)); - logRecord.Contains(testEnricher.KvpRequest.Key, expectedLogRecord.GetEnrichmentProperty(testEnricher.KvpRequest.Key)); - logRecord.NotContains(testEnricher.KvpResponse.Key); - logRecord.Contains(HttpClientLoggingTagNames.Duration, expectedLogRecord.Duration.ToString(CultureInfo.InvariantCulture)); + var logRecord = Assert.Single(logRecords); + Assert.Equal($"{httpRequestMessage.Method} {httpRequestMessage.RequestUri.Host}/{TelemetryConstants.Redacted}", logRecord.Message); + Assert.Same(exception, logRecord.Exception); + + var logRecordState = logRecord.GetStructuredState(); + logRecordState.Contains(HttpClientLoggingTagNames.Host, expectedLogRecord.Host); + logRecordState.Contains(HttpClientLoggingTagNames.Method, expectedLogRecord.Method.ToString()); + logRecordState.Contains(HttpClientLoggingTagNames.Path, TelemetryConstants.Redacted); + logRecordState.Contains(HttpClientLoggingTagNames.RequestBody, expectedLogRecord.RequestBody); + logRecordState.NotContains(HttpClientLoggingTagNames.ResponseBody); + logRecordState.NotContains(HttpClientLoggingTagNames.StatusCode); + logRecordState.Contains(TestExpectedRequestHeaderKey, expectedLogRecord.RequestHeaders.FirstOrDefault().Value); + logRecordState.Contains(testEnricher.KvpRequest.Key, expectedLogRecord.GetEnrichmentProperty(testEnricher.KvpRequest.Key)); + logRecordState.NotContains(testEnricher.KvpResponse.Key); + logRecordState.Contains(HttpClientLoggingTagNames.Duration, EnsureLogRecordDuration); + Assert.DoesNotContain(logRecordState, kvp => kvp.Key.StartsWith(HttpClientLoggingTagNames.ResponseHeaderPrefix)); } [Fact(Skip = "Flaky test, see https://github.com/dotnet/r9/issues/372")] @@ -440,7 +460,6 @@ public async Task HttpLoggingHandler_ReadResponseThrows_LogsException() var responseContent = _fixture.Create(); var requestHeaderValue = _fixture.Create(); var responseHeaderValue = _fixture.Create(); - var fakeTimeProvider = new FakeTimeProvider(DateTimeOffset.UtcNow); var testEnricher = new TestEnricher(); var expectedLogRecord = new LogRecord @@ -448,13 +467,12 @@ public async Task HttpLoggingHandler_ReadResponseThrows_LogsException() Host = "default-uri.com", Method = HttpMethod.Post, Path = "foo/bar", - Duration = 1000, StatusCode = 200, ResponseHeaders = new() { new(TestResponseHeader, Redacted) }, RequestHeaders = new() { new(TestRequestHeader, Redacted) }, RequestBody = requestContent, ResponseBody = responseContent, - EnrichmentTags = testEnricher.EnrichmentCollector + EnrichmentTags = testEnricher.EnrichmentBag }; using var httpRequestMessage = new HttpRequestMessage @@ -463,6 +481,7 @@ public async Task HttpLoggingHandler_ReadResponseThrows_LogsException() RequestUri = new($"http://{expectedLogRecord.Host}/{expectedLogRecord.Path}"), Content = new StringContent(requestContent, Encoding.UTF8, TextPlain) }; + httpRequestMessage.Headers.Add(TestRequestHeader, requestHeaderValue); using var httpResponseMessage = new HttpResponseMessage @@ -470,9 +489,10 @@ public async Task HttpLoggingHandler_ReadResponseThrows_LogsException() StatusCode = HttpStatusCode.OK, Content = new StringContent(responseContent, Encoding.UTF8, TextPlain), }; + httpResponseMessage.Headers.Add(TestResponseHeader, responseHeaderValue); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions + var options = new LoggingOptions { ResponseHeadersDataClasses = new Dictionary { { TestResponseHeader, SimpleClassifications.PrivateData } }, RequestHeadersDataClasses = new Dictionary { { TestRequestHeader, SimpleClassifications.PrivateData } }, @@ -484,17 +504,17 @@ public async Task HttpLoggingHandler_ReadResponseThrows_LogsException() LogRequestStart = false, LogBody = true, RouteParameterDataClasses = { { "userId", SimpleClassifications.PrivateData } }, - }); + }; - var fakeLogger = new FakeLogger( + var fakeLogger = new FakeLogger( new FakeLogCollector( - Microsoft.Extensions.Options.Options.Create(new FakeLogCollectorOptions()))); + Options.Options.Create(new FakeLogCollectorOptions()))); var mockHeadersRedactor = new Mock(); mockHeadersRedactor .Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(options, mockHeadersRedactor.Object); + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), mockHeadersRedactor.Object); var exception = new InvalidOperationException("test"); @@ -518,43 +538,35 @@ public async Task HttpLoggingHandler_ReadResponseThrows_LogsException() It.IsAny())) .ThrowsAsync(exception); - using var handler = new HttpLoggingHandler( - fakeLogger, - mockedRequestReader.Object, - new List { testEnricher }, - options) - { - InnerHandler = new TestingHandlerStub((_, _) => - { - fakeTimeProvider.Advance(TimeSpan.FromMilliseconds(1000)); - return Task.FromResult(httpResponseMessage); - }) - }; - - handler.TimeProvider = fakeTimeProvider; + using var handler = new TestLoggingHandler( + new HttpClientLogger( + fakeLogger, + mockedRequestReader.Object, + new List { testEnricher }, + options), + new TestingHandlerStub((_, _) => Task.FromResult(httpResponseMessage))); - using var client = new System.Net.Http.HttpClient(handler); + using var client = new HttpClient(handler); var act = async () => await client .SendAsync(httpRequestMessage, It.IsAny()) .ConfigureAwait(false); - await act.Should().ThrowAsync().ConfigureAwait(false); + await Assert.ThrowsAsync(act); var logRecords = fakeLogger.Collector.GetSnapshot(); - logRecords.Count.Should().Be(1); - logRecords[0].Exception.Should().Be(exception); - - var logRecord = logRecords[0].GetStructuredState(); - logRecord.Contains(HttpClientLoggingTagNames.Host, expectedLogRecord.Host); - logRecord.Contains(HttpClientLoggingTagNames.Method, expectedLogRecord.Method.ToString()); - logRecord.Contains(HttpClientLoggingTagNames.Path, TelemetryConstants.Redacted); - logRecord.Contains(HttpClientLoggingTagNames.RequestBody, expectedLogRecord.RequestBody); - logRecord.NotContains(HttpClientLoggingTagNames.ResponseBody); - logRecord.NotContains(HttpClientLoggingTagNames.StatusCode); - logRecord.Contains(TestExpectedRequestHeaderKey, expectedLogRecord.RequestHeaders.FirstOrDefault().Value); - logRecord.Should().NotContain(kvp => kvp.Key.StartsWith(HttpClientLoggingTagNames.ResponseHeaderPrefix)); - logRecord.Contains(testEnricher.KvpRequest.Key, expectedLogRecord.GetEnrichmentProperty(testEnricher.KvpRequest.Key)); - logRecord.Contains(testEnricher.KvpResponse.Key, expectedLogRecord.GetEnrichmentProperty(testEnricher.KvpResponse.Key)); - logRecord.Contains(HttpClientLoggingTagNames.Duration, expectedLogRecord.Duration.ToString(CultureInfo.InvariantCulture)); + var logRecord = Assert.Single(logRecords); + + var logRecordState = logRecord.GetStructuredState(); + logRecordState.Contains(HttpClientLoggingTagNames.Host, expectedLogRecord.Host); + logRecordState.Contains(HttpClientLoggingTagNames.Method, expectedLogRecord.Method.ToString()); + logRecordState.Contains(HttpClientLoggingTagNames.Path, TelemetryConstants.Redacted); + logRecordState.Contains(HttpClientLoggingTagNames.RequestBody, expectedLogRecord.RequestBody); + logRecordState.NotContains(HttpClientLoggingTagNames.ResponseBody); + logRecordState.NotContains(HttpClientLoggingTagNames.StatusCode); + logRecordState.Contains(TestExpectedRequestHeaderKey, expectedLogRecord.RequestHeaders.FirstOrDefault().Value); + logRecordState.Contains(testEnricher.KvpRequest.Key, expectedLogRecord.GetEnrichmentProperty(testEnricher.KvpRequest.Key)); + logRecordState.Contains(testEnricher.KvpResponse.Key, expectedLogRecord.GetEnrichmentProperty(testEnricher.KvpResponse.Key)); + logRecordState.Contains(HttpClientLoggingTagNames.Duration, EnsureLogRecordDuration); + Assert.DoesNotContain(logRecordState, kvp => kvp.Key.StartsWith(HttpClientLoggingTagNames.ResponseHeaderPrefix)); } [Fact] @@ -564,7 +576,6 @@ public async Task HttpLoggingHandler_AllOptionsTransferEncodingIsNotChunked_Logs var responseContent = _fixture.Create(); var requestHeaderValue = _fixture.Create(); var responseHeaderValue = _fixture.Create(); - var fakeTimeProvider = new FakeTimeProvider(DateTimeOffset.UtcNow); var testEnricher = new TestEnricher(); var expectedLogRecord = new LogRecord @@ -572,13 +583,12 @@ public async Task HttpLoggingHandler_AllOptionsTransferEncodingIsNotChunked_Logs Host = "default-uri.com", Method = HttpMethod.Post, Path = "foo/bar", - Duration = 1000, StatusCode = 200, ResponseHeaders = new() { new(TestResponseHeader, Redacted) }, RequestHeaders = new() { new(TestRequestHeader, Redacted) }, RequestBody = requestContent, ResponseBody = responseContent, - EnrichmentTags = testEnricher.EnrichmentCollector, + EnrichmentTags = testEnricher.EnrichmentBag, }; using var httpRequestMessage = new HttpRequestMessage @@ -597,7 +607,7 @@ public async Task HttpLoggingHandler_AllOptionsTransferEncodingIsNotChunked_Logs httpResponseMessage.Headers.Add(TestResponseHeader, responseHeaderValue); httpResponseMessage.Headers.TransferEncoding.Add(new("compress")); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions + var options = new LoggingOptions { ResponseHeadersDataClasses = new Dictionary { { TestResponseHeader, SimpleClassifications.PrivateData } }, RequestHeadersDataClasses = new Dictionary { { TestRequestHeader, SimpleClassifications.PrivateData } }, @@ -609,49 +619,43 @@ public async Task HttpLoggingHandler_AllOptionsTransferEncodingIsNotChunked_Logs LogRequestStart = false, LogBody = true, RouteParameterDataClasses = { { "userId", SimpleClassifications.PrivateData } }, - }); + }; - var fakeLogger = new FakeLogger(new FakeLogCollector(Microsoft.Extensions.Options.Options.Create(new FakeLogCollectorOptions()))); + var fakeLogger = new FakeLogger(new FakeLogCollector(Options.Options.Create(new FakeLogCollectorOptions()))); var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(options, mockHeadersRedactor.Object); - - using var handler = new HttpLoggingHandler( - fakeLogger, - new HttpRequestReader( - options, - GetHttpRouteFormatter(), - headersReader, RequestMetadataContext), - new List { testEnricher }, - options) - { - InnerHandler = new TestingHandlerStub((_, _) => - { - fakeTimeProvider.Advance(TimeSpan.FromMilliseconds(1000)); - return Task.FromResult(httpResponseMessage); - }) - }; - handler.TimeProvider = fakeTimeProvider; - - using var client = new System.Net.Http.HttpClient(handler); + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), mockHeadersRedactor.Object); + + using var handler = new TestLoggingHandler( + new HttpClientLogger( + fakeLogger, + new HttpRequestReader( + options, + GetHttpRouteFormatter(), + headersReader, RequestMetadataContext), + new List { testEnricher }, + options), + new TestingHandlerStub((_, _) => Task.FromResult(httpResponseMessage))); + + using var client = new HttpClient(handler); await client.SendAsync(httpRequestMessage, It.IsAny()).ConfigureAwait(false); var logRecords = fakeLogger.Collector.GetSnapshot(); - logRecords.Count.Should().Be(1); - - var logRecord = logRecords[0].GetStructuredState(); - logRecord.Contains(HttpClientLoggingTagNames.Host, expectedLogRecord.Host); - logRecord.Contains(HttpClientLoggingTagNames.Method, expectedLogRecord.Method.ToString()); - logRecord.Contains(HttpClientLoggingTagNames.Path, TelemetryConstants.Redacted); - logRecord.Contains(HttpClientLoggingTagNames.Duration, expectedLogRecord.Duration.ToString(CultureInfo.InvariantCulture)); - logRecord.Contains(HttpClientLoggingTagNames.StatusCode, expectedLogRecord.StatusCode.Value.ToString(CultureInfo.InvariantCulture)); - logRecord.Contains(HttpClientLoggingTagNames.RequestBody, expectedLogRecord.RequestBody); - logRecord.Contains(HttpClientLoggingTagNames.ResponseBody, expectedLogRecord.ResponseBody); - logRecord.Contains(TestExpectedRequestHeaderKey, expectedLogRecord.RequestHeaders.FirstOrDefault().Value); - logRecord.Contains(TestExpectedResponseHeaderKey, expectedLogRecord.ResponseHeaders.FirstOrDefault().Value); - logRecord.Contains(testEnricher.KvpRequest.Key, expectedLogRecord.GetEnrichmentProperty(testEnricher.KvpRequest.Key)); + var logRecord = Assert.Single(logRecords); + + var logRecordState = logRecord.GetStructuredState(); + logRecordState.Contains(HttpClientLoggingTagNames.Host, expectedLogRecord.Host); + logRecordState.Contains(HttpClientLoggingTagNames.Method, expectedLogRecord.Method.ToString()); + logRecordState.Contains(HttpClientLoggingTagNames.Path, TelemetryConstants.Redacted); + logRecordState.Contains(HttpClientLoggingTagNames.Duration, EnsureLogRecordDuration); + logRecordState.Contains(HttpClientLoggingTagNames.StatusCode, expectedLogRecord.StatusCode.Value.ToString(CultureInfo.InvariantCulture)); + logRecordState.Contains(HttpClientLoggingTagNames.RequestBody, expectedLogRecord.RequestBody); + logRecordState.Contains(HttpClientLoggingTagNames.ResponseBody, expectedLogRecord.ResponseBody); + logRecordState.Contains(TestExpectedRequestHeaderKey, expectedLogRecord.RequestHeaders.FirstOrDefault().Value); + logRecordState.Contains(TestExpectedResponseHeaderKey, expectedLogRecord.ResponseHeaders.FirstOrDefault().Value); + logRecordState.Contains(testEnricher.KvpRequest.Key, expectedLogRecord.GetEnrichmentProperty(testEnricher.KvpRequest.Key)); } [Fact] @@ -659,24 +663,25 @@ public async Task HttpLoggingHandler_WithEnrichers_CallsEnrichMethodExactlyOnce( { var enricher1 = new Mock(); var enricher2 = new Mock(); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions()); + var options = new LoggingOptions(); var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var fakeLogger = new FakeLogger(); - using var handler = new HttpLoggingHandler( - fakeLogger, - new HttpRequestReader( - options, - GetHttpRouteFormatter(), - new HttpHeadersReader(options, mockHeadersRedactor.Object), RequestMetadataContext), - new List { enricher1.Object, enricher2.Object }, - options) - { - InnerHandler = new TestingHandlerStub((_, _) => Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK))) - }; - using var client = new System.Net.Http.HttpClient(handler); + var fakeLogger = new FakeLogger(); + using var handler = new TestLoggingHandler( + new HttpClientLogger( + fakeLogger, + new HttpRequestReader( + options, + GetHttpRouteFormatter(), + new HttpHeadersReader(options.ToOptionsMonitor(), mockHeadersRedactor.Object), + RequestMetadataContext), + new List { enricher1.Object, enricher2.Object }, + options), + new TestingHandlerStub((_, _) => Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK)))); + + using var client = new HttpClient(handler); using var httpRequestMessage = new HttpRequestMessage { Method = HttpMethod.Post, @@ -687,10 +692,10 @@ public async Task HttpLoggingHandler_WithEnrichers_CallsEnrichMethodExactlyOnce( await client.SendAsync(httpRequestMessage, It.IsAny()).ConfigureAwait(false); var logRecords = fakeLogger.Collector.GetSnapshot(); - logRecords.Count.Should().Be(1); + _ = Assert.Single(logRecords); - enricher1.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); - enricher2.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); + enricher1.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); + enricher2.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); } [Fact] @@ -698,27 +703,27 @@ public async Task HttpLoggingHandler_WithEnrichersAndLogRequestStart_CallsEnrich { var enricher1 = new Mock(); var enricher2 = new Mock(); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions + var options = new LoggingOptions { LogRequestStart = true - }); + }; var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var fakeLogger = new FakeLogger(); - using var handler = new HttpLoggingHandler( - fakeLogger, - new HttpRequestReader( - options, - GetHttpRouteFormatter(), - new HttpHeadersReader(options, mockHeadersRedactor.Object), RequestMetadataContext), - new List { enricher1.Object, enricher2.Object }, - options) - { - InnerHandler = new TestingHandlerStub((_, _) => Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK))) - }; - - using var client = new System.Net.Http.HttpClient(handler); + var fakeLogger = new FakeLogger(); + using var handler = new TestLoggingHandler( + new HttpClientLogger( + fakeLogger, + new HttpRequestReader( + options, + GetHttpRouteFormatter(), + new HttpHeadersReader(options.ToOptionsMonitor(), mockHeadersRedactor.Object), + RequestMetadataContext), + new List { enricher1.Object, enricher2.Object }, + options), + new TestingHandlerStub((_, _) => Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK)))); + + using var client = new HttpClient(handler); using var httpRequestMessage = new HttpRequestMessage { Method = HttpMethod.Post, @@ -729,10 +734,10 @@ public async Task HttpLoggingHandler_WithEnrichersAndLogRequestStart_CallsEnrich await client.SendAsync(httpRequestMessage, It.IsAny()).ConfigureAwait(false); var logRecords = fakeLogger.Collector.GetSnapshot(); - logRecords.Count.Should().Be(2); + Assert.Equal(2, logRecords.Count); - enricher1.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); - enricher2.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); + enricher1.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); + enricher2.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); } [Fact] @@ -741,23 +746,22 @@ public async Task HttpLoggingHandler_WithEnrichers_OneEnricherThrows_LogsEnrichm var exception = new ArgumentNullException(); var enricher1 = new Mock(); enricher1 - .Setup(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny())) + .Setup(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny())) .Throws(exception); var enricher2 = new Mock(); - var fakeLogger = new FakeLogger(); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions()); - var headersReader = new HttpHeadersReader(options, new Mock().Object); + var fakeLogger = new FakeLogger(); + var options = new LoggingOptions(); + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), Mock.Of()); var requestReader = new HttpRequestReader(options, GetHttpRouteFormatter(), headersReader, RequestMetadataContext); var enrichers = new List { enricher1.Object, enricher2.Object }; - using var handler = new HttpLoggingHandler(fakeLogger, requestReader, enrichers, options) - { - InnerHandler = new TestingHandlerStub( - (_, _) => Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK))) - }; + using var handler = new TestLoggingHandler( + new HttpClientLogger(fakeLogger, requestReader, enrichers, options), + new TestingHandlerStub( + (_, _) => Task.FromResult(new HttpResponseMessage(HttpStatusCode.OK)))); - using var client = new System.Net.Http.HttpClient(handler); + using var client = new HttpClient(handler); using var httpRequestMessage = new HttpRequestMessage { Method = HttpMethod.Post, @@ -768,15 +772,15 @@ public async Task HttpLoggingHandler_WithEnrichers_OneEnricherThrows_LogsEnrichm await client.SendAsync(httpRequestMessage, It.IsAny()).ConfigureAwait(false); var logRecords = fakeLogger.Collector.GetSnapshot(); - logRecords.Count.Should().Be(2); + Assert.Equal(2, logRecords.Count); Assert.Equal(nameof(Log.EnrichmentError), logRecords[0].Id.Name); Assert.Equal(exception, logRecords[0].Exception); Assert.Equal(nameof(Log.OutgoingRequest), logRecords[1].Id.Name); - enricher1.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); - enricher2.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); + enricher1.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); + enricher2.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); } [Fact] @@ -785,24 +789,23 @@ public async Task HttpLoggingHandler_WithEnrichers_SendAsyncAndOneEnricher_LogsE var enrichmentException = new ArgumentNullException(); var enricher1 = new Mock(); enricher1 - .Setup(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny())) + .Setup(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny())) .Throws(enrichmentException) .Verifiable(); var enricher2 = new Mock(); - var fakeLogger = new FakeLogger(); - - var sendAsyncException = new OperationCanceledException(); - using var handler = new HttpLoggingHandler( - fakeLogger, - new Mock().Object, - new List { enricher1.Object, enricher2.Object }, - Microsoft.Extensions.Options.Options.Create(new LoggingOptions())) - { - InnerHandler = new TestingHandlerStub((_, _) => throw sendAsyncException) - }; - - using var client = new System.Net.Http.HttpClient(handler); + var fakeLogger = new FakeLogger(); + + var sendAsyncException = new TaskCanceledException(); + using var handler = new TestLoggingHandler( + new HttpClientLogger( + fakeLogger, + Mock.Of(), + new List { enricher1.Object, enricher2.Object }, + new LoggingOptions()), + new TestingHandlerStub((_, _) => throw sendAsyncException)); + + using var client = new HttpClient(handler); using var httpRequestMessage = new HttpRequestMessage { Method = HttpMethod.Post, @@ -810,11 +813,11 @@ public async Task HttpLoggingHandler_WithEnrichers_SendAsyncAndOneEnricher_LogsE Content = new StringContent(_fixture.Create(), Encoding.UTF8, TextPlain) }; - var act = () => client.SendAsync(httpRequestMessage, It.IsAny()); - await act.Should().ThrowAsync(); + var act = () => client.SendAsync(httpRequestMessage, CancellationToken.None); + await Assert.ThrowsAsync(act); var logRecords = fakeLogger.Collector.GetSnapshot(); - logRecords.Count.Should().Be(2); + Assert.Equal(2, logRecords.Count); Assert.Equal(nameof(Log.EnrichmentError), logRecords[0].Id.Name); Assert.Equal(enrichmentException, logRecords[0].Exception); @@ -822,8 +825,8 @@ public async Task HttpLoggingHandler_WithEnrichers_SendAsyncAndOneEnricher_LogsE Assert.Equal(nameof(Log.OutgoingRequestError), logRecords[1].Id.Name); Assert.Equal(sendAsyncException, logRecords[1].Exception); - enricher1.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); - enricher2.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); + enricher1.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); + enricher2.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny()), Times.Exactly(1)); } [Fact] @@ -847,7 +850,7 @@ public async Task HttpLoggingHandler_AllOptionsTransferEncodingChunked_LogsOutgo RequestHeaders = new() { new(TestExpectedRequestHeaderKey, Redacted) }, RequestBody = requestInput, ResponseBody = responseInput, - EnrichmentTags = testEnricher.EnrichmentCollector + EnrichmentTags = testEnricher.EnrichmentBag }; using var requestContent = new StreamContent(new NotSeekableStream(new(Encoding.UTF8.GetBytes(requestInput)))); @@ -872,7 +875,7 @@ public async Task HttpLoggingHandler_AllOptionsTransferEncodingChunked_LogsOutgo httpResponseMessage.Headers.Add(TestResponseHeader, responseHeaderValue); httpResponseMessage.Headers.TransferEncoding.Add(new("chunked")); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions + var options = new LoggingOptions { ResponseHeadersDataClasses = new Dictionary { { TestResponseHeader, SimpleClassifications.PrivateData } }, RequestHeadersDataClasses = new Dictionary { { TestRequestHeader, SimpleClassifications.PrivateData } }, @@ -884,43 +887,40 @@ public async Task HttpLoggingHandler_AllOptionsTransferEncodingChunked_LogsOutgo LogRequestStart = false, LogBody = true, RouteParameterDataClasses = { { "userId", SimpleClassifications.PrivateData } }, - }); + }; - var fakeLogger = new FakeLogger(new FakeLogCollector(Microsoft.Extensions.Options.Options.Create(new FakeLogCollectorOptions()))); + var fakeLogger = new FakeLogger(new FakeLogCollector(Options.Options.Create(new FakeLogCollectorOptions()))); var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(options, mockHeadersRedactor.Object); - - using var handler = new HttpLoggingHandler( - fakeLogger, - new HttpRequestReader( - options, - GetHttpRouteFormatter(), - headersReader, RequestMetadataContext), - new List { testEnricher }, - options) - { - InnerHandler = new TestingHandlerStub((_, _) => + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), mockHeadersRedactor.Object); + + using var handler = new TestLoggingHandler( + new HttpClientLogger( + fakeLogger, + new HttpRequestReader( + options, + GetHttpRouteFormatter(), + headersReader, RequestMetadataContext), + new List { testEnricher }, + options), + new TestingHandlerStub((_, _) => { fakeTimeProvider.Advance(TimeSpan.FromMilliseconds(1000)); return Task.FromResult(httpResponseMessage); - }) - }; - handler.TimeProvider = fakeTimeProvider; + })); - using var client = new System.Net.Http.HttpClient(handler); + using var client = new HttpClient(handler); await client.SendAsync(httpRequestMessage, It.IsAny()).ConfigureAwait(false); var logRecords = fakeLogger.Collector.GetSnapshot(); - logRecords.Count.Should().Be(1); + var logRecord = Assert.Single(logRecords).GetStructuredState(); - var logRecord = logRecords[0].GetStructuredState(); logRecord.Contains(HttpClientLoggingTagNames.Host, expectedLogRecord.Host); logRecord.Contains(HttpClientLoggingTagNames.Method, expectedLogRecord.Method.ToString()); logRecord.Contains(HttpClientLoggingTagNames.Path, TelemetryConstants.Redacted); - logRecord.Contains(HttpClientLoggingTagNames.Duration, expectedLogRecord.Duration.ToString(CultureInfo.InvariantCulture)); + logRecord.Contains(HttpClientLoggingTagNames.Duration, EnsureLogRecordDuration); logRecord.Contains(HttpClientLoggingTagNames.StatusCode, expectedLogRecord.StatusCode.Value.ToString(CultureInfo.InvariantCulture)); logRecord.Contains(HttpClientLoggingTagNames.RequestBody, expectedLogRecord.RequestBody); logRecord.Contains(HttpClientLoggingTagNames.ResponseBody, expectedLogRecord.ResponseBody); @@ -939,125 +939,68 @@ public async Task HttpLoggingHandler_AllOptionsTransferEncodingChunked_LogsOutgo public async Task HttpLoggingHandler_OnDifferentHttpStatusCodes_LogsOutgoingRequestWithAppropriateLogLevel( int httpStatusCode, LogLevel expectedLogLevel) { - var fakeLogger = new FakeLogger(new FakeLogCollector()); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions()); - var headersReader = new HttpHeadersReader(options, new Mock().Object); + var fakeLogger = new FakeLogger(); + var options = new LoggingOptions(); + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), new Mock().Object); var requestReader = new HttpRequestReader( options, GetHttpRouteFormatter(), headersReader, RequestMetadataContext); - using var handler = new HttpLoggingHandler( - fakeLogger, requestReader, new List(), options) - { - InnerHandler = new TestingHandlerStub((_, _) => - Task.FromResult(new HttpResponseMessage((HttpStatusCode)httpStatusCode))) - }; + using var handler = new TestLoggingHandler( + new HttpClientLogger(fakeLogger, requestReader, Array.Empty(), options), + new TestingHandlerStub((_, _) => + Task.FromResult(new HttpResponseMessage((HttpStatusCode)httpStatusCode)))); - using var client = new System.Net.Http.HttpClient(handler); + using var client = new HttpClient(handler); using var httpRequestMessage = new HttpRequestMessage { Method = HttpMethod.Post, RequestUri = new($"http://default-uri.com/foo/bar"), Content = new StringContent("request_content", Encoding.UTF8, TextPlain) }; + await client.SendAsync(httpRequestMessage, It.IsAny()).ConfigureAwait(false); var logRecord = fakeLogger.Collector.GetSnapshot().Single(); Assert.Equal(expectedLogLevel, logRecord.Level); } - private static System.Net.Http.HttpClient CreateClientWithException( - Exception exception, - bool isLoggingEnabled = true) - { - var loggerMock = new Mock>(MockBehavior.Strict); - loggerMock.Setup(m => m.IsEnabled(It.IsAny())).Returns(isLoggingEnabled); - var mockedLogger = new MockedLogger(loggerMock); - - var mockHandler = new Mock(); - mockHandler.Protected().Setup>( - "SendAsync", - ItExpr.IsAny(), - ItExpr.IsAny()).Throws(exception); - - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions()); - - var mockHeadersRedactor = new Mock(); - mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) - .Returns(Redacted); - var headersReader = new HttpHeadersReader(options, mockHeadersRedactor.Object); - -#pragma warning disable CA2000 // Dispose objects before losing scope - no, it is required for the HttpClient to work properly - var handler = new HttpLoggingHandler( - mockedLogger, - new HttpRequestReader( - options, - GetHttpRouteFormatter(), headersReader, RequestMetadataContext), - Enumerable.Empty(), - options) - { - InnerHandler = mockHandler.Object - }; -#pragma warning restore CA2000 // Dispose objects before losing scope - - var client = new System.Net.Http.HttpClient(handler); - return client; - } - - private static System.Net.Http.HttpClient CreateClientWithOperationCanceledException( - Exception exception, - bool isLoggingEnabled = true) + [Fact] + public async Task HttpClientLogger_LogsAnError_WhenResponseReaderThrows() { - var requestReaderMock = new Mock(MockBehavior.Strict); - requestReaderMock.Setup(e => - e.ReadRequestAsync(It.IsAny(), - It.IsAny(), -It.IsAny>>(), - It.IsAny())).Throws(exception); - var mockedRequestReader = new MockedRequestReader(requestReaderMock); - - var loggerMock = new Mock>(); - loggerMock.Setup(m => m.IsEnabled(It.IsAny())).Returns(isLoggingEnabled); - var mockedLogger = new MockedLogger(loggerMock); + var exception = new InvalidOperationException("Test exception"); + var requestReaderMock = new Mock(); + requestReaderMock + .Setup(r => r.ReadResponseAsync(It.IsAny(), It.IsAny(), It.IsAny>?>(), It.IsAny())) + .ThrowsAsync(exception); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions()); + var fakeLogger = new FakeLogger(); + var logger = new HttpClientLogger(fakeLogger, requestReaderMock.Object, Array.Empty(), new()); - using var handler = new HttpLoggingHandler( - mockedLogger, - mockedRequestReader, - Enumerable.Empty(), - options); + using var httpRequestMessage = new HttpRequestMessage(); + using var httpResponseMessage = new HttpResponseMessage(); + await logger.LogRequestStopAsync(new LogRecord(), httpRequestMessage, httpResponseMessage, TimeSpan.Zero); - var client = new System.Net.Http.HttpClient(handler); - return client; + var logRecords = fakeLogger.Collector.GetSnapshot(); + var logRecord = Assert.Single(logRecords); + Assert.Equal(LogLevel.Error, logRecord.Level); + Assert.Same(exception, logRecord.Exception); } - private static System.Net.Http.HttpClient CreateClient( - HttpResponseMessage httpResponseMessage, - LogLevel logLevel = LogLevel.Information, - bool isLoggingEnabled = true, - Action? setupOptions = null) + [Fact] + public void SyncMethods_ShouldThrow() { - var options = new LoggingOptions - { - BodyReadTimeout = TimeSpan.FromMinutes(5) - }; - - var loggerMock = new Mock>(MockBehavior.Strict); - loggerMock.Setup(m => m.IsEnabled(logLevel)).Returns(isLoggingEnabled); - var logger = new MockedLogger(loggerMock); - - setupOptions?.Invoke(options); + var options = new LoggingOptions(); + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), Mock.Of()); + var requestReader = new HttpRequestReader( + options, GetHttpRouteFormatter(), headersReader, RequestMetadataContext); - using var handler = new HttpLoggingHandler( - logger, Mock.Of(), - Empty.Enumerable(), - Microsoft.Extensions.Options.Options.Create(options)) - { - InnerHandler = new TestingHandlerStub((_, _) => Task.FromResult(httpResponseMessage)) - }; + var logger = new HttpClientLogger(new FakeLogger(), requestReader, Array.Empty(), options); + using var httpRequestMessage = new HttpRequestMessage(); + using var httpResponseMessage = new HttpResponseMessage(); - var client = new System.Net.Http.HttpClient(handler); - return client; + Assert.Throws(() => logger.LogRequestStart(httpRequestMessage)); + Assert.Throws(() => logger.LogRequestStop(null, httpRequestMessage, httpResponseMessage, TimeSpan.Zero)); + Assert.Throws(() => logger.LogRequestFailed(null, httpRequestMessage, null, new InvalidOperationException(), TimeSpan.Zero)); } private static IHttpRouteFormatter GetHttpRouteFormatter() @@ -1070,5 +1013,12 @@ private static IHttpRouteFormatter GetHttpRouteFormatter() return builder.GetService()!; } - private static IOutgoingRequestContext RequestMetadataContext => new Mock().Object; + private static void EnsureLogRecordDuration(string? actualValue) + { + Assert.NotNull(actualValue); + Assert.InRange(int.Parse(actualValue), 0, int.MaxValue); + } + + private static IOutgoingRequestContext RequestMetadataContext + => new Mock().Object; } diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingAcceptanceTest.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingAcceptanceTest.cs deleted file mode 100644 index b5e29ad163b..00000000000 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingAcceptanceTest.cs +++ /dev/null @@ -1,74 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using System; -using System.Collections.Generic; -using System.Linq; -using System.Net.Http; -using System.Text; -using System.Threading.Tasks; -using FluentAssertions; -using Microsoft.Extensions.Compliance.Testing; -using Microsoft.Extensions.DependencyInjection; -using Microsoft.Extensions.Http.Telemetry.Logging.Test.Internal; -using Microsoft.Extensions.Telemetry.Testing.Logging; -using Xunit; - -namespace Microsoft.Extensions.Http.Telemetry.Logging.Test; - -public class HttpClientLoggingAcceptanceTest -{ - [Theory] - [InlineData(4_096)] - [InlineData(8_192)] - [InlineData(16_384)] - [InlineData(32_768)] - [InlineData(315_883)] - public async Task HttpClientLoggingHandler_LogsBodyDataUpToSpecifiedLimit(int limit) - { - const string RequestPath = "https://we.wont.hit.this.dd22anyway.com"; - - await using var provider = new ServiceCollection() - .AddFakeLogging() - .AddFakeRedaction() - .AddHttpClient(nameof(HttpClientLoggingHandler_LogsBodyDataUpToSpecifiedLimit)) - .AddHttpClientLogging(x => - { - x.ResponseHeadersDataClasses.Add("ResponseHeader", SimpleClassifications.PrivateData); - x.RequestHeadersDataClasses.Add("RequestHeader", SimpleClassifications.PrivateData); - x.RequestHeadersDataClasses.Add("RequestHeader2", SimpleClassifications.PrivateData); - x.RequestBodyContentTypes.Add("application/json"); - x.ResponseBodyContentTypes.Add("application/json"); - x.BodySizeLimit = limit; - x.LogBody = true; - }) - .Services - .BlockRemoteCall() - .BuildServiceProvider(); - - var client = provider - .GetRequiredService() - .CreateClient(nameof(HttpClientLoggingHandler_LogsBodyDataUpToSpecifiedLimit)); - using var httpRequestMessage = new HttpRequestMessage - { - Method = HttpMethod.Get, - RequestUri = new Uri(RequestPath), - }; - httpRequestMessage.Headers.Add("requestHeader", "Request Value"); - httpRequestMessage.Headers.Add("ReQuEStHeAdEr2", new List { "Request Value 2", "Request Value 3" }); - - var content = await client.SendAsync(httpRequestMessage, HttpCompletionOption.ResponseHeadersRead).ConfigureAwait(false); - var responseStream = await content.Content.ReadAsStreamAsync(); - var length = (int)responseStream.Length > limit ? limit : (int)responseStream.Length; - var buffer = new byte[length]; - _ = await responseStream.ReadAsync(buffer, 0, length); - var responseString = Encoding.UTF8.GetString(buffer); - - var collector = provider.GetFakeLogCollector(); - var logRecord = collector.GetSnapshot().Single(l => l.Category == "Microsoft.Extensions.Http.Telemetry.Logging.Internal.HttpLoggingHandler"); - var state = logRecord.State as List>; - state.Should().Contain(kvp => kvp.Value == responseString); - state.Should().Contain(kvp => kvp.Value == "Request Value"); - state.Should().Contain(kvp => kvp.Value == "Request Value 2,Request Value 3"); - } -} diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingExtensionsTest.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingExtensionsTest.cs index f2be6caa75a..3a4b464974f 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingExtensionsTest.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingExtensionsTest.cs @@ -3,9 +3,7 @@ using System; using System.Collections.Generic; -using System.Linq; using System.Net.Http; -using System.Text; using System.Threading; using System.Threading.Tasks; using AutoFixture; @@ -16,9 +14,9 @@ using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Hosting.Testing; +using Microsoft.Extensions.Http.Logging; using Microsoft.Extensions.Http.Telemetry.Logging.Test.Internal; using Microsoft.Extensions.Options; -using Microsoft.Extensions.Telemetry.Testing.Logging; using Moq; using Xunit; @@ -83,7 +81,7 @@ public void AddHttpClientLogging_ConfiguredOptionsWithNamedClient_ShouldNotBeSam { var services = new ServiceCollection(); - var provider = services + using var provider = services .AddHttpClient("test1") .AddHttpClientLogging(options => options.BodyReadTimeout = TimeSpan.FromSeconds(1)) .Services @@ -106,7 +104,7 @@ public void AddHttpClientLogging_ConfiguredOptionsWithTypedClient_ShouldNotBeSam { var services = new ServiceCollection(); - var provider = services + using var provider = services .AddHttpClient() .AddHttpClientLogging(options => options.BodyReadTimeout = TimeSpan.FromSeconds(1)) .Services @@ -129,7 +127,7 @@ public void AddHttpClientLogging_DefaultOptions_CreatesOptionsCorrectly() { var services = new ServiceCollection(); - var provider = services + using var provider = services .AddHttpClient("") .AddHttpClientLogging(o => o.RequestHeadersDataClasses.Add("test1", SimpleClassifications.PrivateData)) .Services @@ -313,7 +311,7 @@ public void AddHttpClientLogging_ServiceCollection_GivenActionDelegate_Registers [Fact] public async Task AddHttpClientLogging_ServiceCollection_GivenInvalidOptions_Throws() { - var provider = new ServiceCollection() + using var provider = new ServiceCollection() .AddFakeRedaction() .AddHttpClient() .AddDefaultHttpClientLogging(options => @@ -331,34 +329,41 @@ public async Task AddHttpClientLogging_ServiceCollection_GivenInvalidOptions_Thr } [Fact] - public void AddHttpClientLogging_ServiceCollectionAndHttpClientBuilder_Throws() + public void AddHttpClientLogging_ServiceCollectionAndHttpClientBuilder_DoesNotDuplicate() { - var provider = new ServiceCollection() + const string ClientName = "test"; + + using var provider = new ServiceCollection() .AddFakeRedaction() - .AddHttpClient("test") - .AddHttpClientLogging().Services - .AddDefaultHttpClientLogging() + .AddHttpClient(ClientName) + .AddHttpClientLogging(x => + { + x.BodySizeLimit = 100500; + x.RequestHeadersDataClasses.Add(ClientName, SimpleClassifications.PublicData); + }).Services + .AddDefaultHttpClientLogging(x => + { + x.BodySizeLimit = 347; + x.RequestHeadersDataClasses.Add("default", SimpleClassifications.PrivateData); + }) .BuildServiceProvider(); - var act = () => provider.GetRequiredService().CreateClient("test"); - act.Should().Throw().WithMessage(HttpClientLoggingExtensions.HandlerAddedTwiceExceptionMessage); + EnsureSingleLogger(provider, ClientName); } [Fact] - public void AddHttpClientLogging_HttpClientBuilderAndServiceCollection_Throws() + public void AddHttpClientLogging_HttpClientBuilderAndServiceCollection_DoesNotDuplicate() { - var provider = new ServiceCollection() + const string ClientName = "test"; + + using var provider = new ServiceCollection() .AddFakeRedaction() .AddDefaultHttpClientLogging() - .AddHttpClient("test") - .ConfigureAdditionalHttpMessageHandlers((handlers, _) => - handlers.Add(Mock - .Of())) // this is to kill mutants with .Any() vs. .All() calls when detecting already added delegating handlers. + .AddHttpClient(ClientName) .AddHttpClientLogging().Services .BuildServiceProvider(); - var act = () => provider.GetRequiredService().CreateClient("test"); - act.Should().Throw().WithMessage(HttpClientLoggingExtensions.HandlerAddedTwiceExceptionMessage); + EnsureSingleLogger(provider, ClientName); } [Theory] @@ -399,489 +404,13 @@ public void AddHttpClientLogging_ServiceCollection_CreatesClientSuccessfully() Assert.NotNull(httpClient); } - [Fact] - public async Task AddHttpClientLogging_ServiceCollectionAndEnrichers_EnrichesLogsWithAllEnrichers() - { - const string RequestPath = "https://we.wont.hit.this.dd22anyway.com"; - - await using var sp = new ServiceCollection() - .AddFakeLogging() - .AddFakeRedaction() - .AddDefaultHttpClientLogging() - .AddHttpClientLogEnricher() - .AddHttpClientLogEnricher() - .AddHttpClient("testClient").Services - .BlockRemoteCall() - .BuildServiceProvider(); - - using var httpClient = sp.GetRequiredService().CreateClient("testClient"); - using var httpRequestMessage = new HttpRequestMessage - { - Method = HttpMethod.Get, - RequestUri = new Uri(RequestPath), - }; - - _ = await httpClient.SendAsync(httpRequestMessage).ConfigureAwait(false); - var collector = sp.GetFakeLogCollector(); - var logRecord = collector.GetSnapshot().Single(logRecord => logRecord.Category == "Microsoft.Extensions.Http.Telemetry.Logging.Internal.HttpLoggingHandler"); - - Assert.Empty(logRecord.Message); - var state = logRecord.StructuredState; - var enricher1 = sp.GetServices().SingleOrDefault(enn => enn is EnricherWithCounter) as EnricherWithCounter; - var enricher2 = sp.GetServices().SingleOrDefault(enn => enn is TestEnricher) as TestEnricher; - - enricher1.Should().NotBeNull(); - enricher2.Should().NotBeNull(); - - enricher1!.TimesCalled.Should().Be(1); - state!.Single(kvp => kvp.Key == enricher2!.KvpRequest.Key).Value.Should().Be(enricher2!.KvpRequest.Value!.ToString()); - } - - [Fact] - public async Task AddHttpClientLogging_WithNamedHttpClients_WorksCorrectly() - { - const string RequestPath = "https://we.wont.hit.this.dd22anyway.com"; - - await using var provider = new ServiceCollection() - .AddFakeLogging() - .AddFakeRedaction() - .AddHttpClient("namedClient1") - .AddHttpClientLogging(o => - { - o.ResponseHeadersDataClasses.Add("ResponseHeader", SimpleClassifications.PrivateData); - o.RequestHeadersDataClasses.Add("RequestHeader", SimpleClassifications.PrivateData); - o.RequestHeadersDataClasses.Add("RequestHeaderFirst", SimpleClassifications.PrivateData); - o.RequestBodyContentTypes.Add("application/json"); - o.ResponseBodyContentTypes.Add("application/json"); - o.LogBody = true; - }).Services - .AddHttpClient("namedClient2") - .AddHttpClientLogging(o => - { - o.ResponseHeadersDataClasses.Add("ResponseHeader", SimpleClassifications.PrivateData); - o.RequestHeadersDataClasses.Add("RequestHeader", SimpleClassifications.PrivateData); - o.RequestHeadersDataClasses.Add("RequestHeaderSecond", SimpleClassifications.PrivateData); - o.RequestBodyContentTypes.Add("application/json"); - o.ResponseBodyContentTypes.Add("application/json"); - o.LogBody = true; - }).Services - .BlockRemoteCall() - .BuildServiceProvider(); - - using var namedClient1 = provider.GetRequiredService().CreateClient("namedClient1"); - using var namedClient2 = provider.GetRequiredService().CreateClient("namedClient2"); - - using var httpRequestMessage = new HttpRequestMessage - { - Method = HttpMethod.Get, - RequestUri = new Uri(RequestPath), - }; - httpRequestMessage.Headers.Add("requestHeader", "Request Value"); - httpRequestMessage.Headers.Add("ReQuEStHeAdErFirst", new List { "Request Value 2", "Request Value 3" }); - var responseString = await SendRequest(namedClient1, httpRequestMessage); - var collector = provider.GetFakeLogCollector(); - var logRecord = collector.GetSnapshot().Single(l => l.Category == "Microsoft.Extensions.Http.Telemetry.Logging.Internal.HttpLoggingHandler"); - var state = logRecord.State as List>; - state.Should().Contain(kvp => kvp.Value == responseString); - state.Should().Contain(kvp => kvp.Value == "Request Value"); - state.Should().Contain(kvp => kvp.Value == "Request Value 2,Request Value 3"); - - using var httpRequestMessage2 = new HttpRequestMessage - { - Method = HttpMethod.Get, - RequestUri = new Uri(RequestPath), - }; - httpRequestMessage2.Headers.Add("requestHeader", "Request Value"); - httpRequestMessage2.Headers.Add("ReQuEStHeAdErSecond", new List { "Request Value 2", "Request Value 3" }); - collector.Clear(); - responseString = await SendRequest(namedClient2, httpRequestMessage2); - logRecord = collector.GetSnapshot().Single(l => l.Category == "Microsoft.Extensions.Http.Telemetry.Logging.Internal.HttpLoggingHandler"); - state = logRecord.State as List>; - state.Should().Contain(kvp => kvp.Value == responseString); - state.Should().Contain(kvp => kvp.Value == "Request Value"); - state.Should().Contain(kvp => kvp.Value == "Request Value 2,Request Value 3"); - } - - private static async Task SendRequest(System.Net.Http.HttpClient httpClient, HttpRequestMessage httpRequestMessage) - { - var content = await httpClient - .SendAsync(httpRequestMessage, HttpCompletionOption.ResponseHeadersRead) - .ConfigureAwait(false); - var responseStream = await content.Content.ReadAsStreamAsync(); - var buffer = new byte[32768]; - _ = await responseStream.ReadAsync(buffer, 0, 32768); - return Encoding.UTF8.GetString(buffer); - } - - [Fact] - public async Task AddHttpClientLogging_WithTypedHttpClients_WorksCorrectly() - { - const string RequestPath = "https://we.wont.hit.this.dd22anyway.com"; - - await using var provider = new ServiceCollection() - .AddFakeLogging() - .AddFakeRedaction() - .AddSingleton() - .AddSingleton() - .AddHttpClient() - .AddHttpClientLogging(x => - { - x.ResponseHeadersDataClasses.Add("ResponseHeader", SimpleClassifications.PrivateData); - x.RequestHeadersDataClasses.Add("RequestHeader", SimpleClassifications.PrivateData); - x.RequestHeadersDataClasses.Add("RequestHeader2", SimpleClassifications.PrivateData); - x.RequestBodyContentTypes.Add("application/json"); - x.ResponseBodyContentTypes.Add("application/json"); - x.BodySizeLimit = 10000; - x.LogBody = true; - }).Services - .AddHttpClient() - .AddHttpClientLogging(x => - { - x.ResponseHeadersDataClasses.Add("ResponseHeader", SimpleClassifications.PrivateData); - x.RequestHeadersDataClasses.Add("RequestHeader", SimpleClassifications.PrivateData); - x.RequestHeadersDataClasses.Add("RequestHeader2", SimpleClassifications.PrivateData); - x.RequestBodyContentTypes.Add("application/json"); - x.ResponseBodyContentTypes.Add("application/json"); - x.BodySizeLimit = 20000; - x.LogBody = true; - }).Services - .BlockRemoteCall() - .BuildServiceProvider(); - - var firstClient = provider.GetService() as TestHttpClient1; - var secondClient = provider.GetService() as TestHttpClient2; - - using var httpRequestMessage = new HttpRequestMessage - { - Method = HttpMethod.Get, - RequestUri = new Uri(RequestPath), - }; - httpRequestMessage.Headers.Add("requestHeader", "Request Value"); - httpRequestMessage.Headers.Add("ReQuEStHeAdEr2", new List { "Request Value 2", "Request Value 3" }); - var content = await firstClient!.SendRequest(httpRequestMessage).ConfigureAwait(false); - var collector = provider.GetFakeLogCollector(); - var responseStream = await content.Content.ReadAsStreamAsync(); - var buffer = new byte[10000]; - _ = await responseStream.ReadAsync(buffer, 0, 10000); - var responseString = Encoding.UTF8.GetString(buffer); - - var logRecord = collector.GetSnapshot().Single(l => l.Category == "Microsoft.Extensions.Http.Telemetry.Logging.Internal.HttpLoggingHandler"); - var state = logRecord.State as List>; - state.Should().Contain(kvp => kvp.Value == responseString); - state.Should().Contain(kvp => kvp.Value == "Request Value"); - state.Should().Contain(kvp => kvp.Value == "Request Value 2,Request Value 3"); - - using var httpRequestMessage2 = new HttpRequestMessage - { - Method = HttpMethod.Get, - RequestUri = new Uri(RequestPath), - }; - httpRequestMessage2.Headers.Add("requestHeader", "Request Value"); - httpRequestMessage2.Headers.Add("ReQuEStHeAdEr2", new List { "Request Value 2", "Request Value 3" }); - collector.Clear(); - content = await secondClient!.SendRequest(httpRequestMessage2).ConfigureAwait(false); - responseStream = await content.Content.ReadAsStreamAsync(); - buffer = new byte[20000]; - _ = await responseStream.ReadAsync(buffer, 0, 20000); - responseString = Encoding.UTF8.GetString(buffer); - - logRecord = collector.GetSnapshot().Single(l => l.Category == "Microsoft.Extensions.Http.Telemetry.Logging.Internal.HttpLoggingHandler"); - state = logRecord.State as List>; - state.Should().Contain(kvp => kvp.Value == responseString); - state.Should().Contain(kvp => kvp.Value == "Request Value"); - state.Should().Contain(kvp => kvp.Value == "Request Value 2,Request Value 3"); - } - - [Theory] - [InlineData(HttpRouteParameterRedactionMode.Strict, "v1/unit/REDACTED/users/REDACTED:123")] - [InlineData(HttpRouteParameterRedactionMode.Loose, "v1/unit/999/users/REDACTED:123")] - [InlineData(HttpRouteParameterRedactionMode.None, "/v1/unit/999/users/123")] - public async Task AddHttpClientLogging_RedactSensitivePrams(HttpRouteParameterRedactionMode parameterRedactionMode, string redactedPath) - { - const string RequestPath = "https://fake.com/v1/unit/999/users/123"; - - await using var sp = new ServiceCollection() - .AddFakeLogging() - .AddFakeRedaction(o => o.RedactionFormat = "REDACTED:{0}") - .AddHttpClient() - .AddDefaultHttpClientLogging(o => - { - o.RouteParameterDataClasses.Add("userId", SimpleClassifications.PrivateData); - o.RequestPathParameterRedactionMode = parameterRedactionMode; - }) - .BlockRemoteCall() - .BuildServiceProvider(); - - using var httpClient = sp.GetRequiredService().CreateClient(); - using var httpRequestMessage = new HttpRequestMessage - { - Method = HttpMethod.Get, - RequestUri = new Uri(RequestPath), - }; - - var requestContext = sp.GetRequiredService(); - requestContext.SetRequestMetadata(new RequestMetadata - { - RequestRoute = "/v1/unit/{unitId}/users/{userId}" - }); - - _ = await httpClient.SendAsync(httpRequestMessage).ConfigureAwait(false); - - var collector = sp.GetFakeLogCollector(); - var logRecord = collector.GetSnapshot().Single(logRecord => logRecord.Category == "Microsoft.Extensions.Http.Telemetry.Logging.Internal.HttpLoggingHandler"); - var state = logRecord.State as List>; - state!.Single(kvp => kvp.Key == "httpPath").Value.Should().Be(redactedPath); - } - - [Theory] - [InlineData(HttpRouteParameterRedactionMode.Strict, "v1/unit/REDACTED/users/REDACTED:123")] - [InlineData(HttpRouteParameterRedactionMode.Loose, "v1/unit/999/users/REDACTED:123")] - public async Task AddHttpClientLogging_NamedHttpClient_RedactSensitivePrams(HttpRouteParameterRedactionMode parameterRedactionMode, string redactedPath) - { - const string RequestPath = "https://fake.com/v1/unit/999/users/123"; - - await using var sp = new ServiceCollection() - .AddFakeLogging() - .AddFakeRedaction(o => o.RedactionFormat = "REDACTED:{0}") - .AddHttpClient("test") - .AddHttpClientLogging(o => - { - o.RouteParameterDataClasses.Add("userId", SimpleClassifications.PrivateData); - o.RequestPathParameterRedactionMode = parameterRedactionMode; - }) - .Services - .BlockRemoteCall() - .BuildServiceProvider(); - - using var httpClient = sp.GetRequiredService().CreateClient("test"); - using var httpRequestMessage = new HttpRequestMessage - { - Method = HttpMethod.Get, - RequestUri = new Uri(RequestPath), - }; - - var requestContext = sp.GetRequiredService(); - requestContext.SetRequestMetadata(new RequestMetadata - { - RequestRoute = "/v1/unit/{unitId}/users/{userId}" - }); - - _ = await httpClient.SendAsync(httpRequestMessage).ConfigureAwait(false); - - var collector = sp.GetFakeLogCollector(); - var logRecord = collector.GetSnapshot().Single(logRecord => logRecord.Category == "Microsoft.Extensions.Http.Telemetry.Logging.Internal.HttpLoggingHandler"); - var state = logRecord.State as List>; - state!.Single(kvp => kvp.Key == "httpPath").Value.Should().Be(redactedPath); - } - - [Fact] - public void AddHttpClientLogging_WithNamedClients_RegistersNamedOptions() + private static void EnsureSingleLogger(IServiceProvider serviceProvider, string serviceKey) + where T : IHttpClientLogger { - const string FirstClientName = "1"; - const string SecondClientName = "2"; - - using var provider = new ServiceCollection() - .AddFakeRedaction() - .AddHttpClient(FirstClientName) - .AddHttpClientLogging(options => - { - options.LogRequestStart = true; - options.ResponseHeadersDataClasses = new Dictionary { { "test1", SimpleClassifications.PrivateData } }; - }) - .Services - .AddHttpClient(SecondClientName) - .AddHttpClientLogging(options => - { - options.LogRequestStart = false; - options.ResponseHeadersDataClasses = new Dictionary { { "test2", SimpleClassifications.PrivateData } }; - }) - .Services - .BuildServiceProvider(); - - var factory = provider.GetRequiredService(); - - var firstClient = factory.CreateClient(FirstClientName); - var secondClient = factory.CreateClient(SecondClientName); - firstClient.Should().NotBe(secondClient); - - var optionsFirst = provider.GetRequiredService>().Get(FirstClientName); - var optionsSecond = provider.GetRequiredService>().Get(SecondClientName); - optionsFirst.Should().NotBeNull(); - optionsSecond.Should().NotBeNull(); - optionsFirst.Should().NotBeEquivalentTo(optionsSecond); - } - - [Fact] - public void AddHttpClientLogging_WithTypedClients_RegistersNamedOptions() - { - using var provider = new ServiceCollection() - .AddFakeRedaction() - .AddSingleton() - .AddSingleton() - .AddHttpClient() - .AddHttpClientLogging(options => - { - options.LogRequestStart = true; - options.ResponseHeadersDataClasses = new Dictionary { { "test1", SimpleClassifications.PrivateData } }; - }) - .Services - .AddHttpClient() - .AddHttpClientLogging(options => - { - options.LogRequestStart = false; - options.ResponseHeadersDataClasses = new Dictionary { { "test2", SimpleClassifications.PrivateData } }; - }) - .Services - .BuildServiceProvider(); - - var firstClient = provider.GetService() as TestHttpClient1; - var secondClient = provider.GetService() as TestHttpClient2; - - firstClient.Should().NotBe(secondClient); - - var optionsFirst = provider.GetRequiredService>().Get(nameof(ITestHttpClient1)); - var optionsSecond = provider.GetRequiredService>().Get(nameof(ITestHttpClient2)); - optionsFirst.Should().NotBeNull(); - optionsSecond.Should().NotBeNull(); - optionsFirst.Should().NotBeEquivalentTo(optionsSecond); - } - - [Fact] - public void AddHttpClientLogging_WithTypedAndNamedClients_RegistersNamedOptions() - { - using var provider = new ServiceCollection() - .AddFakeRedaction() - .AddSingleton() - .AddSingleton() - .AddHttpClient() - .AddHttpClientLogging(options => - { - options.ResponseHeadersDataClasses = new Dictionary { { "test1", SimpleClassifications.PrivateData } }; - }) - .Services - .AddHttpClient() - .AddHttpClientLogging(options => - { - options.ResponseHeadersDataClasses = new Dictionary { { "test2", SimpleClassifications.PrivateData } }; - }) - .Services - .AddHttpClient("testClient3") - .AddHttpClientLogging(options => - { - options.ResponseHeadersDataClasses = new Dictionary { { "test3", SimpleClassifications.PrivateData } }; - }) - .Services - .AddHttpClient("testClient4") - .AddHttpClientLogging(options => - { - options.ResponseHeadersDataClasses = new Dictionary { { "test4", SimpleClassifications.PrivateData } }; - }) - .Services - .AddHttpClient("testClient5") - .AddHttpClientLogging(options => - { - options.ResponseHeadersDataClasses = new Dictionary { { "test5", SimpleClassifications.PrivateData } }; - }) - .Services - .AddDefaultHttpClientLogging(options => - { - options.ResponseHeadersDataClasses = new Dictionary { { "test6", SimpleClassifications.PrivateData } }; - }) - .BuildServiceProvider(); - - var optionsFirst = provider.GetRequiredService>().Get(nameof(ITestHttpClient1)); - var optionsSecond = provider.GetRequiredService>().Get(nameof(ITestHttpClient2)); - var optionsThird = provider.GetRequiredService>().Get("testClient3"); - var optionsFourth = provider.GetRequiredService>().Get("testClient4"); - var optionsFifth = provider.GetRequiredService>().Get("testClient5"); - var optionsSixth = provider.GetRequiredService>().Value; - - optionsFirst.Should().NotBeNull(); - optionsSecond.Should().NotBeNull(); - optionsFirst.Should().NotBeEquivalentTo(optionsSecond); - - optionsThird.Should().NotBeNull(); - optionsFourth.Should().NotBeNull(); - optionsThird.Should().NotBeEquivalentTo(optionsFourth); - - optionsFifth.Should().NotBeNull(); - optionsFifth.Should().NotBeEquivalentTo(optionsFourth); - - optionsSixth.Should().NotBeNull(); - optionsSixth.Should().NotBeEquivalentTo(optionsFifth); - } - - [Fact] - public async Task AddHttpClientLogging_DisablesNetScope() - { - const string RequestPath = "https://we.wont.hit.this.dd22anyway.com"; - await using var provider = new ServiceCollection() - .AddFakeLogging() - .AddFakeRedaction() - .AddHttpClient("test") - .AddHttpClientLogging() - .Services - .BlockRemoteCall() - .BuildServiceProvider(); - var options = provider.GetRequiredService>().Get("test"); - var client = provider.GetRequiredService().CreateClient("test"); - using var httpRequestMessage = new HttpRequestMessage(HttpMethod.Get, new Uri(RequestPath)); - - _ = await client.SendAsync(httpRequestMessage, HttpCompletionOption.ResponseHeadersRead).ConfigureAwait(false); - var collector = provider.GetFakeLogCollector(); - var logRecord = collector.GetSnapshot().Single(l => l.Category == "Microsoft.Extensions.Http.Telemetry.Logging.Internal.HttpLoggingHandler"); - - logRecord.Scopes.Should().HaveCount(0); - } - - [Fact] - public async Task AddHttpClientLogging_CallFromOtherClient_HasBuiltInLogging() - { - const string RequestPath = "https://we.wont.hit.this.dd22anyway.com"; - await using var provider = new ServiceCollection() - .AddFakeLogging() - .AddFakeRedaction() - .AddHttpClient("test") - .AddHttpClientLogging() - .Services - .AddHttpClient("normal") - .Services - .BlockRemoteCall() - .BuildServiceProvider(); - - // The test client has AddHttpClientLogging. The normal client doesn't. - // The normal client should still log via the builtin HTTP logging. - var client = provider.GetRequiredService().CreateClient("normal"); - using var httpRequestMessage = new HttpRequestMessage(HttpMethod.Get, new Uri(RequestPath)); - - _ = await client.SendAsync(httpRequestMessage, HttpCompletionOption.ResponseHeadersRead).ConfigureAwait(false); - var collector = provider.GetFakeLogCollector(); - var logRecords = collector.GetSnapshot().Where(l => l.Category == "System.Net.Http.HttpClient.normal.LogicalHandler").ToList(); - - Assert.Collection(logRecords, - r => Assert.Equal("RequestPipelineStart", r.Id.Name), - r => Assert.Equal("RequestPipelineEnd", r.Id.Name)); - } - - [Fact] - public async Task AddDefaultHttpClientLogging_DisablesNetScope() - { - const string RequestPath = "https://we.wont.hit.this.dd22anyway.com"; - await using var provider = new ServiceCollection() - .AddFakeLogging() - .AddFakeRedaction() - .AddHttpClient() - .AddDefaultHttpClientLogging() - .BlockRemoteCall() - .BuildServiceProvider(); - var options = provider.GetRequiredService>().Get("test"); - var client = provider.GetRequiredService().CreateClient("test"); - using var httpRequestMessage = new HttpRequestMessage(HttpMethod.Get, new Uri(RequestPath)); - - _ = await client.SendAsync(httpRequestMessage, HttpCompletionOption.ResponseHeadersRead).ConfigureAwait(false); - var collector = provider.GetFakeLogCollector(); - var logRecord = collector.GetSnapshot().Single(l => l.Category == "Microsoft.Extensions.Http.Telemetry.Logging.Internal.HttpLoggingHandler"); + var loggers = serviceProvider.GetServices(); + loggers.Should().ContainSingle(); - logRecord.Scopes.Should().HaveCount(0); + var keyedLoggers = serviceProvider.GetKeyedServices(serviceKey); + keyedLoggers.Should().ContainSingle(); } } diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingDimensionsTest.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingTagNamesTest.cs similarity index 81% rename from test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingDimensionsTest.cs rename to test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingTagNamesTest.cs index 68d49c2439d..52345ab239d 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingDimensionsTest.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpClientLoggingTagNamesTest.cs @@ -8,12 +8,12 @@ namespace Microsoft.Extensions.Http.Telemetry.Logging.Test; -public class HttpClientLoggingDimensionsTest +public class HttpClientLoggingTagNamesTest { [Fact] - public void GetDimensionNames_ReturnsAnArrayOfDimensionNames() + public void GetTagNames_ReturnsAnArrayOfTagNames() { - var actualDimensions = HttpClientLoggingTagNames.DimensionNames; + var actualDimensions = HttpClientLoggingTagNames.TagNames; var expectedDimensions = GetStringConstants(typeof(HttpClientLoggingTagNames)); actualDimensions.Should().BeEquivalentTo(expectedDimensions); diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpHeadersReaderTest.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpHeadersReaderTest.cs index d7f0e60d6ef..e922f020efd 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpHeadersReaderTest.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpHeadersReaderTest.cs @@ -8,6 +8,7 @@ using Microsoft.Extensions.Compliance.Classification; using Microsoft.Extensions.Compliance.Testing; using Microsoft.Extensions.Http.Telemetry.Logging.Internal; +using Microsoft.Extensions.Http.Telemetry.Logging.Test.Internal; using Microsoft.Extensions.Telemetry.Internal; using Moq; using Xunit; @@ -16,22 +17,14 @@ namespace Microsoft.Extensions.Http.Telemetry.Logging.Test; public class HttpHeadersReaderTest { - [Fact] - public void HttpHeadersReader_WhenAnyArgumentIsNull_Throws() - { - var options = Microsoft.Extensions.Options.Options.Create((LoggingOptions)null!); - var act = () => new HttpHeadersReader(options, Mock.Of()); - act.Should().Throw(); - } - [Fact] public void HttpHeadersReader_WhenEmptyHeaders_DoesNothing() { using var httpRequest = new HttpRequestMessage(); using var httpResponse = new HttpResponseMessage(); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions()); + var options = new LoggingOptions(); - var headersReader = new HttpHeadersReader(options, Mock.Of()); + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), Mock.Of()); var buffer = new List>(); headersReader.ReadRequestHeaders(httpRequest, buffer); @@ -54,7 +47,7 @@ public void HttpHeadersReader_WhenHeadersProvided_ReadsThem() mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), SimpleClassifications.PublicData)) .Returns, DataClassification>((x, _) => string.Join(",", x)); - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions + var options = new LoggingOptions { RequestHeadersDataClasses = new Dictionary { @@ -67,9 +60,9 @@ public void HttpHeadersReader_WhenHeadersProvided_ReadsThem() { "Header4", SimpleClassifications.PublicData }, { "hEaDeR7", SimpleClassifications.PrivateData } }, - }); + }; - var headersReader = new HttpHeadersReader(options, mockHeadersRedactor.Object); + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), mockHeadersRedactor.Object); var buffer = new List>(); headersReader.ReadRequestHeaders(httpRequest, buffer); @@ -110,8 +103,9 @@ public void HttpHeadersReader_WhenHeadersProvided_ReadsThem() [Fact] public void HttpHeadersReader_WhenBufferIsNull_DoesNothing() { - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions()); - var headersReader = new HttpHeadersReader(options, Mock.Of()); + var options = new LoggingOptions(); + + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), Mock.Of()); List>? responseBuffer = null; using var httpRequest = new HttpRequestMessage(); diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpRequestBodyReaderTest.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpRequestBodyReaderTest.cs index 07d3f139232..40762fcc2f0 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpRequestBodyReaderTest.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpRequestBodyReaderTest.cs @@ -16,8 +16,6 @@ using Moq; using Xunit; -using IOptionsFactory = Microsoft.Extensions.Options.Options; - namespace Microsoft.Extensions.Http.Telemetry.Logging.Test; public class HttpRequestBodyReaderTest @@ -29,22 +27,15 @@ public HttpRequestBodyReaderTest() _fixture = new Fixture(); } - [Fact] - public void Reader_NullOptions_Throws() - { - var options = IOptionsFactory.Create((LoggingOptions)null!); - var act = () => new HttpRequestBodyReader(options); - act.Should().Throw(); - } - [Fact] public async Task Reader_SimpleContent_ReadsContent() { var input = _fixture.Create(); - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { RequestBodyContentTypes = new HashSet { "text/plain" } - }); + }; + using var httpRequest = new HttpRequestMessage { Content = new StringContent(input, Encoding.UTF8, "text/plain"), @@ -60,10 +51,11 @@ public async Task Reader_SimpleContent_ReadsContent() [Fact] public async Task Reader_EmptyContent_ErrorMessage() { - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { RequestBodyContentTypes = new HashSet { "text/plain" } - }); + }; + using var httpRequest = new HttpRequestMessage { Content = new StreamContent(new MemoryStream()), @@ -83,10 +75,10 @@ public async Task Reader_UnreadableContent_ErrorMessage( string contentType) { var input = _fixture.Create(); - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { RequestBodyContentTypes = new HashSet { "text/plain" } - }); + }; using var httpRequest = new HttpRequestMessage { @@ -104,10 +96,11 @@ public async Task Reader_UnreadableContent_ErrorMessage( public async Task Reader_OperationCanceled_ThrowsTaskCanceledException() { var input = _fixture.Create(); - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { RequestBodyContentTypes = new HashSet { "text/plain" } - }); + }; + using var httpRequest = new HttpRequestMessage { Content = new StringContent(input, Encoding.UTF8, "text/plain"), @@ -129,12 +122,13 @@ await act.Should().ThrowAsync() public async Task Reader_BigContent_TrimsAtTheEnd([CombinatorialValues(32, 256, 4095, 4096, 4097, 65536, 131072)] int limit) { var input = RandomStringGenerator.Generate(limit * 2); - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { BodySizeLimit = limit, RequestBodyContentTypes = new HashSet { "text/plain" }, BodyReadTimeout = TimeSpan.FromMinutes(100) - }); + }; + using var httpRequest = new HttpRequestMessage { Content = new StringContent(input, Encoding.UTF8, "text/plain"), @@ -152,12 +146,13 @@ public async Task Reader_BigContent_TrimsAtTheEnd([CombinatorialValues(32, 256, public async Task Reader_SmallContentBigLimit_ReadsCorrectly([CombinatorialValues(32, 256, 4095, 4096, 4097, 65536, 131072)] int limit) { var input = RandomStringGenerator.Generate(limit / 2); - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { BodySizeLimit = limit, RequestBodyContentTypes = new HashSet { "text/plain" }, BodyReadTimeout = TimeSpan.FromMinutes(100) - }); + }; + using var httpRequest = new HttpRequestMessage { Content = new StringContent(input, Encoding.UTF8, "text/plain"), @@ -173,10 +168,11 @@ public async Task Reader_SmallContentBigLimit_ReadsCorrectly([CombinatorialValue [Fact] public async Task Reader_ReadingTakesTooLong_Timesout() { - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { RequestBodyContentTypes = new HashSet { "text/plain" } - }); + }; + var streamMock = new Mock(); #if NETCOREAPP3_1_OR_GREATER streamMock.Setup(x => x.ReadAsync(It.IsAny>(), It.IsAny())).Throws(); @@ -205,15 +201,17 @@ public async Task Reader_ReadingTakesTooLong_Timesout() [Fact] public async Task Reader_NullContent_ReturnsEmpty() { - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { RequestBodyContentTypes = new HashSet { "text/plain" } - }); + }; + using var httpRequest = new HttpRequestMessage { Content = null, Method = HttpMethod.Post }; + var httpRequestBodyReader = new HttpRequestBodyReader(options); var requestBody = await httpRequestBodyReader.ReadAsync(httpRequest, CancellationToken.None).ConfigureAwait(false); @@ -224,10 +222,10 @@ public async Task Reader_NullContent_ReturnsEmpty() [Fact] public async Task Reader_MethodIsGet_ReturnsEmpty() { - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { RequestBodyContentTypes = new HashSet { "text/plain" } - }); + }; using var httpRequest = new HttpRequestMessage { @@ -245,8 +243,7 @@ public async Task Reader_MethodIsGet_ReturnsEmpty() [Fact] public void HttpRequestBodyReader_Has_Infinite_Timeout_For_Reading_A_Body_When_Debugger_Is_Attached() { - var options = IOptionsFactory.Create(new LoggingOptions()); - var reader = new HttpRequestBodyReader(options, DebuggerState.Attached); + var reader = new HttpRequestBodyReader(new(), DebuggerState.Attached); Assert.Equal(reader.RequestReadTimeout, Timeout.InfiniteTimeSpan); } @@ -255,7 +252,7 @@ public void HttpRequestBodyReader_Has_Infinite_Timeout_For_Reading_A_Body_When_D public void HttpRequestBodyReader_Has_Option_Defined_Timeout_For_Reading_A_Body_When_Debugger_Is_Detached() { var timeout = TimeSpan.FromSeconds(274); - var options = IOptionsFactory.Create(new LoggingOptions { BodyReadTimeout = timeout }); + var options = new LoggingOptions { BodyReadTimeout = timeout }; var reader = new HttpRequestBodyReader(options, DebuggerState.Detached); Assert.Equal(reader.RequestReadTimeout, timeout); diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpRequestReaderTest.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpRequestReaderTest.cs index 15316427cb9..8c58d016036 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpRequestReaderTest.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpRequestReaderTest.cs @@ -14,6 +14,7 @@ using Microsoft.Extensions.Compliance.Testing; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Http.Telemetry.Logging.Internal; +using Microsoft.Extensions.Http.Telemetry.Logging.Test.Internal; using Microsoft.Extensions.Telemetry; using Microsoft.Extensions.Telemetry.Internal; using Microsoft.Extensions.Telemetry.Logging; @@ -55,7 +56,7 @@ public async Task ReadAsync_AllData_ReturnsLogRecord() ResponseBody = responseContent, }; - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions + var options = new LoggingOptions { RequestHeadersDataClasses = new Dictionary { { header1.Key, SimpleClassifications.PrivateData }, { header3.Key, SimpleClassifications.PrivateData } }, ResponseHeadersDataClasses = new Dictionary { { header2.Key, SimpleClassifications.PrivateData }, { header3.Key, SimpleClassifications.PrivateData } }, @@ -63,14 +64,18 @@ public async Task ReadAsync_AllData_ReturnsLogRecord() ResponseBodyContentTypes = new HashSet { plainTextMedia }, BodyReadTimeout = TimeSpan.FromSeconds(100000), LogBody = true, - }); + }; var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(options, mockHeadersRedactor.Object); - var reader = new HttpRequestReader(options, GetHttpRouteFormatter(), headersReader, RequestMetadataContext); + var serviceKey = "my-key"; + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(serviceKey), mockHeadersRedactor.Object, serviceKey); + using var serviceProvider = GetServiceProvider(headersReader, serviceKey); + + var reader = new HttpRequestReader(serviceProvider, options.ToOptionsMonitor(serviceKey), serviceProvider.GetRequiredService(), + RequestMetadataContext, serviceKey: serviceKey); using var httpRequestMessage = new HttpRequestMessage { @@ -78,6 +83,7 @@ public async Task ReadAsync_AllData_ReturnsLogRecord() RequestUri = new Uri("http://default-uri.com/foo"), Content = new StringContent(requestContent, Encoding.UTF8) }; + httpRequestMessage.Headers.Add(header1.Key, header1.Value); httpRequestMessage.Headers.Add(header3.Key, header3.Value); @@ -86,6 +92,7 @@ public async Task ReadAsync_AllData_ReturnsLogRecord() StatusCode = HttpStatusCode.OK, Content = new StringContent(responseContent, Encoding.UTF8) }; + httpResponseMessage.Headers.Add(header2.Key, header2.Value); httpResponseMessage.Headers.Add(header3.Key, header3.Value); @@ -101,6 +108,7 @@ public async Task ReadAsync_AllData_ReturnsLogRecord() .Excluding(m => m.RequestBody) .Excluding(m => m.ResponseBody) .ComparingByMembers()); + logRecord.RequestBody.Should().BeEquivalentTo(expectedRecord.RequestBody); logRecord.ResponseBody.Should().BeEquivalentTo(expectedRecord.ResponseBody); } @@ -121,19 +129,23 @@ public async Task ReadAsync_NoHost_ReturnsLogRecordWithoutHost() RequestBody = requestContent, ResponseBody = responseContent, }; - var options = Microsoft.Extensions.Options.Options.Create(new LoggingOptions + + var options = new LoggingOptions { RequestBodyContentTypes = new HashSet { PlainTextMedia }, ResponseBodyContentTypes = new HashSet { PlainTextMedia }, BodyReadTimeout = TimeSpan.FromSeconds(10), LogBody = true, - }); + }; var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(options, mockHeadersRedactor.Object); - var reader = new HttpRequestReader(options, GetHttpRouteFormatter(), headersReader, RequestMetadataContext); + + var headersReader = new HttpHeadersReader(options.ToOptionsMonitor(), mockHeadersRedactor.Object); + using var serviceProvider = GetServiceProvider(headersReader); + + var reader = new HttpRequestReader(serviceProvider, options.ToOptionsMonitor(), serviceProvider.GetRequiredService(), RequestMetadataContext); using var httpRequestMessage = new HttpRequestMessage { @@ -161,6 +173,7 @@ public async Task ReadAsync_NoHost_ReturnsLogRecordWithoutHost() .Excluding(m => m.RequestBody) .Excluding(m => m.ResponseBody) .ComparingByMembers()); + actualRecord.RequestBody.Should().BeEquivalentTo(expectedRecord.RequestBody); actualRecord.ResponseBody.Should().BeEquivalentTo(expectedRecord.ResponseBody); } @@ -196,13 +209,17 @@ public async Task ReadAsync_AllDataWithRequestMetadataSet_ReturnsLogRecord() BodyReadTimeout = TimeSpan.FromSeconds(10), LogBody = true, }; + opts.RouteParameterDataClasses.Add("userId", SimpleClassifications.PrivateData); var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(Microsoft.Extensions.Options.Options.Create(opts), mockHeadersRedactor.Object); - var reader = new HttpRequestReader(Microsoft.Extensions.Options.Options.Create(opts), - GetHttpRouteFormatter(), headersReader, RequestMetadataContext); + + var headersReader = new HttpHeadersReader(opts.ToOptionsMonitor(), mockHeadersRedactor.Object); + using var serviceProvider = GetServiceProvider(headersReader); + + var reader = new HttpRequestReader(serviceProvider, opts.ToOptionsMonitor(), + serviceProvider.GetRequiredService(), RequestMetadataContext); using var httpRequestMessage = new HttpRequestMessage { @@ -210,6 +227,7 @@ public async Task ReadAsync_AllDataWithRequestMetadataSet_ReturnsLogRecord() RequestUri = new Uri("http://default-uri.com/foo/bar/123"), Content = new StringContent(requestContent, Encoding.UTF8), }; + httpRequestMessage.Headers.Add(header1.Key, header1.Value); httpRequestMessage.SetRequestMetadata(new RequestMetadata { @@ -221,6 +239,7 @@ public async Task ReadAsync_AllDataWithRequestMetadataSet_ReturnsLogRecord() StatusCode = HttpStatusCode.OK, Content = new StringContent(responseContent, Encoding.UTF8) }; + httpResponseMessage.Headers.Add(header2.Key, header2.Value); var requestHeadersBuffer = new List>(); @@ -261,6 +280,7 @@ public async Task ReadAsync_FormatRequestPathDisabled_ReturnsLogRecordWithRoute( RequestBody = requestContent, ResponseBody = responseContent, }; + var opts = new LoggingOptions { LogRequestStart = true, @@ -272,20 +292,26 @@ public async Task ReadAsync_FormatRequestPathDisabled_ReturnsLogRecordWithRoute( BodyReadTimeout = TimeSpan.FromSeconds(10), RequestPathLoggingMode = OutgoingPathLoggingMode.Structured }; + opts.RouteParameterDataClasses.Add("userId", SimpleClassifications.PrivateData); var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(Microsoft.Extensions.Options.Options.Create(opts), mockHeadersRedactor.Object); - var reader = new HttpRequestReader(Microsoft.Extensions.Options.Options.Create(opts), - GetHttpRouteFormatter(), headersReader, RequestMetadataContext); + + var headersReader = new HttpHeadersReader(opts.ToOptionsMonitor(), mockHeadersRedactor.Object); + using var serviceProvider = GetServiceProvider(headersReader); + + var reader = new HttpRequestReader(serviceProvider, opts.ToOptionsMonitor(), + serviceProvider.GetRequiredService(), RequestMetadataContext); + using var httpRequestMessage = new HttpRequestMessage { Method = HttpMethod.Post, RequestUri = new Uri("http://default-uri.com/foo/bar/123"), Content = new StringContent(requestContent, Encoding.UTF8), }; + httpRequestMessage.Headers.Add(header1.Key, header1.Value); httpRequestMessage.SetRequestMetadata(new RequestMetadata { @@ -297,6 +323,7 @@ public async Task ReadAsync_FormatRequestPathDisabled_ReturnsLogRecordWithRoute( StatusCode = HttpStatusCode.OK, Content = new StringContent(responseContent, Encoding.UTF8) }; + httpResponseMessage.Headers.Add(header2.Key, header2.Value); var requestHeadersBuffer = new List>(); @@ -333,6 +360,7 @@ public async Task ReadAsync_RouteParameterRedactionModeNone_ReturnsLogRecordWith RequestHeaders = new() { new("Header1", Redacted) }, RequestBody = requestContent, }; + var opts = new LoggingOptions { LogRequestStart = true, @@ -343,20 +371,26 @@ public async Task ReadAsync_RouteParameterRedactionModeNone_ReturnsLogRecordWith BodyReadTimeout = TimeSpan.FromSeconds(10), RequestPathLoggingMode = OutgoingPathLoggingMode.Structured }; + opts.RouteParameterDataClasses.Add("userId", SimpleClassifications.PrivateData); var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(Microsoft.Extensions.Options.Options.Create(opts), mockHeadersRedactor.Object); - var reader = new HttpRequestReader(Microsoft.Extensions.Options.Options.Create(opts), - GetHttpRouteFormatter(), headersReader, RequestMetadataContext); + + var headersReader = new HttpHeadersReader(opts.ToOptionsMonitor(), mockHeadersRedactor.Object); + using var serviceProvider = GetServiceProvider(headersReader); + + var reader = new HttpRequestReader(serviceProvider, opts.ToOptionsMonitor(), + serviceProvider.GetRequiredService(), RequestMetadataContext); + using var httpRequestMessage = new HttpRequestMessage { Method = HttpMethod.Post, RequestUri = new Uri("http://default-uri.com/foo/bar/123"), Content = new StringContent(requestContent, Encoding.UTF8), }; + httpRequestMessage.Headers.Add(header1.Key, header1.Value); var requestHeadersBuffer = new List>(); @@ -404,13 +438,17 @@ public async Task ReadAsync_RequestMetadataRequestNameSetAndRouteMissing_Returns BodyReadTimeout = TimeSpan.FromSeconds(10), LogBody = true, }; + opts.RouteParameterDataClasses.Add("userId", SimpleClassifications.PrivateData); var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(Microsoft.Extensions.Options.Options.Create(opts), mockHeadersRedactor.Object); - var reader = new HttpRequestReader(Microsoft.Extensions.Options.Options.Create(opts), - GetHttpRouteFormatter(), headersReader, RequestMetadataContext); + + var headersReader = new HttpHeadersReader(opts.ToOptionsMonitor(), mockHeadersRedactor.Object); + using var serviceProvider = GetServiceProvider(headersReader); + + var reader = new HttpRequestReader(serviceProvider, opts.ToOptionsMonitor(), + serviceProvider.GetRequiredService(), RequestMetadataContext); using var httpRequestMessage = new HttpRequestMessage { @@ -418,6 +456,7 @@ public async Task ReadAsync_RequestMetadataRequestNameSetAndRouteMissing_Returns RequestUri = new Uri("http://default-uri.com/foo/bar/123"), Content = new StringContent(requestContent, Encoding.UTF8), }; + httpRequestMessage.Headers.Add(header1.Key, header1.Value); httpRequestMessage.SetRequestMetadata(new RequestMetadata { @@ -429,6 +468,7 @@ public async Task ReadAsync_RequestMetadataRequestNameSetAndRouteMissing_Returns StatusCode = HttpStatusCode.OK, Content = new StringContent(responseContent, Encoding.UTF8) }; + httpResponseMessage.Headers.Add(header2.Key, header2.Value); var requestHeadersBuffer = new List>(); @@ -444,6 +484,7 @@ public async Task ReadAsync_RequestMetadataRequestNameSetAndRouteMissing_Returns .Excluding(m => m.RequestBody) .Excluding(m => m.ResponseBody) .ComparingByMembers()); + actualRecord.RequestBody.Should().BeEquivalentTo(expectedRecord.RequestBody); actualRecord.ResponseBody.Should().BeEquivalentTo(expectedRecord.ResponseBody); } @@ -479,13 +520,17 @@ public async Task ReadAsync_NoMetadataUsesRedactedString_ReturnsLogRecord() BodyReadTimeout = TimeSpan.FromSeconds(10), LogBody = true, }; + opts.RouteParameterDataClasses.Add("userId", SimpleClassifications.PrivateData); var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(Microsoft.Extensions.Options.Options.Create(opts), mockHeadersRedactor.Object); - var reader = new HttpRequestReader(Microsoft.Extensions.Options.Options.Create(opts), - GetHttpRouteFormatter(), headersReader, RequestMetadataContext); + + var headersReader = new HttpHeadersReader(opts.ToOptionsMonitor(), mockHeadersRedactor.Object); + using var serviceProvider = GetServiceProvider(headersReader); + + var reader = new HttpRequestReader(serviceProvider, opts.ToOptionsMonitor(), + serviceProvider.GetRequiredService(), RequestMetadataContext); using var httpRequestMessage = new HttpRequestMessage { @@ -493,6 +538,7 @@ public async Task ReadAsync_NoMetadataUsesRedactedString_ReturnsLogRecord() RequestUri = new Uri("http://default-uri.com/foo/bar/123"), Content = new StringContent(requestContent, Encoding.UTF8), }; + httpRequestMessage.Headers.Add(header1.Key, header1.Value); using var httpResponseMessage = new HttpResponseMessage @@ -500,6 +546,7 @@ public async Task ReadAsync_NoMetadataUsesRedactedString_ReturnsLogRecord() StatusCode = HttpStatusCode.OK, Content = new StringContent(responseContent, Encoding.UTF8) }; + httpResponseMessage.Headers.Add(header2.Key, header2.Value); var requestHeadersBuffer = new List>(); @@ -550,13 +597,17 @@ public async Task ReadAsync_MetadataWithoutRequestRouteOrNameUsesConstants_Retur BodyReadTimeout = TimeSpan.FromSeconds(10), LogBody = true, }; + opts.RouteParameterDataClasses.Add("userId", SimpleClassifications.PrivateData); var mockHeadersRedactor = new Mock(); mockHeadersRedactor.Setup(r => r.Redact(It.IsAny>(), It.IsAny())) .Returns(Redacted); - var headersReader = new HttpHeadersReader(Microsoft.Extensions.Options.Options.Create(opts), mockHeadersRedactor.Object); - var reader = new HttpRequestReader(Microsoft.Extensions.Options.Options.Create(opts), - GetHttpRouteFormatter(), headersReader, RequestMetadataContext); + + var headersReader = new HttpHeadersReader(opts.ToOptionsMonitor(), mockHeadersRedactor.Object); + using var serviceProvider = GetServiceProvider(headersReader); + + var reader = new HttpRequestReader(serviceProvider, opts.ToOptionsMonitor(), + serviceProvider.GetRequiredService(), RequestMetadataContext); using var httpRequestMessage = new HttpRequestMessage { @@ -564,6 +615,7 @@ public async Task ReadAsync_MetadataWithoutRequestRouteOrNameUsesConstants_Retur RequestUri = new Uri("http://default-uri.com/foo/bar/123"), Content = new StringContent(requestContent, Encoding.UTF8), }; + httpRequestMessage.Headers.Add(header1.Key, header1.Value); httpRequestMessage.SetRequestMetadata(new RequestMetadata()); @@ -572,6 +624,7 @@ public async Task ReadAsync_MetadataWithoutRequestRouteOrNameUsesConstants_Retur StatusCode = HttpStatusCode.OK, Content = new StringContent(responseContent, Encoding.UTF8) }; + httpResponseMessage.Headers.Add(header2.Key, header2.Value); var requestHeadersBuffer = new List>(); @@ -587,19 +640,28 @@ public async Task ReadAsync_MetadataWithoutRequestRouteOrNameUsesConstants_Retur .Excluding(m => m.RequestBody) .Excluding(m => m.ResponseBody) .ComparingByMembers()); + actualRecord.RequestBody.Should().BeEquivalentTo(expectedRecord.RequestBody); actualRecord.ResponseBody.Should().BeEquivalentTo(expectedRecord.ResponseBody); } - private static IHttpRouteFormatter GetHttpRouteFormatter() + private static ServiceProvider GetServiceProvider(HttpHeadersReader headersReader, string? serviceKey = null) { - var builder = new ServiceCollection() + var services = new ServiceCollection(); + if (serviceKey is null) + { + _ = services.AddSingleton(headersReader); + } + else + { + _ = services.AddKeyedSingleton(serviceKey, headersReader); + } + + return services .AddFakeRedaction() .AddHttpRouteProcessor() .BuildServiceProvider(); - - return builder.GetService()!; } - private static IOutgoingRequestContext RequestMetadataContext => new Mock().Object; + private static IOutgoingRequestContext RequestMetadataContext => Mock.Of(); } diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpResponseBodyReaderTest.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpResponseBodyReaderTest.cs index 7dd011f542a..b595585a65d 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpResponseBodyReaderTest.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/HttpResponseBodyReaderTest.cs @@ -16,8 +16,6 @@ using Moq; using Xunit; -using IOptionsFactory = Microsoft.Extensions.Options.Options; - namespace Microsoft.Extensions.Http.Telemetry.Logging.Test; public class HttpResponseBodyReaderTest @@ -29,21 +27,14 @@ public HttpResponseBodyReaderTest() _fixture = new Fixture(); } - [Fact] - public void Reader_NullOptions_Throws() - { - var options = IOptionsFactory.Create((LoggingOptions)null!); - var act = () => new HttpResponseBodyReader(options); - act.Should().Throw(); - } - [Fact] public async Task Reader_SimpleContent_ReadsContent() { - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { ResponseBodyContentTypes = new HashSet { "text/plain" } - }); + }; + var httpResponseBodyReader = new HttpResponseBodyReader(options); var expectedContentBody = _fixture.Create(); using var httpResponse = new HttpResponseMessage @@ -59,10 +50,11 @@ public async Task Reader_SimpleContent_ReadsContent() [Fact] public async Task Reader_EmptyContent_ErrorMessage() { - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { ResponseBodyContentTypes = new HashSet { "text/plain" } - }); + }; + using var httpResponse = new HttpResponseMessage { Content = new StreamContent(new MemoryStream()) @@ -81,10 +73,11 @@ public async Task Reader_UnreadableContent_ErrorMessage( "application/javascript")] string contentType) { - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { ResponseBodyContentTypes = new HashSet { "text/plain" } - }); + }; + var httpResponseBodyReader = new HttpResponseBodyReader(options); var expectedContentBody = _fixture.Create(); using var httpResponse = new HttpResponseMessage @@ -100,10 +93,11 @@ public async Task Reader_UnreadableContent_ErrorMessage( [Fact] public async Task Reader_OperationCanceled_ThrowsTaskCanceledException() { - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { ResponseBodyContentTypes = new HashSet { "text/plain" } - }); + }; + var httpResponseBodyReader = new HttpResponseBodyReader(options); var input = _fixture.Create(); using var httpResponse = new HttpResponseMessage @@ -122,11 +116,12 @@ public async Task Reader_OperationCanceled_ThrowsTaskCanceledException() [CombinatorialData] public async Task Reader_BigContent_TrimsAtTheEnd([CombinatorialValues(32, 256, 4095, 4096, 4097, 65536, 131072)] int limit) { - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { BodySizeLimit = limit, ResponseBodyContentTypes = new HashSet { "text/plain" } - }); + }; + var httpResponseBodyReader = new HttpResponseBodyReader(options); var bigContent = RandomStringGenerator.Generate(limit * 2); using var httpResponse = new HttpResponseMessage @@ -142,10 +137,11 @@ public async Task Reader_BigContent_TrimsAtTheEnd([CombinatorialValues(32, 256, [Fact] public async Task Reader_ReadingTakesTooLong_TimesOut() { - var options = IOptionsFactory.Create(new LoggingOptions + var options = new LoggingOptions { ResponseBodyContentTypes = new HashSet { "text/plain" } - }); + }; + var httpResponseBodyReader = new HttpResponseBodyReader(options); var streamMock = new Mock(); #if NETCOREAPP3_1_OR_GREATER @@ -157,6 +153,7 @@ public async Task Reader_ReadingTakesTooLong_TimesOut() { Content = new StreamContent(streamMock.Object) }; + httpResponse.Content.Headers.Add("Content-type", "text/plain"); var requestBody = await httpResponseBodyReader.ReadAsync(httpResponse, CancellationToken.None).ConfigureAwait(false); @@ -167,7 +164,7 @@ public async Task Reader_ReadingTakesTooLong_TimesOut() [Fact] public void HttpResponseBodyReader_Has_Infinite_Timeout_For_Reading_A_Body_When_Debugger_Is_Attached() { - var options = IOptionsFactory.Create(new LoggingOptions()); + var options = new LoggingOptions(); var reader = new HttpResponseBodyReader(options, DebuggerState.Attached); Assert.Equal(reader.ResponseReadTimeout, Timeout.InfiniteTimeSpan); @@ -177,7 +174,7 @@ public void HttpResponseBodyReader_Has_Infinite_Timeout_For_Reading_A_Body_When_ public void HttpResponseBodyReader_Has_Option_Defined_Timeout_For_Reading_A_Body_When_Debugger_Is_Detached() { var timeout = TimeSpan.FromSeconds(274); - var options = IOptionsFactory.Create(new LoggingOptions { BodyReadTimeout = timeout }); + var options = new LoggingOptions { BodyReadTimeout = timeout }; var reader = new HttpResponseBodyReader(options, DebuggerState.Detached); Assert.Equal(reader.ResponseReadTimeout, timeout); diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/EmptyEnricher.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/EmptyEnricher.cs index 0fb2b89663d..d4e5c4e176b 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/EmptyEnricher.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/EmptyEnricher.cs @@ -1,6 +1,7 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System; using System.Net.Http; using Microsoft.Extensions.Telemetry.Enrichment; @@ -8,7 +9,7 @@ namespace Microsoft.Extensions.Http.Telemetry.Logging.Test.Internal; internal class EmptyEnricher : IHttpClientLogEnricher { - public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage? request = null, HttpResponseMessage? response = null) + public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage request, HttpResponseMessage? response = null, Exception? exception = null) { // intentionally left empty. } diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/EnricherWithCounter.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/EnricherWithCounter.cs index ad6a7e4feba..631335f2016 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/EnricherWithCounter.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/EnricherWithCounter.cs @@ -1,6 +1,7 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System; using System.Net.Http; using Microsoft.Extensions.Telemetry.Enrichment; @@ -10,7 +11,6 @@ internal class EnricherWithCounter : IHttpClientLogEnricher { public int TimesCalled; - public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage? request = null, - HttpResponseMessage? response = null) => - TimesCalled++; + public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage request, HttpResponseMessage? response = null, Exception? exception = null) + => TimesCalled++; } diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/HelperExtensions.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/HelperExtensions.cs index bdb2aca45db..b3c043f9cd4 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/HelperExtensions.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/HelperExtensions.cs @@ -3,6 +3,8 @@ using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Http; +using Microsoft.Extensions.Options; +using Moq; namespace Microsoft.Extensions.Http.Telemetry.Logging.Test.Internal; @@ -20,4 +22,24 @@ public static IServiceCollection BlockRemoteCall(this IServiceCollection service }); }); } + + public static IOptionsMonitor ToOptionsMonitor(this LoggingOptions options, string? key = null) + { + var snapshotMock = new Mock>(); + + if (key is not null) + { + snapshotMock + .Setup(monitor => monitor.Get(key)) + .Returns(options); + } + else + { + snapshotMock + .SetupGet(monitor => monitor.CurrentValue) + .Returns(options); + } + + return snapshotMock.Object; + } } diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/LogRecordExtensions.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/LogRecordExtensions.cs index dd258dca68b..6f2768067e5 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/LogRecordExtensions.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/LogRecordExtensions.cs @@ -1,6 +1,7 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System; using System.Collections.Generic; using System.Linq; using Microsoft.Extensions.Http.Telemetry.Logging.Internal; @@ -23,14 +24,20 @@ public static string GetEnrichmentProperty(this LogRecord logRecord, string name return logRecord.EnrichmentTags!.FirstOrDefault(kvp => kvp.Key == name).Value!.ToString()!; } - public static void Contains(this Dictionary logRecord, string key, string value) + public static void Contains(this IDictionary logRecordState, string key, string expectedValue) { - Assert.True(logRecord.ContainsKey(key)); - Assert.Equal(value, logRecord[key]); + var actualValue = Assert.Contains(key, logRecordState); + Assert.Equal(expectedValue, actualValue); } - public static void NotContains(this Dictionary logRecord, string key) + public static void Contains(this IDictionary logRecordState, string key, Action assertion) { - Assert.False(logRecord.ContainsKey(key)); + var actualValue = Assert.Contains(key, logRecordState); + assertion(actualValue); + } + + public static void NotContains(this IDictionary logRecord, string key) + { + Assert.DoesNotContain(key, logRecord); } } diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/MockedLogger.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/MockedLogger.cs deleted file mode 100644 index aa3634759ad..00000000000 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/MockedLogger.cs +++ /dev/null @@ -1,30 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using System; -using Microsoft.Extensions.Logging; -using Moq; - -namespace Microsoft.Extensions.Http.Telemetry.Logging.Test.Internal; - -public class MockedLogger : ILogger -{ - public Mock> Mock { get; } - - public MockedLogger(Mock> mock) - { - Mock = mock; - } - - public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, - Func formatter) => Mock.Object.Log(logLevel, eventId, state, exception, formatter); - - public bool IsEnabled(LogLevel logLevel) => Mock.Object.IsEnabled(logLevel); - -#pragma warning disable CS8633 -#pragma warning disable CS8766 - public IDisposable? BeginScope(TState state) - where TState : notnull => Mock.Object.BeginScope(state); -#pragma warning restore CS8633 -#pragma warning restore CS8766 -} diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/TestEnricher.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/TestEnricher.cs index e4cd58c37f4..72ea7df1002 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/TestEnricher.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/TestEnricher.cs @@ -1,6 +1,7 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System; using System.Collections.Generic; using System.Net.Http; using Microsoft.Extensions.Telemetry.Enrichment; @@ -12,19 +13,34 @@ internal class TestEnricher : IHttpClientLogEnricher { internal readonly KeyValuePair KvpRequest = new("test key request", "test value"); internal readonly KeyValuePair KvpResponse = new("test key response", "test value"); - public LogMethodHelper EnrichmentCollector => new() { KvpRequest, KvpResponse }; + private readonly bool _throwOnEnrich; - public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage? request = null, - HttpResponseMessage? response = null) + public LoggerMessageState EnrichmentBag { get; } + + public TestEnricher(bool throwOnEnrich = false) + { + EnrichmentBag = new(); + var index = EnrichmentBag.ReserveTagSpace(2); + EnrichmentBag.TagArray[index++] = KvpRequest; + EnrichmentBag.TagArray[index++] = KvpResponse; + _throwOnEnrich = throwOnEnrich; + } + + public void Enrich(IEnrichmentTagCollector tagCollector, HttpRequestMessage request, HttpResponseMessage? response = null, Exception? exception = null) { + if (_throwOnEnrich) + { + throw new NotSupportedException("Synthetic exception from enricher"); + } + if (request is not null) { - collector.Add(KvpRequest.Key, KvpRequest.Value!); + tagCollector.Add(KvpRequest.Key, KvpRequest.Value!); } if (response is not null) { - collector.Add(KvpResponse.Key, KvpResponse.Value!); + tagCollector.Add(KvpResponse.Key, KvpResponse.Value!); } } } diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/TestLoggingHandler.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/TestLoggingHandler.cs new file mode 100644 index 00000000000..d0b52dbbc6d --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/Internal/TestLoggingHandler.cs @@ -0,0 +1,35 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Diagnostics.CodeAnalysis; +using System.Net.Http; +using Microsoft.Extensions.Http.Logging; +using Xunit; + +namespace Microsoft.Extensions.Http.Telemetry.Test.Logging.Internal; + +internal sealed class TestLoggingHandler : DelegatingHandler +{ + [SuppressMessage("Reliability", "CA2000:Dispose objects before losing scope", Justification = "Base class disposes the handler")] + public TestLoggingHandler(IHttpClientLogger logger, HttpMessageHandler? innerHandler) + : base(CreateInternalBclLoggingHandler(logger, innerHandler)) + { + } + + private static DelegatingHandler CreateInternalBclLoggingHandler(IHttpClientLogger logger, HttpMessageHandler? innerHandler) + { + var handlerType = typeof(IHttpClientFactory).Assembly.GetType("Microsoft.Extensions.Http.Logging.HttpClientLoggerHandler"); + Assert.NotNull(handlerType); + var handler = Activator.CreateInstance(handlerType, logger); + Assert.NotNull(handler); + + var delegatingHandler = Assert.IsAssignableFrom(handler); + if (innerHandler is not null) + { + delegatingHandler.InnerHandler = innerHandler; + } + + return delegatingHandler; + } +} diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/LogRecordPooledObjectPolicyTest.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/LogRecordPoolingTest.cs similarity index 82% rename from test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/LogRecordPooledObjectPolicyTest.cs rename to test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/LogRecordPoolingTest.cs index 9c67c1b0347..ccf099a4a3e 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/LogRecordPooledObjectPolicyTest.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Logging/LogRecordPoolingTest.cs @@ -10,16 +10,16 @@ namespace Microsoft.Extensions.Http.Telemetry.Logging.Test; -public class LogRecordPooledObjectPolicyTest +public class LogRecordPoolingTest { [Fact] - public void LogRecordPooledObjectPolicy_ResetsLogRecord() + public void LogRecordInPool_ResetsItsState() { - var pool = PoolFactory.CreatePool(new LogRecordPooledObjectPolicy()); + var pool = PoolFactory.CreateResettingPool(); var testObject = new Fixture().Create(); testObject.RequestHeaders!.Add(new KeyValuePair("key1", "value1")); testObject.ResponseHeaders!.Add(new KeyValuePair("key2", "value2")); - testObject.EnrichmentTags!.Add("key3", "value3"); + testObject.EnrichmentTags!.AddTag("key3", "value3"); var logRecord1 = pool.Get(); logRecord1.Host = testObject.Host; @@ -42,8 +42,8 @@ public void LogRecordPooledObjectPolicy_ResetsLogRecord() logRecord2.StatusCode.Should().BeNull(); logRecord2.RequestHeaders.Should().BeNull(); logRecord2.ResponseHeaders.Should().BeNull(); - logRecord2.RequestBody.Should().Be(string.Empty); - logRecord2.ResponseBody.Should().Be(string.Empty); + logRecord2.RequestBody.Should().BeNull(); + logRecord2.ResponseBody.Should().BeNull(); logRecord2.EnrichmentTags.Should().BeNull(); } } diff --git a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Tracing/HttpClientTracingExtensionsTests.cs b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Tracing/HttpClientTracingExtensionsTests.cs index ba3dcd2b92e..a54e40bc5c1 100644 --- a/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Tracing/HttpClientTracingExtensionsTests.cs +++ b/test/Libraries/Microsoft.Extensions.Http.Telemetry.Tests/Tracing/HttpClientTracingExtensionsTests.cs @@ -240,7 +240,9 @@ public async Task AddHttpClientTracing_WithException_CallsEnrichOnce() // no op } - mockTraceEnricher.Verify(e => e.Enrich(It.IsAny(), It.IsAny(), It.IsAny()), Times.Once); + // We check for the specific URL because we can catch traces from other tests: + mockTraceEnricher.Verify(e => + e.Enrich(It.IsAny(), It.Is(x => x.RequestUri != null && x.RequestUri.AbsoluteUri == UriString), It.IsAny()), Times.Once); } [Fact]