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; } }