From 266508f37f4c45bc5b5e0a64fad2b3c4c70bc633 Mon Sep 17 00:00:00 2001 From: Harsha Nalluru Date: Fri, 1 Nov 2024 14:15:33 -0700 Subject: [PATCH] Test proxy logs - sanitizer info (#9164) * draft testing logs for sanitizerAdd ToString, logging, and SanitizerId; update commentsAdded a ToString method to RecordEntry for string representation.Introduced logging in RecordSession to track sanitizer changes.Added SanitizerId to RecordedTestSanitizer for unique identification.Updated RegisteredSanitizer constructor to set SanitizerId.Corrected copyright comment in RequestOrResponse.cs.Added necessary using directives to RecordEntry.cs. * Enhance logging and string representation in RecordEntry * simplification * log message improve * unneeded pkg * Update tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordSession.cs Co-authored-by: Scott Beddall <45376673+scbedd@users.noreply.github.com> * Update tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordSession.cs Co-authored-by: Scott Beddall <45376673+scbedd@users.noreply.github.com> * address feedback, modifications are more granular, logs under Debug flag * sets flags only under Debug flag for fewer computations * remove ToString impl * Environment.NewLine, null checks for body, fix Logging tests * fix build and if-check indentation * Address feedback * fix logging test * improve the logging experience * Use StringBuilder * address feedback; logging modifications when entries are removed * remove modified flag tracker logic in favour of tracking them at the time of sanitization * format * default getter and setter back * fix cloning body bug * log improvements and comments * simplifications * fix tests * revert linebreak change --------- Co-authored-by: Scott Beddall <45376673+scbedd@users.noreply.github.com> --- .../LoggingTests.cs | 16 +- .../Common/RecordEntry.cs | 26 ++- .../Common/RecordSession.cs | 194 +++++++++++++++++- .../Common/RecordedTestSanitizer.cs | 3 + .../Common/SanitizerDictionary.cs | 1 + 5 files changed, 232 insertions(+), 8 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 24af1277aa2..48f9fb543a3 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs @@ -52,7 +52,7 @@ public async Task PlaybackLogsSanitizedRequest() HttpResponse response = new DefaultHttpContext().Response; await testRecordingHandler.HandlePlaybackRequest(recordingId, request, response); - AssertLogs(logger, 4, 8, 12); + AssertLogs(logger, 4, 16, 12, "playback"); } finally { @@ -89,10 +89,9 @@ public async Task RecordingHandlerLogsSanitizedRequests() await testRecordingHandler.HandleRecordRequestAsync(recordingId, request, httpContext.Response); await testRecordingHandler.StopRecording(recordingId); - try { - AssertLogs(logger, 2, 8, 12); + AssertLogs(logger, 2, 11, 12, "record"); } finally { @@ -101,7 +100,7 @@ public async Task RecordingHandlerLogsSanitizedRequests() } } - private static void AssertLogs(TestLogger logger, int offset, int expectedLength, int expectedContentLength) + private static void AssertLogs(TestLogger logger, int offset, int expectedLength, int expectedContentLength, string testType) { Assert.Equal(expectedLength, logger.Logs.Count); Assert.Equal( @@ -116,12 +115,21 @@ private static void AssertLogs(TestLogger logger, int offset, int expectedLength Assert.Equal( "Request Body Content{\"key\":\"Location\",\"value\":\"https://fakeazsdktestaccount.table.core.windows.net/Tables\"}", logger.Logs[2 + offset].ToString()); + if (testType == "playback") + { + offset = offset + 5; + } Assert.Equal("URI: [ https://Sanitized.table.core.windows.net/Tables]" + Environment.NewLine + "Headers: [{\"Accept\":[\"application/json;odata=minimalmetadata\"],\"Accept-Encoding\":[\"gzip, deflate\"],\"Authorization\":[\"Sanitized\"],\"Connection\":[\"keep-alive\"]," + "\"Content-Length\":[\"" + expectedContentLength + "\"],\"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\":[\"Sanitized\"]," + "\"x-ms-date\":[\"Tue, 18 May 2021 23:27:42 GMT\"],\"x-ms-version\":[\"2019-02-02\"]}]" + Environment.NewLine, logger.Logs[3 + offset].ToString()); + if (testType == "playback") + { + offset = offset - 1; + } + Assert.Equal("Central sanitizer rule AZSDK4001 modified the entry" + Environment.NewLine + "RequestUri is modified" + Environment.NewLine + "before:" + Environment.NewLine + " https://fakeazsdktestaccount.table.core.windows.net/Tables" + Environment.NewLine + "after: " + Environment.NewLine + " https://Sanitized.table.core.windows.net/Tables" + Environment.NewLine, logger.Logs[7 + offset].ToString()); } private static async Task AddSanitizerAsync(RecordingHandler testRecordingHandler, TestLogger logger) diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordEntry.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordEntry.cs index 235780323c0..f5001ed48cf 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordEntry.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordEntry.cs @@ -2,13 +2,14 @@ // Licensed under the MIT License. using Azure.Core; +using Microsoft.Extensions.Logging; using System; using System.Collections.Generic; using System.IO; +using System.Linq; using System.Text; using System.Text.Encodings.Web; using System.Text.Json; -using System.Text.Unicode; namespace Azure.Sdk.Tools.TestProxy.Common { @@ -35,7 +36,7 @@ public class RecordEntry public int StatusCode { get; set; } public static RecordEntry Deserialize(JsonElement element) - { + { var record = new RecordEntry(); if (element.TryGetProperty(nameof(RequestMethod), out JsonElement property)) @@ -316,5 +317,26 @@ public static bool IsTextContentType(IDictionary requestHeader return TryGetContentType(requestHeaders, out string contentType) && ContentTypeUtilities.TryGetTextEncoding(contentType, out encoding); } + + /// + /// Creates a copy of the provided record entry (Only the RequestUri, Request and Response are copied over). + /// Used primarily for sanitization logging. + /// + /// The copied record entry. + public RecordEntry Clone() + { + // Create a copy of the record entry + var copiedRecordEntry = new RecordEntry(); + copiedRecordEntry.RequestUri = this.RequestUri; + + copiedRecordEntry.Request = new RequestOrResponse(); + copiedRecordEntry.Request.Headers = new SortedDictionary(this.Request.Headers.ToDictionary(kvp => kvp.Key, kvp => (string[])kvp.Value.Clone())); + copiedRecordEntry.Request.Body = this.Request.Body != null ? (byte[])this.Request.Body.Clone() : null; + + copiedRecordEntry.Response = new RequestOrResponse(); + copiedRecordEntry.Response.Headers = new SortedDictionary(this.Response.Headers.ToDictionary(kvp => kvp.Key, kvp => (string[])kvp.Value.Clone())); + copiedRecordEntry.Response.Body = this.Response.Body != null ? (byte[])this.Response.Body.Clone() : null; + return copiedRecordEntry; + } } } diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordSession.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordSession.cs index ba51b7d355d..24a0affccac 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordSession.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordSession.cs @@ -2,10 +2,16 @@ // Licensed under the MIT License. using System; +using System.Collections; using System.Collections.Generic; +using System.Data; +using System.Linq; +using System.Text; using System.Text.Json; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Newtonsoft.Json.Linq; namespace Azure.Sdk.Tools.TestProxy.Common { @@ -100,7 +106,18 @@ public RecordEntry Lookup(RecordEntry requestEntry, RecordMatcher matcher, IEnum { foreach (RecordedTestSanitizer sanitizer in sanitizers) { + RecordEntry reqEntryPreSanitize = null; + if (DebugLogger.CheckLogLevel(LogLevel.Debug)) + { + reqEntryPreSanitize = requestEntry.Clone(); + } + sanitizer.Sanitize(requestEntry); + + if (DebugLogger.CheckLogLevel(LogLevel.Debug)) + { + LogSanitizerModification(sanitizer.SanitizerId, reqEntryPreSanitize, requestEntry); + } } // normalize request body with STJ using relaxed escaping to match behavior when Deserializing from session files @@ -110,7 +127,7 @@ public RecordEntry Lookup(RecordEntry requestEntry, RecordMatcher matcher, IEnum if (remove) { Entries.Remove(entry); - DebugLogger.LogDebug($"We successfully matched and popped request URI {entry.RequestUri} for recordingId {sessionId??"Unknown"}"); + DebugLogger.LogDebug($"We successfully matched and popped request URI {entry.RequestUri} for recordingId {sessionId ?? "Unknown"}"); } return entry; @@ -122,7 +139,7 @@ public async Task Remove(RecordEntry entry, bool shouldLock = true) { await EntryLock.WaitAsync(); } - + try { Entries.Remove(entry); @@ -145,7 +162,34 @@ public async Task Sanitize(RecordedTestSanitizer sanitizer, bool shouldLock = tr try { + var entriesPreSanitize = Array.Empty(); + if (DebugLogger.CheckLogLevel(LogLevel.Debug)) + { + entriesPreSanitize = this.Entries.Select(requestEntry => requestEntry.Clone()).ToArray(); + } + sanitizer.Sanitize(this); + + if (DebugLogger.CheckLogLevel(LogLevel.Debug)) + { + if (entriesPreSanitize.Length > this.Entries.Count) + { + DebugLogger.LogDebug(GetSanitizerInfoLogPrefix(sanitizer.SanitizerId) + " has removed some entries"); + } + else if (entriesPreSanitize.Length < this.Entries.Count) + { + throw new Exception("Something went wrong. The number of entries increased after sanitization with " + GetSanitizerInfoLogPrefix(sanitizer.SanitizerId)); + } + else + { + for (int i = 0; i < entriesPreSanitize.Length; i++) + { + + LogSanitizerModification(sanitizer.SanitizerId, entriesPreSanitize[i], this.Entries[i]); + + } + } + } } finally { @@ -167,7 +211,32 @@ public async Task Sanitize(IEnumerable sanitizers, bool s { foreach (var sanitizer in sanitizers) { + var entriesPreSanitize = Array.Empty(); + if (DebugLogger.CheckLogLevel(LogLevel.Debug)) + { + entriesPreSanitize = this.Entries.Select(requestEntry => requestEntry.Clone()).ToArray(); + } + sanitizer.Sanitize(this); + + if (DebugLogger.CheckLogLevel(LogLevel.Debug)) + { + if (entriesPreSanitize.Length > this.Entries.Count) + { + DebugLogger.LogDebug(GetSanitizerInfoLogPrefix(sanitizer.SanitizerId) + " has removed some entries"); + } + else if (entriesPreSanitize.Length < this.Entries.Count) + { + throw new Exception("Something went wrong. The number of entries increased after sanitization with " + GetSanitizerInfoLogPrefix(sanitizer.SanitizerId)); + } + else + { + for (int i = 0; i < entriesPreSanitize.Length; i++) + { + LogSanitizerModification(sanitizer.SanitizerId, entriesPreSanitize[i], this.Entries[i]); + } + } + } } } finally @@ -178,5 +247,126 @@ public async Task Sanitize(IEnumerable sanitizers, bool s } } } + + /// + /// Logs the modifications made by a sanitizer to a record entry. + /// + /// The ID of the sanitizer. + /// The record entry before sanitization. + /// The record entry after sanitization. + private void LogSanitizerModification(string sanitizerId, RecordEntry entryPreSanitize, RecordEntry entryPostSanitize) + { + bool isRequestUriModified = entryPreSanitize.RequestUri != entryPostSanitize.RequestUri; + bool areRequestHeadersModified = AreHeadersModified(entryPreSanitize.Request.Headers, entryPostSanitize.Request.Headers); + bool isRequestBodyModified = IsBodyModified(entryPreSanitize.Request.Body, entryPostSanitize.Request.Body); + bool areResponseHeadersModified = AreHeadersModified(entryPreSanitize.Response.Headers, entryPostSanitize.Response.Headers); + bool isResponseBodyModified = IsBodyModified(entryPreSanitize.Response.Body, entryPostSanitize.Response.Body); + + bool isRecordModified = isRequestUriModified || areRequestHeadersModified || isRequestBodyModified || areResponseHeadersModified || isResponseBodyModified; + if (!isRecordModified) + { + return; + } + + // Record has been modified by the sanitizer, log the granular changes to assist in debugging + StringBuilder logMessage = new StringBuilder(); + logMessage.AppendLine(GetSanitizerInfoLogPrefix(sanitizerId) + " modified the entry"); + + var before = $"{Environment.NewLine}before:{Environment.NewLine} "; + var after = $"{Environment.NewLine}after: {Environment.NewLine} "; + + if (isRequestUriModified) + { + logMessage.AppendLine($"RequestUri is modified{before}{entryPreSanitize.RequestUri}{after}{entryPostSanitize.RequestUri}"); + } + + void LogBodyModification(RequestOrResponse pre, RequestOrResponse post, bool isRequest) + { + if (pre.Body != null && pre.TryGetBodyAsText(out string bodyTextPre) && + post.Body != null && post.TryGetBodyAsText(out string bodyTextPost) && + !string.IsNullOrWhiteSpace(bodyTextPre) && + !string.IsNullOrWhiteSpace(bodyTextPost)) + { + logMessage.AppendLine($"{(isRequest ? "Request" : "Response")} Body is modified{before}{bodyTextPre}{after}{bodyTextPost}"); + } + } + if (isRequestBodyModified) + { + LogBodyModification(entryPreSanitize.Request, entryPostSanitize.Request, true); + } + if (isResponseBodyModified) + { + LogBodyModification(entryPreSanitize.Response, entryPostSanitize.Response, false); + } + + void LogHeadersModification(RequestOrResponse pre, RequestOrResponse post, bool isRequest) + { + logMessage.AppendLine($"{(isRequest ? "Request" : "Response")} Headers are modified{before}{HeadersAsString(pre.Headers)}{after}{HeadersAsString(post.Headers)}"); + } + if (areRequestHeadersModified) + { + LogHeadersModification(entryPreSanitize.Request, entryPostSanitize.Request, true); + } + if (areResponseHeadersModified) + { + LogHeadersModification(entryPreSanitize.Response, entryPostSanitize.Response, false); + } + + DebugLogger.LogDebug(logMessage.ToString()); + } + + /// + /// Generates a log prefix string that provides information about the sanitizer. + /// + /// The ID of the sanitizer. + /// A string that indicates whether the sanitizer is a central sanitizer or user-specified, followed by the sanitizer ID. + private string GetSanitizerInfoLogPrefix(string sanitizerId) + { + return (sanitizerId != null && sanitizerId.StartsWith("AZSDK") ? "Central sanitizer" : "User specified") + " rule " + sanitizerId; + } + + /// + /// Checks if the headers in two dictionaries are modified. + /// + /// The first dictionary of headers. + /// The second dictionary of headers. + /// True if the headers are modified, otherwise false. + private bool AreHeadersModified(SortedDictionary dict1, SortedDictionary dict2) + { + if (dict1 == null || dict2 == null) + return !(dict1 == dict2); + + if (dict1.Count != dict2.Count) + return true; + + return !dict1.All(kvp => dict2.TryGetValue(kvp.Key, out var value) && kvp.Value.SequenceEqual(value)); + } + + /// + /// Checks if the body content has been modified. + /// + /// The body content before modification. + /// The body content after modification. + /// True if the body content is modified, otherwise false. + private bool IsBodyModified(byte[] array1, byte[] array2) + { + if (array1 == null && array2 == null) + return false; + + if (array1 == null || array2 == null) + return true; + + return !array1.SequenceEqual(array2); + } + + /// + /// Converts the headers dictionary to a string representation. + /// + /// The dictionary of headers. + /// A string representation of the headers. + private string HeadersAsString(SortedDictionary sortedDict) + { + return string.Join(Environment.NewLine + " ", sortedDict.Select(kvp => $"{kvp.Key}: {string.Join(", ", kvp.Value)}")); + } } } diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordedTestSanitizer.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordedTestSanitizer.cs index b548c13d23a..4449437da59 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordedTestSanitizer.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordedTestSanitizer.cs @@ -17,6 +17,9 @@ namespace Azure.Sdk.Tools.TestProxy.Common public class RecordedTestSanitizer { public const string SanitizeValue = "Sanitized"; + + public string SanitizerId { get; set; } + public List JsonPathSanitizers { get; } = new List(); public ApplyCondition Condition { get; protected set; } = null; diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/SanitizerDictionary.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/SanitizerDictionary.cs index 706dfb742e0..4047db0c075 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/SanitizerDictionary.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/SanitizerDictionary.cs @@ -21,6 +21,7 @@ public RegisteredSanitizer(RecordedTestSanitizer sanitizer, string id, string de Id = id; Sanitizer = sanitizer; Description = description; + sanitizer.SanitizerId = id; } }