Sanitize requests when logging

tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/Directory.Build.targets

@@ -0,0 +1,9 @@
+<Project ToolsVersion="15.0" xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
+  <Import Project="$([MSBuild]::GetDirectoryNameOfFileAbove($(MSBuildThisFileDirectory).., Directory.Build.targets))\Directory.Build.targets" />
+  <PropertyGroup>
+    <!-- Sign the test assembly so that we can use Internals Visible To for it-->
+    <SignAssembly>true</SignAssembly>
+    <DelaySign>false</DelaySign>
+    <AssemblyOriginatorKeyFile>$(RepoEngPath)\AzureSDKToolsKey.snk</AssemblyOriginatorKeyFile>
+  </PropertyGroup>
+</Project>

tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs

@@ -0,0 +1,115 @@
+using System.IO;
+using System.Net.Http;
+using System.Text;
+using System.Threading.Tasks;
+using Azure.Sdk.Tools.TestProxy.Common;
+using Microsoft.AspNetCore.Http;
+using Microsoft.AspNetCore.Mvc;
+using Microsoft.Extensions.Logging.Abstractions;
+using Xunit;
+
+namespace Azure.Sdk.Tools.TestProxy.Tests
+{
+    /// <summary>
+    /// Logging tests cannot be run in parallel with other tests because they share a static logger.
+    /// </summary>
+    [Collection(nameof(LoggingCollection))]
+    public class LoggingTests
+    {
+        [Fact]
+        public async Task PlaybackLogsSanitizedRequest()
+        {
+            var logger = new TestLogger();
+            DebugLogger.Logger = logger;
+
+            try
+            {
+                RecordingHandler testRecordingHandler = new RecordingHandler(Directory.GetCurrentDirectory());
+                var httpContext = new DefaultHttpContext();
+                var body = "{\"x-recording-file\":\"Test.RecordEntries/request_with_binary_content.json\"}";
+                httpContext.Request.Body = TestHelpers.GenerateStreamRequestBody(body);
+                httpContext.Request.ContentLength = body.Length;
+
+                var controller = new Playback(testRecordingHandler, new NullLoggerFactory())
+                {
+                    ControllerContext = new ControllerContext()
+                    {
+                        HttpContext = httpContext
+                    }
+                };
+                await controller.Start();
+
+                var recordingId = httpContext.Response.Headers["x-recording-id"].ToString();
+                Assert.NotNull(recordingId);
+                Assert.True(testRecordingHandler.PlaybackSessions.ContainsKey(recordingId));
+                var entry = testRecordingHandler.PlaybackSessions[recordingId].Session.Entries[0];
+                HttpRequest request = TestHelpers.CreateRequestFromEntry(entry);
+                request.Headers["Authorization"] = "fake-auth-header";
+
+                HttpResponse response = new DefaultHttpContext().Response;
+                await testRecordingHandler.HandlePlaybackRequest(recordingId, request, response);
+
+                Assert.Single(logger.Logs);
+                var logEntry = logger.Logs[0].ToString();
+                Assert.DoesNotContain(@"""Authorization"":[""fake-auth-header""]", logEntry);
+                Assert.Contains(@"""Authorization"":[""Sanitized""]", logEntry);
+            }
+            finally
+            {
+                DebugLogger.Logger = null;
+            }
+        }
+
+        [Fact]
+        public async Task RecordingHandlerLogsSanitizedRequests()
+        {
+            var logger = new TestLogger();
+            DebugLogger.Logger = logger;
+            var httpContext = new DefaultHttpContext();
+            var bodyBytes = Encoding.UTF8.GetBytes("{\"hello\":\"world\"}");
+            var mockClient = new HttpClient(new MockHttpHandler(bodyBytes, "application/json"));
+            var path = Directory.GetCurrentDirectory();
+            var recordingHandler = new RecordingHandler(path)
+            {
+                RedirectableClient = mockClient,
+                RedirectlessClient = mockClient
+            };
+
+            var relativePath = "recordings/logs";
+            var fullPathToRecording = Path.Combine(path, relativePath) + ".json";
+
+            await recordingHandler.StartRecordingAsync(relativePath, httpContext.Response);
+
+            var recordingId = httpContext.Response.Headers["x-recording-id"].ToString();
+
+            httpContext.Request.ContentType = "application/json";
+            httpContext.Request.Headers["Authorization"] = "fake-auth-header";
+            httpContext.Request.ContentLength = 0;
+            httpContext.Request.Headers["x-recording-id"] = recordingId;
+            httpContext.Request.Headers["x-recording-upstream-base-uri"] = "http://example.org";
+            httpContext.Request.Method = "GET";
+            httpContext.Request.Body = new MemoryStream(CompressionUtilities.CompressBody(bodyBytes, httpContext.Request.Headers));
+
+            await recordingHandler.HandleRecordRequestAsync(recordingId, httpContext.Request, httpContext.Response);
+            recordingHandler.StopRecording(recordingId);
+
+            try
+            {
+                Assert.Single(logger.Logs);
+                var logEntry = logger.Logs[0].ToString();
+                Assert.DoesNotContain(@"""Authorization"":[""fake-auth-header""]", logEntry);
+                Assert.Contains(@"""Authorization"":[""Sanitized""]", logEntry);
+            }
+            finally
+            {
+                File.Delete(fullPathToRecording);
+                DebugLogger.Logger = null;
+            }
+        }
+    }
+
+    [CollectionDefinition(nameof(LoggingCollection), DisableParallelization = true)]
+    public class LoggingCollection
+    {
+    }
+}

tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/TestLogger.cs

@@ -0,0 +1,27 @@
+using System;
+using System.Collections.Generic;
+using Microsoft.Extensions.Logging;
+
+namespace Azure.Sdk.Tools.TestProxy.Tests
+{
+    public class TestLogger : ILogger
+    {
+        internal List<object> Logs { get; }= new List<object>();
+
+        public IDisposable BeginScope<TState>(TState state)
+        {
+            throw new NotImplementedException();
+        }
+
+        public bool IsEnabled(LogLevel logLevel)
+        {
+            return true;
+        }
+
+        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception,
+            Func<TState, Exception, string> formatter)
+        {
+            Logs.Add(state);
+        }
+    }
+}

tools/test-proxy/Azure.Sdk.Tools.TestProxy/Admin.cs

@@ -28,25 +28,25 @@ public Admin(RecordingHandler recordingHandler, ILoggerFactory loggingFactory)
         }
 
         [HttpPost]
-        public async Task Reset()
+        public void Reset()
         {
-            await DebugLogger.LogRequestDetailsAsync(_logger, Request);
+            DebugLogger.LogRequestDetails(_logger, Request);
             var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true);
 
             _recordingHandler.SetDefaultExtensions(recordingId);
         }
 
         [HttpGet]
-        public async Task IsAlive()
+        public void IsAlive()
         {
-            await DebugLogger.LogRequestDetailsAsync(_logger, Request);
+            DebugLogger.LogRequestDetails(_logger, Request);
             Response.StatusCode = 200;
         }
 
         [HttpPost]
         public async Task AddTransform()
         {
-            await DebugLogger.LogRequestDetailsAsync(_logger, Request);
+            DebugLogger.LogRequestDetails(_logger, Request);
             var tName = RecordingHandler.GetHeader(Request, "x-abstraction-identifier");
             var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true);
 
@@ -65,7 +65,7 @@ public async Task AddTransform()
         [HttpPost]
         public async Task AddSanitizer()
         {
-            await DebugLogger.LogRequestDetailsAsync(_logger, Request);
+            DebugLogger.LogRequestDetails(_logger, Request);
             var sName = RecordingHandler.GetHeader(Request, "x-abstraction-identifier");
             var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true);
 
@@ -84,7 +84,7 @@ public async Task AddSanitizer()
         [HttpPost]
         public async Task SetMatcher()
         {
-            await DebugLogger.LogRequestDetailsAsync(_logger, Request);
+            DebugLogger.LogRequestDetails(_logger, Request);
             var mName = RecordingHandler.GetHeader(Request, "x-abstraction-identifier");
             var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true);
 
@@ -102,9 +102,9 @@ public async Task SetMatcher()
 
         [HttpPost]
         [AllowEmptyBody]
-        public async Task SetRecordingOptions([FromBody()] IDictionary<string, object> options = null)
+        public void SetRecordingOptions([FromBody()] IDictionary<string, object> options = null)
         {
-            await DebugLogger.LogRequestDetailsAsync(_logger, Request);
+            DebugLogger.LogRequestDetails(_logger, Request);
 
             var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true);
 

tools/test-proxy/Azure.Sdk.Tools.TestProxy/Common/DebugLogger.cs

@@ -4,6 +4,7 @@
 using System.Text;
 using System.IO;
 using System;
+using System.Collections.Generic;
 using System.Diagnostics;
 using System.Text.Json;
 using Microsoft.AspNetCore.Http.Extensions;
@@ -32,13 +33,14 @@ namespace Azure.Sdk.Tools.TestProxy.Common
     /// </summary>
     public static class DebugLogger
     {
-        private static ILogger logger = null;
+        // internal for testing
+        internal static ILogger Logger { get; set; }
 
         public static void ConfigureLogger(ILoggerFactory factory)
         {
-            if (logger == null && factory != null)
+            if (Logger == null && factory != null)
             {
-                logger = factory.CreateLogger("DebugLogging");
+                Logger = factory.CreateLogger("DebugLogging");
             }
         }
 
@@ -50,7 +52,7 @@ public static void ConfigureLogger(ILoggerFactory factory)
         /// <returns></returns>
         public static bool CheckLogLevel(LogLevel level)
         {
-            var result = logger?.IsEnabled(LogLevel.Debug);
+            var result = Logger?.IsEnabled(LogLevel.Debug);
 
             if (result.HasValue)
             {
@@ -68,9 +70,9 @@ public static bool CheckLogLevel(LogLevel level)
         /// <param name="details">The content which should be logged.</param>
         public static void LogInformation(string details)
         {
-            if (null != logger)
+            if (null != Logger)
             {
-                logger.LogInformation(details);
+                Logger.LogInformation(details);
             }
             else
             {
@@ -80,9 +82,9 @@ public static void LogInformation(string details)
 
         public static void LogError(string details)
         {
-            if (null != logger)
+            if (null != Logger)
             {
-                logger.LogError(details);
+                Logger.LogError(details);
             }
             else
             {
@@ -93,9 +95,9 @@ public static void LogError(string details)
         public static void LogError(int statusCode, Exception e)
         {
             var details = statusCode.ToString() + Environment.NewLine + e.Message + Environment.NewLine + e.StackTrace;
-            if (null != logger)
+            if (null != Logger)
             {
-                logger.LogError(details);
+                Logger.LogError(details);
             }
             else
             {
@@ -109,9 +111,9 @@ public static void LogError(int statusCode, Exception e)
         /// <param name="details">The content which should be logged.</param>
         public static void LogDebug(string details)
         {
-            if (logger != null)
+            if (Logger != null)
             {
-                logger.LogDebug(details);
+                Logger.LogDebug(details);
             }
             else
             {
@@ -151,11 +153,11 @@ public static void LogDebug(string details)
         /// <param name="loggerInstance">Usually will be the DI-ed individual ILogger instance from a controller. However any valid ILogger instance is fine here.</param>
         /// <param name="req">The http request which needs to be detailed.</param>
         /// <returns></returns>
-        public static async Task LogRequestDetailsAsync(ILogger loggerInstance, HttpRequest req)
+        public static void LogRequestDetails(ILogger loggerInstance, HttpRequest req)
         {
             if(CheckLogLevel(LogLevel.Debug))
             {
-                loggerInstance.LogDebug(await _generateLogLine(req));
+                loggerInstance.LogDebug(_generateLogLine(req, null));
             }
         }
 
@@ -164,33 +166,40 @@ public static async Task LogRequestDetailsAsync(ILogger loggerInstance, HttpRequ
         /// actually logging anything, this function is entirely passthrough.
         /// </summary>
         /// <param name="req">The http request which needs to be detailed.</param>
-        /// <returns></returns>
-        public static async Task LogRequestDetailsAsync(HttpRequest req)
+        /// <param name="sanitizers">The set of sanitizers to apply before logging.</param>
+        /// <returns>The log line.</returns>
+        public static void LogRequestDetails(HttpRequest req, IEnumerable<RecordedTestSanitizer> sanitizers)
         {
             if (CheckLogLevel(LogLevel.Debug))
             {
-                logger.LogDebug(await _generateLogLine(req));
+                Logger.LogDebug(_generateLogLine(req, sanitizers));
             }
         }
 
         /// <summary>
         /// Generate a line of data from an http request. This is non-destructive, which means it does not mess 
         /// with the request Body stream at all.
         /// </summary>
-        /// <param name="req"></param>
-        /// <returns></returns>
-        private static async Task<string> _generateLogLine(HttpRequest req)
+        /// <param name="req">The request</param>
+        /// <param name="sanitizers">The set of sanitizers to apply before logging.</param>
+        /// <returns>The log line.</returns>
+        private static string _generateLogLine(HttpRequest req, IEnumerable<RecordedTestSanitizer> sanitizers)
         {
-            StringBuilder sb = new StringBuilder();
-            string headers = string.Empty;
+            RecordEntry entry = RecordingHandler.CreateNoBodyRecordEntry(req);
 
-            using (MemoryStream ms = new MemoryStream())
+            if (sanitizers != null)
             {
-                await JsonSerializer.SerializeAsync(ms, req.Headers);
-                headers = Encoding.UTF8.GetString(ms.ToArray());
+                foreach (var sanitizer in sanitizers)
+                {
+                    sanitizer.Sanitize(entry);
+                }
             }
 
-            sb.AppendLine("URI: [ " + req.GetDisplayUrl() + "]");
+            var headers = Encoding.UTF8.GetString(JsonSerializer.SerializeToUtf8Bytes(entry.Request.Headers));
+
+            StringBuilder sb = new StringBuilder();
+
+            sb.AppendLine("URI: [ " + entry.RequestUri + "]");
             sb.AppendLine("Headers: [" + headers + "]");
 
             return sb.ToString();

tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs

@@ -63,7 +63,7 @@ public void Stop()
         [HttpPost]
         public async Task Reset([FromBody()] IDictionary<string, object> options = null)
         {
-            await DebugLogger.LogRequestDetailsAsync(_logger, Request);
+            DebugLogger.LogRequestDetails(_logger, Request);
 
             var pathToAssets = RecordingHandler.GetAssetsJsonLocation(StoreResolver.ParseAssetsJsonBody(options), _recordingHandler.ContextDirectory);
 
@@ -73,7 +73,7 @@ public async Task Reset([FromBody()] IDictionary<string, object> options = null)
         [HttpPost]
         public async Task Restore([FromBody()] IDictionary<string, object> options = null)
         {
-            await DebugLogger.LogRequestDetailsAsync(_logger, Request);
+            DebugLogger.LogRequestDetails(_logger, Request);
 
             var pathToAssets = RecordingHandler.GetAssetsJsonLocation(StoreResolver.ParseAssetsJsonBody(options), _recordingHandler.ContextDirectory);
 

tools/test-proxy/Azure.Sdk.Tools.TestProxy/Properties/AssemblyInfo.cs

@@ -0,0 +1,7 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+using System.Runtime.CompilerServices;
+
+[assembly: InternalsVisibleTo("Azure.Sdk.Tools.TestProxy.Tests, PublicKey=0024000004800000940000000602000000240000525341310004000001000100259ae92701e6c1d912e6126950be871a0aa0bc76c69b573a8f549708e4f5b9658246d97f239964447af47052f09df117f955af39c1bfc43c369ada5460750e7dd0b0f178a70bb970a8fb74f9d892636a4ac38234157de5482482d3debd80f082d6b55a5761cc97c261e5ad3ba3025c06990011f1f86cc021de48381c8174049a")]
+