From f8ce4de006e8e59396be764127a7eff4d654af82 Mon Sep 17 00:00:00 2001 From: "Scott Beddall (from Dev Box)" Date: Fri, 6 Oct 2023 13:52:32 -0700 Subject: [PATCH 1/4] add additional logging --- tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs | 6 ++++++ tools/test-proxy/Azure.Sdk.Tools.TestProxy/Record.cs | 6 ++++++ 2 files changed, 12 insertions(+) diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs index 8959a49d492..8c9cc1b6216 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs @@ -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); @@ -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); @@ -83,6 +88,7 @@ public async Task Restore([FromBody()] IDictionary options = nul public async Task HandleRequest() { string id = RecordingHandler.GetHeader(Request, "x-recording-id"); + DebugLogger.LogAdminRequestDetails(_logger, Request); await _recordingHandler.HandlePlaybackRequest(id, Request, Response); } diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Record.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Record.cs index b9de1d732f7..dec80453111 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Record.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Record.cs @@ -34,6 +34,7 @@ public async Task Start() if (body == null) { + DebugLogger.LogAdminRequestDetails(_logger, Request); await _recordingHandler.StartRecordingAsync(null, Response, null); } else @@ -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."); @@ -81,6 +85,8 @@ public void Stop([FromBody()] IDictionary variables = null) save = false; } + DebugLogger.LogAdminRequestDetails(_logger, Request); + _recordingHandler.StopRecording(id, variables: variables, saveRecording: save); } From af3aa198cc61834e6c41ed94cb40a829178df398 Mon Sep 17 00:00:00 2001 From: "Scott Beddall (from Dev Box)" Date: Fri, 6 Oct 2023 16:09:38 -0700 Subject: [PATCH 2/4] update logging tests --- .../LoggingTests.cs | 16 ++++++++-------- .../Properties/launchSettings.json | 4 +++- .../RecordingHandler.cs | 18 ++++++++++++++++++ 3 files changed, 29 insertions(+), 9 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 0cd4e10a407..28d50ab09cd 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); + AssertLogs(logger, 4, 8); } finally { @@ -92,7 +92,7 @@ public async Task RecordingHandlerLogsSanitizedRequests() try { - AssertLogs(logger); + AssertLogs(logger, 2, 8); } finally { @@ -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) diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Properties/launchSettings.json b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Properties/launchSettings.json index 77fea943f32..766ec103a6b 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Properties/launchSettings.json +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Properties/launchSettings.json @@ -2,9 +2,11 @@ "profiles": { "Azure.Sdk.Tools.TestProxy": { "commandName": "Project", + "commandLineArgs": "--storage-location=\"C:/repo/azure-sdk-for-java\"", "environmentVariables": { "ASPNETCORE_ENVIRONMENT": "Development", - "Logging__LogLevel__Microsoft": "Information" + "Logging__LogLevel__Microsoft": "Debug", + "Logging__LogLevel__Default": "Debug" }, "applicationUrl": "https://localhost:5001;http://localhost:5000" } diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs index f6272b4d7d3..f3e68e029b4 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs @@ -105,6 +105,10 @@ public RecordingHandler(string targetDirectory, IAssetsStore store = null, Store #region recording functionality public void StopRecording(string sessionId, IDictionary variables = null, bool saveRecording = true) { + + var id = Guid.NewGuid().ToString(); + DebugLogger.LogInformation($"RECORD STOP BEGIN {id}."); + if (!RecordingSessions.TryRemove(sessionId, out var recordingSession)) { return; @@ -149,6 +153,8 @@ public void StopRecording(string sessionId, IDictionary variable stream.Write(Encoding.UTF8.GetBytes(Environment.NewLine)); } } + + DebugLogger.LogInformation($"RECORD STOP END {id}."); } /// @@ -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.LogInformation($"RECORD START BEGIN {id}."); await RestoreAssetsJson(assetsJson, false); @@ -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.LogInformation($"RECORD START END {id}."); outgoingResponse.Headers.Add("x-recording-id", id); } @@ -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.LogInformation($"PLAYBACK START BEGIN {id}."); + ModifiableRecordSession session; if (mode == RecordingType.InMemory) @@ -402,10 +412,16 @@ public async Task StartPlaybackAsync(string sessionId, HttpResponse outgoingResp // Write to the response await outgoingResponse.WriteAsync(json); + + DebugLogger.LogInformation($"PLAYBACK START END {id}."); } public void StopPlayback(string recordingId, bool purgeMemoryStore = false) { + + var id = Guid.NewGuid().ToString(); + DebugLogger.LogInformation($"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}."); @@ -427,6 +443,8 @@ public void StopPlayback(string recordingId, bool purgeMemoryStore = false) GC.Collect(); } + + DebugLogger.LogInformation($"PLAYBACK STOP END {id}."); } public async Task HandlePlaybackRequest(string recordingId, HttpRequest incomingRequest, HttpResponse outgoingResponse) From ad11f59d6825f151571da812f0663e188bc2b552 Mon Sep 17 00:00:00 2001 From: "Scott Beddall (from Dev Box)" Date: Fri, 13 Oct 2023 16:19:10 -0700 Subject: [PATCH 3/4] Reverting launchSettings.json to get rid of accidentally added changes. Adding LogTrace to DebugLogger. Update start/stop messages to DebugLogger.LogTrace --- .../Azure.Sdk.Tools.TestProxy/Common/DebugLogger.cs | 12 ++++++++++++ .../test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs | 1 - .../Properties/launchSettings.json | 4 +--- .../Azure.Sdk.Tools.TestProxy/RecordingHandler.cs | 8 ++++---- 4 files changed, 17 insertions(+), 8 deletions(-) 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 25cd9e7a49e..a6f41f12a1e 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/DebugLogger.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/DebugLogger.cs @@ -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); + } + } + /// /// Simple access to the logging api. Accepts a simple message (preformatted) and logs to debug logger. /// diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs index 8c9cc1b6216..640af0eb14d 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs @@ -88,7 +88,6 @@ public async Task Restore([FromBody()] IDictionary options = nul public async Task HandleRequest() { string id = RecordingHandler.GetHeader(Request, "x-recording-id"); - DebugLogger.LogAdminRequestDetails(_logger, Request); await _recordingHandler.HandlePlaybackRequest(id, Request, Response); } diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Properties/launchSettings.json b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Properties/launchSettings.json index 766ec103a6b..77fea943f32 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Properties/launchSettings.json +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Properties/launchSettings.json @@ -2,11 +2,9 @@ "profiles": { "Azure.Sdk.Tools.TestProxy": { "commandName": "Project", - "commandLineArgs": "--storage-location=\"C:/repo/azure-sdk-for-java\"", "environmentVariables": { "ASPNETCORE_ENVIRONMENT": "Development", - "Logging__LogLevel__Microsoft": "Debug", - "Logging__LogLevel__Default": "Debug" + "Logging__LogLevel__Microsoft": "Information" }, "applicationUrl": "https://localhost:5001;http://localhost:5000" } diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs index f3e68e029b4..a612b9ea60b 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs @@ -107,7 +107,7 @@ public void StopRecording(string sessionId, IDictionary variable { var id = Guid.NewGuid().ToString(); - DebugLogger.LogInformation($"RECORD STOP BEGIN {id}."); + DebugLogger.LogTrace($"RECORD STOP BEGIN {id}."); if (!RecordingSessions.TryRemove(sessionId, out var recordingSession)) { @@ -154,7 +154,7 @@ public void StopRecording(string sessionId, IDictionary variable } } - DebugLogger.LogInformation($"RECORD STOP END {id}."); + DebugLogger.LogTrace($"RECORD STOP END {id}."); } /// @@ -368,7 +368,7 @@ 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.LogInformation($"PLAYBACK START BEGIN {id}."); + DebugLogger.LogTrace($"PLAYBACK START BEGIN {id}."); ModifiableRecordSession session; @@ -413,7 +413,7 @@ public async Task StartPlaybackAsync(string sessionId, HttpResponse outgoingResp // Write to the response await outgoingResponse.WriteAsync(json); - DebugLogger.LogInformation($"PLAYBACK START END {id}."); + DebugLogger.LogTrace($"PLAYBACK START END {id}."); } public void StopPlayback(string recordingId, bool purgeMemoryStore = false) From 20e39b3a22d384e59bc646b3e545f6f9dbaafeca Mon Sep 17 00:00:00 2001 From: "Scott Beddall (from Dev Box)" Date: Wed, 25 Oct 2023 11:13:44 -0700 Subject: [PATCH 4/4] ensure that all the logs in recordinghandler are propelery set to the TRACE level --- .../Azure.Sdk.Tools.TestProxy/RecordingHandler.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs index a612b9ea60b..0beb7fca889 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs @@ -174,7 +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.LogInformation($"RECORD START BEGIN {id}."); + DebugLogger.LogTrace($"RECORD START BEGIN {id}."); await RestoreAssetsJson(assetsJson, false); @@ -189,7 +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.LogInformation($"RECORD START END {id}."); + DebugLogger.LogTrace($"RECORD START END {id}."); outgoingResponse.Headers.Add("x-recording-id", id); } @@ -420,7 +420,7 @@ public void StopPlayback(string recordingId, bool purgeMemoryStore = false) { var id = Guid.NewGuid().ToString(); - DebugLogger.LogInformation($"PLAYBACK STOP BEGIN {id}."); + DebugLogger.LogTrace($"PLAYBACK STOP BEGIN {id}."); if (!PlaybackSessions.TryRemove(recordingId, out var session)) { @@ -444,7 +444,7 @@ public void StopPlayback(string recordingId, bool purgeMemoryStore = false) GC.Collect(); } - DebugLogger.LogInformation($"PLAYBACK STOP END {id}."); + DebugLogger.LogTrace($"PLAYBACK STOP END {id}."); } public async Task HandlePlaybackRequest(string recordingId, HttpRequest incomingRequest, HttpResponse outgoingResponse)