From d3b0e776f0398c9a350312694f0122703be2fa86 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Thu, 20 Jun 2024 02:40:13 +0200 Subject: [PATCH 01/18] Do not log query strings in HttpClientFactory --- .../src/Logging/LoggingHttpMessageHandler.cs | 15 +++++-- .../Logging/LoggingScopeHttpMessageHandler.cs | 11 +---- .../Logging/HttpClientLoggerTest.cs | 41 +++++++++++++++++++ .../Microsoft.Extensions.Http.Tests.csproj | 3 ++ 4 files changed, 57 insertions(+), 13 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs index e592e7d236fbb4..3fb8ba4287332e 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; @@ -88,6 +89,8 @@ protected override HttpResponseMessage Send(HttpRequestMessage request, Cancella // Used in tests. internal static class Log { + private static readonly bool s_logQueryString = AppContext.TryGetSwitch("Microsoft.Extensions.Http.LogQueryString", out bool value) && value; + public static class EventIds { public static readonly EventId RequestStart = new EventId(100, "RequestStart"); @@ -144,11 +147,15 @@ public static void RequestEnd(ILogger logger, HttpResponseMessage response, Time } } - private static string? GetUriString(Uri? requestUri) + internal static string? GetUriString(Uri? uri) { - return requestUri?.IsAbsoluteUri == true - ? requestUri.AbsoluteUri - : requestUri?.ToString(); + if (uri is null) + { + return null; + } + + Debug.Assert(uri.IsAbsoluteUri, "HttpClient should not forward relative Uri to its handlers."); + return s_logQueryString ? uri.AbsoluteUri : $"{uri.Scheme}://{uri.Host}{uri.AbsolutePath}"; } } } diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs index 1894a005f84a68..3eb56c689c05bd 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs @@ -113,12 +113,12 @@ public static class EventIds public static IDisposable? BeginRequestPipelineScope(ILogger logger, HttpRequestMessage request) { - return _beginRequestPipelineScope(logger, request.Method, GetUriString(request.RequestUri)); + return _beginRequestPipelineScope(logger, request.Method, LoggingHttpMessageHandler.Log.GetUriString(request.RequestUri)); } public static void RequestPipelineStart(ILogger logger, HttpRequestMessage request, Func shouldRedactHeaderValue) { - _requestPipelineStart(logger, request.Method, GetUriString(request.RequestUri), null); + _requestPipelineStart(logger, request.Method, LoggingHttpMessageHandler.Log.GetUriString(request.RequestUri), null); if (logger.IsEnabled(LogLevel.Trace)) { @@ -145,13 +145,6 @@ public static void RequestPipelineEnd(ILogger logger, HttpResponseMessage respon (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/HttpClientLoggerTest.cs b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs index 039ba46b186251..0b339ed345f0fc 100644 --- a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs +++ b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs @@ -7,6 +7,7 @@ using System.Net.Http; using System.Threading; using System.Threading.Tasks; +using Microsoft.DotNet.RemoteExecutor; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Testing; @@ -27,6 +28,46 @@ public HttpClientLoggerTest(ITestOutputHelper output) _output = output; } + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData(true)] + [InlineData(false)] + public async Task QueryStringIsNotLoggedByDefault(bool enableQueryStringLogging) + { + await RemoteExecutor.Invoke(static async (enableQueryStringLoggingStr) => + { + bool enableQueryStringLogging = bool.Parse(enableQueryStringLoggingStr); + + if (enableQueryStringLogging) + { + AppContext.SetSwitch("Microsoft.Extensions.Http.LogQueryString", 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"); + + string queryString = "a=1&b=2"; + _ = await client.GetAsync($"{Url}?{queryString}"); + + string[] writes = sink.Writes.Select(w => w.Message).Where(m => m.Contains(Url)).ToArray(); + Assert.NotEmpty(writes); + bool writesContainQueryString = writes.Any(w => w.Contains(queryString)); + bool scopeContainsQueryString = sink.Scopes.Single().Scope.ToString().Contains(queryString); + Assert.Equal(enableQueryStringLogging, writesContainQueryString); + Assert.Equal(scopeContainsQueryString, writesContainQueryString); + + }, enableQueryStringLogging.ToString()).DisposeAsync(); + } + [Fact] public async Task RemoveAllLoggers_Success() { 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 f81246bb66d002..b1a3e853dc5cbc 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" /> + From af01fc6aefaf1db0a7e5663e7885d444349ef520 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Thu, 20 Jun 2024 17:19:33 +0200 Subject: [PATCH 02/18] shuffle tests --- .../Logging/HttpClientLoggerTest.cs | 40 ---- .../Logging/LoggingUriOutputTests.cs | 212 ++++++------------ 2 files changed, 65 insertions(+), 187 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs index 0b339ed345f0fc..6ad61470262355 100644 --- a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs +++ b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs @@ -28,46 +28,6 @@ public HttpClientLoggerTest(ITestOutputHelper output) _output = output; } - [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - [InlineData(true)] - [InlineData(false)] - public async Task QueryStringIsNotLoggedByDefault(bool enableQueryStringLogging) - { - await RemoteExecutor.Invoke(static async (enableQueryStringLoggingStr) => - { - bool enableQueryStringLogging = bool.Parse(enableQueryStringLoggingStr); - - if (enableQueryStringLogging) - { - AppContext.SetSwitch("Microsoft.Extensions.Http.LogQueryString", 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"); - - string queryString = "a=1&b=2"; - _ = await client.GetAsync($"{Url}?{queryString}"); - - string[] writes = sink.Writes.Select(w => w.Message).Where(m => m.Contains(Url)).ToArray(); - Assert.NotEmpty(writes); - bool writesContainQueryString = writes.Any(w => w.Contains(queryString)); - bool scopeContainsQueryString = sink.Scopes.Single().Scope.ToString().Contains(queryString); - Assert.Equal(enableQueryStringLogging, writesContainQueryString); - Assert.Equal(scopeContainsQueryString, writesContainQueryString); - - }, enableQueryStringLogging.ToString()).DisposeAsync(); - } - [Fact] public async Task RemoveAllLoggers_Success() { 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 bdd204f709df39..7977adb631b26d 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,74 @@ namespace Microsoft.Extensions.Http.Tests.Logging { public class LoggingUriOutputTests { - [Fact] - public async Task LoggingHttpMessageHandler_LogsAbsoluteUri() - { - // 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); - - // 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); - } - - [Fact] - public async Task LoggingScopeHttpMessageHandler_LogsAbsoluteUri() - { - // 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); - - // Assert - var messages = sink.Writes.ToArray(); - - var message = Assert.Single(messages.Where(m => - { - 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()); - } - + [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() - { - // 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"); - - client.Send(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); - } - - [ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsNetCore))] - public void LoggingScopeHttpMessageHandler_LogsAbsoluteUri_Sync() + [InlineData(true, false)] + [InlineData(true, true)] +#endif + public async Task LogsAbsoluteUrl(bool syncApi, bool logQueryString) { - // 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"); + const string BaseUri = "http://api.example.com/search"; + const string QueryString = "term=Western%20Australia"; + const string FullUri = $"{BaseUri}?{QueryString}"; - client.Send(request); - - // Assert - var messages = sink.Writes.ToArray(); - - var message = Assert.Single(messages.Where(m => + await RemoteExecutor.Invoke(static async (syncApiStr, enableQueryStringLoggingStr) => { - 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()); - } + bool syncApi = bool.Parse(syncApiStr); + bool enableQueryStringLogging = bool.Parse(enableQueryStringLoggingStr); + + if (enableQueryStringLogging) + { + AppContext.SetSwitch("Microsoft.Extensions.Http.LogQueryString", 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, FullUri); +#if NET + if (syncApi) + { + client.Send(request); + await Task.Yield(); + } + else #endif + { + _ = await client.SendAsync(request); + } + + var pipelineStartMessage = Assert.Single(sink.Writes.Where(m => + { + return + m.EventId == LoggingScopeHttpMessageHandler.Log.EventIds.PipelineStart && + m.LoggerName == "System.Net.Http.HttpClient.test.LogicalHandler"; + })); + + var requestStartMessage = Assert.Single(sink.Writes.Where(m => + { + return + m.EventId == LoggingHttpMessageHandler.Log.EventIds.RequestStart && + m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler"; + })); + + string expectedUri = enableQueryStringLogging ? FullUri : BaseUri; + + 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); + + }, syncApi.ToString(), logQueryString.ToString()).DisposeAsync(); + } } } From e3fb18411afbb654b435b1dc78c239583be3b1ef Mon Sep 17 00:00:00 2001 From: Anton Firszov Date: Thu, 20 Jun 2024 22:30:28 +0200 Subject: [PATCH 03/18] Update GetUriString Co-authored-by: Miha Zupan --- .../src/Logging/LoggingHttpMessageHandler.cs | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs index 3fb8ba4287332e..e527e4f800cb8b 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs @@ -154,8 +154,18 @@ public static void RequestEnd(ILogger logger, HttpResponseMessage response, Time return null; } - Debug.Assert(uri.IsAbsoluteUri, "HttpClient should not forward relative Uri to its handlers."); - return s_logQueryString ? uri.AbsoluteUri : $"{uri.Scheme}://{uri.Host}{uri.AbsolutePath}"; + if (uri.IsAbsoluteUri) + { + return s_logQueryString + ? uri.AbsoluteUri + : uri.GetComponents(UriComponents.AbsoluteUri & ~UriComponents.Query, UriFormat.UriEscaped); + } + + string uriString = uri.ToString(); + int queryOffset = s_logQueryString ? -1 : uriString.IndexOf('?'); + return queryOffset < 0 + ? uriString + : uriString.Substring(0, queryOffset); } } } From ea4b8ad9215f613626cc3ce6a03106d5234886cc Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Thu, 20 Jun 2024 23:23:26 +0200 Subject: [PATCH 04/18] add tests for relative Uri logging --- .../Logging/LoggingUriOutputTests.cs | 113 +++++++++++++++--- 1 file changed, 95 insertions(+), 18 deletions(-) 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 7977adb631b26d..37e6cd461bdc05 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 @@ -16,6 +16,89 @@ namespace Microsoft.Extensions.Http.Tests.Logging { public class LoggingUriOutputTests { + public static TheoryData Handlers_LogAbsoluteUri_Data() + { + TheoryData result = new(); + bool[] booleans = { true, false }; + bool[] syncApiVals = +#if NET + booleans; +#else + { false }; +#endif + foreach (bool syncApi in syncApiVals) + { + foreach (bool logQueryString in booleans) + { + foreach (bool absoluteUri in booleans) + { + foreach (bool scopeHandler in booleans) + { + result.Add(syncApi, logQueryString, absoluteUri, scopeHandler); + } + } + } + } + return result; + } + + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [MemberData(nameof(Handlers_LogAbsoluteUri_Data))] + public async Task Handlers_LogExpectedUri(bool syncApi, bool logQueryString, bool absoluteUri, bool scopeHandler) + { + await RemoteExecutor.Invoke(static async (syncApiStr, logQueryStringStr, absoluteUriStr, scopeHandlerStr) => + { + bool syncApi = bool.Parse(syncApiStr); + bool logQueryString = bool.Parse(logQueryStringStr); + bool absoluteUri = bool.Parse(absoluteUriStr); + bool scopeHandler = bool.Parse(scopeHandlerStr); + + string baseUri = absoluteUri ? "http://api.example.com/search" : "/search"; + const string queryString = "term=Western%20Australia"; + string destinationUri = $"{baseUri}?{queryString}"; + + if (logQueryString) + { + AppContext.SetSwitch("Microsoft.Extensions.Http.LogQueryString", true); + } + + var sink = new TestSink(); + var logger = new TestLogger("test", sink, enabled: true); + + DelegatingHandler handler = scopeHandler ? new LoggingScopeHttpMessageHandler(logger) : new LoggingHttpMessageHandler(logger); + handler.InnerHandler = new TestMessageHandler(); + + using HttpMessageInvoker invoker = new HttpMessageInvoker(handler); + using var request = new HttpRequestMessage(HttpMethod.Get, destinationUri); + +#if NET + if (syncApi) + { + _ = invoker.Send(request, default); + await Task.Yield(); + } + else +#endif + { + _ = await invoker.SendAsync(request, default); + } + + string expectedUri = logQueryString ? destinationUri : baseUri; + + if (scopeHandler) + { + var pipelineStartMessage = Assert.Single(sink.Writes.Where(m => m.EventId == LoggingScopeHttpMessageHandler.Log.EventIds.PipelineStart)); + Assert.Equal($"HTTP GET {expectedUri}", pipelineStartMessage.Scope.ToString()); + Assert.Equal($"Start processing HTTP request GET {expectedUri}", pipelineStartMessage.Message); + } + else + { + var requestStartMessage = Assert.Single(sink.Writes.Where(m => m.EventId == LoggingHttpMessageHandler.Log.EventIds.RequestStart)); + Assert.Equal($"Sending HTTP request GET {expectedUri}", requestStartMessage.Message); + } + }, syncApi.ToString(), logQueryString.ToString(), absoluteUri.ToString(), scopeHandler.ToString()).DisposeAsync(); + } + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] [InlineData(false, false)] [InlineData(false, true)] @@ -23,18 +106,18 @@ public class LoggingUriOutputTests [InlineData(true, false)] [InlineData(true, true)] #endif - public async Task LogsAbsoluteUrl(bool syncApi, bool logQueryString) + public async Task Integration_LogsExpectedAbsoluteUri(bool syncApi, bool logQueryString) { - const string BaseUri = "http://api.example.com/search"; - const string QueryString = "term=Western%20Australia"; - const string FullUri = $"{BaseUri}?{QueryString}"; + 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, enableQueryStringLoggingStr) => + await RemoteExecutor.Invoke(static async (syncApiStr, logQueryStringStr) => { bool syncApi = bool.Parse(syncApiStr); - bool enableQueryStringLogging = bool.Parse(enableQueryStringLoggingStr); + bool logQueryString = bool.Parse(logQueryStringStr); - if (enableQueryStringLogging) + if (logQueryString) { AppContext.SetSwitch("Microsoft.Extensions.Http.LogQueryString", true); } @@ -50,11 +133,11 @@ await RemoteExecutor.Invoke(static async (syncApiStr, enableQueryStringLoggingSt var factory = services.GetRequiredService(); var client = factory.CreateClient("test"); - using var request = new HttpRequestMessage(HttpMethod.Get, FullUri); + using var request = new HttpRequestMessage(HttpMethod.Get, destinationUri); #if NET if (syncApi) { - client.Send(request); + _ = client.Send(request); await Task.Yield(); } else @@ -64,20 +147,14 @@ await RemoteExecutor.Invoke(static async (syncApiStr, enableQueryStringLoggingSt } var pipelineStartMessage = Assert.Single(sink.Writes.Where(m => - { - return m.EventId == LoggingScopeHttpMessageHandler.Log.EventIds.PipelineStart && - m.LoggerName == "System.Net.Http.HttpClient.test.LogicalHandler"; - })); + m.LoggerName == "System.Net.Http.HttpClient.test.LogicalHandler")); var requestStartMessage = Assert.Single(sink.Writes.Where(m => - { - return m.EventId == LoggingHttpMessageHandler.Log.EventIds.RequestStart && - m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler"; - })); + m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler")); - string expectedUri = enableQueryStringLogging ? FullUri : BaseUri; + string expectedUri = logQueryString ? destinationUri : baseUri; Assert.Equal($"HTTP GET {expectedUri}", pipelineStartMessage.Scope.ToString()); Assert.Equal($"Start processing HTTP request GET {expectedUri}", pipelineStartMessage.Message); From 7a7bf09c62a4b92b1773a994cf4ba169dff02ce3 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Thu, 20 Jun 2024 23:25:50 +0200 Subject: [PATCH 05/18] remove unnecessary using --- .../Logging/HttpClientLoggerTest.cs | 1 - 1 file changed, 1 deletion(-) diff --git a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs index 6ad61470262355..039ba46b186251 100644 --- a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs +++ b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs @@ -7,7 +7,6 @@ using System.Net.Http; using System.Threading; using System.Threading.Tasks; -using Microsoft.DotNet.RemoteExecutor; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Testing; From 098279afc4a7d67e6ae9ab1c7117fda6876fd4cf Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Fri, 21 Jun 2024 19:22:23 +0200 Subject: [PATCH 06/18] move log message implementation into LogHelper, introduce an environment variable for the fallback switch --- .../src/Logging/LogHelper.cs | 167 ++++++++++++++++++ .../src/Logging/LoggingHttpMessageHandler.cs | 87 +-------- .../Logging/LoggingScopeHttpMessageHandler.cs | 66 +------ .../Logging/LoggingUriOutputTests.cs | 64 +++++-- .../RedactedLogValueIntegrationTest.cs | 25 ++- 5 files changed, 236 insertions(+), 173 deletions(-) create mode 100644 src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs 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 00000000000000..1f8713a2a316f7 --- /dev/null +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -0,0 +1,167 @@ +// 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 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_logQueryString = GetLogQueryStringSettingValue(); + + 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 GetLogQueryStringSettingValue() + { + if (AppContext.TryGetSwitch("Microsoft.Extensions.Http.LogQueryString", out bool value)) + { + return value; + } + + string? envVar = Environment.GetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_LOGQUERYSTRING"); + + 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 GetUriString 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) + { + return _beginRequestPipelineScope(logger, request.Method, GetRedactedUriString(request.RequestUri)); + } + + public static void LogRequestPipelineStart(this ILogger logger, HttpRequestMessage request, Func shouldRedactHeaderValue) + { + _requestPipelineStart(logger, request.Method, GetRedactedUriString(request.RequestUri), 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()); + } + } + + private static string? GetRedactedUriString(Uri? uri) + { + if (uri is null) + { + return null; + } + + if (uri.IsAbsoluteUri) + { + return s_logQueryString + ? uri.AbsoluteUri + : uri.GetComponents(UriComponents.AbsoluteUri & ~UriComponents.Query, UriFormat.UriEscaped); + } + + string uriString = uri.ToString(); + int queryOffset = s_logQueryString ? -1 : uriString.IndexOf('?'); + return queryOffset < 0 + ? uriString + : uriString.Substring(0, queryOffset); + } + } +} diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs index e527e4f800cb8b..c86d149a0f2c69 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs @@ -59,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) @@ -68,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; } @@ -85,88 +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 - { - private static readonly bool s_logQueryString = AppContext.TryGetSwitch("Microsoft.Extensions.Http.LogQueryString", out bool value) && value; - - 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()); - } - } - - internal static string? GetUriString(Uri? uri) - { - if (uri is null) - { - return null; - } - - if (uri.IsAbsoluteUri) - { - return s_logQueryString - ? uri.AbsoluteUri - : uri.GetComponents(UriComponents.AbsoluteUri & ~UriComponents.Query, UriFormat.UriEscaped); - } - - string uriString = uri.ToString(); - int queryOffset = s_logQueryString ? -1 : uriString.IndexOf('?'); - return queryOffset < 0 - ? uriString - : uriString.Substring(0, queryOffset); - } - } } } diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs index 3eb56c689c05bd..afcdfccc071a36 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)) { - Log.RequestPipelineStart(_logger, request, shouldRedactHeaderValue); + _logger.LogRequestPipelineStart(request, 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,65 +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, LoggingHttpMessageHandler.Log.GetUriString(request.RequestUri)); - } - - public static void RequestPipelineStart(ILogger logger, HttpRequestMessage request, Func shouldRedactHeaderValue) - { - _requestPipelineStart(logger, request.Method, LoggingHttpMessageHandler.Log.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()); - } - } - } } } 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 37e6cd461bdc05..b88cdf9be45b38 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 @@ -16,9 +16,18 @@ namespace Microsoft.Extensions.Http.Tests.Logging { public class LoggingUriOutputTests { - public static TheoryData Handlers_LogAbsoluteUri_Data() + private static class EventIds { - TheoryData result = new(); + public static readonly EventId RequestStart = new EventId(100, "RequestStart"); + public static readonly EventId RequestEnd = new EventId(101, "RequestEnd"); + + public static readonly EventId PipelineStart = new EventId(100, "RequestPipelineStart"); + public static readonly EventId PipelineEnd = new EventId(101, "RequestPipelineEnd"); + } + + public static TheoryData Handlers_LogAbsoluteUri_Data() + { + TheoryData result = new(); bool[] booleans = { true, false }; bool[] syncApiVals = #if NET @@ -28,28 +37,41 @@ public static TheoryData Handlers_LogAbsoluteUri_Data() #endif foreach (bool syncApi in syncApiVals) { - foreach (bool logQueryString in booleans) + foreach (bool absoluteUri in booleans) { - foreach (bool absoluteUri in booleans) + foreach (bool scopeHandler in booleans) { - foreach (bool scopeHandler in booleans) + // valid values for logQueryStringEnabler: + // "" - Do not enable query string logging. + // "AppCtx" - Enable via AppContext switch. + // "EnvVarTrue" - Enable by setting the environment *_LOGQUERYSTRING variable to 'true'. + // "EnvVar1" - Enable by setting the environment *_LOGQUERYSTRING variable to '1'. + + + string[] lqs = ["", "AppCtx"]; + foreach (string logQueryStringEnabler in lqs) { - result.Add(syncApi, logQueryString, absoluteUri, scopeHandler); + result.Add(syncApi, absoluteUri, scopeHandler, logQueryStringEnabler); } } } } + + result.Add(false, false, false, "EnvVarTrue"); + result.Add(false, false, false, "EnvVar1"); + result.Add(false, false, true, "EnvVarTrue"); + result.Add(false, false, true, "EnvVar1"); + return result; } [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] [MemberData(nameof(Handlers_LogAbsoluteUri_Data))] - public async Task Handlers_LogExpectedUri(bool syncApi, bool logQueryString, bool absoluteUri, bool scopeHandler) + public async Task Handlers_LogExpectedUri(bool syncApi, bool absoluteUri, bool scopeHandler, string logQueryStringEnabler) { - await RemoteExecutor.Invoke(static async (syncApiStr, logQueryStringStr, absoluteUriStr, scopeHandlerStr) => + await RemoteExecutor.Invoke(static async (syncApiStr, absoluteUriStr, scopeHandlerStr, logQueryStringEnabler) => { bool syncApi = bool.Parse(syncApiStr); - bool logQueryString = bool.Parse(logQueryStringStr); bool absoluteUri = bool.Parse(absoluteUriStr); bool scopeHandler = bool.Parse(scopeHandlerStr); @@ -57,9 +79,17 @@ await RemoteExecutor.Invoke(static async (syncApiStr, logQueryStringStr, absolut const string queryString = "term=Western%20Australia"; string destinationUri = $"{baseUri}?{queryString}"; - if (logQueryString) + switch (logQueryStringEnabler) { - AppContext.SetSwitch("Microsoft.Extensions.Http.LogQueryString", true); + case "AppCtx": + AppContext.SetSwitch("Microsoft.Extensions.Http.LogQueryString", true); + break; + case "EnvVarTrue": + Environment.SetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_LOGQUERYSTRING", "True"); + break; + case "EnvVar1": + Environment.SetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_LOGQUERYSTRING", "1"); + break; } var sink = new TestSink(); @@ -83,20 +113,20 @@ await RemoteExecutor.Invoke(static async (syncApiStr, logQueryStringStr, absolut _ = await invoker.SendAsync(request, default); } - string expectedUri = logQueryString ? destinationUri : baseUri; + string expectedUri = !string.IsNullOrEmpty(logQueryStringEnabler) ? destinationUri : baseUri; if (scopeHandler) { - var pipelineStartMessage = Assert.Single(sink.Writes.Where(m => m.EventId == LoggingScopeHttpMessageHandler.Log.EventIds.PipelineStart)); + var pipelineStartMessage = Assert.Single(sink.Writes.Where(m => m.EventId == EventIds.PipelineStart)); Assert.Equal($"HTTP GET {expectedUri}", pipelineStartMessage.Scope.ToString()); Assert.Equal($"Start processing HTTP request GET {expectedUri}", pipelineStartMessage.Message); } else { - var requestStartMessage = Assert.Single(sink.Writes.Where(m => m.EventId == LoggingHttpMessageHandler.Log.EventIds.RequestStart)); + var requestStartMessage = Assert.Single(sink.Writes.Where(m => m.EventId == EventIds.RequestStart)); Assert.Equal($"Sending HTTP request GET {expectedUri}", requestStartMessage.Message); } - }, syncApi.ToString(), logQueryString.ToString(), absoluteUri.ToString(), scopeHandler.ToString()).DisposeAsync(); + }, syncApi.ToString(), absoluteUri.ToString(), scopeHandler.ToString(), logQueryStringEnabler).DisposeAsync(); } [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] @@ -147,11 +177,11 @@ await RemoteExecutor.Invoke(static async (syncApiStr, logQueryStringStr) => } var pipelineStartMessage = Assert.Single(sink.Writes.Where(m => - m.EventId == LoggingScopeHttpMessageHandler.Log.EventIds.PipelineStart && + m.EventId == EventIds.PipelineStart && m.LoggerName == "System.Net.Http.HttpClient.test.LogicalHandler")); var requestStartMessage = Assert.Single(sink.Writes.Where(m => - m.EventId == LoggingHttpMessageHandler.Log.EventIds.RequestStart && + m.EventId == EventIds.RequestStart && m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler")); string expectedUri = logQueryString ? destinationUri : baseUri; 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 4a4c1327401c1f..20279de259856c 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( From 9ebabcc8eadc6a725f0a97ebbca7f55c6f96db5b Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Fri, 21 Jun 2024 22:05:18 +0200 Subject: [PATCH 07/18] redact query string with '*' --- .../src/Logging/LogHelper.cs | 35 ++++++--- .../Logging/LoggingUriOutputTests.cs | 73 ++++++++++++------- 2 files changed, 70 insertions(+), 38 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs index 1f8713a2a316f7..d62dcf8ee63513 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.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; @@ -143,25 +144,39 @@ public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessag } } - private static string? GetRedactedUriString(Uri? uri) + internal static string? GetRedactedUriString(Uri? uri) { if (uri is null) { return null; } - if (uri.IsAbsoluteUri) + string uriString = uri.IsAbsoluteUri ? uri.AbsoluteUri : uri.ToString(); + + if (s_logQueryString) + { + return uriString; + } + + int queryOffset = uriString.IndexOf('?'); + + if (queryOffset < 0 || queryOffset == uriString.Length - 1) { - return s_logQueryString - ? uri.AbsoluteUri - : uri.GetComponents(UriComponents.AbsoluteUri & ~UriComponents.Query, UriFormat.UriEscaped); + // No query string or empty query string. + return uriString; } - string uriString = uri.ToString(); - int queryOffset = s_logQueryString ? -1 : uriString.IndexOf('?'); - return queryOffset < 0 - ? uriString - : uriString.Substring(0, queryOffset); +#if NET + return string.Create(queryOffset + 2, (uriString, queryOffset), (result, s) => + { + ReadOnlySpan withoutQuery = s.uriString.AsSpan(0, s.queryOffset + 1); + withoutQuery.CopyTo(result); + Debug.Assert(result[^2] == '?'); + result[^1] = '*'; + }); +#else + return $"{uriString.Substring(0, queryOffset)}?*"; +#endif } } } 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 b88cdf9be45b38..165838d2fe7d07 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 @@ -25,9 +25,32 @@ private static class EventIds public static readonly EventId PipelineEnd = new EventId(101, "RequestPipelineEnd"); } - public static TheoryData Handlers_LogAbsoluteUri_Data() + public static readonly TheoryData GetRedactedUriString_Data = new TheoryData() { - TheoryData result = new(); + { null, null }, + { "http://q.app/foo", "http://q.app/foo" }, + { "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?*" }, + { "/cat/1/2", "/cat/1/2" }, + { "/cat/1/2?", "/cat/1/2?" }, + { "/cat/1/2?X", "/cat/1/2?*" }, + { "/cat/1/2?a=b%20c&x=1", "/cat/1/2?*" }, + }; + + [Theory] + [MemberData(nameof(GetRedactedUriString_Data))] + public void GetRedactedUriString(string original, string expected) + { + Uri? uri = original != null ? new Uri(original, UriKind.RelativeOrAbsolute) : null; + string? actual = LogHelper.GetRedactedUriString(uri); + + Assert.Equal(expected, actual); + } + + public static TheoryData Handlers_LogExpectedUri_Data() + { + TheoryData result = new(); bool[] booleans = { true, false }; bool[] syncApiVals = #if NET @@ -37,45 +60,39 @@ public static TheoryData Handlers_LogAbsoluteUri_Data( #endif foreach (bool syncApi in syncApiVals) { - foreach (bool absoluteUri in booleans) + foreach (bool scopeHandler in booleans) { - foreach (bool scopeHandler in booleans) + // valid values for logQueryStringEnabler: + // "" - Do not enable query string logging. + // "AppCtx" - Enable via AppContext switch. + // "EnvVarTrue" - Enable by setting the environment *_LOGQUERYSTRING variable to 'true'. + // "EnvVar1" - Enable by setting the environment *_LOGQUERYSTRING variable to '1'. + string[] lqs = ["", "AppCtx"]; + foreach (string logQueryStringEnabler in lqs) { - // valid values for logQueryStringEnabler: - // "" - Do not enable query string logging. - // "AppCtx" - Enable via AppContext switch. - // "EnvVarTrue" - Enable by setting the environment *_LOGQUERYSTRING variable to 'true'. - // "EnvVar1" - Enable by setting the environment *_LOGQUERYSTRING variable to '1'. - - - string[] lqs = ["", "AppCtx"]; - foreach (string logQueryStringEnabler in lqs) - { - result.Add(syncApi, absoluteUri, scopeHandler, logQueryStringEnabler); - } + result.Add(syncApi, scopeHandler, logQueryStringEnabler); } } } - result.Add(false, false, false, "EnvVarTrue"); - result.Add(false, false, false, "EnvVar1"); - result.Add(false, false, true, "EnvVarTrue"); - result.Add(false, false, true, "EnvVar1"); + result.Add(false, false, "EnvVarTrue"); + result.Add(false, false, "EnvVar1"); + result.Add(false, true, "EnvVarTrue"); + result.Add(false, true, "EnvVar1"); return result; } [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - [MemberData(nameof(Handlers_LogAbsoluteUri_Data))] - public async Task Handlers_LogExpectedUri(bool syncApi, bool absoluteUri, bool scopeHandler, string logQueryStringEnabler) + [MemberData(nameof(Handlers_LogExpectedUri_Data))] + public async Task Handlers_LogExpectedUri(bool syncApi, bool scopeHandler, string logQueryStringEnabler) { - await RemoteExecutor.Invoke(static async (syncApiStr, absoluteUriStr, scopeHandlerStr, logQueryStringEnabler) => + await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr, logQueryStringEnabler) => { bool syncApi = bool.Parse(syncApiStr); - bool absoluteUri = bool.Parse(absoluteUriStr); bool scopeHandler = bool.Parse(scopeHandlerStr); - string baseUri = absoluteUri ? "http://api.example.com/search" : "/search"; + string baseUri = "http://api.example.com/search"; const string queryString = "term=Western%20Australia"; string destinationUri = $"{baseUri}?{queryString}"; @@ -113,7 +130,7 @@ await RemoteExecutor.Invoke(static async (syncApiStr, absoluteUriStr, scopeHandl _ = await invoker.SendAsync(request, default); } - string expectedUri = !string.IsNullOrEmpty(logQueryStringEnabler) ? destinationUri : baseUri; + string expectedUri = !string.IsNullOrEmpty(logQueryStringEnabler) ? destinationUri : $"{baseUri}?*"; if (scopeHandler) { @@ -126,7 +143,7 @@ await RemoteExecutor.Invoke(static async (syncApiStr, absoluteUriStr, scopeHandl var requestStartMessage = Assert.Single(sink.Writes.Where(m => m.EventId == EventIds.RequestStart)); Assert.Equal($"Sending HTTP request GET {expectedUri}", requestStartMessage.Message); } - }, syncApi.ToString(), absoluteUri.ToString(), scopeHandler.ToString(), logQueryStringEnabler).DisposeAsync(); + }, syncApi.ToString(), scopeHandler.ToString(), logQueryStringEnabler).DisposeAsync(); } [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] @@ -184,7 +201,7 @@ await RemoteExecutor.Invoke(static async (syncApiStr, logQueryStringStr) => m.EventId == EventIds.RequestStart && m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler")); - string expectedUri = logQueryString ? destinationUri : baseUri; + string expectedUri = logQueryString ? destinationUri : $"{baseUri}?*"; Assert.Equal($"HTTP GET {expectedUri}", pipelineStartMessage.Scope.ToString()); Assert.Equal($"Start processing HTTP request GET {expectedUri}", pipelineStartMessage.Message); From 0d49a237cb4a722e49f6c6388c4170a9df648fe5 Mon Sep 17 00:00:00 2001 From: Anton Firszov Date: Mon, 24 Jun 2024 17:51:31 +0200 Subject: [PATCH 08/18] suggestion Co-authored-by: Miha Zupan --- .../Microsoft.Extensions.Http/src/Logging/LogHelper.cs | 8 +------- 1 file changed, 1 insertion(+), 7 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs index d62dcf8ee63513..4c21c53606813a 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -167,13 +167,7 @@ public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessag } #if NET - return string.Create(queryOffset + 2, (uriString, queryOffset), (result, s) => - { - ReadOnlySpan withoutQuery = s.uriString.AsSpan(0, s.queryOffset + 1); - withoutQuery.CopyTo(result); - Debug.Assert(result[^2] == '?'); - result[^1] = '*'; - }); + return $"{uriString.AsSpan(0, queryOffset + 1)}*"; #else return $"{uriString.Substring(0, queryOffset)}?*"; #endif From f6c3095080b0dc36c4b255c86501d0fc4fa38b89 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Mon, 24 Jun 2024 18:00:03 +0200 Subject: [PATCH 09/18] rename switch --- .../Microsoft.Extensions.Http/src/Logging/LogHelper.cs | 10 +++++----- .../Logging/LoggingUriOutputTests.cs | 8 ++++---- 2 files changed, 9 insertions(+), 9 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs index 4c21c53606813a..d3cb0252b3e128 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -14,7 +14,7 @@ namespace Microsoft.Extensions.Http.Logging internal static class LogHelper { private static readonly LogDefineOptions s_skipEnabledCheckLogDefineOptions = new LogDefineOptions() { SkipEnabledCheck = true }; - private static readonly bool s_logQueryString = GetLogQueryStringSettingValue(); + private static readonly bool s_logQueryString = GetDisableUriQueryRedactionSettingValue(); private static class EventIds { @@ -54,14 +54,14 @@ private static class EventIds EventIds.PipelineEnd, "End processing HTTP request after {ElapsedMilliseconds}ms - {StatusCode}"); - private static bool GetLogQueryStringSettingValue() + private static bool GetDisableUriQueryRedactionSettingValue() { - if (AppContext.TryGetSwitch("Microsoft.Extensions.Http.LogQueryString", out bool value)) + if (AppContext.TryGetSwitch("Microsoft.Extensions.Http.DisableUriQueryRedaction", out bool value)) { return value; } - string? envVar = Environment.GetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_LOGQUERYSTRING"); + string? envVar = Environment.GetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_DISABLEURIQUERYREDACTION"); if (bool.TryParse(envVar, out value)) { @@ -169,7 +169,7 @@ public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessag #if NET return $"{uriString.AsSpan(0, queryOffset + 1)}*"; #else - return $"{uriString.Substring(0, queryOffset)}?*"; + return $"{uriString.Substring(0, queryOffset + 1)}*"; #endif } } 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 165838d2fe7d07..8ee0ccf6985c55 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 @@ -99,13 +99,13 @@ await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr, logQueryS switch (logQueryStringEnabler) { case "AppCtx": - AppContext.SetSwitch("Microsoft.Extensions.Http.LogQueryString", true); + AppContext.SetSwitch("Microsoft.Extensions.Http.DisableUriQueryRedaction", true); break; case "EnvVarTrue": - Environment.SetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_LOGQUERYSTRING", "True"); + Environment.SetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_DISABLEURIQUERYREDACTION", "True"); break; case "EnvVar1": - Environment.SetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_LOGQUERYSTRING", "1"); + Environment.SetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_DISABLEURIQUERYREDACTION", "1"); break; } @@ -166,7 +166,7 @@ await RemoteExecutor.Invoke(static async (syncApiStr, logQueryStringStr) => if (logQueryString) { - AppContext.SetSwitch("Microsoft.Extensions.Http.LogQueryString", true); + AppContext.SetSwitch("Microsoft.Extensions.Http.DisableUriQueryRedaction", true); } var sink = new TestSink(); From 8361df7c316ebd08ec4cd8243f54b5dd21641024 Mon Sep 17 00:00:00 2001 From: Anton Firszov Date: Fri, 28 Jun 2024 21:34:42 +0200 Subject: [PATCH 10/18] suggestions Co-authored-by: Natalia Kondratyeva --- .../Microsoft.Extensions.Http/src/Logging/LogHelper.cs | 2 +- .../Logging/LoggingUriOutputTests.cs | 6 +++--- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs index d3cb0252b3e128..f588de092af258 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -14,7 +14,7 @@ namespace Microsoft.Extensions.Http.Logging internal static class LogHelper { private static readonly LogDefineOptions s_skipEnabledCheckLogDefineOptions = new LogDefineOptions() { SkipEnabledCheck = true }; - private static readonly bool s_logQueryString = GetDisableUriQueryRedactionSettingValue(); + private static readonly bool s_disableUriQueryRedaction = GetDisableUriQueryRedactionSettingValue(); private static class EventIds { 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 8ee0ccf6985c55..1e35b076b8b038 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 @@ -65,8 +65,8 @@ public static TheoryData Handlers_LogExpectedUri_Data() // valid values for logQueryStringEnabler: // "" - Do not enable query string logging. // "AppCtx" - Enable via AppContext switch. - // "EnvVarTrue" - Enable by setting the environment *_LOGQUERYSTRING variable to 'true'. - // "EnvVar1" - Enable by setting the environment *_LOGQUERYSTRING variable to '1'. + // "EnvVarTrue" - Enable by setting the environment *_DISABLEURIQUERYREDACTION variable to 'true'. + // "EnvVar1" - Enable by setting the environment *DISABLEURIQUERYREDACTION variable to '1'. string[] lqs = ["", "AppCtx"]; foreach (string logQueryStringEnabler in lqs) { @@ -153,7 +153,7 @@ await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr, logQueryS [InlineData(true, false)] [InlineData(true, true)] #endif - public async Task Integration_LogsExpectedAbsoluteUri(bool syncApi, bool logQueryString) + public async Task Integration_LogsExpectedAbsoluteUri(bool syncApi, bool disableUriQueryRedaction) { const string baseUri = "http://api.example.com/search"; const string queryString = "term=Western%20Australia"; From b9daee406f54dbd0afb6f0a18556f2cf72ec0ca0 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Fri, 28 Jun 2024 21:45:37 +0200 Subject: [PATCH 11/18] adjustments --- .../src/Logging/LogHelper.cs | 2 +- .../Logging/LoggingUriOutputTests.cs | 14 +++++++------- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs index f588de092af258..742fe8ca715a8a 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -153,7 +153,7 @@ public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessag string uriString = uri.IsAbsoluteUri ? uri.AbsoluteUri : uri.ToString(); - if (s_logQueryString) + if (s_disableUriQueryRedaction) { return uriString; } 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 1e35b076b8b038..8ae0b59ea626f8 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 @@ -68,9 +68,9 @@ public static TheoryData Handlers_LogExpectedUri_Data() // "EnvVarTrue" - Enable by setting the environment *_DISABLEURIQUERYREDACTION variable to 'true'. // "EnvVar1" - Enable by setting the environment *DISABLEURIQUERYREDACTION variable to '1'. string[] lqs = ["", "AppCtx"]; - foreach (string logQueryStringEnabler in lqs) + foreach (string queryRedactionDisabler in lqs) { - result.Add(syncApi, scopeHandler, logQueryStringEnabler); + result.Add(syncApi, scopeHandler, queryRedactionDisabler); } } } @@ -85,9 +85,9 @@ public static TheoryData Handlers_LogExpectedUri_Data() [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] [MemberData(nameof(Handlers_LogExpectedUri_Data))] - public async Task Handlers_LogExpectedUri(bool syncApi, bool scopeHandler, string logQueryStringEnabler) + public async Task Handlers_LogExpectedUri(bool syncApi, bool scopeHandler, string queryRedactionDisabler) { - await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr, logQueryStringEnabler) => + await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr, queryRedactionDisabler) => { bool syncApi = bool.Parse(syncApiStr); bool scopeHandler = bool.Parse(scopeHandlerStr); @@ -96,7 +96,7 @@ await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr, logQueryS const string queryString = "term=Western%20Australia"; string destinationUri = $"{baseUri}?{queryString}"; - switch (logQueryStringEnabler) + switch (queryRedactionDisabler) { case "AppCtx": AppContext.SetSwitch("Microsoft.Extensions.Http.DisableUriQueryRedaction", true); @@ -130,7 +130,7 @@ await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr, logQueryS _ = await invoker.SendAsync(request, default); } - string expectedUri = !string.IsNullOrEmpty(logQueryStringEnabler) ? destinationUri : $"{baseUri}?*"; + string expectedUri = !string.IsNullOrEmpty(queryRedactionDisabler) ? destinationUri : $"{baseUri}?*"; if (scopeHandler) { @@ -143,7 +143,7 @@ await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr, logQueryS var requestStartMessage = Assert.Single(sink.Writes.Where(m => m.EventId == EventIds.RequestStart)); Assert.Equal($"Sending HTTP request GET {expectedUri}", requestStartMessage.Message); } - }, syncApi.ToString(), scopeHandler.ToString(), logQueryStringEnabler).DisposeAsync(); + }, syncApi.ToString(), scopeHandler.ToString(), queryRedactionDisabler).DisposeAsync(); } [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] From a894f8bafaa2ab71913ba87452e9e636b4f0af99 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Fri, 28 Jun 2024 22:59:27 +0200 Subject: [PATCH 12/18] handle fragment --- .../src/Logging/LogHelper.cs | 27 ++++++++++++++++--- .../Logging/LoggingUriOutputTests.cs | 18 +++++++++---- 2 files changed, 36 insertions(+), 9 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs index 742fe8ca715a8a..f0a98199953eea 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -158,19 +158,38 @@ public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessag return uriString; } + int fragmentOffset = uriString.IndexOf('#'); int queryOffset = uriString.IndexOf('?'); + if (fragmentOffset >= 0 && queryOffset > fragmentOffset) + { + // Not a query delimiter, but a '?' in the fragment. + queryOffset = -1; + } - if (queryOffset < 0 || queryOffset == uriString.Length - 1) + if (queryOffset < 0 || queryOffset == uriString.Length - 1 || queryOffset == fragmentOffset - 1) { - // No query string or empty query string. + // No query or empty query. return uriString; } + if (fragmentOffset < 0) + { +#if NET + return $"{uriString.AsSpan(0, queryOffset + 1)}*"; +#else + return $"{uriString.Substring(0, queryOffset + 1)}*"; +#endif + } + else + { #if NET - return $"{uriString.AsSpan(0, queryOffset + 1)}*"; + ReadOnlySpan uriSpan = uriString.AsSpan(); + return $"{uriSpan[..(queryOffset + 1)]}*{uriSpan[fragmentOffset..]}"; #else - return $"{uriString.Substring(0, queryOffset + 1)}*"; + return $"{uriString.Substring(0, queryOffset + 1)}*{uriString.Substring(fragmentOffset)}"; #endif + } + } } } 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 8ae0b59ea626f8..e671d7609cb03f 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 @@ -32,10 +32,18 @@ private static class EventIds { "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/#", "http://q.app/#" }, // Has empty fragment. + { "http://q.app#f", "http://q.app/#f" }, // Has fragment. + { "http://q.app#f?a=b", "http://q.app/#f?a=b" }, // Has fragment with a '?'. + { "http://q.app/?a=b#f?a=b", "http://q.app/?*#f?a=b" }, // Has query and fragment with a '?'. + { "http://q.app?#f", "http://q.app/?#f" }, // Has empty query and fragment. { "/cat/1/2", "/cat/1/2" }, { "/cat/1/2?", "/cat/1/2?" }, { "/cat/1/2?X", "/cat/1/2?*" }, { "/cat/1/2?a=b%20c&x=1", "/cat/1/2?*" }, + { "#", "#" }, + { "?#", "?#" }, + { "?lol#???", "?*#???" } }; [Theory] @@ -159,12 +167,12 @@ public async Task Integration_LogsExpectedAbsoluteUri(bool syncApi, bool disable const string queryString = "term=Western%20Australia"; const string destinationUri = $"{baseUri}?{queryString}"; - await RemoteExecutor.Invoke(static async (syncApiStr, logQueryStringStr) => + await RemoteExecutor.Invoke(static async (syncApiStr, disableUriQueryRedactionStr) => { bool syncApi = bool.Parse(syncApiStr); - bool logQueryString = bool.Parse(logQueryStringStr); + bool disableUriQueryRedaction = bool.Parse(disableUriQueryRedactionStr); - if (logQueryString) + if (disableUriQueryRedaction) { AppContext.SetSwitch("Microsoft.Extensions.Http.DisableUriQueryRedaction", true); } @@ -201,13 +209,13 @@ await RemoteExecutor.Invoke(static async (syncApiStr, logQueryStringStr) => m.EventId == EventIds.RequestStart && m.LoggerName == "System.Net.Http.HttpClient.test.ClientHandler")); - string expectedUri = logQueryString ? destinationUri : $"{baseUri}?*"; + string expectedUri = disableUriQueryRedaction ? destinationUri : $"{baseUri}?*"; 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); - }, syncApi.ToString(), logQueryString.ToString()).DisposeAsync(); + }, syncApi.ToString(), disableUriQueryRedaction.ToString()).DisposeAsync(); } } } From fed974bdd0e0129c9c3c3059e14c65f6ed73a473 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Sat, 29 Jun 2024 01:25:58 +0200 Subject: [PATCH 13/18] remove userinfo from absolute Uri-s --- .../Microsoft.Extensions.Http/src/Logging/LogHelper.cs | 4 +++- .../Logging/LoggingUriOutputTests.cs | 3 ++- 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs index f0a98199953eea..b6c1003dbbfef2 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -151,7 +151,9 @@ public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessag return null; } - string uriString = uri.IsAbsoluteUri ? uri.AbsoluteUri : uri.ToString(); + string uriString = uri.IsAbsoluteUri + ? uri.GetComponents(UriComponents.AbsoluteUri & ~UriComponents.UserInfo, UriFormat.UriEscaped) + : uri.ToString(); if (s_disableUriQueryRedaction) { 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 e671d7609cb03f..1e463384298adc 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 @@ -29,6 +29,7 @@ private static class EventIds { { null, null }, { "http://q.app/foo", "http://q.app/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?*" }, @@ -36,7 +37,7 @@ private static class EventIds { "http://q.app#f", "http://q.app/#f" }, // Has fragment. { "http://q.app#f?a=b", "http://q.app/#f?a=b" }, // Has fragment with a '?'. { "http://q.app/?a=b#f?a=b", "http://q.app/?*#f?a=b" }, // Has query and fragment with a '?'. - { "http://q.app?#f", "http://q.app/?#f" }, // Has empty query and fragment. + { "http://q.app?#f", "http://q.app/?#f" }, // Has empty query and fragment.s { "/cat/1/2", "/cat/1/2" }, { "/cat/1/2?", "/cat/1/2?" }, { "/cat/1/2?X", "/cat/1/2?*" }, From ca88ab0cc3298cc1d2cf763c23e29bc78178d93b Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Mon, 1 Jul 2024 19:04:36 +0200 Subject: [PATCH 14/18] Redact relative Uri unconditionally --- .../src/Logging/LogHelper.cs | 13 ++++++++++--- .../Logging/LoggingUriOutputTests.cs | 11 +++-------- 2 files changed, 13 insertions(+), 11 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs index b6c1003dbbfef2..e9f52ab9d02f7f 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -151,9 +151,16 @@ public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessag return null; } - string uriString = uri.IsAbsoluteUri - ? uri.GetComponents(UriComponents.AbsoluteUri & ~UriComponents.UserInfo, UriFormat.UriEscaped) - : 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 uriString = uri.GetComponents(UriComponents.AbsoluteUri & ~UriComponents.UserInfo, UriFormat.UriEscaped); if (s_disableUriQueryRedaction) { 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 1e463384298adc..374730f547a1b8 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 @@ -37,14 +37,9 @@ private static class EventIds { "http://q.app#f", "http://q.app/#f" }, // Has fragment. { "http://q.app#f?a=b", "http://q.app/#f?a=b" }, // Has fragment with a '?'. { "http://q.app/?a=b#f?a=b", "http://q.app/?*#f?a=b" }, // Has query and fragment with a '?'. - { "http://q.app?#f", "http://q.app/?#f" }, // Has empty query and fragment.s - { "/cat/1/2", "/cat/1/2" }, - { "/cat/1/2?", "/cat/1/2?" }, - { "/cat/1/2?X", "/cat/1/2?*" }, - { "/cat/1/2?a=b%20c&x=1", "/cat/1/2?*" }, - { "#", "#" }, - { "?#", "?#" }, - { "?lol#???", "?*#???" } + { "http://q.app?#f", "http://q.app/?#f" }, // Has empty query and fragment. + { "/cat/1/2", "*" }, // Relative Uris are fully redacted. + { "/cat/1/2?a=b%20c&x=1", "*" }, }; [Theory] From e5573306bbc5be2e2653eafb66072f1e26480344 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Tue, 2 Jul 2024 22:55:35 +0200 Subject: [PATCH 15/18] Harmonize redaction: - Use a shared switch to opt-out from redaction entirely (System.Net.Http.DisableUriRedaction) - Simplify and optimize redaction logic, always omit Fragment when redacting - Adjust and consolidate tests --- .../src/Logging/LogHelper.cs | 57 ++++------- .../Logging/LoggingUriOutputTests.cs | 96 ++++++++----------- 2 files changed, 61 insertions(+), 92 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs index e9f52ab9d02f7f..5cce7ece289f5a 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -14,7 +14,7 @@ namespace Microsoft.Extensions.Http.Logging internal static class LogHelper { private static readonly LogDefineOptions s_skipEnabledCheckLogDefineOptions = new LogDefineOptions() { SkipEnabledCheck = true }; - private static readonly bool s_disableUriQueryRedaction = GetDisableUriQueryRedactionSettingValue(); + private static readonly bool s_disableUriRedaction = GetDisableUriRedactionSettingValue(); private static class EventIds { @@ -54,14 +54,14 @@ private static class EventIds EventIds.PipelineEnd, "End processing HTTP request after {ElapsedMilliseconds}ms - {StatusCode}"); - private static bool GetDisableUriQueryRedactionSettingValue() + private static bool GetDisableUriRedactionSettingValue() { - if (AppContext.TryGetSwitch("Microsoft.Extensions.Http.DisableUriQueryRedaction", out bool value)) + if (AppContext.TryGetSwitch("System.Net.Http.DisableUriRedaction", out bool value)) { return value; } - string? envVar = Environment.GetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_DISABLEURIQUERYREDACTION"); + string? envVar = Environment.GetEnvironmentVariable("DOTNET_SYSTEM_NET_HTTP_DISABLEURIREDACTION"); if (bool.TryParse(envVar, out value)) { @@ -151,6 +151,11 @@ public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessag 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. @@ -160,45 +165,25 @@ public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessag return "*"; } - string uriString = uri.GetComponents(UriComponents.AbsoluteUri & ~UriComponents.UserInfo, UriFormat.UriEscaped); + string pathAndQuery = uri.PathAndQuery; + int queryIndex = pathAndQuery.IndexOf('?'); - if (s_disableUriQueryRedaction) - { - return uriString; - } + bool redactQuery = queryIndex >= 0 && // Query is present. + queryIndex < pathAndQuery.Length - 1; // Query is not empty. - int fragmentOffset = uriString.IndexOf('#'); - int queryOffset = uriString.IndexOf('?'); - if (fragmentOffset >= 0 && queryOffset > fragmentOffset) + return (redactQuery, uri.IsDefaultPort) switch { - // Not a query delimiter, but a '?' in the fragment. - queryOffset = -1; - } - - if (queryOffset < 0 || queryOffset == uriString.Length - 1 || queryOffset == fragmentOffset - 1) - { - // No query or empty query. - return uriString; - } + (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 (fragmentOffset < 0) - { -#if NET - return $"{uriString.AsSpan(0, queryOffset + 1)}*"; -#else - return $"{uriString.Substring(0, queryOffset + 1)}*"; -#endif - } - else - { #if NET - ReadOnlySpan uriSpan = uriString.AsSpan(); - return $"{uriSpan[..(queryOffset + 1)]}*{uriSpan[fragmentOffset..]}"; + static ReadOnlySpan GetPath(string pathAndQuery, int queryIndex) => pathAndQuery.AsSpan(0, queryIndex + 1); #else - return $"{uriString.Substring(0, queryOffset + 1)}*{uriString.Substring(fragmentOffset)}"; + static string GetPath(string pathAndQuery, int queryIndex) => pathAndQuery.Substring(0, queryIndex + 1); #endif - } - } } } 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 374730f547a1b8..2e71063d1334dc 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 @@ -29,22 +29,19 @@ private static class EventIds { { 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/#", "http://q.app/#" }, // Has empty fragment. - { "http://q.app#f", "http://q.app/#f" }, // Has fragment. - { "http://q.app#f?a=b", "http://q.app/#f?a=b" }, // Has fragment with a '?'. - { "http://q.app/?a=b#f?a=b", "http://q.app/?*#f?a=b" }, // Has query and fragment with a '?'. - { "http://q.app?#f", "http://q.app/?#f" }, // Has empty query and fragment. + { "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(string original, string expected) + public void GetRedactedUriString_RedactsUriByDefault(string original, string expected) { Uri? uri = original != null ? new Uri(original, UriKind.RelativeOrAbsolute) : null; string? actual = LogHelper.GetRedactedUriString(uri); @@ -52,46 +49,48 @@ public void GetRedactedUriString(string original, string expected) Assert.Equal(expected, actual); } - public static TheoryData Handlers_LogExpectedUri_Data() + [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) { - TheoryData result = new(); - bool[] booleans = { true, false }; - bool[] syncApiVals = -#if NET - booleans; -#else - { false }; -#endif - foreach (bool syncApi in syncApiVals) + RemoteExecutor.Invoke(static queryRedactionDisabler => { - foreach (bool scopeHandler in booleans) + switch (queryRedactionDisabler) { - // valid values for logQueryStringEnabler: - // "" - Do not enable query string logging. - // "AppCtx" - Enable via AppContext switch. - // "EnvVarTrue" - Enable by setting the environment *_DISABLEURIQUERYREDACTION variable to 'true'. - // "EnvVar1" - Enable by setting the environment *DISABLEURIQUERYREDACTION variable to '1'. - string[] lqs = ["", "AppCtx"]; - foreach (string queryRedactionDisabler in lqs) - { - result.Add(syncApi, scopeHandler, 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; } - } - result.Add(false, false, "EnvVarTrue"); - result.Add(false, false, "EnvVar1"); - result.Add(false, true, "EnvVarTrue"); - result.Add(false, true, "EnvVar1"); + Uri[] uris = GetRedactedUriString_Data.Select(a => a[0] == null ? null : new Uri((string)a[0], UriKind.RelativeOrAbsolute)).ToArray(); - return result; + 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))] - [MemberData(nameof(Handlers_LogExpectedUri_Data))] - public async Task Handlers_LogExpectedUri(bool syncApi, bool scopeHandler, string queryRedactionDisabler) + [InlineData(false, false)] + [InlineData(false, true)] +#if NET + [InlineData(true, false)] + [InlineData(true, true)] +#endif + public async Task Handlers_LogExpectedUri(bool syncApi, bool scopeHandler) { - await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr, queryRedactionDisabler) => + await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr) => { bool syncApi = bool.Parse(syncApiStr); bool scopeHandler = bool.Parse(scopeHandlerStr); @@ -100,19 +99,6 @@ await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr, queryReda const string queryString = "term=Western%20Australia"; string destinationUri = $"{baseUri}?{queryString}"; - switch (queryRedactionDisabler) - { - case "AppCtx": - AppContext.SetSwitch("Microsoft.Extensions.Http.DisableUriQueryRedaction", true); - break; - case "EnvVarTrue": - Environment.SetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_DISABLEURIQUERYREDACTION", "True"); - break; - case "EnvVar1": - Environment.SetEnvironmentVariable("DOTNET_MICROSOFT_EXTENSIONS_HTTP_DISABLEURIQUERYREDACTION", "1"); - break; - } - var sink = new TestSink(); var logger = new TestLogger("test", sink, enabled: true); @@ -134,20 +120,18 @@ await RemoteExecutor.Invoke(static async (syncApiStr, scopeHandlerStr, queryReda _ = await invoker.SendAsync(request, default); } - string expectedUri = !string.IsNullOrEmpty(queryRedactionDisabler) ? destinationUri : $"{baseUri}?*"; - if (scopeHandler) { var pipelineStartMessage = Assert.Single(sink.Writes.Where(m => m.EventId == EventIds.PipelineStart)); - Assert.Equal($"HTTP GET {expectedUri}", pipelineStartMessage.Scope.ToString()); - Assert.Equal($"Start processing HTTP request GET {expectedUri}", pipelineStartMessage.Message); + 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 {expectedUri}", requestStartMessage.Message); + Assert.Equal($"Sending HTTP request GET {baseUri}?*", requestStartMessage.Message); } - }, syncApi.ToString(), scopeHandler.ToString(), queryRedactionDisabler).DisposeAsync(); + }, syncApi.ToString(), scopeHandler.ToString()).DisposeAsync(); } [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] @@ -170,7 +154,7 @@ await RemoteExecutor.Invoke(static async (syncApiStr, disableUriQueryRedactionSt if (disableUriQueryRedaction) { - AppContext.SetSwitch("Microsoft.Extensions.Http.DisableUriQueryRedaction", true); + AppContext.SetSwitch("System.Net.Http.DisableUriRedaction", true); } var sink = new TestSink(); From 902f459616fb5cde43a2294e9f7c21256104a0b3 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Tue, 2 Jul 2024 23:04:20 +0200 Subject: [PATCH 16/18] AggressiveInlining --- .../Microsoft.Extensions.Http/src/Logging/LogHelper.cs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs index 5cce7ece289f5a..977af7cf10e143 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -4,6 +4,7 @@ using System; using System.Diagnostics; using System.Net.Http; +using System.Runtime.CompilerServices; using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.Internal; @@ -180,8 +181,10 @@ public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessag }; #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 } From 74b1d040d4a48cf08c201d4936f80d766aa1b9c0 Mon Sep 17 00:00:00 2001 From: antonfirsov Date: Thu, 4 Jul 2024 01:33:46 +0200 Subject: [PATCH 17/18] save 1 allocation in LoggingScopeHttpMessageHandler --- .../Microsoft.Extensions.Http/src/Logging/LogHelper.cs | 9 +++++---- .../src/Logging/LoggingScopeHttpMessageHandler.cs | 4 ++-- 2 files changed, 7 insertions(+), 6 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs index 977af7cf10e143..bd13c6cfb1741f 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -110,14 +110,15 @@ public static void LogRequestEnd(this ILogger logger, HttpResponseMessage respon } } - public static IDisposable? BeginRequestPipelineScope(this ILogger logger, HttpRequestMessage request) + public static IDisposable? BeginRequestPipelineScope(this ILogger logger, HttpRequestMessage request, out string? formattedUri) { - return _beginRequestPipelineScope(logger, request.Method, GetRedactedUriString(request.RequestUri)); + formattedUri = GetRedactedUriString(request.RequestUri); + return _beginRequestPipelineScope(logger, request.Method, formattedUri); } - public static void LogRequestPipelineStart(this ILogger logger, HttpRequestMessage request, Func shouldRedactHeaderValue) + public static void LogRequestPipelineStart(this ILogger logger, HttpRequestMessage request, string? formattedUri, Func shouldRedactHeaderValue) { - _requestPipelineStart(logger, request.Method, GetRedactedUriString(request.RequestUri), null); + _requestPipelineStart(logger, request.Method, formattedUri, null); if (logger.IsEnabled(LogLevel.Trace)) { diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs index afcdfccc071a36..a25a9366ac8e29 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 (_logger.BeginRequestPipelineScope(request)) + using (_logger.BeginRequestPipelineScope(request, out string? formattedUri)) { - _logger.LogRequestPipelineStart(request, shouldRedactHeaderValue); + _logger.LogRequestPipelineStart(request, formattedUri, shouldRedactHeaderValue); HttpResponseMessage response = useAsync ? await base.SendAsync(request, cancellationToken).ConfigureAwait(false) #if NET From 956de73d88550500136d276f52310357df7753cb Mon Sep 17 00:00:00 2001 From: Anton Firszov Date: Thu, 4 Jul 2024 01:39:08 +0200 Subject: [PATCH 18/18] Update src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs Co-authored-by: Miha Zupan --- .../Microsoft.Extensions.Http/src/Logging/LogHelper.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs index bd13c6cfb1741f..2a37f6b3f3d1f8 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs @@ -78,7 +78,7 @@ private static bool GetDisableUriRedactionSettingValue() public static void LogRequestStart(this ILogger logger, HttpRequestMessage request, Func shouldRedactHeaderValue) { - // We check here to avoid allocating in the GetUriString call unnecessarily + // We check here to avoid allocating in the GetRedactedUriString call unnecessarily if (logger.IsEnabled(LogLevel.Information)) { _requestStart(logger, request.Method, GetRedactedUriString(request.RequestUri), null);