From 920afb2430633607839c7c882e2f660efca54152 Mon Sep 17 00:00:00 2001 From: Scott Beddall <45376673+scbedd@users.noreply.github.com> Date: Tue, 6 Aug 2024 08:29:25 -0700 Subject: [PATCH] Add proxy audit log and other assorted fixes (#8781) * Use a unified lock for all access to a recording. sanitizers or recording entries. * Creating an audit log so we can see raw associated information for important events about a specific recording. * obtain a lock before stopping playback, ensuring that ongoing writes in other threads won't be broken --------- Co-authored-by: semick-dev --- .../PlaybackTests.cs | 12 +- .../RecordSessionTests.cs | 6 + .../RecordingHandlerTests.cs | 4 +- .../TestHelpers.cs | 13 ++ .../Azure.Sdk.Tools.TestProxy/Admin.cs | 19 +-- .../Azure.Sdk.Tools.TestProxy/Audit.cs | 50 ++++++ .../Common/AuditLogItem.cs | 39 +++++ .../Common/DebugLogger.cs | 1 + .../Common/ModifiableRecordSession.cs | 12 +- .../Common/RecordSession.cs | 2 - .../Common/SanitizerDictionary.cs | 42 +++-- .../Azure.Sdk.Tools.TestProxy/Playback.cs | 4 +- .../Properties/launchSettings.json | 1 + .../RecordingHandler.cs | 158 ++++++++++++++++-- 14 files changed, 306 insertions(+), 57 deletions(-) create mode 100644 tools/test-proxy/Azure.Sdk.Tools.TestProxy/Audit.cs create mode 100644 tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/AuditLogItem.cs diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/PlaybackTests.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/PlaybackTests.cs index b4a68b67967..7b4c6a9094a 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/PlaybackTests.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/PlaybackTests.cs @@ -151,10 +151,16 @@ public async void TestStopPlaybackSimple() }; await controller.Start(); var targetRecordingId = httpContext.Response.Headers["x-recording-id"].ToString(); - + httpContext.Request.Headers["x-recording-id"] = new string[] { targetRecordingId }; - controller.Stop(); + await controller.Stop(); + + var auditSession = testRecordingHandler.AuditSessions[targetRecordingId]; + + Assert.NotNull(auditSession); + var auditResults = TestHelpers.ExhaustQueue(auditSession); + Assert.Equal(2, auditResults.Count); Assert.False(testRecordingHandler.PlaybackSessions.ContainsKey(targetRecordingId)); } @@ -189,7 +195,7 @@ public async void TestStopPlaybackInMemory() await playbackController.Start(); var targetRecordingId = playbackContext.Response.Headers["x-recording-id"].ToString(); playbackContext.Request.Headers["x-recording-id"] = new string[] { targetRecordingId }; - playbackController.Stop(); + await playbackController.Stop(); testRecordingHandler.InMemorySessions.ContainsKey(targetRecordingId); } diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/RecordSessionTests.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/RecordSessionTests.cs index c0f902dc12a..5a91981c648 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/RecordSessionTests.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/RecordSessionTests.cs @@ -165,6 +165,12 @@ public async Task CanRoundTripDockerDigest() session.Session.Entries.Add(testEntry); await handler.StopRecording(recordingId); + // ensure that we audited properly + var auditSession = handler.AuditSessions[recordingId]; + var auditItems = TestHelpers.ExhaustQueue(auditSession); + + Assert.Equal(2, auditItems.Count); + // now load it, did we avoid mangling it? var sessionFromDisk = TestHelpers.LoadRecordSession(Path.Combine(testFolder, testName)); var targetEntry = sessionFromDisk.Session.Entries[0]; diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/RecordingHandlerTests.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/RecordingHandlerTests.cs index 5edb697dea3..633a4a9786b 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/RecordingHandlerTests.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/RecordingHandlerTests.cs @@ -273,7 +273,7 @@ public async Task TestInMemoryPurgesSucessfully() await recordingHandler.StartPlaybackAsync(key, httpContext.Response, Common.RecordingType.InMemory); var playbackSession = httpContext.Response.Headers["x-recording-id"]; - recordingHandler.StopPlayback(playbackSession, true); + await recordingHandler.StopPlayback(playbackSession, true); Assert.True(0 == recordingHandler.InMemorySessions.Count); } @@ -287,7 +287,7 @@ public async Task TestInMemoryDoesntPurgeErroneously() await recordingHandler.StartPlaybackAsync(key, httpContext.Response, Common.RecordingType.InMemory); var playbackSession = httpContext.Response.Headers["x-recording-id"]; - recordingHandler.StopPlayback(playbackSession, false); + await recordingHandler.StopPlayback(playbackSession, false); Assert.True(1 == recordingHandler.InMemorySessions.Count); } diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/TestHelpers.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/TestHelpers.cs index 3fdf58d63bb..c8864a23c80 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/TestHelpers.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/TestHelpers.cs @@ -12,6 +12,7 @@ using Xunit; using System.Threading.Tasks; using System.Security.Cryptography; +using System.Collections.Concurrent; namespace Azure.Sdk.Tools.TestProxy.Tests { @@ -35,6 +36,18 @@ public static class TestHelpers { public static readonly string DisableBranchCleanupEnvVar = "DISABLE_INTEGRATION_BRANCH_CLEANUP"; + public static List ExhaustQueue(ConcurrentQueue queue) + { + List results = new List(); + + while (queue.TryDequeue(out var item)) + { + results.Add(item); + } + + return results; + } + public static string GetValueFromCertificateFile(string certName) { var path = Path.Join(Directory.GetCurrentDirectory(), "Test.Certificates", certName); diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Admin.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Admin.cs index 60c5874a454..c59f518e58e 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Admin.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Admin.cs @@ -158,22 +158,11 @@ public async Task AddSanitizers() throw new HttpException(HttpStatusCode.BadRequest, "When bulk adding sanitizers, ensure there is at least one sanitizer added in each batch. Received 0 work items."); } - var registeredSanitizers = new List(); + // we need check if a recording id is present BEFORE the loop, as we want to encapsulate the entire + // sanitizer add operation in a single lock, rather than gathering and releasing a sanitizer lock + // for the session/recording on _each_ sanitizer addition. - // register them all - foreach(var sanitizer in workload) - { - if (recordingId != null) - { - var registeredId = await _recordingHandler.RegisterSanitizer(sanitizer, recordingId); - registeredSanitizers.Add(registeredId); - } - else - { - var registeredId = await _recordingHandler.RegisterSanitizer(sanitizer); - registeredSanitizers.Add(registeredId); - } - } + var registeredSanitizers = await _recordingHandler.RegisterSanitizers(workload, recordingId); if (recordingId != null) { diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Audit.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Audit.cs new file mode 100644 index 00000000000..2245d7f213e --- /dev/null +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Audit.cs @@ -0,0 +1,50 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +using Azure.Sdk.Tools.TestProxy.Common; +using Azure.Sdk.Tools.TestProxy.Common.Exceptions; +using Azure.Sdk.Tools.TestProxy.Store; +using Microsoft.AspNetCore.Http; +using Microsoft.AspNetCore.Mvc; +using Microsoft.Extensions.Logging; +using System; +using System.Collections.Generic; +using System.Net; +using System.Text; +using System.Threading.Tasks; + +namespace Azure.Sdk.Tools.TestProxy +{ + [ApiController] + [Route("[controller]/[action]")] + public sealed class Audit : ControllerBase + { + private readonly RecordingHandler _recordingHandler; + + public Audit(RecordingHandler recordingHandler) + { + _recordingHandler = recordingHandler; + } + + [HttpGet] + public async Task Logs() + { + + var allAuditSessions = _recordingHandler.RetrieveOngoingAuditLogs(); + allAuditSessions.AddRange(_recordingHandler.AuditSessions.Values); + + StringBuilder stringBuilder = new StringBuilder(); + + foreach (var auditLogQueue in allAuditSessions) { + while (auditLogQueue.TryDequeue(out var logItem)) + { + stringBuilder.Append(logItem.ToCsvString() + Environment.NewLine); + } + } + + Response.ContentType = "text/plain"; + + await Response.WriteAsync(stringBuilder.ToString()); + } + } +} diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/AuditLogItem.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/AuditLogItem.cs new file mode 100644 index 00000000000..f737312221d --- /dev/null +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/AuditLogItem.cs @@ -0,0 +1,39 @@ +using System; + +namespace Azure.Sdk.Tools.TestProxy.Common +{ + public class AuditLogItem + { + public string RecordingId { get; set; } + + public DateTime Timestamp { get; set; } + + public string Uri { get; set; } + + public string Verb { get; set; } + + public string Message { get; set; } + + public AuditLogItem(string recordingId, string requestUri, string requestMethod) { + RecordingId = recordingId; + Timestamp = DateTime.UtcNow; + + Uri = requestUri; + Verb = requestMethod; + } + + public string ToCsvString() + { + return $"{RecordingId},{Timestamp.ToString("o")},{Verb},{Uri},{Message}"; + } + + public AuditLogItem(string recordingId, string message) + { + RecordingId = recordingId; + Timestamp = DateTime.UtcNow; + + Message = message; + } + + } +} 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 a6f41f12a1e..b80a7ed0bf5 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/DebugLogger.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/DebugLogger.cs @@ -5,6 +5,7 @@ using System.Collections.Generic; using System.Text.Json; using Microsoft.AspNetCore.Http.Extensions; +using System.Collections.Concurrent; namespace Azure.Sdk.Tools.TestProxy.Common { diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/ModifiableRecordSession.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/ModifiableRecordSession.cs index 1be776abde9..61154cd8847 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/ModifiableRecordSession.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/ModifiableRecordSession.cs @@ -1,4 +1,5 @@ using System; +using System.Collections.Concurrent; using System.Collections.Generic; using System.Linq; using System.Net.Http; @@ -9,13 +10,13 @@ namespace Azure.Sdk.Tools.TestProxy.Common { public class ModifiableRecordSession { - public RecordMatcher CustomMatcher { get; set;} + public RecordMatcher CustomMatcher { get; set; } public RecordSession Session { get; } public ModifiableRecordSession(SanitizerDictionary sanitizerRegistry, string sessionId) { - lock(sanitizerRegistry.SessionSanitizerLock) + lock (sanitizerRegistry.SessionSanitizerLock) { this.AppliedSanitizers = sanitizerRegistry.SessionSanitizers.ToList(); } @@ -42,8 +43,6 @@ public ModifiableRecordSession(RecordSession session, SanitizerDictionary saniti public List AdditionalTransforms { get; } = new List(); - public SemaphoreSlim SanitizerLock = new SemaphoreSlim(1); - public List AppliedSanitizers { get; set; } = new List(); public List ForRemoval { get; } = new List(); @@ -51,9 +50,10 @@ public ModifiableRecordSession(RecordSession session, SanitizerDictionary saniti public int PlaybackResponseTime { get; set; } + public ConcurrentQueue AuditLog { get; set; } = new ConcurrentQueue(); public async void ResetExtensions(SanitizerDictionary sanitizerDictionary) { - await SanitizerLock.WaitAsync(); + await Session.EntryLock.WaitAsync(); try { AdditionalTransforms.Clear(); @@ -66,7 +66,7 @@ public async void ResetExtensions(SanitizerDictionary sanitizerDictionary) } finally { - SanitizerLock.Release(); + Session.EntryLock.Release(); } } } 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 e7ef8fa41cc..a104e4083ce 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordSession.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/RecordSession.cs @@ -3,8 +3,6 @@ using System; using System.Collections.Generic; -using System.IO; -using System.Linq; using System.Text.Json; using System.Threading; using System.Threading.Tasks; 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 792ebce87c1..706dfb742e0 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/SanitizerDictionary.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/SanitizerDictionary.cs @@ -2,7 +2,6 @@ using System.Collections.Generic; using System.Linq; using System.Text.Json; -using System.Text.RegularExpressions; using System.Threading; using System.Threading.Tasks; using Azure.Sdk.Tools.TestProxy.Common.Exceptions; @@ -749,7 +748,7 @@ public async Task> GetSanitizers() /// public async Task> GetRegisteredSanitizers(ModifiableRecordSession session) { - await session.SanitizerLock.WaitAsync(); + await session.Session.EntryLock.WaitAsync(); try { var sanitizers = new List(); @@ -770,7 +769,7 @@ public async Task> GetRegisteredSanitizers(ModifiableR } finally { - session.SanitizerLock.Release(); + session.Session.EntryLock.Release(); } } @@ -816,14 +815,19 @@ private bool _register(RecordedTestSanitizer sanitizer, string id) /// /// Ensuring that session level sanitizers can be identified internally /// - /// + /// The sanitizer being registered + /// /// The Id of the newly registered sanitizer. /// - public async Task Register(RecordedTestSanitizer sanitizer) + public async Task Register(RecordedTestSanitizer sanitizer, bool shouldLock = true) { var strCurrent = IdFactory.GetNextId().ToString(); - await SessionSanitizerLock.WaitAsync(); + if (shouldLock) + { + await SessionSanitizerLock.WaitAsync(); + } + try { if (_register(sanitizer, strCurrent)) @@ -834,7 +838,10 @@ public async Task Register(RecordedTestSanitizer sanitizer) } finally { - SessionSanitizerLock.Release(); + if (shouldLock) + { + SessionSanitizerLock.Release(); + } } throw new HttpException(System.Net.HttpStatusCode.InternalServerError, $"Unable to register global sanitizer id \"{strCurrent}\" with value '{JsonSerializer.Serialize(sanitizer)}'"); } @@ -844,13 +851,19 @@ public async Task Register(RecordedTestSanitizer sanitizer) /// /// /// + /// /// The Id of the newly registered sanitizer. /// - public async Task Register(ModifiableRecordSession session, RecordedTestSanitizer sanitizer) + public async Task Register(ModifiableRecordSession session, RecordedTestSanitizer sanitizer, bool shouldLock = true) { var strCurrent = IdFactory.GetNextId().ToString(); - await SessionSanitizerLock.WaitAsync(); + session.AuditLog.Enqueue(new AuditLogItem(session.SessionId, $"Starting registration of sanitizerId {strCurrent}")); + + if(shouldLock) + { + await session.Session.EntryLock.WaitAsync(); + } try { @@ -864,9 +877,13 @@ public async Task Register(ModifiableRecordSession session, RecordedTest } finally { - SessionSanitizerLock.Release(); + if (shouldLock) + { + session.Session.EntryLock.Release(); + } } + session.AuditLog.Enqueue(new AuditLogItem(session.SessionId, $"Finished registration of sanitizerId {strCurrent}")); return string.Empty; } @@ -904,7 +921,7 @@ public async Task Unregister(string sanitizerId) /// public async Task Unregister(string sanitizerId, ModifiableRecordSession session) { - await session.SanitizerLock.WaitAsync(); + await session.Session.EntryLock.WaitAsync(); try { if (session.AppliedSanitizers.Contains(sanitizerId)) @@ -915,8 +932,9 @@ public async Task Unregister(string sanitizerId, ModifiableRecordSession } finally { - session.SanitizerLock.Release(); + session.Session.EntryLock.Release(); } + session.AuditLog.Enqueue(new AuditLogItem(session.SessionId, $"Starting unregister of {sanitizerId}.")); return string.Empty; } diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs index 640af0eb14d..df97f51ec80 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs @@ -55,14 +55,14 @@ public async Task Start() } [HttpPost] - public void Stop() + public async Task 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); - _recordingHandler.StopPlayback(id, purgeMemoryStore: shouldPurgeRecording); + await _recordingHandler.StopPlayback(id, purgeMemoryStore: shouldPurgeRecording); } [HttpPost] 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..964f0eaddb3 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Properties/launchSettings.json +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/Properties/launchSettings.json @@ -2,6 +2,7 @@ "profiles": { "Azure.Sdk.Tools.TestProxy": { "commandName": "Project", + "commandLineArgs": "", "environmentVariables": { "ASPNETCORE_ENVIRONMENT": "Development", "Logging__LogLevel__Microsoft": "Information" diff --git a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs index 59f540977da..e6dc2eb4b9e 100644 --- a/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs +++ b/tools/test-proxy/Azure.Sdk.Tools.TestProxy/RecordingHandler.cs @@ -20,6 +20,7 @@ using System.Text.Json; using System.Threading; using System.Threading.Tasks; +using static System.Collections.Specialized.BitVector32; namespace Azure.Sdk.Tools.TestProxy { @@ -81,6 +82,47 @@ public readonly ConcurrentDictionary InMemorySe public readonly ConcurrentDictionary PlaybackSessions = new ConcurrentDictionary(); + public readonly ConcurrentDictionary> AuditSessions + = new ConcurrentDictionary>(); + + + /// + /// This exists to grab any sessions that might be ongoing. I don't have any evidence that sessions are being left behind, but + /// we have to have this to be certain! + /// + /// + public List> RetrieveOngoingAuditLogs() + { + List> results = new List>(); + + if (PlaybackSessions.Keys.Any()) + { + foreach(var value in PlaybackSessions.Values) + { + results.Add(value.AuditLog); + } + } + + if (RecordingSessions.Keys.Any()) + { + foreach (var value in RecordingSessions.Values) + { + results.Add(value.AuditLog); + } + } + + if (InMemorySessions.Keys.Any()) + { + foreach (var value in InMemorySessions.Values) + { + results.Add(value.AuditLog); + } + } + + return results; + } + + public RecordingHandler(string targetDirectory, IAssetsStore store = null, StoreResolver storeResolver = null) { ContextDirectory = targetDirectory; @@ -113,6 +155,12 @@ public async Task StopRecording(string sessionId, IDictionary va return; } + recordingSession.AuditLog.Enqueue(new AuditLogItem(sessionId, $"Stopping recording for {sessionId}.")); + if (!AuditSessions.TryAdd(sessionId, recordingSession.AuditLog)) + { + DebugLogger.LogError($"Unable to save audit log for {sessionId}"); + } + var sanitizers = await SanitizerRegistry.GetSanitizers(recordingSession); await recordingSession.Session.Sanitize(sanitizers); @@ -172,6 +220,7 @@ public async Task StartRecordingAsync(string sessionId, HttpResponse outgoingRes { var id = Guid.NewGuid().ToString(); DebugLogger.LogTrace($"RECORD START BEGIN {id}."); + var auditEntry = new AuditLogItem(id, $"Starting record for path {sessionId}, which will return recordingId {id}."); await RestoreAssetsJson(assetsJson, false); @@ -181,11 +230,14 @@ public async Task StartRecordingAsync(string sessionId, HttpResponse outgoingRes Client = null }; + session.AuditLog.Enqueue(auditEntry); + if (!RecordingSessions.TryAdd(id, session)) { 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); } @@ -197,6 +249,9 @@ public async Task HandleRecordRequestAsync(string recordingId, HttpRequest incom throw new HttpException(HttpStatusCode.BadRequest, $"There is no active recording session under id {recordingId}."); } + RecordEntry noBodyEntry = RecordingHandler.CreateNoBodyRecordEntry(incomingRequest); + session.AuditLog.Enqueue(new AuditLogItem(recordingId, noBodyEntry.RequestUri, noBodyEntry.RequestMethod.ToString())); + var sanitizers = await SanitizerRegistry.GetSanitizers(session); DebugLogger.LogRequestDetails(incomingRequest, sanitizers); @@ -250,8 +305,9 @@ public async Task HandleRecordRequestAsync(string recordingId, HttpRequest incom if (mode != EntryRecordMode.DontRecord) { await session.Session.EntryLock.WaitAsync(); - try + try { + session.AuditLog.Enqueue(new AuditLogItem(recordingId, $"Lock obtained. Adding entry {entry.RequestMethod} {entry.RequestUri} to session {recordingId}.")); session.Session.Entries.Add(entry); } finally @@ -259,6 +315,7 @@ public async Task HandleRecordRequestAsync(string recordingId, HttpRequest incom session.Session.EntryLock.Release(); } + Interlocked.Increment(ref Startup.RequestsRecorded); } @@ -373,6 +430,7 @@ public async Task StartPlaybackAsync(string sessionId, HttpResponse outgoingResp DebugLogger.LogTrace($"PLAYBACK START BEGIN {id}."); ModifiableRecordSession session = new ModifiableRecordSession(SanitizerRegistry, id); + var auditEntry = new AuditLogItem(id, $"Starting playback for path {sessionId}, which will return recordingId {id}."); if (mode == RecordingType.InMemory) { @@ -399,6 +457,7 @@ public async Task StartPlaybackAsync(string sessionId, HttpResponse outgoingResp { Path = path }; + session.AuditLog.Enqueue(auditEntry); } if (!PlaybackSessions.TryAdd(id, session)) @@ -418,35 +477,53 @@ public async Task StartPlaybackAsync(string sessionId, HttpResponse outgoingResp DebugLogger.LogTrace($"PLAYBACK START END {id}."); } - public void StopPlayback(string recordingId, bool purgeMemoryStore = false) + public async Task StopPlayback(string recordingId, bool purgeMemoryStore = false) { var id = Guid.NewGuid().ToString(); DebugLogger.LogTrace($"PLAYBACK STOP BEGIN {id}."); - if (!PlaybackSessions.TryRemove(recordingId, out var session)) + + // obtain the playbacksession so we can get grab a lock on it. if there is a streaming response we will HAVE TO WAIT for that to complete + // before we finish + if (!PlaybackSessions.TryGetValue(recordingId, out var session)) { throw new HttpException(HttpStatusCode.BadRequest, $"There is no active playback session under recording id {recordingId}."); } - if (!String.IsNullOrEmpty(session.SourceRecordingId) && purgeMemoryStore) + await session.Session.EntryLock.WaitAsync(); + + try { - if (!InMemorySessions.TryGetValue(session.SourceRecordingId, out var inMemorySession)) + if (!PlaybackSessions.TryRemove(recordingId, out var removedSession)) { - throw new HttpException(HttpStatusCode.InternalServerError, $"Unexpectedly failed to retrieve in-memory session {session.SourceRecordingId}."); + throw new HttpException(HttpStatusCode.BadRequest, $"There is no active playback session under recording id {recordingId}."); } + session.AuditLog.Enqueue(new AuditLogItem(recordingId, $"Lock obtained, stopping playback for {recordingId}.")); - Interlocked.Add(ref Startup.RequestsRecorded, -1 * inMemorySession.Session.Entries.Count); + if (!AuditSessions.TryAdd(recordingId, session.AuditLog)) + { + DebugLogger.LogError($"Unable to save audit log for {recordingId}"); + } - if (!InMemorySessions.TryRemove(session.SourceRecordingId, out _)) + if (!String.IsNullOrEmpty(session.SourceRecordingId) && purgeMemoryStore) { - throw new HttpException(HttpStatusCode.InternalServerError, $"Unexpectedly failed to remove in-memory session {session.SourceRecordingId}."); + if (!InMemorySessions.TryRemove(session.SourceRecordingId, out var inMemorySession)) + { + throw new HttpException(HttpStatusCode.InternalServerError, $"Unexpectedly failed to remove in-memory session {session.SourceRecordingId}."); + } + + Interlocked.Add(ref Startup.RequestsRecorded, -1 * inMemorySession.Session.Entries.Count); + + GC.Collect(); } - GC.Collect(); + DebugLogger.LogTrace($"PLAYBACK STOP END {id}."); + } + finally + { + session.Session.EntryLock.Release(); } - - DebugLogger.LogTrace($"PLAYBACK STOP END {id}."); } public async Task HandlePlaybackRequest(string recordingId, HttpRequest incomingRequest, HttpResponse outgoingResponse) @@ -455,24 +532,29 @@ public async Task HandlePlaybackRequest(string recordingId, HttpRequest incoming { throw new HttpException(HttpStatusCode.BadRequest, $"There is no active playback session under recording id {recordingId}."); } + + RecordEntry noBodyEntry = RecordingHandler.CreateNoBodyRecordEntry(incomingRequest); + session.AuditLog.Enqueue(new AuditLogItem(recordingId, noBodyEntry.RequestUri, noBodyEntry.RequestMethod.ToString())); var sanitizers = await SanitizerRegistry.GetSanitizers(session); if (!session.IsSanitized) { // we don't need to re-sanitize with recording-applicable sanitizers every time. just the very first one - await session.SanitizerLock.WaitAsync(); + await session.Session.EntryLock.WaitAsync(); try { if (!session.IsSanitized) { + session.AuditLog.Enqueue(new AuditLogItem(recordingId, $"In 'one-time' sanitization for {recordingId}. I am applying {sanitizers.Count} sanitizers.")); await session.Session.Sanitize(sanitizers, false); session.IsSanitized = true; } } finally { - session.SanitizerLock.Release(); + session.Session.EntryLock.Release(); + session.AuditLog.Enqueue(new AuditLogItem(recordingId, $"Finished 'one-time' sanitization for {recordingId}. I applied {sanitizers.Count} sanitizers.")); } } @@ -508,7 +590,7 @@ public async Task HandlePlaybackRequest(string recordingId, HttpRequest incoming { outgoingResponse.ContentLength = bodyData.Length; } - + session.AuditLog.Enqueue(new AuditLogItem(recordingId, $"Beginning body write for {recordingId}.")); await WriteBodyBytes(bodyData, session.PlaybackResponseTime, outgoingResponse); } @@ -526,6 +608,7 @@ public async Task HandlePlaybackRequest(string recordingId, HttpRequest incoming if (remove) { + session.AuditLog.Enqueue(new AuditLogItem(recordingId, $"Now popping entry {entry.RequestMethod} {match.RequestUri} from entries for {recordingId}.")); await session.Session.Remove(match, shouldLock: false); } } @@ -931,18 +1014,63 @@ public async Task UnregisterSanitizer(string sanitizerId, string recordi if (!string.IsNullOrWhiteSpace(recordingId)) { var session = GetActiveSession(recordingId); + + session.AuditLog.Enqueue(new AuditLogItem(recordingId, $"Starting unregister of {sanitizerId}.")); + return await SanitizerRegistry.Unregister(sanitizerId, session); } return await SanitizerRegistry.Unregister(sanitizerId); } + + public async Task> RegisterSanitizers(List sanitizers, string recordingId = null) + { + var registrations = new List(); + + if (!string.IsNullOrWhiteSpace(recordingId)) + { + var session = GetActiveSession(recordingId); + + await session.Session.EntryLock.WaitAsync(); + try + { + foreach (var sanitizer in sanitizers) + { + session.AuditLog.Enqueue(new AuditLogItem(recordingId, $"Starting registration of sanitizer {sanitizer.GetType()}")); + await SanitizerRegistry.Register(session, sanitizer, shouldLock: false); + } + } + finally + { + session.Session.EntryLock.Release(); + } + } + else + { + await SanitizerRegistry.SessionSanitizerLock.WaitAsync(); + try { + foreach (var sanitizer in sanitizers) + { + registrations.Add(await SanitizerRegistry.Register(sanitizer, shouldLock: false)); + } + } + finally + { + SanitizerRegistry.SessionSanitizerLock.Release(); + } + } + + return registrations; + } + public async Task RegisterSanitizer(RecordedTestSanitizer sanitizer, string recordingId = null) { if (!string.IsNullOrWhiteSpace(recordingId)) { var session = GetActiveSession(recordingId); + session.AuditLog.Enqueue(new AuditLogItem(recordingId, $"Starting registration of sanitizer {sanitizer.GetType()}")); return await SanitizerRegistry.Register(session, sanitizer); }