diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs new file mode 100644 index 0000000000000..2a37f6b3f3d1f --- /dev/null +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -0,0 +1,193 @@ +// 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; +using System.Net.Http; +using System.Runtime.CompilerServices; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Extensions.Internal; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Extensions.Http.Logging +{ + internal static class LogHelper + { + private static readonly LogDefineOptions s_skipEnabledCheckLogDefineOptions = new LogDefineOptions() { SkipEnabledCheck = true }; + private static readonly bool s_disableUriRedaction = GetDisableUriRedactionSettingValue(); + + private static class EventIds + { + public static readonly EventId RequestStart = new EventId(100, "RequestStart"); + public static readonly EventId RequestEnd = new EventId(101, "RequestEnd"); + + public static readonly EventId RequestHeader = new EventId(102, "RequestHeader"); + public static readonly EventId ResponseHeader = new EventId(103, "ResponseHeader"); + + public static readonly EventId PipelineStart = new EventId(100, "RequestPipelineStart"); + public static readonly EventId PipelineEnd = new EventId(101, "RequestPipelineEnd"); + + public static readonly EventId RequestPipelineRequestHeader = new EventId(102, "RequestPipelineRequestHeader"); + public static readonly EventId RequestPipelineResponseHeader = new EventId(103, "RequestPipelineResponseHeader"); + } + + private static readonly Action _requestStart = LoggerMessage.Define( + LogLevel.Information, + EventIds.RequestStart, + "Sending HTTP request {HttpMethod} {Uri}", + s_skipEnabledCheckLogDefineOptions); + + private static readonly Action _requestEnd = LoggerMessage.Define( + LogLevel.Information, + EventIds.RequestEnd, + "Received HTTP response headers after {ElapsedMilliseconds}ms - {StatusCode}"); + + private static readonly Func _beginRequestPipelineScope = LoggerMessage.DefineScope("HTTP {HttpMethod} {Uri}"); + + private static readonly Action _requestPipelineStart = LoggerMessage.Define( + LogLevel.Information, + EventIds.PipelineStart, + "Start processing HTTP request {HttpMethod} {Uri}"); + + private static readonly Action _requestPipelineEnd = LoggerMessage.Define( + LogLevel.Information, + EventIds.PipelineEnd, + "End processing HTTP request after {ElapsedMilliseconds}ms - {StatusCode}"); + + private static bool GetDisableUriRedactionSettingValue() + { + if (AppContext.TryGetSwitch("System.Net.Http.DisableUriRedaction", out bool value)) + { + return value; + } + + string? envVar = Environment.GetEnvironmentVariable("DOTNET_SYSTEM_NET_HTTP_DISABLEURIREDACTION"); + + if (bool.TryParse(envVar, out value)) + { + return value; + } + else if (uint.TryParse(envVar, out uint intVal)) + { + return intVal != 0; + } + + return false; + } + + public static void LogRequestStart(this ILogger logger, HttpRequestMessage request, Func shouldRedactHeaderValue) + { + // We check here to avoid allocating in the GetRedactedUriString call unnecessarily + if (logger.IsEnabled(LogLevel.Information)) + { + _requestStart(logger, request.Method, GetRedactedUriString(request.RequestUri), null); + } + + if (logger.IsEnabled(LogLevel.Trace)) + { + logger.Log( + LogLevel.Trace, + EventIds.RequestHeader, + new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Request, request.Headers, request.Content?.Headers, shouldRedactHeaderValue), + null, + (state, ex) => state.ToString()); + } + } + + public static void LogRequestEnd(this ILogger logger, HttpResponseMessage response, TimeSpan duration, Func shouldRedactHeaderValue) + { + _requestEnd(logger, duration.TotalMilliseconds, (int)response.StatusCode, null); + + if (logger.IsEnabled(LogLevel.Trace)) + { + logger.Log( + LogLevel.Trace, + EventIds.ResponseHeader, + new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Response, response.Headers, response.Content?.Headers, shouldRedactHeaderValue), + null, + (state, ex) => state.ToString()); + } + } + + public static IDisposable? BeginRequestPipelineScope(this ILogger logger, HttpRequestMessage request, out string? formattedUri) + { + formattedUri = GetRedactedUriString(request.RequestUri); + return _beginRequestPipelineScope(logger, request.Method, formattedUri); + } + + public static void LogRequestPipelineStart(this ILogger logger, HttpRequestMessage request, string? formattedUri, Func shouldRedactHeaderValue) + { + _requestPipelineStart(logger, request.Method, formattedUri, null); + + if (logger.IsEnabled(LogLevel.Trace)) + { + logger.Log( + LogLevel.Trace, + EventIds.RequestPipelineRequestHeader, + new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Request, request.Headers, request.Content?.Headers, shouldRedactHeaderValue), + null, + (state, ex) => state.ToString()); + } + } + + public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessage response, TimeSpan duration, Func shouldRedactHeaderValue) + { + _requestPipelineEnd(logger, duration.TotalMilliseconds, (int)response.StatusCode, null); + + if (logger.IsEnabled(LogLevel.Trace)) + { + logger.Log( + LogLevel.Trace, + EventIds.RequestPipelineResponseHeader, + new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Response, response.Headers, response.Content?.Headers, shouldRedactHeaderValue), + null, + (state, ex) => state.ToString()); + } + } + + internal static string? GetRedactedUriString(Uri? uri) + { + if (uri is null) + { + return null; + } + + if (s_disableUriRedaction) + { + return uri.IsAbsoluteUri ? uri.AbsoluteUri : uri.ToString(); + } + + if (!uri.IsAbsoluteUri) + { + // We cannot guarantee the redaction of UserInfo for relative Uris without implementing some subset of Uri parsing in this package. + // To avoid this, we redact the whole Uri. Seeing a relative Uri in LoggingHttpMessageHandler or LoggingScopeHttpMessageHandler + // requires a custom handler chain with custom expansion logic implemented by the user's HttpMessageHandler. + // In such advanced scenarios we recommend users to log the Uri in their handler. + return "*"; + } + + string pathAndQuery = uri.PathAndQuery; + int queryIndex = pathAndQuery.IndexOf('?'); + + bool redactQuery = queryIndex >= 0 && // Query is present. + queryIndex < pathAndQuery.Length - 1; // Query is not empty. + + return (redactQuery, uri.IsDefaultPort) switch + { + (true, true) => $"{uri.Scheme}://{uri.Host}{GetPath(pathAndQuery, queryIndex)}*", + (true, false) => $"{uri.Scheme}://{uri.Host}:{uri.Port}{GetPath(pathAndQuery, queryIndex)}*", + (false, true) => $"{uri.Scheme}://{uri.Host}{pathAndQuery}", + (false, false) => $"{uri.Scheme}://{uri.Host}:{uri.Port}{pathAndQuery}" + }; + +#if NET + [MethodImpl(MethodImplOptions.AggressiveInlining)] + static ReadOnlySpan GetPath(string pathAndQuery, int queryIndex) => pathAndQuery.AsSpan(0, queryIndex + 1); +#else + [MethodImpl(MethodImplOptions.AggressiveInlining)] + static string GetPath(string pathAndQuery, int queryIndex) => pathAndQuery.Substring(0, queryIndex + 1); +#endif + } + } +} diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs index e592e7d236fbb..c86d149a0f2c6 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs @@ -2,6 +2,7 @@ // The .NET Foundation licenses this file to you under the MIT license. using System; +using System.Diagnostics; using System.Net.Http; using System.Threading; using System.Threading.Tasks; @@ -58,7 +59,7 @@ async Task Core(HttpRequestMessage request, bool useAsync, // Not using a scope here because we always expect this to be at the end of the pipeline, thus there's // not really anything to surround. - Log.RequestStart(_logger, request, shouldRedactHeaderValue); + _logger.LogRequestStart(request, shouldRedactHeaderValue); var stopwatch = ValueStopwatch.StartNew(); HttpResponseMessage response = useAsync ? await base.SendAsync(request, cancellationToken).ConfigureAwait(false) @@ -67,7 +68,7 @@ async Task Core(HttpRequestMessage request, bool useAsync, #else : throw new NotImplementedException("Unreachable code"); #endif - Log.RequestEnd(_logger, response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue); + _logger.LogRequestEnd(response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue); return response; } @@ -84,72 +85,5 @@ protected override Task SendAsync(HttpRequestMessage reques protected override HttpResponseMessage Send(HttpRequestMessage request, CancellationToken cancellationToken) => SendCoreAsync(request, useAsync: false, cancellationToken).GetAwaiter().GetResult(); #endif - - // Used in tests. - internal static class Log - { - public static class EventIds - { - public static readonly EventId RequestStart = new EventId(100, "RequestStart"); - public static readonly EventId RequestEnd = new EventId(101, "RequestEnd"); - - public static readonly EventId RequestHeader = new EventId(102, "RequestHeader"); - public static readonly EventId ResponseHeader = new EventId(103, "ResponseHeader"); - } - - private static readonly LogDefineOptions _skipEnabledCheckLogDefineOptions = new LogDefineOptions() { SkipEnabledCheck = true }; - - private static readonly Action _requestStart = LoggerMessage.Define( - LogLevel.Information, - EventIds.RequestStart, - "Sending HTTP request {HttpMethod} {Uri}", - _skipEnabledCheckLogDefineOptions); - - private static readonly Action _requestEnd = LoggerMessage.Define( - LogLevel.Information, - EventIds.RequestEnd, - "Received HTTP response headers after {ElapsedMilliseconds}ms - {StatusCode}"); - - public static void RequestStart(ILogger logger, HttpRequestMessage request, Func shouldRedactHeaderValue) - { - // We check here to avoid allocating in the GetUriString call unnecessarily - if (logger.IsEnabled(LogLevel.Information)) - { - _requestStart(logger, request.Method, GetUriString(request.RequestUri), null); - } - - if (logger.IsEnabled(LogLevel.Trace)) - { - logger.Log( - LogLevel.Trace, - EventIds.RequestHeader, - new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Request, request.Headers, request.Content?.Headers, shouldRedactHeaderValue), - null, - (state, ex) => state.ToString()); - } - } - - public static void RequestEnd(ILogger logger, HttpResponseMessage response, TimeSpan duration, Func shouldRedactHeaderValue) - { - _requestEnd(logger, duration.TotalMilliseconds, (int)response.StatusCode, null); - - if (logger.IsEnabled(LogLevel.Trace)) - { - logger.Log( - LogLevel.Trace, - EventIds.ResponseHeader, - new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Response, response.Headers, response.Content?.Headers, shouldRedactHeaderValue), - null, - (state, ex) => state.ToString()); - } - } - - private static string? GetUriString(Uri? requestUri) - { - return requestUri?.IsAbsoluteUri == true - ? requestUri.AbsoluteUri - : requestUri?.ToString(); - } - } } } diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs index 1894a005f84a6..a25a9366ac8e2 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs @@ -58,9 +58,9 @@ async Task Core(HttpRequestMessage request, bool useAsync, Func shouldRedactHeaderValue = _options?.ShouldRedactHeaderValue ?? _shouldNotRedactHeaderValue; - using (Log.BeginRequestPipelineScope(_logger, request)) + using (_logger.BeginRequestPipelineScope(request, out string? formattedUri)) { - Log.RequestPipelineStart(_logger, request, shouldRedactHeaderValue); + _logger.LogRequestPipelineStart(request, formattedUri, shouldRedactHeaderValue); HttpResponseMessage response = useAsync ? await base.SendAsync(request, cancellationToken).ConfigureAwait(false) #if NET @@ -68,7 +68,7 @@ async Task Core(HttpRequestMessage request, bool useAsync, #else : throw new NotImplementedException("Unreachable code"); #endif - Log.RequestPipelineEnd(_logger, response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue); + _logger.LogRequestPipelineEnd(response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue); return response; } @@ -86,72 +86,5 @@ protected override Task SendAsync(HttpRequestMessage reques protected override HttpResponseMessage Send(HttpRequestMessage request, CancellationToken cancellationToken) => SendCoreAsync(request, useAsync: false, cancellationToken).GetAwaiter().GetResult(); #endif - - // Used in tests - internal static class Log - { - public static class EventIds - { - public static readonly EventId PipelineStart = new EventId(100, "RequestPipelineStart"); - public static readonly EventId PipelineEnd = new EventId(101, "RequestPipelineEnd"); - - public static readonly EventId RequestHeader = new EventId(102, "RequestPipelineRequestHeader"); - public static readonly EventId ResponseHeader = new EventId(103, "RequestPipelineResponseHeader"); - } - - private static readonly Func _beginRequestPipelineScope = LoggerMessage.DefineScope("HTTP {HttpMethod} {Uri}"); - - private static readonly Action _requestPipelineStart = LoggerMessage.Define( - LogLevel.Information, - EventIds.PipelineStart, - "Start processing HTTP request {HttpMethod} {Uri}"); - - private static readonly Action _requestPipelineEnd = LoggerMessage.Define( - LogLevel.Information, - EventIds.PipelineEnd, - "End processing HTTP request after {ElapsedMilliseconds}ms - {StatusCode}"); - - public static IDisposable? BeginRequestPipelineScope(ILogger logger, HttpRequestMessage request) - { - return _beginRequestPipelineScope(logger, request.Method, GetUriString(request.RequestUri)); - } - - public static void RequestPipelineStart(ILogger logger, HttpRequestMessage request, Func shouldRedactHeaderValue) - { - _requestPipelineStart(logger, request.Method, GetUriString(request.RequestUri), null); - - if (logger.IsEnabled(LogLevel.Trace)) - { - logger.Log( - LogLevel.Trace, - EventIds.RequestHeader, - new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Request, request.Headers, request.Content?.Headers, shouldRedactHeaderValue), - null, - (state, ex) => state.ToString()); - } - } - - public static void RequestPipelineEnd(ILogger logger, HttpResponseMessage response, TimeSpan duration, Func shouldRedactHeaderValue) - { - _requestPipelineEnd(logger, duration.TotalMilliseconds, (int)response.StatusCode, null); - - if (logger.IsEnabled(LogLevel.Trace)) - { - logger.Log( - LogLevel.Trace, - EventIds.ResponseHeader, - new HttpHeadersLogValue(HttpHeadersLogValue.Kind.Response, response.Headers, response.Content?.Headers, shouldRedactHeaderValue), - null, - (state, ex) => state.ToString()); - } - } - - private static string? GetUriString(Uri? requestUri) - { - return requestUri?.IsAbsoluteUri == true - ? requestUri.AbsoluteUri - : requestUri?.ToString(); - } - } } } diff --git a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/LoggingUriOutputTests.cs b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/LoggingUriOutputTests.cs index bdd204f709df3..2e71063d1334d 100644 --- a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/LoggingUriOutputTests.cs +++ b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/LoggingUriOutputTests.cs @@ -4,8 +4,8 @@ using System; using System.Linq; using System.Net.Http; -using System.Threading; using System.Threading.Tasks; +using Microsoft.DotNet.RemoteExecutor; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Http.Logging; using Microsoft.Extensions.Logging; @@ -16,156 +16,186 @@ namespace Microsoft.Extensions.Http.Tests.Logging { public class LoggingUriOutputTests { - [Fact] - public async Task LoggingHttpMessageHandler_LogsAbsoluteUri() + private static class EventIds { - // Arrange - var sink = new TestSink(); + public static readonly EventId RequestStart = new EventId(100, "RequestStart"); + public static readonly EventId RequestEnd = new EventId(101, "RequestEnd"); - var serviceCollection = new ServiceCollection(); - serviceCollection.AddLogging(); - serviceCollection.AddSingleton(new TestLoggerFactory(sink, enabled: true)); - - serviceCollection - .AddHttpClient("test") - .ConfigurePrimaryHttpMessageHandler(() => new TestMessageHandler()); - - var services = serviceCollection.BuildServiceProvider(); - - var client = services.GetRequiredService().CreateClient("test"); - - - // Act - var request = new HttpRequestMessage(HttpMethod.Get, "http://api.example.com/search?term=Western%20Australia"); - - await client.SendAsync(request); - - // Assert - var messages = sink.Writes.ToArray(); - - var message = Assert.Single(messages.Where(m => - { - return - m.EventId == LoggingHttpMessageHandler.Log.EventIds.RequestStart && - m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler"; - })); - - Assert.Equal("Sending HTTP request GET http://api.example.com/search?term=Western%20Australia", message.Message); + public static readonly EventId PipelineStart = new EventId(100, "RequestPipelineStart"); + public static readonly EventId PipelineEnd = new EventId(101, "RequestPipelineEnd"); } - [Fact] - public async Task LoggingScopeHttpMessageHandler_LogsAbsoluteUri() + public static readonly TheoryData GetRedactedUriString_Data = new TheoryData() { - // Arrange - var sink = new TestSink(); - - var serviceCollection = new ServiceCollection(); - serviceCollection.AddLogging(); - serviceCollection.AddSingleton(new TestLoggerFactory(sink, enabled: true)); - - serviceCollection - .AddHttpClient("test") - .ConfigurePrimaryHttpMessageHandler(() => new TestMessageHandler()); - - var services = serviceCollection.BuildServiceProvider(); - - var client = services.GetRequiredService().CreateClient("test"); - - - // Act - var request = new HttpRequestMessage(HttpMethod.Get, "http://api.example.com/search?term=Western%20Australia"); - - await client.SendAsync(request); + { null, null }, + { "http://q.app/foo", "http://q.app/foo" }, + { "http://q.app:123/foo", "http://q.app:123/foo" }, + { "http://user:xxx@q.app/foo", "http://q.app/foo" }, // has user info + { "http://q.app/foo?", "http://q.app/foo?" }, + { "http://q.app/foo?XXX", "http://q.app/foo?*" }, + { "http://q.app/a/b/c?a=b%20c&x=1", "http://q.app/a/b/c?*" }, + { "http://q.app:4242/a/b/c?a=b%20c&x=1", "http://q.app:4242/a/b/c?*" }, + { "/cat/1/2", "*" }, // Relative Uris are fully redacted. + { "/cat/1/2?a=b%20c&x=1", "*" }, + }; + + [Theory] + [MemberData(nameof(GetRedactedUriString_Data))] + public void GetRedactedUriString_RedactsUriByDefault(string original, string expected) + { + Uri? uri = original != null ? new Uri(original, UriKind.RelativeOrAbsolute) : null; + string? actual = LogHelper.GetRedactedUriString(uri); - // Assert - var messages = sink.Writes.ToArray(); + Assert.Equal(expected, actual); + } - var message = Assert.Single(messages.Where(m => + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData("AppCtx")] // AppContext switch System.Net.Http.DisableUriRedaction = true + [InlineData("EnvVar1")] // Env. var DOTNET_SYSTEM_NET_DISABLEURIREDACTION = "1" + [InlineData("EnvVarTrue")] // Env. var DOTNET_SYSTEM_NET_DISABLEURIREDACTION = "true" + public void GetRedactedUriString_DisableUriRedaction_DoesNotRedactUri(string queryRedactionDisabler) + { + RemoteExecutor.Invoke(static queryRedactionDisabler => { - return - m.EventId == LoggingScopeHttpMessageHandler.Log.EventIds.PipelineStart && - m.LoggerName == "System.Net.Http.HttpClient.test.LogicalHandler"; - })); - - Assert.Equal("Start processing HTTP request GET http://api.example.com/search?term=Western%20Australia", message.Message); - Assert.Equal("HTTP GET http://api.example.com/search?term=Western%20Australia", message.Scope.ToString()); + switch (queryRedactionDisabler) + { + case "AppCtx": + AppContext.SetSwitch("System.Net.Http.DisableUriRedaction", true); + break; + case "EnvVarTrue": + Environment.SetEnvironmentVariable("DOTNET_SYSTEM_NET_HTTP_DISABLEURIREDACTION", "true"); + break; + case "EnvVar1": + Environment.SetEnvironmentVariable("DOTNET_SYSTEM_NET_HTTP_DISABLEURIREDACTION", "1"); + break; + } + + Uri[] uris = GetRedactedUriString_Data.Select(a => a[0] == null ? null : new Uri((string)a[0], UriKind.RelativeOrAbsolute)).ToArray(); + + foreach (Uri uri in uris) + { + string? expected = uri != null ? uri.IsAbsoluteUri ? uri.AbsoluteUri : uri.ToString() : null; + string? actual = LogHelper.GetRedactedUriString(uri); + Assert.Equal(expected, actual); + } + }, queryRedactionDisabler).Dispose(); } + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData(false, false)] + [InlineData(false, true)] #if NET - [ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsNetCore))] - public void LoggingHttpMessageHandler_LogsAbsoluteUri_Sync() + [InlineData(true, false)] + [InlineData(true, true)] +#endif + public async Task Handlers_LogExpectedUri(bool syncApi, bool scopeHandler) { - // Arrange - var sink = new TestSink(); - - var serviceCollection = new ServiceCollection(); - serviceCollection.AddLogging(); - serviceCollection.AddSingleton(new TestLoggerFactory(sink, enabled: true)); - - serviceCollection - .AddHttpClient("test") - .ConfigurePrimaryHttpMessageHandler(() => new TestMessageHandler()); - - var services = serviceCollection.BuildServiceProvider(); - - var client = services.GetRequiredService().CreateClient("test"); - + await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr) => + { + bool syncApi = bool.Parse(syncApiStr); + bool scopeHandler = bool.Parse(scopeHandlerStr); - // Act - var request = new HttpRequestMessage(HttpMethod.Get, "http://api.example.com/search?term=Western%20Australia"); + string baseUri = "http://api.example.com/search"; + const string queryString = "term=Western%20Australia"; + string destinationUri = $"{baseUri}?{queryString}"; - client.Send(request); + var sink = new TestSink(); + var logger = new TestLogger("test", sink, enabled: true); - // Assert - var messages = sink.Writes.ToArray(); + DelegatingHandler handler = scopeHandler ? new LoggingScopeHttpMessageHandler(logger) : new LoggingHttpMessageHandler(logger); + handler.InnerHandler = new TestMessageHandler(); - var message = Assert.Single(messages.Where(m => - { - return - m.EventId == LoggingHttpMessageHandler.Log.EventIds.RequestStart && - m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler"; - })); + using HttpMessageInvoker invoker = new HttpMessageInvoker(handler); + using var request = new HttpRequestMessage(HttpMethod.Get, destinationUri); - Assert.Equal("Sending HTTP request GET http://api.example.com/search?term=Western%20Australia", message.Message); +#if NET + if (syncApi) + { + _ = invoker.Send(request, default); + await Task.Yield(); + } + else +#endif + { + _ = await invoker.SendAsync(request, default); + } + + if (scopeHandler) + { + var pipelineStartMessage = Assert.Single(sink.Writes.Where(m => m.EventId == EventIds.PipelineStart)); + Assert.Equal($"HTTP GET {baseUri}?*", pipelineStartMessage.Scope.ToString()); + Assert.Equal($"Start processing HTTP request GET {baseUri}?*", pipelineStartMessage.Message); + } + else + { + var requestStartMessage = Assert.Single(sink.Writes.Where(m => m.EventId == EventIds.RequestStart)); + Assert.Equal($"Sending HTTP request GET {baseUri}?*", requestStartMessage.Message); + } + }, syncApi.ToString(), scopeHandler.ToString()).DisposeAsync(); } - [ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsNetCore))] - public void LoggingScopeHttpMessageHandler_LogsAbsoluteUri_Sync() + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData(false, false)] + [InlineData(false, true)] +#if NET + [InlineData(true, false)] + [InlineData(true, true)] +#endif + public async Task Integration_LogsExpectedAbsoluteUri(bool syncApi, bool disableUriQueryRedaction) { - // Arrange - var sink = new TestSink(); - - var serviceCollection = new ServiceCollection(); - serviceCollection.AddLogging(); - serviceCollection.AddSingleton(new TestLoggerFactory(sink, enabled: true)); - - serviceCollection - .AddHttpClient("test") - .ConfigurePrimaryHttpMessageHandler(() => new TestMessageHandler()); - - var services = serviceCollection.BuildServiceProvider(); - - var client = services.GetRequiredService().CreateClient("test"); + const string baseUri = "http://api.example.com/search"; + const string queryString = "term=Western%20Australia"; + const string destinationUri = $"{baseUri}?{queryString}"; + await RemoteExecutor.Invoke(static async (syncApiStr, disableUriQueryRedactionStr) => + { + bool syncApi = bool.Parse(syncApiStr); + bool disableUriQueryRedaction = bool.Parse(disableUriQueryRedactionStr); + + if (disableUriQueryRedaction) + { + AppContext.SetSwitch("System.Net.Http.DisableUriRedaction", true); + } + + var sink = new TestSink(); + var serviceCollection = new ServiceCollection(); + serviceCollection.AddLogging(); + serviceCollection.AddSingleton(new TestLoggerFactory(sink, enabled: true)); + serviceCollection.AddTransient(); + serviceCollection.AddHttpClient("test").ConfigurePrimaryHttpMessageHandler(); + + var services = serviceCollection.BuildServiceProvider(); + var factory = services.GetRequiredService(); + var client = factory.CreateClient("test"); + + using var request = new HttpRequestMessage(HttpMethod.Get, destinationUri); +#if NET + if (syncApi) + { + _ = client.Send(request); + await Task.Yield(); + } + else +#endif + { + _ = await client.SendAsync(request); + } - // Act - var request = new HttpRequestMessage(HttpMethod.Get, "http://api.example.com/search?term=Western%20Australia"); + var pipelineStartMessage = Assert.Single(sink.Writes.Where(m => + m.EventId == EventIds.PipelineStart && + m.LoggerName == "System.Net.Http.HttpClient.test.LogicalHandler")); - client.Send(request); + var requestStartMessage = Assert.Single(sink.Writes.Where(m => + m.EventId == EventIds.RequestStart && + m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler")); - // Assert - var messages = sink.Writes.ToArray(); + string expectedUri = disableUriQueryRedaction ? destinationUri : $"{baseUri}?*"; - var message = Assert.Single(messages.Where(m => - { - return - m.EventId == LoggingScopeHttpMessageHandler.Log.EventIds.PipelineStart && - m.LoggerName == "System.Net.Http.HttpClient.test.LogicalHandler"; - })); + Assert.Equal($"HTTP GET {expectedUri}", pipelineStartMessage.Scope.ToString()); + Assert.Equal($"Start processing HTTP request GET {expectedUri}", pipelineStartMessage.Message); + Assert.Equal($"Sending HTTP request GET {expectedUri}", requestStartMessage.Message); - Assert.Equal("Start processing HTTP request GET http://api.example.com/search?term=Western%20Australia", message.Message); - Assert.Equal("HTTP GET http://api.example.com/search?term=Western%20Australia", message.Scope.ToString()); + }, syncApi.ToString(), disableUriQueryRedaction.ToString()).DisposeAsync(); } -#endif } } diff --git a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/RedactedLogValueIntegrationTest.cs b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/RedactedLogValueIntegrationTest.cs index 4a4c1327401c1..20279de259856 100644 --- a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/RedactedLogValueIntegrationTest.cs +++ b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/RedactedLogValueIntegrationTest.cs @@ -16,6 +16,15 @@ namespace Microsoft.Extensions.Http.Logging { public class RedactedLogValueIntegrationTest { + private static class EventIds + { + public static readonly EventId RequestHeader = new EventId(102, "RequestHeader"); + public static readonly EventId ResponseHeader = new EventId(103, "ResponseHeader"); + + public static readonly EventId RequestPipelineRequestHeader = new EventId(102, "RequestPipelineRequestHeader"); + public static readonly EventId RequestPipelineResponseHeader = new EventId(103, "RequestPipelineResponseHeader"); + } + [Fact] public async Task RedactHeaderValueWithHeaderList_ValueIsRedactedBeforeLogging() { @@ -48,7 +57,7 @@ public async Task RedactHeaderValueWithHeaderList_ValueIsRedactedBeforeLogging() var message = Assert.Single(messages.Where(m => { return - m.EventId == LoggingScopeHttpMessageHandler.Log.EventIds.RequestHeader && + m.EventId == EventIds.RequestPipelineRequestHeader && m.LoggerName == "System.Net.Http.HttpClient.test.LogicalHandler"; })); Assert.StartsWith(LineEndingsHelper.Normalize( @@ -60,7 +69,7 @@ public async Task RedactHeaderValueWithHeaderList_ValueIsRedactedBeforeLogging() message = Assert.Single(messages.Where(m => { return - m.EventId == LoggingHttpMessageHandler.Log.EventIds.RequestHeader && + m.EventId == EventIds.RequestHeader && m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler"; })); Assert.StartsWith(LineEndingsHelper.Normalize( @@ -72,7 +81,7 @@ public async Task RedactHeaderValueWithHeaderList_ValueIsRedactedBeforeLogging() message = Assert.Single(messages.Where(m => { return - m.EventId == LoggingHttpMessageHandler.Log.EventIds.ResponseHeader && + m.EventId == EventIds.ResponseHeader && m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler"; })); Assert.StartsWith(LineEndingsHelper.Normalize( @@ -84,7 +93,7 @@ public async Task RedactHeaderValueWithHeaderList_ValueIsRedactedBeforeLogging() message = Assert.Single(messages.Where(m => { return - m.EventId == LoggingScopeHttpMessageHandler.Log.EventIds.ResponseHeader && + m.EventId == EventIds.RequestPipelineResponseHeader && m.LoggerName == "System.Net.Http.HttpClient.test.LogicalHandler"; })); Assert.StartsWith(LineEndingsHelper.Normalize( @@ -129,7 +138,7 @@ public async Task RedactHeaderValueWithPredicate_ValueIsRedactedBeforeLogging() var message = Assert.Single(messages.Where(m => { return - m.EventId == LoggingScopeHttpMessageHandler.Log.EventIds.RequestHeader && + m.EventId == EventIds.RequestPipelineRequestHeader && m.LoggerName == "System.Net.Http.HttpClient.test.LogicalHandler"; })); Assert.StartsWith(LineEndingsHelper.Normalize( @@ -141,7 +150,7 @@ public async Task RedactHeaderValueWithPredicate_ValueIsRedactedBeforeLogging() message = Assert.Single(messages.Where(m => { return - m.EventId == LoggingHttpMessageHandler.Log.EventIds.RequestHeader && + m.EventId == EventIds.RequestHeader && m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler"; })); Assert.StartsWith(LineEndingsHelper.Normalize( @@ -153,7 +162,7 @@ public async Task RedactHeaderValueWithPredicate_ValueIsRedactedBeforeLogging() message = Assert.Single(messages.Where(m => { return - m.EventId == LoggingHttpMessageHandler.Log.EventIds.ResponseHeader && + m.EventId == EventIds.ResponseHeader && m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler"; })); Assert.StartsWith(LineEndingsHelper.Normalize( @@ -165,7 +174,7 @@ public async Task RedactHeaderValueWithPredicate_ValueIsRedactedBeforeLogging() message = Assert.Single(messages.Where(m => { return - m.EventId == LoggingScopeHttpMessageHandler.Log.EventIds.ResponseHeader && + m.EventId == EventIds.RequestPipelineResponseHeader && m.LoggerName == "System.Net.Http.HttpClient.test.LogicalHandler"; })); Assert.StartsWith(LineEndingsHelper.Normalize( diff --git a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Microsoft.Extensions.Http.Tests.csproj b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Microsoft.Extensions.Http.Tests.csproj index f81246bb66d00..b1a3e853dc5cb 100644 --- a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Microsoft.Extensions.Http.Tests.csproj +++ b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Microsoft.Extensions.Http.Tests.csproj @@ -3,6 +3,7 @@ $(NetCoreAppCurrent);$(NetFrameworkMinimum) true + true @@ -20,6 +21,8 @@ Link="tests\DI.Common\Common\src\TestLoggerFactory.cs" /> +