Skip to content

Commit

Permalink
Test proxy logs - sanitizer info (#9164)
Browse files Browse the repository at this point in the history 
* 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 <[email protected]>

* Update tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordSession.cs

Co-authored-by: Scott Beddall <[email protected]>

* 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 <[email protected]>
  • Loading branch information
@HarshaNalluru @scbedd
HarshaNalluru and scbedd authored Nov 1, 2024
1 parent bf7c4cf commit 266508f
Show file tree
Hide file tree
Showing 5 changed files with 232 additions and 8 deletions.
16 changes: 12 additions & 4 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
{
Expand Down Expand Up @@ -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
{
Expand All @@ -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(
Expand All @@ -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)
Expand Down
26 changes: 24 additions & 2 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordEntry.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
{
Expand All @@ -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))
Expand Down Expand Up @@ -316,5 +317,26 @@ public static bool IsTextContentType(IDictionary<string, string[]> requestHeader
return TryGetContentType(requestHeaders, out string contentType) &&
ContentTypeUtilities.TryGetTextEncoding(contentType, out encoding);
}

/// <summary>
/// Creates a copy of the provided record entry (Only the RequestUri, Request and Response are copied over).
/// Used primarily for sanitization logging.
/// </summary>
/// <returns>The copied record entry.</returns>
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<string, string[]>(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<string, string[]>(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;
}
}
}
194 changes: 192 additions & 2 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordSession.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
{
Expand Down Expand Up @@ -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
Expand All @@ -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;
Expand All @@ -122,7 +139,7 @@ public async Task Remove(RecordEntry entry, bool shouldLock = true)
{
await EntryLock.WaitAsync();
}

try
{
Entries.Remove(entry);
Expand All @@ -145,7 +162,34 @@ public async Task Sanitize(RecordedTestSanitizer sanitizer, bool shouldLock = tr

try
{
var entriesPreSanitize = Array.Empty<RecordEntry>();
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
{
Expand All @@ -167,7 +211,32 @@ public async Task Sanitize(IEnumerable<RecordedTestSanitizer> sanitizers, bool s
{
foreach (var sanitizer in sanitizers)
{
var entriesPreSanitize = Array.Empty<RecordEntry>();
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
Expand All @@ -178,5 +247,126 @@ public async Task Sanitize(IEnumerable<RecordedTestSanitizer> sanitizers, bool s
}
}
}

/// <summary>
/// Logs the modifications made by a sanitizer to a record entry.
/// </summary>
/// <param name="sanitizerId">The ID of the sanitizer.</param>
/// <param name="entryPreSanitize">The record entry before sanitization.</param>
/// <param name="entryPostSanitize">The record entry after sanitization.</param>
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());
}

/// <summary>
/// Generates a log prefix string that provides information about the sanitizer.
/// </summary>
/// <param name="sanitizerId">The ID of the sanitizer.</param>
/// <returns>A string that indicates whether the sanitizer is a central sanitizer or user-specified, followed by the sanitizer ID.</returns>
private string GetSanitizerInfoLogPrefix(string sanitizerId)
{
return (sanitizerId != null && sanitizerId.StartsWith("AZSDK") ? "Central sanitizer" : "User specified") + " rule " + sanitizerId;
}

/// <summary>
/// Checks if the headers in two dictionaries are modified.
/// </summary>
/// <param name="dict1">The first dictionary of headers.</param>
/// <param name="dict2">The second dictionary of headers.</param>
/// <returns>True if the headers are modified, otherwise false.</returns>
private bool AreHeadersModified(SortedDictionary<string, string[]> dict1, SortedDictionary<string, string[]> 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));
}

/// <summary>
/// Checks if the body content has been modified.
/// </summary>
/// <param name="array1">The body content before modification.</param>
/// <param name="array2">The body content after modification.</param>
/// <returns>True if the body content is modified, otherwise false.</returns>
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);
}

/// <summary>
/// Converts the headers dictionary to a string representation.
/// </summary>
/// <param name="sortedDict">The dictionary of headers.</param>
/// <returns>A string representation of the headers.</returns>
private string HeadersAsString(SortedDictionary<string, string[]> sortedDict)
{
return string.Join(Environment.NewLine + " ", sortedDict.Select(kvp => $"{kvp.Key}: {string.Join(", ", kvp.Value)}"));
}
}
}
3 changes: 3 additions & 0 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordedTestSanitizer.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<string> JsonPathSanitizers { get; } = new List<string>();

public ApplyCondition Condition { get; protected set; } = null;
Expand Down
1 change: 1 addition & 0 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/SanitizerDictionary.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@ public RegisteredSanitizer(RecordedTestSanitizer sanitizer, string id, string de
Id = id;
Sanitizer = sanitizer;
Description = description;
sanitizer.SanitizerId = id;
}
}

Expand Down

0 comments on commit 266508f

Please sign in to comment.