Skip to content

Commit

Permalink
Fix admin logging (#6812)
Browse files Browse the repository at this point in the history 
* Fix admin logging

* commit assert fix for multiplat

* all \r\n -> Environment.NewLine in AssertLogs

---------

Co-authored-by: Scott Beddall (from Dev Box) <[email protected]>
  • Loading branch information
@JoshLove-msft @scbedd
JoshLove-msft and scbedd authored Aug 18, 2023
1 parent db9b7b1 commit a5325e5
Show file tree
Hide file tree
Showing 6 changed files with 107 additions and 36 deletions.
91 changes: 66 additions & 25 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/LoggingTests.cs
View file
Original file line number Diff line number Diff line change
@@ -1,11 +1,11 @@
using System.IO;
using System;
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
Expand All @@ -30,17 +30,20 @@ public async Task PlaybackLogsSanitizedRequest()
httpContext.Request.Body = TestHelpers.GenerateStreamRequestBody(body);
httpContext.Request.ContentLength = body.Length;

var controller = new Playback(testRecordingHandler, new NullLoggerFactory())
var playback = new Playback(testRecordingHandler, new TestLoggingFactory(logger))
{
ControllerContext = new ControllerContext()
{
HttpContext = httpContext
}
};
await controller.Start();
await playback.Start();

var recordingId = httpContext.Response.Headers["x-recording-id"].ToString();
Assert.NotNull(recordingId);

await AddSanitizerAsync(testRecordingHandler, logger);

Assert.True(testRecordingHandler.PlaybackSessions.ContainsKey(recordingId));
var entry = testRecordingHandler.PlaybackSessions[recordingId].Session.Entries[0];
HttpRequest request = TestHelpers.CreateRequestFromEntry(entry);
Expand All @@ -49,10 +52,7 @@ public async Task PlaybackLogsSanitizedRequest()
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);
AssertLogs(logger);
}
finally
{
Expand All @@ -65,11 +65,14 @@ public async Task RecordingHandlerLogsSanitizedRequests()
{
var logger = new TestLogger();
DebugLogger.Logger = logger;

var session = TestHelpers.LoadRecordSession("Test.RecordEntries/request_with_binary_content.json");
var request = TestHelpers.CreateRequestFromEntry(session.Session.Entries[0]);
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)
var testRecordingHandler = new RecordingHandler(path)
{
RedirectableClient = mockClient,
RedirectlessClient = mockClient
Expand All @@ -78,38 +81,76 @@ public async Task RecordingHandlerLogsSanitizedRequests()
var relativePath = "recordings/logs";
var fullPathToRecording = Path.Combine(path, relativePath) + ".json";

await recordingHandler.StartRecordingAsync(relativePath, httpContext.Response);
await testRecordingHandler.StartRecordingAsync(relativePath, httpContext.Response);

var recordingId = httpContext.Response.Headers["x-recording-id"].ToString();
await AddSanitizerAsync(testRecordingHandler, logger);

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));
var recordingId = httpContext.Response.Headers["x-recording-id"].ToString();

await recordingHandler.HandleRecordRequestAsync(recordingId, httpContext.Request, httpContext.Response);
recordingHandler.StopRecording(recordingId);
await testRecordingHandler.HandleRecordRequestAsync(recordingId, request, httpContext.Response);
testRecordingHandler.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);
AssertLogs(logger);
}
finally
{
File.Delete(fullPathToRecording);
DebugLogger.Logger = null;
}
}

private static void AssertLogs(TestLogger logger)
{
Assert.Equal(4, 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());
Assert.Equal(
"Request Body Content{\"key\":\"Location\",\"value\":\"https://fakeazsdktestaccount.table.core.windows.net/Tables\"}",
logger.Logs[1].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());
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());
}

private static async Task AddSanitizerAsync(RecordingHandler testRecordingHandler, TestLogger logger)
{
var httpContext = new DefaultHttpContext();
httpContext.Request.Scheme = "http";
httpContext.Request.Host = new HostString("127.0.0.1:5000");
httpContext.Request.Path = "/admin/addsanitizer";
httpContext.Request.Headers["x-abstraction-identifier"] = "HeaderRegexSanitizer";
httpContext.Request.Body =
TestHelpers.GenerateStreamRequestBody(
"{ \"key\": \"Location\", \"value\": \"https://fakeazsdktestaccount.table.core.windows.net/Tables\" }");
httpContext.Request.ContentLength = 92;

var admin = new Admin(testRecordingHandler, new TestLoggingFactory(logger))
{
ControllerContext = new ControllerContext()
{
HttpContext = httpContext
}
};
await admin.AddSanitizer();
}
}



[CollectionDefinition(nameof(LoggingCollection), DisableParallelization = true)]
public class LoggingCollection
{
}
}
}
25 changes: 25 additions & 0 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy.Tests/TestLogger.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,4 +24,29 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
Logs.Add(state);
}
}

public class TestLoggingFactory : ILoggerFactory
{
private readonly TestLogger _logger;

public TestLoggingFactory(TestLogger logger)
{
_logger = logger;
}

public void Dispose()
{
throw new NotImplementedException();
}

public void AddProvider(ILoggerProvider provider)
{
throw new NotImplementedException();
}

public ILogger CreateLogger(string categoryName)
{
return _logger;
}
}
}
12 changes: 6 additions & 6 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy/Admin.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -30,7 +30,7 @@ public Admin(RecordingHandler recordingHandler, ILoggerFactory loggingFactory)
[HttpPost]
public void Reset()
{
DebugLogger.LogRequestDetails(_logger, Request);
DebugLogger.LogAdminRequestDetails(_logger, Request);
var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true);

_recordingHandler.SetDefaultExtensions(recordingId);
Expand All @@ -39,14 +39,14 @@ public void Reset()
[HttpGet]
public void IsAlive()
{
DebugLogger.LogRequestDetails(_logger, Request);
DebugLogger.LogAdminRequestDetails(_logger, Request);
Response.StatusCode = 200;
}

[HttpPost]
public async Task AddTransform()
{
DebugLogger.LogRequestDetails(_logger, Request);
DebugLogger.LogAdminRequestDetails(_logger, Request);
var tName = RecordingHandler.GetHeader(Request, "x-abstraction-identifier");
var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true);

Expand All @@ -65,7 +65,7 @@ public async Task AddTransform()
[HttpPost]
public async Task AddSanitizer()
{
DebugLogger.LogRequestDetails(_logger, Request);
DebugLogger.LogAdminRequestDetails(_logger, Request);
var sName = RecordingHandler.GetHeader(Request, "x-abstraction-identifier");
var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true);

Expand All @@ -84,7 +84,7 @@ public async Task AddSanitizer()
[HttpPost]
public async Task SetMatcher()
{
DebugLogger.LogRequestDetails(_logger, Request);
DebugLogger.LogAdminRequestDetails(_logger, Request);
var mName = RecordingHandler.GetHeader(Request, "x-abstraction-identifier");
var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true);

Expand All @@ -104,7 +104,7 @@ public async Task SetMatcher()
[AllowEmptyBody]
public void SetRecordingOptions([FromBody()] IDictionary<string, object> options = null)
{
DebugLogger.LogRequestDetails(_logger, Request);
DebugLogger.LogAdminRequestDetails(_logger, Request);

var recordingId = RecordingHandler.GetHeader(Request, "x-recording-id", allowNulls: true);

Expand Down
9 changes: 7 additions & 2 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 @@ -4,6 +4,7 @@
using System;
using System.Collections.Generic;
using System.Text.Json;
using Microsoft.AspNetCore.Http.Extensions;

namespace Azure.Sdk.Tools.TestProxy.Common
{
Expand Down Expand Up @@ -147,11 +148,15 @@ 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 void LogRequestDetails(ILogger loggerInstance, HttpRequest req)
public static void LogAdminRequestDetails(ILogger loggerInstance, HttpRequest req)
{
if(CheckLogLevel(LogLevel.Debug))
{
loggerInstance.LogDebug(_generateLogLine(req, null));
var headers = Encoding.UTF8.GetString(JsonSerializer.SerializeToUtf8Bytes(req.Headers));
StringBuilder sb = new StringBuilder();
sb.AppendLine("URI: [ " + req.GetDisplayUrl() + "]");
sb.AppendLine("Headers: [" + headers + "]");
loggerInstance.LogDebug(sb.ToString());
}
}

Expand Down
4 changes: 2 additions & 2 deletions tools/test-proxy/Azure.Sdk.Tools.TestProxy/Playback.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -63,7 +63,7 @@ public void Stop()
[HttpPost]
public async Task Reset([FromBody()] IDictionary<string, object> options = null)
{
DebugLogger.LogRequestDetails(_logger, Request);
DebugLogger.LogAdminRequestDetails(_logger, Request);

var pathToAssets = RecordingHandler.GetAssetsJsonLocation(StoreResolver.ParseAssetsJsonBody(options), _recordingHandler.ContextDirectory);

Expand All @@ -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)
{
DebugLogger.LogRequestDetails(_logger, Request);
DebugLogger.LogAdminRequestDetails(_logger, Request);

var pathToAssets = RecordingHandler.GetAssetsJsonLocation(StoreResolver.ParseAssetsJsonBody(options), _recordingHandler.ContextDirectory);

Expand Down
2 changes: 1 addition & 1 deletion tools/test-proxy/Azure.Sdk.Tools.TestProxy/Record.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -56,7 +56,7 @@ public async Task Start()
[HttpPost]
public async Task Push([FromBody()] IDictionary<string, object> options = null)
{
DebugLogger.LogRequestDetails(_logger, Request);
DebugLogger.LogAdminRequestDetails(_logger, Request);

var pathToAssets = RecordingHandler.GetAssetsJsonLocation(StoreResolver.ParseAssetsJsonBody(options), _recordingHandler.ContextDirectory);

Expand Down

0 comments on commit a5325e5

Please sign in to comment.