Skip to content

Commit

Permalink
Add Additional Logging to Startup/Stop (#7076)
Browse files Browse the repository at this point in the history 
* Explicitly log each incoming request at the "debug" level at start/stop 
* Adding LogTrace to DebugLogger. Update start/stop messages to DebugLogger.LogTrace
  • Loading branch information
@scbedd
scbedd authored Oct 25, 2023
1 parent bc819d5 commit da308e1
Show file tree
Hide file tree
Showing 5 changed files with 49 additions and 8 deletions.
16 changes: 8 additions & 8 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);
AssertLogs(logger, 4, 8);
}
finally
{
Expand Down Expand Up @@ -92,7 +92,7 @@ public async Task RecordingHandlerLogsSanitizedRequests()

try
{
AssertLogs(logger);
AssertLogs(logger, 2, 8);
}
finally
{
Expand All @@ -101,27 +101,27 @@ public async Task RecordingHandlerLogsSanitizedRequests()
}
}

private static void AssertLogs(TestLogger logger)
private static void AssertLogs(TestLogger logger, int offset, int expectedLength)
{
Assert.Equal(4, logger.Logs.Count);
Assert.Equal(expectedLength, logger.Logs.Count);
Assert.Equal(
$"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\"]}]" + Environment.NewLine,
logger.Logs[0].ToString());
logger.Logs[0 + offset].ToString());
Assert.Equal(
"Request Body Content{\"key\":\"Location\",\"value\":\"https://fakeazsdktestaccount.table.core.windows.net/Tables\"}",
logger.Logs[1].ToString());
logger.Logs[1 + offset].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());
logger.Logs[2 + offset].ToString());
Assert.Equal("URI: [ https://fakeazsdktestaccount.table.core.windows.net/Tables]" +
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\"]}]" + Environment.NewLine,
logger.Logs[3].ToString());
logger.Logs[3 + offset].ToString());
}

private static async Task AddSanitizerAsync(RecordingHandler testRecordingHandler, TestLogger logger)
Expand Down
12 changes: 12 additions & 0 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/DebugLogger.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -100,6 +100,18 @@ public static void LogError(int statusCode, Exception e)
}
}

public static void LogTrace(string details)
{
if (null != Logger)
{
Logger.LogTrace(details);
}
else
{
System.Console.WriteLine(details);
}
}

/// <summary>
/// Simple access to the logging api. Accepts a simple message (preformatted) and logs to debug logger.
/// </summary>
Expand Down
5 changes: 5 additions & 0 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,9 @@ public async Task Start()
HttpRequestInteractions.GetBodyKey(body, "x-recording-assets-file", allowNulls: true),
_recordingHandler.ContextDirectory);

DebugLogger.LogAdminRequestDetails(_logger, Request);
_logger.LogDebug($"Attempting to start recording for {file??"In-Memory Recording"} {assetsJson ?? string.Empty}");

if (String.IsNullOrEmpty(file) && !String.IsNullOrEmpty(recordingId))
{
await _recordingHandler.StartPlaybackAsync(recordingId, Response, RecordingType.InMemory, assetsJson);
Expand All @@ -54,6 +57,8 @@ public async Task Start()
[HttpPost]
public void Stop()
{
DebugLogger.LogAdminRequestDetails(_logger, Request);

string id = RecordingHandler.GetHeader(Request, "x-recording-id");
bool.TryParse(RecordingHandler.GetHeader(Request, "x-purge-inmemory-recording", true), out var shouldPurgeRecording);

Expand Down
6 changes: 6 additions & 0 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy/Record.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -34,6 +34,7 @@ public async Task Start()

if (body == null)
{
DebugLogger.LogAdminRequestDetails(_logger, Request);
await _recordingHandler.StartRecordingAsync(null, Response, null);
}
else
Expand All @@ -43,6 +44,9 @@ public async Task Start()
HttpRequestInteractions.GetBodyKey(body, "x-recording-assets-file", allowNulls: true),
_recordingHandler.ContextDirectory);

DebugLogger.LogAdminRequestDetails(_logger, Request);
_logger.LogDebug($"Attempting to start recording for {file} {assetsJson??string.Empty}");

if (string.IsNullOrWhiteSpace(file))
{
throw new HttpException(HttpStatusCode.BadRequest, "If providing a body to /Record/Start, the key 'x-recording-file' must be provided. If attempting to start an in-memory recording, provide NO body.");
Expand Down Expand Up @@ -81,6 +85,8 @@ public void Stop([FromBody()] IDictionary<string, string> variables = null)
save = false;
}

DebugLogger.LogAdminRequestDetails(_logger, Request);

_recordingHandler.StopRecording(id, variables: variables, saveRecording: save);
}

Expand Down
18 changes: 18 additions & 0 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -105,6 +105,10 @@ public RecordingHandler(string targetDirectory, IAssetsStore store = null, Store
#region recording functionality
public void StopRecording(string sessionId, IDictionary<string, string> variables = null, bool saveRecording = true)
{

var id = Guid.NewGuid().ToString();
DebugLogger.LogTrace($"RECORD STOP BEGIN {id}.");

if (!RecordingSessions.TryRemove(sessionId, out var recordingSession))
{
return;
Expand Down Expand Up @@ -149,6 +153,8 @@ public void StopRecording(string sessionId, IDictionary<string, string> variable
stream.Write(Encoding.UTF8.GetBytes(Environment.NewLine));
}
}

DebugLogger.LogTrace($"RECORD STOP END {id}.");
}

/// <summary>
Expand All @@ -168,6 +174,7 @@ private async Task RestoreAssetsJson(string assetsJson = null, bool forceCheckou
public async Task StartRecordingAsync(string sessionId, HttpResponse outgoingResponse, string assetsJson = null)
{
var id = Guid.NewGuid().ToString();
DebugLogger.LogTrace($"RECORD START BEGIN {id}.");

await RestoreAssetsJson(assetsJson, false);

Expand All @@ -182,6 +189,7 @@ public async Task StartRecordingAsync(string sessionId, HttpResponse outgoingRes
throw new HttpException(HttpStatusCode.InternalServerError, $"Unexpectedly failed to add new recording session under id {id}.");
}

DebugLogger.LogTrace($"RECORD START END {id}.");
outgoingResponse.Headers.Add("x-recording-id", id);
}

Expand Down Expand Up @@ -360,6 +368,8 @@ public HttpRequestMessage CreateUpstreamRequest(HttpRequest incomingRequest, byt
public async Task StartPlaybackAsync(string sessionId, HttpResponse outgoingResponse, RecordingType mode = RecordingType.FilePersisted, string assetsPath = null)
{
var id = Guid.NewGuid().ToString();
DebugLogger.LogTrace($"PLAYBACK START BEGIN {id}.");

ModifiableRecordSession session;

if (mode == RecordingType.InMemory)
Expand Down Expand Up @@ -402,10 +412,16 @@ public async Task StartPlaybackAsync(string sessionId, HttpResponse outgoingResp

// Write to the response
await outgoingResponse.WriteAsync(json);

DebugLogger.LogTrace($"PLAYBACK START END {id}.");
}

public void StopPlayback(string recordingId, bool purgeMemoryStore = false)
{

var id = Guid.NewGuid().ToString();
DebugLogger.LogTrace($"PLAYBACK STOP BEGIN {id}.");

if (!PlaybackSessions.TryRemove(recordingId, out var session))
{
throw new HttpException(HttpStatusCode.BadRequest, $"There is no active playback session under recording id {recordingId}.");
Expand All @@ -427,6 +443,8 @@ public void StopPlayback(string recordingId, bool purgeMemoryStore = false)

GC.Collect();
}

DebugLogger.LogTrace($"PLAYBACK STOP END {id}.");
}

public async Task HandlePlaybackRequest(string recordingId, HttpRequest incomingRequest, HttpResponse outgoingResponse)
Expand Down

0 comments on commit da308e1

Please sign in to comment.