From ec5662213eae735ce641c22249fa73e7cfdc3ef8 Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Fri, 18 Aug 2023 13:20:58 -0700 Subject: [PATCH 1/3] Fix admin logging --- .../LoggingTests.cs | 87 ++++++++++++++----- .../TestLogger.cs | 25 ++++++ .../Azure.Sdk.Tools.TestProxy/Admin.cs | 12 +-- .../Common/DebugLogger.cs | 9 +- .../Azure.Sdk.Tools.TestProxy/Playback.cs | 4 +- .../Azure.Sdk.Tools.TestProxy/Record.cs | 2 +- 6 files changed, 105 insertions(+), 34 deletions(-) diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs index b06106317d8..bd91bae2dca 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs @@ -5,7 +5,7 @@ using Azure.Sdk.Tools.TestProxy.Common; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Mvc; -using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Primitives; using Xunit; namespace Azure.Sdk.Tools.TestProxy.Tests @@ -30,17 +30,20 @@ public async Task PlaybackLogsSanitizedRequest() httpContext.Request.Body = TestHelpers.GenerateStreamRequestBody(body); httpContext.Request.ContentLength = body.Length; - var controller = new Playback(testRecordingHandler, new NullLoggerFactory()) + var playback = new Playback(testRecordingHandler, new TestLoggingFactory(logger)) { ControllerContext = new ControllerContext() { HttpContext = httpContext } }; - await controller.Start(); + await playback.Start(); var recordingId = httpContext.Response.Headers["x-recording-id"].ToString(); Assert.NotNull(recordingId); + + await AddSanitizerAsync(testRecordingHandler, logger); + Assert.True(testRecordingHandler.PlaybackSessions.ContainsKey(recordingId)); var entry = testRecordingHandler.PlaybackSessions[recordingId].Session.Entries[0]; HttpRequest request = TestHelpers.CreateRequestFromEntry(entry); @@ -49,10 +52,7 @@ public async Task PlaybackLogsSanitizedRequest() HttpResponse response = new DefaultHttpContext().Response; await testRecordingHandler.HandlePlaybackRequest(recordingId, request, response); - Assert.Single(logger.Logs); - var logEntry = logger.Logs[0].ToString(); - Assert.DoesNotContain(@"""Authorization"":[""fake-auth-header""]", logEntry); - Assert.Contains(@"""Authorization"":[""Sanitized""]", logEntry); + AssertLogs(logger); } finally { @@ -65,11 +65,14 @@ public async Task RecordingHandlerLogsSanitizedRequests() { var logger = new TestLogger(); DebugLogger.Logger = logger; + + var session = TestHelpers.LoadRecordSession("Test.RecordEntries/request_with_binary_content.json"); + var request = TestHelpers.CreateRequestFromEntry(session.Session.Entries[0]); var httpContext = new DefaultHttpContext(); var bodyBytes = Encoding.UTF8.GetBytes("{\"hello\":\"world\"}"); var mockClient = new HttpClient(new MockHttpHandler(bodyBytes, "application/json")); var path = Directory.GetCurrentDirectory(); - var recordingHandler = new RecordingHandler(path) + var testRecordingHandler = new RecordingHandler(path) { RedirectableClient = mockClient, RedirectlessClient = mockClient @@ -78,27 +81,18 @@ public async Task RecordingHandlerLogsSanitizedRequests() var relativePath = "recordings/logs"; var fullPathToRecording = Path.Combine(path, relativePath) + ".json"; - await recordingHandler.StartRecordingAsync(relativePath, httpContext.Response); + await testRecordingHandler.StartRecordingAsync(relativePath, httpContext.Response); - var recordingId = httpContext.Response.Headers["x-recording-id"].ToString(); + await AddSanitizerAsync(testRecordingHandler, logger); - httpContext.Request.ContentType = "application/json"; - httpContext.Request.Headers["Authorization"] = "fake-auth-header"; - httpContext.Request.ContentLength = 0; - httpContext.Request.Headers["x-recording-id"] = recordingId; - httpContext.Request.Headers["x-recording-upstream-base-uri"] = "http://example.org"; - httpContext.Request.Method = "GET"; - httpContext.Request.Body = new MemoryStream(CompressionUtilities.CompressBody(bodyBytes, httpContext.Request.Headers)); + var recordingId = httpContext.Response.Headers["x-recording-id"].ToString(); - await recordingHandler.HandleRecordRequestAsync(recordingId, httpContext.Request, httpContext.Response); - recordingHandler.StopRecording(recordingId); + await testRecordingHandler.HandleRecordRequestAsync(recordingId, request, httpContext.Response); + testRecordingHandler.StopRecording(recordingId); try { - Assert.Single(logger.Logs); - var logEntry = logger.Logs[0].ToString(); - Assert.DoesNotContain(@"""Authorization"":[""fake-auth-header""]", logEntry); - Assert.Contains(@"""Authorization"":[""Sanitized""]", logEntry); + AssertLogs(logger); } finally { @@ -106,8 +100,55 @@ public async Task RecordingHandlerLogsSanitizedRequests() DebugLogger.Logger = null; } } + + private static void AssertLogs(TestLogger logger) + { + Assert.Equal(4, logger.Logs.Count); + Assert.Equal( + "URI: [ http://127.0.0.1:5000/admin/addsanitizer]\r\nHeaders: " + + "[{\"Host\":[\"127.0.0.1:5000\"],\"x-abstraction-identifier\":[\"HeaderRegexSanitizer\"]," + + "\"Content-Length\":[\"92\"]}]\r\n", + logger.Logs[0].ToString()); + Assert.Equal( + "Request Body Content{\"key\":\"Location\",\"value\":\"https://fakeazsdktestaccount.table.core.windows.net/Tables\"}", + logger.Logs[1].ToString()); + // sanitizer request body is currently duplicated for each key/value pair + Assert.Equal( + "Request Body Content{\"key\":\"Location\",\"value\":\"https://fakeazsdktestaccount.table.core.windows.net/Tables\"}", + logger.Logs[2].ToString()); + Assert.Equal("URI: [ https://fakeazsdktestaccount.table.core.windows.net/Tables]" + + "\r\nHeaders: [{\"Accept\":[\"application/json;odata=minimalmetadata\"],\"Accept-Encoding\":[\"gzip, deflate\"],\"Authorization\":[\"Sanitized\"],\"Connection\":[\"keep-alive\"]," + + "\"Content-Length\":[\"12\"],\"Content-Type\":[\"application/octet-stream\"],\"DataServiceVersion\":[\"3.0\"],\"Date\":[\"Tue, 18 May 2021 23:27:42 GMT\"]," + + "\"User-Agent\":[\"azsdk-python-data-tables/12.0.0b7 Python/3.8.6 (Windows-10-10.0.19041-SP0)\"],\"x-ms-client-request-id\":[\"a4c24b7a-b830-11eb-a05e-10e7c6392c5a\"]," + + "\"x-ms-date\":[\"Tue, 18 May 2021 23:27:42 GMT\"],\"x-ms-version\":[\"2019-02-02\"]}]\r\n", + logger.Logs[3].ToString()); + } + + private static async Task AddSanitizerAsync(RecordingHandler testRecordingHandler, TestLogger logger) + { + var httpContext = new DefaultHttpContext(); + httpContext.Request.Scheme = "http"; + httpContext.Request.Host = new HostString("127.0.0.1:5000"); + httpContext.Request.Path = "/admin/addsanitizer"; + httpContext.Request.Headers["x-abstraction-identifier"] = "HeaderRegexSanitizer"; + httpContext.Request.Body = + TestHelpers.GenerateStreamRequestBody( + "{ \"key\": \"Location\", \"value\": \"https://fakeazsdktestaccount.table.core.windows.net/Tables\" }"); + httpContext.Request.ContentLength = 92; + + var admin = new Admin(testRecordingHandler, new TestLoggingFactory(logger)) + { + ControllerContext = new ControllerContext() + { + HttpContext = httpContext + } + }; + await admin.AddSanitizer(); + } } + + [CollectionDefinition(nameof(LoggingCollection), DisableParallelization = true)] public class LoggingCollection { diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/TestLogger.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/TestLogger.cs index 60116223ca6..90d95226d1c 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/TestLogger.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/TestLogger.cs @@ -24,4 +24,29 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except Logs.Add(state); } } + + public class TestLoggingFactory : ILoggerFactory + { + private readonly TestLogger _logger; + + public TestLoggingFactory(TestLogger logger) + { + _logger = logger; + } + + public void Dispose() + { + throw new NotImplementedException(); + } + + public void AddProvider(ILoggerProvider provider) + { + throw new NotImplementedException(); + } + + public ILogger CreateLogger(string categoryName) + { + return _logger; + } + } } \ No newline at end of file diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Admin.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Admin.cs index 3c26851eaa8..d81b7ce8588 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Admin.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Admin.cs @@ -30,7 +30,7 @@ public Admin(RecordingHandler recordingHandler, ILoggerFactory loggingFactory) [HttpPost] public void Reset() { - DebugLogger.LogRequestDetails(_logger, Request); + DebugLogger.LogAdminRequestDetails(_logger, Request); var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true); _recordingHandler.SetDefaultExtensions(recordingId); @@ -39,14 +39,14 @@ public void Reset() [HttpGet] public void IsAlive() { - DebugLogger.LogRequestDetails(_logger, Request); + DebugLogger.LogAdminRequestDetails(_logger, Request); Response.StatusCode = 200; } [HttpPost] public async Task AddTransform() { - DebugLogger.LogRequestDetails(_logger, Request); + DebugLogger.LogAdminRequestDetails(_logger, Request); var tName = RecordingHandler.GetHeader(Request, "x-abstraction-identifier"); var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true); @@ -65,7 +65,7 @@ public async Task AddTransform() [HttpPost] public async Task AddSanitizer() { - DebugLogger.LogRequestDetails(_logger, Request); + DebugLogger.LogAdminRequestDetails(_logger, Request); var sName = RecordingHandler.GetHeader(Request, "x-abstraction-identifier"); var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true); @@ -84,7 +84,7 @@ public async Task AddSanitizer() [HttpPost] public async Task SetMatcher() { - DebugLogger.LogRequestDetails(_logger, Request); + DebugLogger.LogAdminRequestDetails(_logger, Request); var mName = RecordingHandler.GetHeader(Request, "x-abstraction-identifier"); var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true); @@ -104,7 +104,7 @@ public async Task SetMatcher() [AllowEmptyBody] public void SetRecordingOptions([FromBody()] IDictionary options = null) { - DebugLogger.LogRequestDetails(_logger, Request); + DebugLogger.LogAdminRequestDetails(_logger, Request); var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true); diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/DebugLogger.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/DebugLogger.cs index d95564e1ddd..25cd9e7a49e 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/DebugLogger.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/DebugLogger.cs @@ -4,6 +4,7 @@ using System; using System.Collections.Generic; using System.Text.Json; +using Microsoft.AspNetCore.Http.Extensions; namespace Azure.Sdk.Tools.TestProxy.Common { @@ -147,11 +148,15 @@ public static void LogDebug(string details) /// Usually will be the DI-ed individual ILogger instance from a controller. However any valid ILogger instance is fine here. /// The http request which needs to be detailed. /// - public static void LogRequestDetails(ILogger loggerInstance, HttpRequest req) + public static void LogAdminRequestDetails(ILogger loggerInstance, HttpRequest req) { if(CheckLogLevel(LogLevel.Debug)) { - loggerInstance.LogDebug(_generateLogLine(req, null)); + var headers = Encoding.UTF8.GetString(JsonSerializer.SerializeToUtf8Bytes(req.Headers)); + StringBuilder sb = new StringBuilder(); + sb.AppendLine("URI: [ " + req.GetDisplayUrl() + "]"); + sb.AppendLine("Headers: [" + headers + "]"); + loggerInstance.LogDebug(sb.ToString()); } } diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs index 44b62c38f31..8959a49d492 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs @@ -63,7 +63,7 @@ public void Stop() [HttpPost] public async Task Reset([FromBody()] IDictionary options = null) { - DebugLogger.LogRequestDetails(_logger, Request); + DebugLogger.LogAdminRequestDetails(_logger, Request); var pathToAssets = RecordingHandler.GetAssetsJsonLocation(StoreResolver.ParseAssetsJsonBody(options), _recordingHandler.ContextDirectory); @@ -73,7 +73,7 @@ public async Task Reset([FromBody()] IDictionary options = null) [HttpPost] public async Task Restore([FromBody()] IDictionary options = null) { - DebugLogger.LogRequestDetails(_logger, Request); + DebugLogger.LogAdminRequestDetails(_logger, Request); var pathToAssets = RecordingHandler.GetAssetsJsonLocation(StoreResolver.ParseAssetsJsonBody(options), _recordingHandler.ContextDirectory); diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Record.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Record.cs index d63be791388..b9de1d732f7 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Record.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Record.cs @@ -56,7 +56,7 @@ public async Task Start() [HttpPost] public async Task Push([FromBody()] IDictionary options = null) { - DebugLogger.LogRequestDetails(_logger, Request); + DebugLogger.LogAdminRequestDetails(_logger, Request); var pathToAssets = RecordingHandler.GetAssetsJsonLocation(StoreResolver.ParseAssetsJsonBody(options), _recordingHandler.ContextDirectory); From 437881da01dbd878ccd3d585dd73458083bd20a5 Mon Sep 17 00:00:00 2001 From: "Scott Beddall (from Dev Box)" Date: Fri, 18 Aug 2023 13:43:16 -0700 Subject: [PATCH 2/3] commit assert fix for multiplat --- .../Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs index bd91bae2dca..e370391a0e1 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs @@ -1,11 +1,11 @@ -using System.IO; +using System; +using System.IO; using System.Net.Http; using System.Text; using System.Threading.Tasks; using Azure.Sdk.Tools.TestProxy.Common; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Mvc; -using Microsoft.Extensions.Primitives; using Xunit; namespace Azure.Sdk.Tools.TestProxy.Tests @@ -117,7 +117,7 @@ private static void AssertLogs(TestLogger logger) "Request Body Content{\"key\":\"Location\",\"value\":\"https://fakeazsdktestaccount.table.core.windows.net/Tables\"}", logger.Logs[2].ToString()); Assert.Equal("URI: [ https://fakeazsdktestaccount.table.core.windows.net/Tables]" + - "\r\nHeaders: [{\"Accept\":[\"application/json;odata=minimalmetadata\"],\"Accept-Encoding\":[\"gzip, deflate\"],\"Authorization\":[\"Sanitized\"],\"Connection\":[\"keep-alive\"]," + + Environment.NewLine + "Headers: [{\"Accept\":[\"application/json;odata=minimalmetadata\"],\"Accept-Encoding\":[\"gzip, deflate\"],\"Authorization\":[\"Sanitized\"],\"Connection\":[\"keep-alive\"]," + "\"Content-Length\":[\"12\"],\"Content-Type\":[\"application/octet-stream\"],\"DataServiceVersion\":[\"3.0\"],\"Date\":[\"Tue, 18 May 2021 23:27:42 GMT\"]," + "\"User-Agent\":[\"azsdk-python-data-tables/12.0.0b7 Python/3.8.6 (Windows-10-10.0.19041-SP0)\"],\"x-ms-client-request-id\":[\"a4c24b7a-b830-11eb-a05e-10e7c6392c5a\"]," + "\"x-ms-date\":[\"Tue, 18 May 2021 23:27:42 GMT\"],\"x-ms-version\":[\"2019-02-02\"]}]\r\n", @@ -153,4 +153,4 @@ private static async Task AddSanitizerAsync(RecordingHandler testRecordingHandle public class LoggingCollection { } -} \ No newline at end of file +} From a076aa62b8ebbbac338faeb10dd14116e1095170 Mon Sep 17 00:00:00 2001 From: "Scott Beddall (from Dev Box)" Date: Fri, 18 Aug 2023 13:50:22 -0700 Subject: [PATCH 3/3] all \r\n -> Environment.NewLine in AssertLogs --- .../Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs index e370391a0e1..0cd4e10a407 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs @@ -105,9 +105,9 @@ private static void AssertLogs(TestLogger logger) { Assert.Equal(4, logger.Logs.Count); Assert.Equal( - "URI: [ http://127.0.0.1:5000/admin/addsanitizer]\r\nHeaders: " + + $"URI: [ http://127.0.0.1:5000/admin/addsanitizer]{Environment.NewLine}Headers: " + "[{\"Host\":[\"127.0.0.1:5000\"],\"x-abstraction-identifier\":[\"HeaderRegexSanitizer\"]," + - "\"Content-Length\":[\"92\"]}]\r\n", + "\"Content-Length\":[\"92\"]}]" + Environment.NewLine, logger.Logs[0].ToString()); Assert.Equal( "Request Body Content{\"key\":\"Location\",\"value\":\"https://fakeazsdktestaccount.table.core.windows.net/Tables\"}", @@ -120,7 +120,7 @@ private static void AssertLogs(TestLogger logger) Environment.NewLine + "Headers: [{\"Accept\":[\"application/json;odata=minimalmetadata\"],\"Accept-Encoding\":[\"gzip, deflate\"],\"Authorization\":[\"Sanitized\"],\"Connection\":[\"keep-alive\"]," + "\"Content-Length\":[\"12\"],\"Content-Type\":[\"application/octet-stream\"],\"DataServiceVersion\":[\"3.0\"],\"Date\":[\"Tue, 18 May 2021 23:27:42 GMT\"]," + "\"User-Agent\":[\"azsdk-python-data-tables/12.0.0b7 Python/3.8.6 (Windows-10-10.0.19041-SP0)\"],\"x-ms-client-request-id\":[\"a4c24b7a-b830-11eb-a05e-10e7c6392c5a\"]," + - "\"x-ms-date\":[\"Tue, 18 May 2021 23:27:42 GMT\"],\"x-ms-version\":[\"2019-02-02\"]}]\r\n", + "\"x-ms-date\":[\"Tue, 18 May 2021 23:27:42 GMT\"],\"x-ms-version\":[\"2019-02-02\"]}]" + Environment.NewLine, logger.Logs[3].ToString()); }