From 927a2598022c56356bd2afa2c9ed5d8eee520582 Mon Sep 17 00:00:00 2001 From: StuartFerguson Date: Sun, 25 Oct 2026 09:20:45 +0000 Subject: [PATCH 1/2] fixess to middleware after some testing --- .../RequestResponseLoggingMiddleware.cs | 247 ++++++++++-------- .../Middleware/ResponseLoggingMemoryStream.cs | 52 +--- 2 files changed, 151 insertions(+), 148 deletions(-) diff --git a/Shared/Middleware/RequestResponseLoggingMiddleware.cs b/Shared/Middleware/RequestResponseLoggingMiddleware.cs index 2b44d8d..f43660f 100644 --- a/Shared/Middleware/RequestResponseLoggingMiddleware.cs +++ b/Shared/Middleware/RequestResponseLoggingMiddleware.cs @@ -1,133 +1,172 @@ #nullable enable using Microsoft.AspNetCore.Http; +using Microsoft.AspNetCore.Http.Extensions; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Primitives; using System; using System.Collections.Generic; using System.Diagnostics; using System.IO; using System.Linq; +using System.Text; using System.Threading.Tasks; namespace Shared.Middleware; public class RequestResponseLoggingMiddleware { - private const String RequestIdField = "requestId"; - private const String HeadersField = "headers"; - private const String BodyStatusField = "bodyStatus"; + private static readonly HashSet RequestRedactedHeaders = + new(StringComparer.OrdinalIgnoreCase) { "Authorization", "Cookie" }; + + private static readonly HashSet ResponseRedactedHeaders = + new(StringComparer.OrdinalIgnoreCase) { "Set-Cookie", "Authorization", "Cookie" }; private readonly RequestDelegate next; - public RequestResponseLoggingMiddleware(RequestDelegate next) => this.next = next; - - public async Task Invoke(HttpContext context, RequestResponseMiddlewareLoggingConfig configuration) - { - String requestId = context.TraceIdentifier; - String path = context.Request.Path.Value ?? String.Empty; - Boolean healthCheck = Helpers.IsHealthCheckRequest(path); - Stream requestBody = context.Request.Body; - Stream responseBody = context.Response.Body; - ResponseLoggingMemoryStream? captureStream = configuration.LogResponses - ? new ResponseLoggingMemoryStream(responseBody, configuration.MaximumResponseBodyBytes) - : null; - Stopwatch timer = Stopwatch.StartNew(); - if (captureStream != null) context.Response.Body = captureStream; - - IReadOnlyDictionary query = SensitiveDataRedactor.RedactQuery(context.Request.Query, configuration.SensitiveFieldNames); - IReadOnlyDictionary requestHeaders = SensitiveDataRedactor.FilterHeaders(context.Request.Headers, configuration.AllowedRequestHeaders, configuration.SensitiveHeaderNames); - Dictionary? requestFields = null; - try - { - if (configuration.LogRequests) - { - BodyCaptureResult requestCapture = await CaptureRequestAsync(context, configuration); - requestFields = new() - { - [RequestIdField] = requestId, ["method"] = context.Request.Method, ["path"] = path, - ["query"] = query, [HeadersField] = requestHeaders, [BodyStatusField] = requestCapture.Status, - ["body"] = requestCapture.Body, ["healthCheck"] = healthCheck - }; - } - await this.next(context); + public RequestResponseLoggingMiddleware(RequestDelegate next) { + this.next = next; + } + + public static Boolean IsHealthCheckRequest(String url) => url switch { + _ when url.EndsWith("/health", StringComparison.OrdinalIgnoreCase) => true, + _ when url.EndsWith("/healthui", StringComparison.OrdinalIgnoreCase) => true, + _ => false, + }; + + internal static void LogMessage(String url, (String messageTemplate, Object[] args) messageToLog, LogLevel logLevel) { + + if (IsHealthCheckRequest(url)) + return; + + switch (logLevel) { + case LogLevel.Trace: + Shared.Logger.Logger.LogTrace(messageToLog.messageTemplate, messageToLog.args); + break; + case LogLevel.Debug: + Shared.Logger.Logger.LogDebug(messageToLog.messageTemplate, messageToLog.args); + break; + case LogLevel.Warning: + Shared.Logger.Logger.LogWarning(messageToLog.messageTemplate, messageToLog.args); + break; + case LogLevel.Error: + Shared.Logger.Logger.LogError(messageToLog.messageTemplate, messageToLog.args); + break; + case LogLevel.Critical: + Shared.Logger.Logger.LogCritical(messageToLog.messageTemplate, messageToLog.args); + break; + default: + Shared.Logger.Logger.LogInformation(messageToLog.messageTemplate, messageToLog.args); + break; } - finally - { - timer.Stop(); - context.Request.Body = requestBody; - if (requestFields != null) - { - LogLevel requestLevel = context.Response.StatusCode is < 200 or > 299 ? LogLevel.Warning : configuration.LoggingLevel; - WriteLog(requestLevel, "HTTP request {requestId} {method} {path} {query} {headers} {bodyStatus} {body} {eventType}", requestFields); - } - if (captureStream != null) - { - context.Response.Body = responseBody; - if (configuration.LogResponses) - { - Byte[] responseBytes = captureStream.GetCapturedBytes(); - BodyCaptureResult responseCapture = SensitiveDataRedactor.RedactBody(responseBytes, context.Response.ContentType, - configuration.SensitiveFieldNames, configuration.MaximumResponseBodyBytes, configuration.SupportedBodyContentTypes); - LogLevel level = context.Response.StatusCode is < 200 or > 299 ? LogLevel.Warning : configuration.LoggingLevel; - Dictionary responseFields = new() - { - [RequestIdField] = requestId, ["statusCode"] = context.Response.StatusCode, ["elapsedMs"] = timer.ElapsedMilliseconds, - [HeadersField] = SensitiveDataRedactor.FilterHeaders(context.Response.Headers, configuration.AllowedResponseHeaders, configuration.SensitiveHeaderNames), - [BodyStatusField] = responseCapture.Status, ["body"] = responseCapture.Body, ["healthCheck"] = healthCheck - }; - WriteLog(level, "HTTP response {requestId} {statusCode} in {elapsedMs}ms {headers} {bodyStatus} {body} {eventType}", responseFields); - if (captureStream.IsDisposed() && context.Request.Headers.ContainsKey("SOAPAction")) captureStream.ForceClose(); - } - } + } + + public async Task Invoke(HttpContext context, RequestResponseMiddlewareLoggingConfig configuration) { + + String url = context.Request.GetDisplayUrl(); + Stream originalRequestBody = context.Request.Body; + Stream originalResponseBody = context.Response.Body; + + String requestBodyText = await CaptureRequestBodyAsync(context, configuration.LogRequests); + ResponseLoggingMemoryStream responseBodyStream = SetupResponseCapture(context, configuration.LogResponses); + + await this.next(context); + + LogLevel effectiveLogLevel = context.Response.StatusCode is < 200 or > 299 + ? LogLevel.Warning + : configuration.LoggingLevel; + + if (configuration.LogRequests) { + (String messageTemplate, Object[] args) requestLog = BuildRequestLog(context, url, requestBodyText); + LogMessage(url, requestLog, effectiveLogLevel); + context.Request.Body = originalRequestBody; + } + + if (configuration.LogResponses) { + await LogResponse(context, url, responseBodyStream, originalResponseBody, effectiveLogLevel); } } - private static async Task CaptureRequestAsync(HttpContext context, RequestResponseMiddlewareLoggingConfig configuration) - { - if (context.Request.ContentLength == 0) return new(null, "empty"); - Int32 limit = Math.Max(0, configuration.MaximumRequestBodyBytes); - Stream? body = null; - try - { - context.Request.EnableBuffering(); - body = context.Request.Body; - using MemoryStream buffer = new(); - Byte[] chunk = new Byte[Math.Min(8192, Math.Max(1, limit + 1))]; - Int32 remaining = limit + 1; - while (remaining > 0) - { - Int32 read = await body.ReadAsync(chunk.AsMemory(0, Math.Min(chunk.Length, remaining))); - if (read == 0) break; - await buffer.WriteAsync(chunk.AsMemory(0, read)); - remaining -= read; - } - return SensitiveDataRedactor.RedactBody(buffer.ToArray(), context.Request.ContentType, configuration.SensitiveFieldNames, - limit, configuration.SupportedBodyContentTypes); + private static async Task CaptureRequestBodyAsync(HttpContext context, Boolean logRequests) { + if (!logRequests) + return String.Empty; + + MemoryStream requestBodyStream = new(); + await context.Request.Body.CopyToAsync(requestBodyStream); + requestBodyStream.Seek(0, SeekOrigin.Begin); + String bodyText = await new StreamReader(requestBodyStream).ReadToEndAsync(); + requestBodyStream.Seek(0, SeekOrigin.Begin); + context.Request.Body = requestBodyStream; + return bodyText; + } + + private static ResponseLoggingMemoryStream SetupResponseCapture(HttpContext context, Boolean logResponses) { + if (!logResponses) + return null; + + ResponseLoggingMemoryStream responseBodyStream = new(); + context.Response.Body = responseBodyStream; + return responseBodyStream; + } + + private static (String messageTemplate, Object[]? args) BuildRequestLog(HttpContext context, String url, String requestBodyText) { + StringBuilder log = new(); + + StringBuilder messageTemplate = new StringBuilder(); + List args = new List(); + messageTemplate.Append("Request: Method: {method} Url: {url} "); + args.Add(context.Request.Method); + args.Add(url); + + AddHeaders(context.Response.Headers, messageTemplate, args); + + if (requestBodyText != String.Empty) { + messageTemplate.Append(" Body: {requestBody}"); + args.Add(requestBodyText); } - catch { return new(null, "redaction_failed"); } - finally - { - if (body?.CanSeek == true) body.Position = 0; + + return (messageTemplate.ToString(), args.ToArray()); + } + + private static async Task LogResponse(HttpContext context, String url, + ResponseLoggingMemoryStream responseBodyStream, Stream originalResponseBody, LogLevel logLevel) { + responseBodyStream.Seek(0, SeekOrigin.Begin); + String responseBody = await new StreamReader(responseBodyStream).ReadToEndAsync(); + + (String messageTemplate, Object[] args) responseLog = BuildResponseLog(context, responseBody); + LogMessage(url, responseLog, logLevel); + + responseBodyStream.Seek(0, SeekOrigin.Begin); + await responseBodyStream.CopyToAsync(originalResponseBody); + if (responseBodyStream.IsDisposed() && context.Request.Headers.ContainsKey("SOAPAction")) { + responseBodyStream.ForceClose(); + } + } + + private static (String messageTemplate, Object[]? args) BuildResponseLog(HttpContext context, String responseBody) { + StringBuilder messageTemplate = new(); + List args = new List(); + messageTemplate.Append("Response: Status Code: {httpStatusCode}"); + args.Add(context.Response.StatusCode); + + AddHeaders(context.Response.Headers, messageTemplate, args); + + if (!String.IsNullOrEmpty(responseBody)) { + messageTemplate.Append(" Body: {responseBody}"); + args.Add(responseBody); } + return (messageTemplate.ToString(), args.ToArray()); } - private static void WriteLog(LogLevel level, String template, Dictionary fields) - { - Object? eventType = fields["healthCheck"] is true ? "HEALTH_CHECK" : "HTTP"; - Object?[] values = fields.ContainsKey("method") - ? [fields["requestId"], fields["method"], fields["path"], fields["query"], fields["headers"], fields[BodyStatusField], fields["body"], eventType] - : [fields["requestId"], fields["statusCode"], fields["elapsedMs"], fields["headers"], fields[BodyStatusField], fields["body"], eventType]; - try - { - switch (level) - { - case LogLevel.Trace: Logger.Logger.LogTrace(template, values); break; - case LogLevel.Debug: Logger.Logger.LogDebug(template, values); break; - case LogLevel.Warning: Logger.Logger.LogWarning(template, values); break; - case LogLevel.Error: Logger.Logger.LogError(template, values); break; - case LogLevel.Critical: Logger.Logger.LogCritical(template, values); break; - default: Logger.Logger.LogInformation(template, values); break; + internal static void AddHeaders(IHeaderDictionary headerDictionary, StringBuilder messageTemplate, List args) { + if (headerDictionary != null && headerDictionary.Any()) { + messageTemplate.Append(" Headers: "); + foreach (KeyValuePair header in headerDictionary) { + String value = RequestRedactedHeaders.Contains(header.Key) || ResponseRedactedHeaders.Contains(header.Key) + ? "***REDACTED***" + : header.Value.ToString(); + messageTemplate.Append($"{header.Key}={{{header.Key}}}"); + args.Add(value); } } - catch { /* Logging must not break request processing or mask an application exception. */ } } } diff --git a/Shared/Middleware/ResponseLoggingMemoryStream.cs b/Shared/Middleware/ResponseLoggingMemoryStream.cs index 02ef0e0..bcfadd1 100644 --- a/Shared/Middleware/ResponseLoggingMemoryStream.cs +++ b/Shared/Middleware/ResponseLoggingMemoryStream.cs @@ -1,55 +1,19 @@ -using System; using System.Diagnostics.CodeAnalysis; using System.IO; -using System.Threading; -using System.Threading.Tasks; namespace Shared.Middleware; [ExcludeFromCodeCoverage] -public sealed class ResponseLoggingMemoryStream : Stream -{ - private readonly Stream destination; - private readonly MemoryStream captured = new(); - private readonly Int32 maximumBytes; - - public ResponseLoggingMemoryStream(Stream destination, Int32 maximumBytes) - { - this.destination = destination; - this.maximumBytes = Math.Max(0, maximumBytes); +public class ResponseLoggingMemoryStream : MemoryStream { + public override void Close() { + // Dont close by default } - public Byte[] GetCapturedBytes() => this.captured.ToArray(); - public Boolean IsDisposed() => this.captured.CanRead && this.captured.CanSeek && this.captured.CanWrite; - public void ForceClose() => this.captured.Close(); - public override Boolean CanRead => false; - public override Boolean CanSeek => false; - public override Boolean CanWrite => true; - public override Int64 Length => throw new NotSupportedException(); - public override Int64 Position { get => throw new NotSupportedException(); set => throw new NotSupportedException(); } - - public override void Flush() => this.destination.Flush(); - public override void Close() - { - // The middleware reads the captured buffer after the response pipeline closes this wrapper. - // Keep the destination stream and captured buffer available until logging has completed. + public void ForceClose() { + base.Close(); } - public override Task FlushAsync(CancellationToken cancellationToken) => this.destination.FlushAsync(cancellationToken); - public override void Write(Byte[] buffer, Int32 offset, Int32 count) - { - Int32 remaining = Math.Max(0, this.maximumBytes + 1 - (Int32)this.captured.Length); - if (remaining > 0) this.captured.Write(buffer, offset, Math.Min(count, remaining)); - this.destination.Write(buffer, offset, count); - } - public override async ValueTask WriteAsync(ReadOnlyMemory buffer, CancellationToken cancellationToken = default) - { - Int32 remaining = Math.Max(0, this.maximumBytes + 1 - (Int32)this.captured.Length); - if (remaining > 0) await this.captured.WriteAsync(buffer[..Math.Min(buffer.Length, remaining)], cancellationToken); - await this.destination.WriteAsync(buffer, cancellationToken); + + public bool IsDisposed() { + return this.CanRead && this.CanSeek && this.CanWrite; } - public override Task WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken) => - this.WriteAsync(new ReadOnlyMemory(buffer, offset, count), cancellationToken).AsTask(); - public override Int32 Read(Byte[] buffer, Int32 offset, Int32 count) => throw new NotSupportedException(); - public override Int64 Seek(Int64 offset, SeekOrigin origin) => throw new NotSupportedException(); - public override void SetLength(Int64 value) => throw new NotSupportedException(); } From 017f858836dcd8f25007dc512edfe8396613ecde Mon Sep 17 00:00:00 2001 From: StuartFerguson Date: Sun, 25 Oct 2026 11:48:06 +0000 Subject: [PATCH 2/2] some more fixes --- Shared.Tests/StructuredLoggingTests.cs | 64 ++++--- .../RequestResponseLoggingMiddleware.cs | 160 +++++++++--------- .../RequestResponseMiddlewareLoggingConfig.cs | 2 - Shared/Middleware/SensitiveDataRedactor.cs | 3 +- 4 files changed, 123 insertions(+), 106 deletions(-) diff --git a/Shared.Tests/StructuredLoggingTests.cs b/Shared.Tests/StructuredLoggingTests.cs index 825790b..a1bea18 100644 --- a/Shared.Tests/StructuredLoggingTests.cs +++ b/Shared.Tests/StructuredLoggingTests.cs @@ -85,14 +85,20 @@ public async Task Middleware_RedactsSensitiveQueryHeadersAndJsonBody() StructuredLogEntry request = logger.Entries.ShouldHaveSingleItem(); request.Template.ShouldContain("{query}"); - String query = JsonSerializer.Serialize(request.Arguments[3]); + request.Template.ShouldContain("{header_Authorization}"); + request.Template.ShouldContain("{header_X_Request_Id}"); + request.Template.ShouldNotContain("X-Unlisted"); + String query = JsonSerializer.Serialize(GetStructuredValue(request, "query")); query.ShouldContain("[REDACTED]"); query.ShouldContain("visible"); - String headers = JsonSerializer.Serialize(request.Arguments[4]); + String headers = JsonSerializer.Serialize(new[] + { + GetStructuredValue(request, "header_Authorization"), + GetStructuredValue(request, "header_X_Request_Id") + }); headers.ShouldContain("[REDACTED]"); headers.ShouldContain("request-123"); - headers.ShouldNotContain("X-Unlisted"); - String body = request.Arguments[6]!.ToString()!; + String body = GetStructuredValue(request, "requestBody")!.ToString()!; body.ShouldContain("[REDACTED]"); body.ShouldContain("alice"); String allFields = String.Join('|', request.Arguments); @@ -127,7 +133,7 @@ public async Task Middleware_PreservesQueryAndHeaderCollectionsWithLegacyLogger( } [Fact] - public async Task Middleware_OmitsBodyWhenRequestExceedsConfiguredLimitAndRestoresRequestStream() + public async Task Middleware_RedactsRequestBodyAndRestoresRequestStream() { CapturingLogger logger = new(); Shared.Logger.Logger.Initialise(logger); @@ -135,14 +141,11 @@ public async Task Middleware_OmitsBodyWhenRequestExceedsConfiguredLimitAndRestor Stream originalBody = context.Request.Body; RequestResponseLoggingMiddleware middleware = new(_ => Task.CompletedTask); - await middleware.Invoke(context, new RequestResponseMiddlewareLoggingConfig(LogLevel.Information, true, false) - { - MaximumRequestBodyBytes = 8 - }); + await middleware.Invoke(context, new RequestResponseMiddlewareLoggingConfig(LogLevel.Information, true, false)); StructuredLogEntry request = logger.Entries.ShouldHaveSingleItem(); - request.Arguments[5].ShouldBe("size_limit"); - request.Arguments[6].ShouldBeNull(); + GetStructuredValue(request, "bodyStatus").ShouldBe("captured"); + GetStructuredValue(request, "requestBody")!.ToString().ShouldContain("123456789"); context.Request.Body.ShouldBeSameAs(originalBody); } @@ -163,7 +166,7 @@ public async Task Middleware_RedactsSensitiveJsonResponseBodyAndPreservesRespons await middleware.Invoke(context, new RequestResponseMiddlewareLoggingConfig(LogLevel.Information, false, true)); StructuredLogEntry log = logger.Entries.ShouldHaveSingleItem(); - String body = log.Arguments[5]!.ToString()!; + String body = GetStructuredValue(log, "responseBody")!.ToString()!; body.ShouldContain("[REDACTED]"); body.ShouldNotContain("response-secret"); context.Response.Body.Position = 0; @@ -182,8 +185,8 @@ public async Task Middleware_ReportsUnsupportedBodyContentTypeWithoutLoggingPayl await middleware.Invoke(context, new RequestResponseMiddlewareLoggingConfig(LogLevel.Information, true, false)); StructuredLogEntry request = logger.Entries.ShouldHaveSingleItem(); - request.Arguments[5].ShouldBe("unsupported_content_type"); - request.Arguments[6].ShouldBeNull(); + GetStructuredValue(request, "bodyStatus").ShouldBe("unsupported_content_type"); + GetStructuredValue(request, "requestBody").ShouldBeNull(); String.Join('|', request.Arguments).ShouldNotContain("binary-secret"); } @@ -202,13 +205,13 @@ public async Task Middleware_RedactsSensitiveFormAndXmlFields(String contentType await middleware.Invoke(context, new RequestResponseMiddlewareLoggingConfig(LogLevel.Information, true, false)); StructuredLogEntry request = logger.Entries.ShouldHaveSingleItem(); - request.Arguments[6].ShouldBe(expectedBody); - String redactedBody = request.Arguments[6] as String ?? String.Empty; + GetStructuredValue(request, "requestBody").ShouldBe(expectedBody); + String redactedBody = GetStructuredValue(request, "requestBody") as String ?? String.Empty; redactedBody.ShouldNotContain("body-secret"); } [Fact] - public async Task Middleware_OmitsResponseBodyWhenItExceedsConfiguredLimit() + public async Task Middleware_RedactsResponseBodyWithoutSizeLimit() { CapturingLogger logger = new(); Shared.Logger.Logger.Initialise(logger); @@ -220,14 +223,11 @@ public async Task Middleware_OmitsResponseBodyWhenItExceedsConfiguredLimit() return inner.Response.WriteAsync(payload, TestContext.Current.CancellationToken); }); - await middleware.Invoke(context, new RequestResponseMiddlewareLoggingConfig(LogLevel.Information, false, true) - { - MaximumResponseBodyBytes = 8 - }); + await middleware.Invoke(context, new RequestResponseMiddlewareLoggingConfig(LogLevel.Information, false, true)); StructuredLogEntry response = logger.Entries.ShouldHaveSingleItem(); - response.Arguments[4].ShouldBe("size_limit"); - response.Arguments[5].ShouldBeNull(); + GetStructuredValue(response, "bodyStatus").ShouldBe("captured"); + GetStructuredValue(response, "responseBody")!.ToString().ShouldContain("a value larger than the limit"); context.Response.Body.Position = 0; using StreamReader reader = new(context.Response.Body, Encoding.UTF8, leaveOpen: true); (await reader.ReadToEndAsync(TestContext.Current.CancellationToken)).ShouldBe(payload); @@ -244,6 +244,24 @@ private static DefaultHttpContext CreateContext(String body, String? contentType return context; } + private static Object? GetStructuredValue(StructuredLogEntry entry, String propertyName) + { + Int32 argumentIndex = 0; + Int32 searchFrom = 0; + while (true) + { + Int32 placeholderStart = entry.Template.IndexOf('{', searchFrom); + if (placeholderStart < 0) break; + Int32 placeholderEnd = entry.Template.IndexOf('}', placeholderStart + 1); + if (placeholderEnd < 0) break; + String currentProperty = entry.Template.Substring(placeholderStart + 1, placeholderEnd - placeholderStart - 1); + if (currentProperty == propertyName) return entry.Arguments[argumentIndex]; + argumentIndex++; + searchFrom = placeholderEnd + 1; + } + throw new InvalidOperationException($"Structured property '{propertyName}' was not found in the log template."); + } + private sealed record StructuredLogEntry(String Template, Object?[] Arguments, LogLevel Level); private sealed class CapturingLogger : Shared.Logger.ILogger diff --git a/Shared/Middleware/RequestResponseLoggingMiddleware.cs b/Shared/Middleware/RequestResponseLoggingMiddleware.cs index f43660f..761fca1 100644 --- a/Shared/Middleware/RequestResponseLoggingMiddleware.cs +++ b/Shared/Middleware/RequestResponseLoggingMiddleware.cs @@ -1,13 +1,9 @@ #nullable enable using Microsoft.AspNetCore.Http; -using Microsoft.AspNetCore.Http.Extensions; using Microsoft.Extensions.Logging; -using Microsoft.Extensions.Primitives; using System; using System.Collections.Generic; -using System.Diagnostics; using System.IO; -using System.Linq; using System.Text; using System.Threading.Tasks; @@ -15,12 +11,6 @@ namespace Shared.Middleware; public class RequestResponseLoggingMiddleware { - private static readonly HashSet RequestRedactedHeaders = - new(StringComparer.OrdinalIgnoreCase) { "Authorization", "Cookie" }; - - private static readonly HashSet ResponseRedactedHeaders = - new(StringComparer.OrdinalIgnoreCase) { "Set-Cookie", "Authorization", "Cookie" }; - private readonly RequestDelegate next; public RequestResponseLoggingMiddleware(RequestDelegate next) { @@ -33,7 +23,7 @@ _ when url.EndsWith("/healthui", StringComparison.OrdinalIgnoreCase) => true, _ => false, }; - internal static void LogMessage(String url, (String messageTemplate, Object[] args) messageToLog, LogLevel logLevel) { + internal static void LogMessage(String url, (String messageTemplate, Object?[] args) messageToLog, LogLevel logLevel) { if (IsHealthCheckRequest(url)) return; @@ -62,44 +52,49 @@ internal static void LogMessage(String url, (String messageTemplate, Object[] ar public async Task Invoke(HttpContext context, RequestResponseMiddlewareLoggingConfig configuration) { - String url = context.Request.GetDisplayUrl(); + String url = $"{context.Request.PathBase}{context.Request.Path}"; Stream originalRequestBody = context.Request.Body; Stream originalResponseBody = context.Response.Body; - String requestBodyText = await CaptureRequestBodyAsync(context, configuration.LogRequests); - ResponseLoggingMemoryStream responseBodyStream = SetupResponseCapture(context, configuration.LogResponses); + Byte[] requestBody = await CaptureRequestBodyAsync(context, configuration.LogRequests); + ResponseLoggingMemoryStream? responseBodyStream = SetupResponseCapture(context, configuration.LogResponses); - await this.next(context); + try { + await this.next(context); - LogLevel effectiveLogLevel = context.Response.StatusCode is < 200 or > 299 - ? LogLevel.Warning - : configuration.LoggingLevel; + LogLevel effectiveLogLevel = context.Response.StatusCode is < 200 or > 299 + ? LogLevel.Warning + : configuration.LoggingLevel; - if (configuration.LogRequests) { - (String messageTemplate, Object[] args) requestLog = BuildRequestLog(context, url, requestBodyText); - LogMessage(url, requestLog, effectiveLogLevel); - context.Request.Body = originalRequestBody; - } + if (configuration.LogRequests) { + (String messageTemplate, Object?[] args) requestLog = BuildRequestLog(context, url, requestBody, configuration); + LogMessage(url, requestLog, effectiveLogLevel); + } - if (configuration.LogResponses) { - await LogResponse(context, url, responseBodyStream, originalResponseBody, effectiveLogLevel); + if (configuration.LogResponses && responseBodyStream != null) { + await LogResponse(context, url, responseBodyStream, originalResponseBody, effectiveLogLevel, configuration); + } + } + finally { + context.Request.Body = originalRequestBody; + context.Response.Body = originalResponseBody; } } - private static async Task CaptureRequestBodyAsync(HttpContext context, Boolean logRequests) { + private static async Task CaptureRequestBodyAsync(HttpContext context, Boolean logRequests) { if (!logRequests) - return String.Empty; + return Array.Empty(); MemoryStream requestBodyStream = new(); await context.Request.Body.CopyToAsync(requestBodyStream); requestBodyStream.Seek(0, SeekOrigin.Begin); - String bodyText = await new StreamReader(requestBodyStream).ReadToEndAsync(); - requestBodyStream.Seek(0, SeekOrigin.Begin); + Byte[] body = requestBodyStream.ToArray(); + requestBodyStream.Position = 0; context.Request.Body = requestBodyStream; - return bodyText; + return body; } - private static ResponseLoggingMemoryStream SetupResponseCapture(HttpContext context, Boolean logResponses) { + private static ResponseLoggingMemoryStream? SetupResponseCapture(HttpContext context, Boolean logResponses) { if (!logResponses) return null; @@ -108,65 +103,72 @@ private static ResponseLoggingMemoryStream SetupResponseCapture(HttpContext cont return responseBodyStream; } - private static (String messageTemplate, Object[]? args) BuildRequestLog(HttpContext context, String url, String requestBodyText) { - StringBuilder log = new(); - - StringBuilder messageTemplate = new StringBuilder(); - List args = new List(); - messageTemplate.Append("Request: Method: {method} Url: {url} "); - args.Add(context.Request.Method); - args.Add(url); - - AddHeaders(context.Response.Headers, messageTemplate, args); - - if (requestBodyText != String.Empty) { - messageTemplate.Append(" Body: {requestBody}"); - args.Add(requestBodyText); - } - + private static (String messageTemplate, Object?[] args) BuildRequestLog(HttpContext context, String url, Byte[] requestBody, RequestResponseMiddlewareLoggingConfig configuration) { + IReadOnlyDictionary query = SensitiveDataRedactor.RedactQuery(context.Request.Query, configuration.SensitiveFieldNames); + IReadOnlyDictionary headers = SensitiveDataRedactor.FilterHeaders(context.Request.Headers, configuration.AllowedRequestHeaders, configuration.SensitiveHeaderNames); + BodyCaptureResult body = requestBody.Length == 0 + ? new(null, "empty") + : SensitiveDataRedactor.RedactBody(requestBody, context.Request.ContentType, configuration.SensitiveFieldNames, configuration.SupportedBodyContentTypes); + + StringBuilder messageTemplate = new("Request: Method: {method} Url: {url} ContentType: {contentType} Query: {query} Headers:"); + List args = [context.Request.Method, url, context.Request.ContentType ?? String.Empty, query]; + AppendHeaderFields(messageTemplate, args, headers); + messageTemplate.Append(" BodyStatus: {bodyStatus} Body: {requestBody}"); + args.Add(body.Status); + args.Add(body.Body); return (messageTemplate.ToString(), args.ToArray()); } private static async Task LogResponse(HttpContext context, String url, - ResponseLoggingMemoryStream responseBodyStream, Stream originalResponseBody, LogLevel logLevel) { - responseBodyStream.Seek(0, SeekOrigin.Begin); - String responseBody = await new StreamReader(responseBodyStream).ReadToEndAsync(); - - (String messageTemplate, Object[] args) responseLog = BuildResponseLog(context, responseBody); - LogMessage(url, responseLog, logLevel); - - responseBodyStream.Seek(0, SeekOrigin.Begin); - await responseBodyStream.CopyToAsync(originalResponseBody); - if (responseBodyStream.IsDisposed() && context.Request.Headers.ContainsKey("SOAPAction")) { - responseBodyStream.ForceClose(); + ResponseLoggingMemoryStream responseBodyStream, Stream originalResponseBody, LogLevel logLevel, + RequestResponseMiddlewareLoggingConfig configuration) { + try { + responseBodyStream.Seek(0, SeekOrigin.Begin); + using MemoryStream capturedBody = new(); + await responseBodyStream.CopyToAsync(capturedBody); + BodyCaptureResult body = capturedBody.Length == 0 + ? new(null, "empty") + : SensitiveDataRedactor.RedactBody(capturedBody.ToArray(), context.Response.ContentType, configuration.SensitiveFieldNames, configuration.SupportedBodyContentTypes); + + (String messageTemplate, Object?[] args) responseLog = BuildResponseLog(context, url, body, configuration); + LogMessage(url, responseLog, logLevel); + } + finally { + responseBodyStream.Seek(0, SeekOrigin.Begin); + await responseBodyStream.CopyToAsync(originalResponseBody); + if (responseBodyStream.IsDisposed() && context.Request.Headers.ContainsKey("SOAPAction")) { + responseBodyStream.ForceClose(); + } } } - private static (String messageTemplate, Object[]? args) BuildResponseLog(HttpContext context, String responseBody) { - StringBuilder messageTemplate = new(); - List args = new List(); - messageTemplate.Append("Response: Status Code: {httpStatusCode}"); - args.Add(context.Response.StatusCode); - - AddHeaders(context.Response.Headers, messageTemplate, args); - - if (!String.IsNullOrEmpty(responseBody)) { - messageTemplate.Append(" Body: {responseBody}"); - args.Add(responseBody); - } + private static (String messageTemplate, Object?[] args) BuildResponseLog(HttpContext context, String url, BodyCaptureResult body, RequestResponseMiddlewareLoggingConfig configuration) { + IReadOnlyDictionary headers = SensitiveDataRedactor.FilterHeaders(context.Response.Headers, configuration.AllowedResponseHeaders, configuration.SensitiveHeaderNames); + StringBuilder messageTemplate = new("Response: Url: {url} Status Code: {httpStatusCode} ContentType: {contentType} Headers:"); + List args = [url, context.Response.StatusCode, context.Response.ContentType ?? String.Empty]; + AppendHeaderFields(messageTemplate, args, headers); + messageTemplate.Append(" BodyStatus: {bodyStatus} Body: {responseBody}"); + args.Add(body.Status); + args.Add(body.Body); return (messageTemplate.ToString(), args.ToArray()); } - internal static void AddHeaders(IHeaderDictionary headerDictionary, StringBuilder messageTemplate, List args) { - if (headerDictionary != null && headerDictionary.Any()) { - messageTemplate.Append(" Headers: "); - foreach (KeyValuePair header in headerDictionary) { - String value = RequestRedactedHeaders.Contains(header.Key) || ResponseRedactedHeaders.Contains(header.Key) - ? "***REDACTED***" - : header.Value.ToString(); - messageTemplate.Append($"{header.Key}={{{header.Key}}}"); - args.Add(value); + private static void AppendHeaderFields(StringBuilder messageTemplate, List args, IReadOnlyDictionary headers) { + HashSet propertyNames = new(StringComparer.Ordinal); + foreach (KeyValuePair header in headers) { + StringBuilder propertyName = new("header_"); + foreach (Char character in header.Key) { + propertyName.Append(Char.IsLetterOrDigit(character) || character == '_' ? character : '_'); } + + String candidate = propertyName.ToString(); + Int32 duplicateIndex = 2; + while (!propertyNames.Add(candidate)) { + candidate = $"{propertyName}_{duplicateIndex++}"; + } + + messageTemplate.Append(' ').Append(header.Key).Append(": {").Append(candidate).Append('}'); + args.Add(header.Value); } } } diff --git a/Shared/Middleware/RequestResponseMiddlewareLoggingConfig.cs b/Shared/Middleware/RequestResponseMiddlewareLoggingConfig.cs index 701cd82..472c3df 100644 --- a/Shared/Middleware/RequestResponseMiddlewareLoggingConfig.cs +++ b/Shared/Middleware/RequestResponseMiddlewareLoggingConfig.cs @@ -13,6 +13,4 @@ public record RequestResponseMiddlewareLoggingConfig(LogLevel LoggingLevel, Bool public IReadOnlySet AllowedRequestHeaders { get; init; } = new HashSet(new[] { "Accept", "Content-Type", "User-Agent", "X-Request-Id", "correlationId", "Authorization", "Cookie" }, StringComparer.OrdinalIgnoreCase); public IReadOnlySet AllowedResponseHeaders { get; init; } = new HashSet(new[] { "Cache-Control", "Content-Length", "Content-Type", "ETag", "X-Response-Id", "Set-Cookie" }, StringComparer.OrdinalIgnoreCase); public IReadOnlySet SupportedBodyContentTypes { get; init; } = new HashSet(new[] { "application/json", "application/*+json", "application/x-www-form-urlencoded", "application/xml", "text/xml", "application/soap+xml" }, StringComparer.OrdinalIgnoreCase); - public Int32 MaximumRequestBodyBytes { get; init; } = 32768; - public Int32 MaximumResponseBodyBytes { get; init; } = 32768; } diff --git a/Shared/Middleware/SensitiveDataRedactor.cs b/Shared/Middleware/SensitiveDataRedactor.cs index 36394bf..df0d867 100644 --- a/Shared/Middleware/SensitiveDataRedactor.cs +++ b/Shared/Middleware/SensitiveDataRedactor.cs @@ -33,9 +33,8 @@ public static IReadOnlyDictionary FilterHeaders(IHeaderDictionar return result; } - public static BodyCaptureResult RedactBody(ReadOnlyMemory body, String? contentType, IReadOnlySet sensitiveFieldNames, Int32 maximumBytes, IReadOnlySet supportedContentTypes) + public static BodyCaptureResult RedactBody(ReadOnlyMemory body, String? contentType, IReadOnlySet sensitiveFieldNames, IReadOnlySet supportedContentTypes) { - if (body.Length > Math.Max(0, maximumBytes)) return new(null, "size_limit"); if (!TryGetBodyFormat(contentType, supportedContentTypes, out BodyFormat format)) return new(null, "unsupported_content_type"); try {