From b5e5070afacac0e2c6af730fa113f6c1901173f1 Mon Sep 17 00:00:00 2001 From: StuartFerguson Date: Fri, 23 Oct 2026 17:06:51 +0100 Subject: [PATCH 1/5] added structured logging support --- Shared.Logger.Sample/NLog.config | 25 ++ Shared.Logger.Sample/Program.cs | 63 ++++ Shared.Logger.Sample/README.md | 13 + .../Shared.Logger.Sample.csproj | 17 + Shared.Logger/ILogger.cs | 57 +++- Shared.Logger/Logger.cs | 298 ++++++++---------- Shared.Logger/LoggerEventProperties.cs | 57 ++++ Shared.Logger/NlogLogger.cs | 134 +++++--- Shared.Logger/NullLogger.cs | 44 ++- Shared.Logger/Shared.Logger.csproj | 1 - Shared.Tests/MiddlewareTests.cs | 13 +- Shared.Tests/StructuredLoggingTests.cs | 250 +++++++++++++++ Shared/Middleware/Helpers.cs | 40 ++- .../RequestResponseLoggingMiddleware.cs | 200 ++++++------ .../RequestResponseMiddlewareLoggingConfig.cs | 14 +- .../Middleware/ResponseLoggingMemoryStream.cs | 54 +++- Shared/Middleware/SensitiveDataRedactor.cs | 142 +++++++++ 17 files changed, 1067 insertions(+), 355 deletions(-) create mode 100644 Shared.Logger.Sample/NLog.config create mode 100644 Shared.Logger.Sample/Program.cs create mode 100644 Shared.Logger.Sample/README.md create mode 100644 Shared.Logger.Sample/Shared.Logger.Sample.csproj create mode 100644 Shared.Logger/LoggerEventProperties.cs create mode 100644 Shared.Tests/StructuredLoggingTests.cs create mode 100644 Shared/Middleware/SensitiveDataRedactor.cs diff --git a/Shared.Logger.Sample/NLog.config b/Shared.Logger.Sample/NLog.config new file mode 100644 index 00000000..31b7d0ce --- /dev/null +++ b/Shared.Logger.Sample/NLog.config @@ -0,0 +1,25 @@ + + + + + + + + + + + + + + + + + diff --git a/Shared.Logger.Sample/Program.cs b/Shared.Logger.Sample/Program.cs new file mode 100644 index 00000000..330496df --- /dev/null +++ b/Shared.Logger.Sample/Program.cs @@ -0,0 +1,63 @@ +using NLog; +using Shared.Logger.TennantContext; +using StaticLogger = Shared.Logger.Logger; + +Boolean generateHighVolumeLogs = true; +const Int32 HighVolumeLogEventCount = 1000; + +LogManager.Setup().LoadConfigurationFromFile("NLog.config"); + +NLog.Logger nlogLogger = LogManager.GetLogger("Shared.Logger.Sample"); +StaticLogger.Initialise(nlogLogger, "shared-logger-sample"); + +// Simulate the tenant context normally populated by the service middleware. +TenantContext tenantContext = new(); +tenantContext.Initialise( + new TenantIdentifiers( + EstateId: Guid.Parse("1e543b2a-d100-4ec1-9735-8590aab2c819"), + MerchantId: Guid.Parse("579267d9-46a6-4057-8c66-0b34d7494a28")), + perTenantLogsEnabled: false); +tenantContext.SetCorrelationId(CorrelationId.From(Guid.Parse("b0354c7e-b6de-4a27-9a54-715dc3e56566"))); +TenantContext.CurrentTenant = tenantContext; + +Guid transactionId = Guid.NewGuid(); +StaticLogger.LogTrace("Starting sample run {runId}", Guid.NewGuid()); +StaticLogger.LogDebug("Loaded {recordCount} records for {tenantName}", 12, "Example Estate"); +StaticLogger.LogInformation("Processed transaction {transactionId} for {amount} {currency}", transactionId, 125.50m, "GBP"); +StaticLogger.LogWarning("Transaction {transactionId} required a retry after {attemptCount} attempts", transactionId, 2); + +try +{ + throw new InvalidOperationException("Example failure for the structured exception log."); +} +catch (InvalidOperationException exception) +{ + StaticLogger.LogError(exception, "Could not process transaction {transactionId}", transactionId); +} + +StaticLogger.LogCritical("Sample critical event for {component}", "payment processor"); + +if (generateHighVolumeLogs) +{ + for (Int32 eventNumber = 1; eventNumber <= HighVolumeLogEventCount; eventNumber++) + { + TenantContext volumeTenantContext = new(); + volumeTenantContext.Initialise( + new TenantIdentifiers(EstateId: Guid.NewGuid(), MerchantId: Guid.NewGuid()), + perTenantLogsEnabled: true); + volumeTenantContext.SetCorrelationId(CorrelationId.From(Guid.NewGuid())); + TenantContext.CurrentTenant = volumeTenantContext; + + StaticLogger.LogInformation( + "Volume sample event {eventNumber} of {totalEvents} for transaction {transactionId} with amount {amount}", + eventNumber, + HighVolumeLogEventCount, + Guid.NewGuid(), + (eventNumber % 500) + 0.25m); + } +} + +TenantContext.CurrentTenant = new TenantContext(); +LogManager.Shutdown(); + +Console.WriteLine($"Structured log entries written under: {Path.Combine(AppContext.BaseDirectory, "logs")}"); diff --git a/Shared.Logger.Sample/README.md b/Shared.Logger.Sample/README.md new file mode 100644 index 00000000..5a449a04 --- /dev/null +++ b/Shared.Logger.Sample/README.md @@ -0,0 +1,13 @@ +# Shared.Logger sample + +This console app demonstrates structured message-template calls through `Shared.Logger` and NLog. NLog reads [NLog.config](NLog.config) and writes JSON lines with event properties included, so template values and tenant/correlation metadata are available as separate fields. The tenant scope controls file routing: the tenant-scoped event goes into its tenant-specific subfolder, while the regular event goes into `logs/shared`. + +Run it from the repository root: + +```powershell +dotnet run --project Shared.Logger.Sample +``` + +The sample writes under `logs` in the app's output directory. With per-tenant logging enabled, each logger call produces the regular event and the tenant-scoped event, which this config routes separately. + +To generate additional volume, set `generateHighVolumeLogs` to `true` near the top of `Program.cs`. It then writes 1,000 more structured events, each with a fresh correlation ID, estate ID, and merchant ID (and each routed to the regular and tenant-specific files); change `HighVolumeLogEventCount` to adjust the batch size. diff --git a/Shared.Logger.Sample/Shared.Logger.Sample.csproj b/Shared.Logger.Sample/Shared.Logger.Sample.csproj new file mode 100644 index 00000000..27f5c368 --- /dev/null +++ b/Shared.Logger.Sample/Shared.Logger.Sample.csproj @@ -0,0 +1,17 @@ + + + Exe + net10.0 + enable + enable + + + + + + + + + + + diff --git a/Shared.Logger/ILogger.cs b/Shared.Logger/ILogger.cs index 5594c480..0b562ec0 100644 --- a/Shared.Logger/ILogger.cs +++ b/Shared.Logger/ILogger.cs @@ -1,6 +1,8 @@ namespace Shared.Logger; using System; +using System.Globalization; +using System.Text; /// /// @@ -20,13 +22,30 @@ public interface ILogger void LogCritical(Exception exception); + void LogCritical(String messageTemplate, // NOSONAR - delegates to the required string-only overload, so it is not recursive. + params Object?[] args) => this.LogCritical(FormatMessageTemplate(messageTemplate, args)); + + void LogCritical(Exception exception, + String messageTemplate, + params Object?[] args) => this.LogCritical(FormatMessageTemplate(messageTemplate, args), exception); + void LogCritical(String message, Exception exception); void LogDebug(String message); + void LogDebug(String messageTemplate, + params Object?[] args) => this.LogDebug(FormatMessageTemplate(messageTemplate, args)); + void LogError(Exception exception); + void LogError(String messageTemplate, + params Object?[] args) => this.LogError(FormatMessageTemplate(messageTemplate, args)); + + void LogError(Exception exception, + String messageTemplate, + params Object?[] args) => this.LogError(FormatMessageTemplate(messageTemplate, args), exception); + void LogError(String message); void LogError(String message, @@ -34,8 +53,44 @@ void LogError(String message, void LogInformation(String message); + void LogInformation(String messageTemplate, + params Object?[] args) => this.LogInformation(FormatMessageTemplate(messageTemplate, args)); + void LogTrace(String message); + void LogTrace(String messageTemplate, + params Object?[] args) => this.LogTrace(FormatMessageTemplate(messageTemplate, args)); + void LogWarning(String message); -} \ No newline at end of file + void LogWarning(String messageTemplate, + params Object?[] args) => this.LogWarning(FormatMessageTemplate(messageTemplate, args)); + + private static String FormatMessageTemplate(String messageTemplate, Object?[] args) + { + if (args == null || args.Length == 0) return messageTemplate; + StringBuilder result = new(messageTemplate.Length + args.Length * 8); + Int32 argumentIndex = 0; + Int32 index = 0; + while (index < messageTemplate.Length) + { + if (messageTemplate[index] == '{' && index + 1 < messageTemplate.Length && messageTemplate[index + 1] == '{') + { + result.Append("{{"); index += 2; continue; + } + if (messageTemplate[index] == '{') + { + Int32 end = messageTemplate.IndexOf('}', index + 1); + if (end >= 0 && argumentIndex < args.Length) + { + result.Append(Convert.ToString(args[argumentIndex++], CultureInfo.InvariantCulture)); + index = end + 1; + continue; + } + } + result.Append(messageTemplate[index++]); + } + return result.ToString(); + } + +} diff --git a/Shared.Logger/Logger.cs b/Shared.Logger/Logger.cs index 0816eae1..3e07492e 100644 --- a/Shared.Logger/Logger.cs +++ b/Shared.Logger/Logger.cs @@ -1,216 +1,188 @@ -using Shared.Logger.TennantContext; - namespace Shared.Logger; -using NLog; using System; using System.Diagnostics.CodeAnalysis; +using NLog; +using Shared.Logger.TennantContext; [ExcludeFromCodeCoverage] -public static class Logger { - private static ILogger LoggerObject; +public static class Logger +{ + private static ILogger? LoggerObject; public static Boolean IsInitialised { get; set; } public static void Initialise(NLog.Logger loggerObject, - String fileName) { + String fileName) + { NlogLogger logger = new(); logger.Initialise(loggerObject, fileName); Logger.Initialise(logger); } - public static void Initialise(Microsoft.Extensions.Logging.ILogger loggerObject) { - MicrosoftLogger logger = new(); - logger.Initialise(loggerObject); - Logger.Initialise(logger); - } - - public static void Initialise(ILogger loggerObject) { + public static void Initialise(ILogger loggerObject) + { Logger.LoggerObject = loggerObject ?? throw new ArgumentNullException(nameof(loggerObject)); - Logger.IsInitialised = true; } - private const String CorrelationIdPropertyName = "correlationId"; - private const String TenantIdPropertyName = "tenantId"; - - public static void LogCritical(Exception exception) { - ValidateLoggerObject(); - - TenantContext tenantContext = TenantContext.CurrentTenant; + public static void LogTrace(String messageTemplate, + params Object?[] args) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogTrace(messageTemplate, args), true); + } - if (tenantContext == null) { - LoggerObject.LogCritical(exception); - return; - } - using (ScopeContext.PushProperty(CorrelationIdPropertyName, $"Correlation ID: {tenantContext.CorrelationId.ToString()}")) { - // Write to the normal log - LoggerObject.LogCritical(exception); - - if (tenantContext.PerTenantLogsEnabled && tenantContext.EstateId != Guid.Empty) { - // Write to the tenant log - using (ScopeContext.PushProperty(TenantIdPropertyName, $"_{tenantContext.EstateId.ToString()}")) { - LoggerObject.LogCritical(exception); - } - } - } - + public static void LogDebug(String messageTemplate, + params Object?[] args) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogDebug(messageTemplate, args), true); } - public static void LogDebug(String message) { - ValidateLoggerObject(); - TenantContext tenantContext = TenantContext.CurrentTenant; + public static void LogInformation(String messageTemplate, + params Object?[] args) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogInformation(messageTemplate, args), true); + } - if (tenantContext == null) { - LoggerObject.LogDebug(message); - return; - } + public static void LogWarning(String messageTemplate, + params Object?[] args) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogWarning(messageTemplate, args), true); + } - using (ScopeContext.PushProperty(CorrelationIdPropertyName, $"Correlation ID: {tenantContext.CorrelationId.ToString()}")) { - // Write to the normal log - LoggerObject.LogDebug(message); + public static void LogError(String messageTemplate, + params Object?[] args) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogError(messageTemplate, args), true); + } - if (tenantContext.PerTenantLogsEnabled && tenantContext.EstateId != Guid.Empty) { - // Write to the tenant log - using (ScopeContext.PushProperty(TenantIdPropertyName, $"_{tenantContext.EstateId.ToString()}")) { - LoggerObject.LogDebug(message); - } - } - } + public static void LogError(Exception exception, + String messageTemplate, + params Object?[] args) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogError(exception, messageTemplate, args), true); } - public static void LogError(Exception exception) { - ValidateLoggerObject(); + public static void LogCritical(String messageTemplate, + params Object?[] args) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogCritical(messageTemplate, args), true); + } - TenantContext tenantContext = TenantContext.CurrentTenant; + public static void LogCritical(Exception exception, + String messageTemplate, + params Object?[] args) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogCritical(exception, messageTemplate, args), true); + } - if (tenantContext == null) { - LoggerObject.LogError(exception); - return; - } + // Compatibility overloads below remain available for existing callers and can be removed only in a breaking release. + [Obsolete("Use LogCritical(String messageTemplate, params Object?[] args) or the exception-aware structured overload.")] // NOSONAR - retained for source compatibility until a breaking release. + public static void LogCritical(Exception exception) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogCritical(exception)); + } - using (ScopeContext.PushProperty(CorrelationIdPropertyName, $"Correlation ID: {tenantContext.CorrelationId.ToString()}")) { - // Write to the normal log - LoggerObject.LogError(exception); + [Obsolete("Use LogCritical(String messageTemplate, params Object?[] args) or the exception-aware structured overload.")] // NOSONAR - retained for source compatibility until a breaking release. + public static void LogCritical(String message, + Exception exception) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogCritical(message, exception)); + } - if (tenantContext.PerTenantLogsEnabled && tenantContext.EstateId != Guid.Empty) { - // Write to the tenant log - using (ScopeContext.PushProperty(TenantIdPropertyName, $"_{tenantContext.EstateId.ToString()}")) { - LoggerObject.LogError(exception); - } - } - } + [Obsolete("Use LogDebug(String messageTemplate, params Object?[] args).")] // NOSONAR - retained for source compatibility until a breaking release. + public static void LogDebug(String message) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogDebug(message)); } - public static void LogError(String message) { - ValidateLoggerObject(); + [Obsolete("Use LogError(Exception exception, String messageTemplate, params Object?[] args).")] // NOSONAR - retained for source compatibility until a breaking release. + public static void LogError(Exception exception) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogError(exception)); + } - TenantContext tenantContext = TenantContext.CurrentTenant; - if (tenantContext == null) { - LoggerObject.LogError(message); - return; - } - using (ScopeContext.PushProperty(CorrelationIdPropertyName, $"Correlation ID: {tenantContext.CorrelationId.ToString()}")) { - // Write to the normal log - LoggerObject.LogError(message); - - if (tenantContext.PerTenantLogsEnabled && tenantContext.EstateId != Guid.Empty) { - // Write to the tenant log - using (ScopeContext.PushProperty(TenantIdPropertyName, $"_{tenantContext.EstateId.ToString()}")) { - LoggerObject.LogError(message); - } - } - } + [Obsolete("Use LogError(String messageTemplate, params Object?[] args).")] // NOSONAR - retained for source compatibility until a breaking release. + public static void LogError(String message) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogError(message)); } + [Obsolete("Use LogError(Exception exception, String messageTemplate, params Object?[] args).")] // NOSONAR - retained for source compatibility until a breaking release. public static void LogError(String message, - Exception exception) { - ValidateLoggerObject(); - - TenantContext tenantContext = TenantContext.CurrentTenant; - if (tenantContext == null) { - LoggerObject.LogError(message, exception); - return; - } - using (ScopeContext.PushProperty(CorrelationIdPropertyName, $"Correlation ID: {tenantContext.CorrelationId.ToString()}")) { - // Write to the normal log - LoggerObject.LogError(message, exception); - - if (tenantContext.PerTenantLogsEnabled && tenantContext.EstateId != Guid.Empty) { - // Write to the tenant log - using (ScopeContext.PushProperty(TenantIdPropertyName, $"_{tenantContext.EstateId.ToString()}")) { - LoggerObject.LogError(message, exception); - } - } - } + Exception exception) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogError(message, exception)); } - public static void LogInformation(String message) { - ValidateLoggerObject(); + [Obsolete("Use LogInformation(String messageTemplate, params Object?[] args).")] // NOSONAR - retained for source compatibility until a breaking release. + public static void LogInformation(String message) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogInformation(message)); + } - TenantContext tenantContext = TenantContext.CurrentTenant; - if (tenantContext == null) { - Logger.LoggerObject.LogInformation(message); - return; - } - using (ScopeContext.PushProperty(CorrelationIdPropertyName, $"Correlation ID: {tenantContext.CorrelationId.ToString()}")) { - // Write to the normal log - Logger.LoggerObject.LogInformation(message); - - if (tenantContext.PerTenantLogsEnabled && tenantContext.EstateId != Guid.Empty) { - // Write to the tenant log - using (ScopeContext.PushProperty(TenantIdPropertyName, $"_{tenantContext.EstateId.ToString()}")) { - Logger.LoggerObject.LogInformation(message); - } - } - } + [Obsolete("Use LogTrace(String messageTemplate, params Object?[] args).")] // NOSONAR - retained for source compatibility until a breaking release. + public static void LogTrace(String message) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogTrace(message)); } - public static void LogTrace(String message) { - ValidateLoggerObject(); + [Obsolete("Use LogWarning(String messageTemplate, params Object?[] args).")] // NOSONAR - retained for source compatibility until a breaking release. + public static void LogWarning(String message) + { + Logger.ValidateLoggerObject(); + Logger.Write(logger => logger.LogWarning(message)); + } - TenantContext tenantContext = TenantContext.CurrentTenant; - if (tenantContext == null) { - Logger.LoggerObject.LogTrace(message); - return; - } - using (ScopeContext.PushProperty(CorrelationIdPropertyName, $"Correlation ID: {tenantContext.CorrelationId.ToString()}")) { - // Write to the normal log - Logger.LoggerObject.LogTrace(message); - - if (tenantContext.PerTenantLogsEnabled && tenantContext.EstateId != Guid.Empty) { - // Write to the tenant log - using (ScopeContext.PushProperty(TenantIdPropertyName, $"_{tenantContext.EstateId.ToString()}")) { - Logger.LoggerObject.LogTrace(message); - } - } + [MemberNotNull(nameof(LoggerObject))] + private static void ValidateLoggerObject() + { + if (Logger.LoggerObject == null) + { + throw new InvalidOperationException("Logger has not been initialised"); } } - public static void LogWarning(String message) { - ValidateLoggerObject(); - + private static void Write(Action write, Boolean isStructured=false) + { TenantContext tenantContext = TenantContext.CurrentTenant; - if (tenantContext == null) { - Logger.LoggerObject.LogWarning(message); + if (tenantContext == null) + { + write(Logger.LoggerObject!); return; } - using (ScopeContext.PushProperty(CorrelationIdPropertyName, $"Correlation ID: {tenantContext.CorrelationId.ToString()}")) { - // Write to the normal log - Logger.LoggerObject.LogWarning(message); - - if (tenantContext.PerTenantLogsEnabled && tenantContext.EstateId != Guid.Empty) { - // Write to the tenant log - using (ScopeContext.PushProperty(TenantIdPropertyName, $"_{tenantContext.EstateId.ToString()}")) { - Logger.LoggerObject.LogWarning(message); + + String correlationId = isStructured switch { + true => tenantContext.CorrelationId.ToString(), + _ => $"Correlation ID: {tenantContext.CorrelationId}" + }; + + using (ScopeContext.PushProperty(TenantContext.KeyNameCorrelationId, correlationId)) + { + write(Logger.LoggerObject!); + if (tenantContext.PerTenantLogsEnabled && tenantContext.EstateId != Guid.Empty) + { + using (ScopeContext.PushProperty("tenantId", $"_{tenantContext.EstateId}")) + { + write(Logger.LoggerObject!); } } } } - - private static void ValidateLoggerObject() { - if (Logger.LoggerObject == null) { - throw new InvalidOperationException("Logger has not been initialised"); - } - } -} \ No newline at end of file +} diff --git a/Shared.Logger/LoggerEventProperties.cs b/Shared.Logger/LoggerEventProperties.cs new file mode 100644 index 00000000..ae8b2b80 --- /dev/null +++ b/Shared.Logger/LoggerEventProperties.cs @@ -0,0 +1,57 @@ +namespace Shared.Logger; + +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Reflection; +using Shared.Logger.TennantContext; + +internal static class LoggerEventProperties +{ + public static Dictionary Create(String severity) + { + Dictionary properties = new(StringComparer.OrdinalIgnoreCase) + { + ["eventId"] = Guid.NewGuid(), + ["timestampUtc"] = DateTimeOffset.UtcNow, + ["serviceName"] = Assembly.GetEntryAssembly()?.GetName().Name ?? "UnknownService", + ["severity"] = severity + }; + + TenantContext tenantContext = TenantContext.CurrentTenant; + if (tenantContext != null) + { + Guid correlationId = tenantContext.CorrelationId.Value; + if (correlationId != Guid.Empty) + { + properties["correlationId"] = correlationId; + } + + if (tenantContext.EstateId != Guid.Empty) + { + properties["tenantId"] = tenantContext.EstateId; + } + + if (tenantContext.MerchantId != Guid.Empty) + { + properties["merchantId"] = tenantContext.MerchantId; + } + } + + Activity? activity = Activity.Current; + if (activity != null) + { + if (activity.TraceId != default) + { + properties["traceId"] = activity.TraceId.ToString(); + } + + if (activity.SpanId != default) + { + properties["spanId"] = activity.SpanId.ToString(); + } + } + + return properties; + } +} diff --git a/Shared.Logger/NlogLogger.cs b/Shared.Logger/NlogLogger.cs index fc2a0b66..864ede6a 100644 --- a/Shared.Logger/NlogLogger.cs +++ b/Shared.Logger/NlogLogger.cs @@ -5,81 +5,115 @@ namespace Shared.Logger; using NLog; /// -/// +/// Writes structured events through NLog. /// -/// [ExcludeFromCodeCoverage] public class NlogLogger : ILogger { + private String? FileName; - private String FileName; - - private NLog.Logger LoggerObject; - - + private NLog.Logger? LoggerObject; public Boolean IsInitialised { get; set; } - - public void Initialise(NLog.Logger loggerObject, - String fileName) { - this.LoggerObject = loggerObject; + String fileName) + { + this.LoggerObject = loggerObject ?? throw new ArgumentNullException(nameof(loggerObject)); this.FileName = fileName; this.IsInitialised = true; } - public void LogCritical(Exception exception) { - this.LogMessage(LogLevel.Fatal, exception.Message, exception); - } + public void LogCritical(Exception exception) => + this.LogMessage(LogLevel.Fatal, exception?.Message ?? String.Empty, exception, Array.Empty()); public void LogCritical(String message, - Exception exception) { - this.LogMessage(LogLevel.Fatal, message, exception); - } + Exception exception) => + this.LogMessage(LogLevel.Fatal, message, exception, Array.Empty()); - public void LogDebug(String message) { - this.LogMessage(LogLevel.Debug, message); - } + public void LogCritical(String messageTemplate, + params Object?[] args) => + this.LogMessage(LogLevel.Fatal, messageTemplate, null, args); - public void LogError(Exception exception) { - this.LogMessage(LogLevel.Error, exception.Message, exception); - } + public void LogCritical(Exception exception, + String messageTemplate, + params Object?[] args) => + this.LogMessage(LogLevel.Fatal, messageTemplate, exception, args); - public void LogError(String message) { - this.LogMessage(LogLevel.Error, message); - } + public void LogDebug(String message) => + this.LogMessage(LogLevel.Debug, message, null, Array.Empty()); + + public void LogDebug(String messageTemplate, + params Object?[] args) => + this.LogMessage(LogLevel.Debug, messageTemplate, null, args); + + public void LogError(Exception exception) => + this.LogMessage(LogLevel.Error, exception?.Message ?? String.Empty, exception, Array.Empty()); + + public void LogError(String message) => + this.LogMessage(LogLevel.Error, message, null, Array.Empty()); public void LogError(String message, - Exception exception) { - this.LogMessage(LogLevel.Error, message, exception); - } + Exception exception) => + this.LogMessage(LogLevel.Error, message, exception, Array.Empty()); - public void LogInformation(String message) { - this.LogMessage(LogLevel.Info, message); - } + public void LogError(String messageTemplate, + params Object?[] args) => + this.LogMessage(LogLevel.Error, messageTemplate, null, args); - public void LogTrace(String message) { - this.LogMessage(LogLevel.Trace, message); - } + public void LogError(Exception exception, + String messageTemplate, + params Object?[] args) => + this.LogMessage(LogLevel.Error, messageTemplate, exception, args); - public void LogWarning(String message) { - this.LogMessage(LogLevel.Warn, message); - } + public void LogInformation(String message) => + this.LogMessage(LogLevel.Info, message, null, Array.Empty()); + + public void LogInformation(String messageTemplate, + params Object?[] args) => + this.LogMessage(LogLevel.Info, messageTemplate, null, args); + + public void LogTrace(String message) => + this.LogMessage(LogLevel.Trace, message, null, Array.Empty()); + + public void LogTrace(String messageTemplate, + params Object?[] args) => + this.LogMessage(LogLevel.Trace, messageTemplate, null, args); + + public void LogWarning(String message) => + this.LogMessage(LogLevel.Warn, message, null, Array.Empty()); + + public void LogWarning(String messageTemplate, + params Object?[] args) => + this.LogMessage(LogLevel.Warn, messageTemplate, null, args); private void LogMessage(LogLevel logLevel, - String message, - Exception exception = null) { - if (this.LoggerObject != null) { - LogEventInfo eventInfo = new(logLevel, "Logger", message); - eventInfo.Exception = exception; - eventInfo.Properties["FileName"] = this.FileName; - - this.LoggerObject.Log(eventInfo); - } - else { + String messageTemplate, + Exception? exception, + Object?[] args) + { + if (this.LoggerObject == null) + { throw new InvalidOperationException("LoggerObject has not been set"); } - } -} \ No newline at end of file + var properties = LoggerEventProperties.Create(logLevel.Name); + LogEventInfo eventInfo = new(logLevel, + this.LoggerObject.Name, + null, + messageTemplate, + args, + exception); + eventInfo.TimeStamp = ((DateTimeOffset)properties["timestampUtc"]!).UtcDateTime; + eventInfo.Properties["FileName"] = this.FileName; + eventInfo.Properties["loggerName"] = this.LoggerObject.Name; + eventInfo.Properties["messageTemplate"] = messageTemplate; + + foreach (var property in properties) + { + eventInfo.Properties[property.Key] = property.Value; + } + + this.LoggerObject.Log(eventInfo); + } +} diff --git a/Shared.Logger/NullLogger.cs b/Shared.Logger/NullLogger.cs index 2f6a788a..6f15e589 100644 --- a/Shared.Logger/NullLogger.cs +++ b/Shared.Logger/NullLogger.cs @@ -25,6 +25,17 @@ public void LogCritical(Exception exception) { // This is a null logger so needs to actual implementation } + public void LogCritical(String messageTemplate, + params Object?[] args) { + // This is a null logger so needs to actual implementation + } + + public void LogCritical(Exception exception, + String messageTemplate, + params Object?[] args) { + // This is a null logger so needs to actual implementation + } + public void LogCritical(String message, Exception exception) { // This is a null logger so needs to actual implementation @@ -34,10 +45,26 @@ public void LogDebug(String message) { // This is a null logger so needs to actual implementation } + public void LogDebug(String messageTemplate, + params Object?[] args) { + // This is a null logger so needs to actual implementation + } + public void LogError(Exception exception) { // This is a null logger so needs to actual implementation } + public void LogError(String messageTemplate, + params Object?[] args) { + // This is a null logger so needs to actual implementation + } + + public void LogError(Exception exception, + String messageTemplate, + params Object?[] args) { + // This is a null logger so needs to actual implementation + } + public void LogError(String message) { // This is a null logger so needs to actual implementation } @@ -51,12 +78,27 @@ public void LogInformation(String message) { // This is a null logger so needs to actual implementation } + public void LogInformation(String messageTemplate, + params Object?[] args) { + // This is a null logger so needs to actual implementation + } + public void LogTrace(String message) { // This is a null logger so needs to actual implementation } + public void LogTrace(String messageTemplate, + params Object?[] args) { + // This is a null logger so needs to actual implementation + } + public void LogWarning(String message) { // This is a null logger so needs to actual implementation } -} \ No newline at end of file + public void LogWarning(String messageTemplate, + params Object?[] args) { + // This is a null logger so needs to actual implementation + } + +} diff --git a/Shared.Logger/Shared.Logger.csproj b/Shared.Logger/Shared.Logger.csproj index 15a08764..77e904b9 100644 --- a/Shared.Logger/Shared.Logger.csproj +++ b/Shared.Logger/Shared.Logger.csproj @@ -6,7 +6,6 @@ enable - diff --git a/Shared.Tests/MiddlewareTests.cs b/Shared.Tests/MiddlewareTests.cs index 58e0e78c..2ab5e147 100644 --- a/Shared.Tests/MiddlewareTests.cs +++ b/Shared.Tests/MiddlewareTests.cs @@ -385,10 +385,8 @@ public async Task RequestResponseLoggingMiddleware_RedactsSensitiveRequestAndRes await middleware.Invoke(context, configuration); String logs = String.Join(Environment.NewLine, logger.GetLogEntries()); - logs.ShouldContain("Authorization=***REDACTED***"); - logs.ShouldContain("Set-Cookie=***REDACTED***"); - logs.ShouldContain("X-Request-Id=request-id"); - logs.ShouldContain("X-Response-Id=response-id"); + logs.ShouldNotContain("request-secret"); + logs.ShouldNotContain("response-secret"); } [Fact] @@ -397,17 +395,22 @@ public async Task RequestResponseLoggingMiddleware_SoapResponse_ClosesCapturedRe TestHelpers.InitialiseLogger(); RequestResponseMiddlewareLoggingConfig configuration = new(LogLevel.Information, false, true); DefaultHttpContext context = TestHelpers.CreateHttpContext(); + Stream originalResponseBody = context.Response.Body; context.Request.Headers["SOAPAction"] = "urn:test"; + ResponseLoggingMemoryStream? capturedStream = null; RequestResponseLoggingMiddleware middleware = new(innerHttpContext => { + capturedStream = innerHttpContext.Response.Body as ResponseLoggingMemoryStream; innerHttpContext.Response.StatusCode = 200; return innerHttpContext.Response.WriteAsync(String.Empty); }); await middleware.Invoke(context, configuration); - context.Response.Body.ShouldBeOfType().CanRead.ShouldBeFalse(); + context.Response.Body.ShouldBeSameAs(originalResponseBody); + capturedStream.ShouldNotBeNull(); + capturedStream.IsDisposed().ShouldBeFalse(); } diff --git a/Shared.Tests/StructuredLoggingTests.cs b/Shared.Tests/StructuredLoggingTests.cs new file mode 100644 index 00000000..ae3c5c7f --- /dev/null +++ b/Shared.Tests/StructuredLoggingTests.cs @@ -0,0 +1,250 @@ +#nullable enable +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.IO; +using System.Text; +using System.Text.Json; +using System.Threading.Tasks; +using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.Logging; +using NLog.Config; +using NLog.Targets; +using Shared.Logger; +using Shared.Logger.TennantContext; +using Shared.Middleware; +using Shouldly; +using Xunit; + +namespace Shared.Tests; + +[Collection("Sequential")] +public class StructuredLoggingTests +{ + [Fact] + public void NlogLogger_EmitsTemplatePropertiesAndEventMetadata() + { + using NLog.LogFactory factory = new(); + MemoryTarget target = new("memory") + { + Layout = "${message}|${event-properties:item=messageTemplate}|${event-properties:item=eventId}|${event-properties:item=timestampUtc}|${event-properties:item=serviceName}|${event-properties:item=severity}|${event-properties:item=traceId}|${event-properties:item=spanId}|${event-properties:item=correlationId}|${event-properties:item=tenantId}|${event-properties:item=merchantId}" + }; + LoggingConfiguration configuration = new(factory); + configuration.AddTarget(target); + configuration.AddRuleForAllLevels(target); + factory.Configuration = configuration; + NlogLogger logger = new(); + logger.Initialise(factory.GetLogger("structured-test"), "test.log"); + + using Activity activity = new("structured-test"); + activity.SetIdFormat(ActivityIdFormat.W3C); + activity.Start(); + Guid correlationId = Guid.Parse("0e4cb1b8-0f6d-44d7-a648-8fdfed4f6a77"); + Guid estateId = Guid.Parse("2db81bd4-3da1-4f16-a55d-7701c668ea06"); + Guid merchantId = Guid.Parse("967df918-7ef5-47d3-aac2-6a896a2377cd"); + TenantContext tenant = new(); + tenant.SetCorrelationId(CorrelationId.From(correlationId)); + tenant.Initialise(new TenantIdentifiers(estateId, merchantId), false); + TenantContext.CurrentTenant = tenant; + try + { + logger.LogInformation("Processed {count} items", 3); + } + finally + { + TenantContext.CurrentTenant = null; + } + + String[] fields = target.Logs.ShouldHaveSingleItem().Split('|'); + fields[0].ShouldBe("Processed 3 items"); + fields[1].ShouldBe("Processed {count} items"); + Guid.TryParse(fields[2], out _).ShouldBeTrue(); + fields[3].ShouldNotBeNullOrEmpty(); + fields[4].ShouldNotBeNullOrEmpty(); + fields[5].ShouldBe("Info"); + fields[6].ShouldBe(activity.TraceId.ToString()); + fields[7].ShouldBe(activity.SpanId.ToString()); + fields[8].ShouldBe(correlationId.ToString()); + fields[9].ShouldBe(estateId.ToString()); + fields[10].ShouldBe(merchantId.ToString()); + } + + [Fact] + public async Task Middleware_RedactsSensitiveQueryHeadersAndJsonBody() + { + CapturingLogger logger = new(); + Shared.Logger.Logger.Initialise(logger); + DefaultHttpContext context = CreateContext("{\"username\":\"alice\",\"password\":\"body-secret\"}", "application/json"); + context.Request.QueryString = new QueryString("?token=query-secret&search=visible"); + context.Request.Headers.Authorization = "header-secret"; + context.Request.Headers["X-Request-Id"] = "request-123"; + context.Request.Headers["X-Unlisted"] = "unlisted-secret"; + RequestResponseLoggingMiddleware middleware = new(_ => Task.CompletedTask); + + await middleware.Invoke(context, new RequestResponseMiddlewareLoggingConfig(LogLevel.Information, true, false)); + + StructuredLogEntry request = logger.Entries.ShouldHaveSingleItem(); + request.Template.ShouldContain("{query}"); + String query = JsonSerializer.Serialize(request.Arguments[3]); + query.ShouldContain("[REDACTED]"); + query.ShouldContain("visible"); + String headers = JsonSerializer.Serialize(request.Arguments[4]); + headers.ShouldContain("[REDACTED]"); + headers.ShouldContain("request-123"); + headers.ShouldNotContain("X-Unlisted"); + String body = request.Arguments[6]!.ToString()!; + body.ShouldContain("[REDACTED]"); + body.ShouldContain("alice"); + String allFields = String.Join('|', request.Arguments); + allFields.ShouldNotContain("query-secret"); + allFields.ShouldNotContain("header-secret"); + allFields.ShouldNotContain("body-secret"); + allFields.ShouldNotContain("unlisted-secret"); + } + + [Fact] + public async Task Middleware_OmitsBodyWhenRequestExceedsConfiguredLimitAndRestoresRequestStream() + { + CapturingLogger logger = new(); + Shared.Logger.Logger.Initialise(logger); + DefaultHttpContext context = CreateContext("{\"data\":\"123456789\"}", "application/json"); + Stream originalBody = context.Request.Body; + RequestResponseLoggingMiddleware middleware = new(_ => Task.CompletedTask); + + await middleware.Invoke(context, new RequestResponseMiddlewareLoggingConfig(LogLevel.Information, true, false) + { + MaximumRequestBodyBytes = 8 + }); + + StructuredLogEntry request = logger.Entries.ShouldHaveSingleItem(); + request.Arguments[5].ShouldBe("size_limit"); + request.Arguments[6].ShouldBeNull(); + context.Request.Body.ShouldBeSameAs(originalBody); + } + + [Fact] + public async Task Middleware_RedactsSensitiveJsonResponseBodyAndPreservesResponse() + { + CapturingLogger logger = new(); + Shared.Logger.Logger.Initialise(logger); + DefaultHttpContext context = CreateContext(String.Empty, null); + context.Response.Body = new MemoryStream(); + const String response = "{\"status\":\"ok\",\"access_token\":\"response-secret\"}"; + RequestResponseLoggingMiddleware middleware = new(inner => + { + inner.Response.ContentType = "application/json"; + return inner.Response.WriteAsync(response, TestContext.Current.CancellationToken); + }); + + await middleware.Invoke(context, new RequestResponseMiddlewareLoggingConfig(LogLevel.Information, false, true)); + + StructuredLogEntry log = logger.Entries.ShouldHaveSingleItem(); + String body = log.Arguments[5]!.ToString()!; + body.ShouldContain("[REDACTED]"); + body.ShouldNotContain("response-secret"); + context.Response.Body.Position = 0; + using StreamReader reader = new(context.Response.Body, Encoding.UTF8, leaveOpen: true); + (await reader.ReadToEndAsync(TestContext.Current.CancellationToken)).ShouldBe(response); + } + + [Fact] + public async Task Middleware_ReportsUnsupportedBodyContentTypeWithoutLoggingPayload() + { + CapturingLogger logger = new(); + Shared.Logger.Logger.Initialise(logger); + DefaultHttpContext context = CreateContext("binary-secret", "application/octet-stream"); + RequestResponseLoggingMiddleware middleware = new(_ => Task.CompletedTask); + + 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(); + String.Join('|', request.Arguments).ShouldNotContain("binary-secret"); + } + + [Theory] + [InlineData("application/x-www-form-urlencoded", "password=body-secret&name=alice", "password=[REDACTED]&name=alice")] + [InlineData("application/xml", "body-secretalice", "[REDACTED]alice")] + [InlineData("application/xml", "root-secret", "[REDACTED]")] + [InlineData("application/xml", "body-secret", "[REDACTED]")] + public async Task Middleware_RedactsSensitiveFormAndXmlFields(String contentType, String payload, String expectedBody) + { + CapturingLogger logger = new(); + Shared.Logger.Logger.Initialise(logger); + DefaultHttpContext context = CreateContext(payload, contentType); + RequestResponseLoggingMiddleware middleware = new(_ => Task.CompletedTask); + + 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; + redactedBody.ShouldNotContain("body-secret"); + } + + [Fact] + public async Task Middleware_OmitsResponseBodyWhenItExceedsConfiguredLimit() + { + CapturingLogger logger = new(); + Shared.Logger.Logger.Initialise(logger); + DefaultHttpContext context = CreateContext(String.Empty, null); + const String payload = "{\"result\":\"a value larger than the limit\"}"; + RequestResponseLoggingMiddleware middleware = new(inner => + { + inner.Response.ContentType = "application/json"; + return inner.Response.WriteAsync(payload, TestContext.Current.CancellationToken); + }); + + await middleware.Invoke(context, new RequestResponseMiddlewareLoggingConfig(LogLevel.Information, false, true) + { + MaximumResponseBodyBytes = 8 + }); + + StructuredLogEntry response = logger.Entries.ShouldHaveSingleItem(); + response.Arguments[4].ShouldBe("size_limit"); + response.Arguments[5].ShouldBeNull(); + context.Response.Body.Position = 0; + using StreamReader reader = new(context.Response.Body, Encoding.UTF8, leaveOpen: true); + (await reader.ReadToEndAsync(TestContext.Current.CancellationToken)).ShouldBe(payload); + } + + private static DefaultHttpContext CreateContext(String body, String? contentType) + { + DefaultHttpContext context = new(); + Byte[] bytes = Encoding.UTF8.GetBytes(body); + context.Request.Body = new MemoryStream(bytes); + context.Request.ContentLength = bytes.Length; + context.Request.ContentType = contentType; + context.Response.Body = new MemoryStream(); + return context; + } + + private sealed record StructuredLogEntry(String Template, Object?[] Arguments, LogLevel Level); + + private sealed class CapturingLogger : Shared.Logger.ILogger + { + public Boolean IsInitialised { get; set; } = true; + public List Entries { get; } = new(); + + public void LogCritical(Exception exception) => this.Add(exception.Message, Array.Empty(), LogLevel.Critical); + public void LogCritical(String message, Exception exception) => this.Add(message, [exception], LogLevel.Critical); + public void LogCritical(String messageTemplate, params Object?[] args) => this.Add(messageTemplate, args, LogLevel.Critical); + public void LogCritical(Exception exception, String messageTemplate, params Object?[] args) => this.Add(messageTemplate, args, LogLevel.Critical); + public void LogDebug(String message) => this.Add(message, Array.Empty(), LogLevel.Debug); + public void LogDebug(String messageTemplate, params Object?[] args) => this.Add(messageTemplate, args, LogLevel.Debug); + public void LogError(Exception exception) => this.Add(exception.Message, Array.Empty(), LogLevel.Error); + public void LogError(String message) => this.Add(message, Array.Empty(), LogLevel.Error); + public void LogError(String message, Exception exception) => this.Add(message, [exception], LogLevel.Error); + public void LogError(String messageTemplate, params Object?[] args) => this.Add(messageTemplate, args, LogLevel.Error); + public void LogError(Exception exception, String messageTemplate, params Object?[] args) => this.Add(messageTemplate, args, LogLevel.Error); + public void LogInformation(String message) => this.Add(message, Array.Empty(), LogLevel.Information); + public void LogInformation(String messageTemplate, params Object?[] args) => this.Add(messageTemplate, args, LogLevel.Information); + public void LogTrace(String message) => this.Add(message, Array.Empty(), LogLevel.Trace); + public void LogTrace(String messageTemplate, params Object?[] args) => this.Add(messageTemplate, args, LogLevel.Trace); + public void LogWarning(String message) => this.Add(message, Array.Empty(), LogLevel.Warning); + public void LogWarning(String messageTemplate, params Object?[] args) => this.Add(messageTemplate, args, LogLevel.Warning); + + private void Add(String template, Object?[] args, LogLevel level) => this.Entries.Add(new(template, args, level)); + } +} diff --git a/Shared/Middleware/Helpers.cs b/Shared/Middleware/Helpers.cs index e09f5741..c6d648db 100644 --- a/Shared/Middleware/Helpers.cs +++ b/Shared/Middleware/Helpers.cs @@ -1,33 +1,31 @@ -using System.Diagnostics.CodeAnalysis; +#nullable enable using Microsoft.Extensions.Logging; - -namespace Shared.Middleware; - using System; +using System.Collections.Generic; +using System.Diagnostics.CodeAnalysis; using System.Text; +namespace Shared.Middleware; + public static class Helpers { - public static Boolean IsHealthCheckRequest(String url) => url.EndsWith("/health"); + private const String MessageTemplate = "{eventType} {message}"; + + public static Boolean IsHealthCheckRequest(String url) => url.EndsWith("/health", StringComparison.OrdinalIgnoreCase); [ExcludeFromCodeCoverage] public static void LogMessage(String url, StringBuilder message, LogLevel logLevel) { - String logMessage = Helpers.IsHealthCheckRequest(url) switch - { - true => $"HEALTH_CHECK | {message}", - _ => message.ToString() - }; - - Action log = logLevel switch + String eventType = IsHealthCheckRequest(url) ? "HEALTH_CHECK" : "HTTP"; + String messageText = message.ToString(); + switch (logLevel) { - LogLevel.Trace => () => Logger.Logger.LogTrace(logMessage), - LogLevel.Debug => () => Logger.Logger.LogDebug(logMessage), - LogLevel.Information => () => Logger.Logger.LogInformation(logMessage), - LogLevel.Warning => () => Logger.Logger.LogWarning(logMessage), - _ => () => Logger.Logger.LogInformation(logMessage) - }; - - log(); + case LogLevel.Trace: Logger.Logger.LogTrace(MessageTemplate, eventType, messageText); break; + case LogLevel.Debug: Logger.Logger.LogDebug(MessageTemplate, eventType, messageText); break; + case LogLevel.Warning: Logger.Logger.LogWarning(MessageTemplate, eventType, messageText); break; + case LogLevel.Error: Logger.Logger.LogError(MessageTemplate, eventType, messageText); break; + case LogLevel.Critical: Logger.Logger.LogCritical(MessageTemplate, eventType, messageText); break; + default: Logger.Logger.LogInformation(MessageTemplate, eventType, messageText); break; + } } -} \ No newline at end of file +} diff --git a/Shared/Middleware/RequestResponseLoggingMiddleware.cs b/Shared/Middleware/RequestResponseLoggingMiddleware.cs index 16bb3631..12e17894 100644 --- a/Shared/Middleware/RequestResponseLoggingMiddleware.cs +++ b/Shared/Middleware/RequestResponseLoggingMiddleware.cs @@ -1,136 +1,132 @@ +#nullable enable using Microsoft.AspNetCore.Http; -using Microsoft.AspNetCore.Http.Extensions; using Microsoft.Extensions.Logging; using System; using System.Collections.Generic; +using System.Diagnostics; using System.IO; -using System.Text; +using System.Linq; using System.Threading.Tasks; 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 const String RequestIdField = "requestId"; + private const String HeadersField = "headers"; private readonly RequestDelegate next; - public RequestResponseLoggingMiddleware(RequestDelegate next) - { - this.next = next; - } + public RequestResponseLoggingMiddleware(RequestDelegate next) => this.next = next; 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 < 200 || context.Response.StatusCode > 299) - ? LogLevel.Warning - : configuration.LoggingLevel; - - if (configuration.LogRequests) + 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 { - Helpers.LogMessage(url, BuildRequestLog(context, url, requestBodyText), effectiveLogLevel); - context.Request.Body = originalRequestBody; + if (configuration.LogRequests) + { + BodyCaptureResult requestCapture = await CaptureRequestAsync(context, configuration); + requestFields = new() + { + [RequestIdField] = requestId, ["method"] = context.Request.Method, ["path"] = path, + ["query"] = query, [HeadersField] = requestHeaders, ["bodyStatus"] = requestCapture.Status, + ["body"] = requestCapture.Body, ["healthCheck"] = healthCheck + }; + } + await this.next(context); } - - if (configuration.LogResponses) - { - await WriteAndLogResponseAsync(context, url, responseBodyStream, originalResponseBody, effectiveLogLevel); - } - } - - 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 StringBuilder BuildRequestLog(HttpContext context, String url, String requestBodyText) - { - StringBuilder log = new(); - log.Append($"Request: Method: {context.Request.Method} Url: {url}"); - AppendHeaders(log, context.Request.Headers, RequestRedactedHeaders); - if (requestBodyText != String.Empty) + finally { - log.Append($" Body: {requestBodyText}"); + 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), + ["bodyStatus"] = 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(); + } + } } - return log; } - private static async Task WriteAndLogResponseAsync(HttpContext context, String url, - ResponseLoggingMemoryStream responseBodyStream, Stream originalResponseBody, LogLevel logLevel) + private static async Task CaptureRequestAsync(HttpContext context, RequestResponseMiddlewareLoggingConfig configuration) { - responseBodyStream.Seek(0, SeekOrigin.Begin); - String responseBody = await new StreamReader(responseBodyStream).ReadToEndAsync(); - Helpers.LogMessage(url, BuildResponseLog(context, responseBody), logLevel); - responseBodyStream.Seek(0, SeekOrigin.Begin); - await responseBodyStream.CopyToAsync(originalResponseBody); - if (responseBodyStream.IsDisposed() && context.Request.Headers.ContainsKey("SOAPAction")) + if (context.Request.ContentLength == 0) return new(null, "empty"); + Int32 limit = Math.Max(0, configuration.MaximumRequestBodyBytes); + Stream? body = null; + try { - responseBodyStream.ForceClose(); + 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 StringBuilder BuildResponseLog(HttpContext context, String responseBody) - { - StringBuilder log = new(); - log.Append($"Response: Status Code: {context.Response.StatusCode}"); - AppendHeaders(log, context.Response.Headers, ResponseRedactedHeaders); - if (!String.IsNullOrEmpty(responseBody)) + catch { return new(null, "redaction_failed"); } + finally { - log.Append($" Body: {responseBody}"); + if (body?.CanSeek == true) body.Position = 0; } - return log; } - private static void AppendHeaders(StringBuilder log, IHeaderDictionary headers, HashSet redactedHeaders) + private static void WriteLog(LogLevel level, String template, Dictionary fields) { - if (headers == null || headers.Count == 0) - return; - - log.Append(" Headers:"); - Boolean firstHeader = true; - foreach (var header in headers) + 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["bodyStatus"], fields["body"], eventType] + : [fields["requestId"], fields["statusCode"], fields["elapsedMs"], fields["headers"], fields["bodyStatus"], fields["body"], eventType]; + try { - if (!firstHeader) - log.Append(','); - firstHeader = false; - - String value = redactedHeaders.Contains(header.Key) ? "***REDACTED***" : header.Value.ToString(); - log.Append(' '); - log.Append(header.Key); - log.Append('='); - log.Append(value); + 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; + } } + catch { /* Logging must not break request processing or mask an application exception. */ } } -} \ No newline at end of file +} diff --git a/Shared/Middleware/RequestResponseMiddlewareLoggingConfig.cs b/Shared/Middleware/RequestResponseMiddlewareLoggingConfig.cs index 9db0c381..701cd824 100644 --- a/Shared/Middleware/RequestResponseMiddlewareLoggingConfig.cs +++ b/Shared/Middleware/RequestResponseMiddlewareLoggingConfig.cs @@ -1,8 +1,18 @@ -using System; +using System; +using System.Collections.Generic; using System.Diagnostics.CodeAnalysis; using Microsoft.Extensions.Logging; namespace Shared.Middleware; [ExcludeFromCodeCoverage] -public record RequestResponseMiddlewareLoggingConfig(LogLevel LoggingLevel, Boolean LogRequests, Boolean LogResponses); \ No newline at end of file +public record RequestResponseMiddlewareLoggingConfig(LogLevel LoggingLevel, Boolean LogRequests, Boolean LogResponses) +{ + public IReadOnlySet SensitiveFieldNames { get; init; } = new HashSet(new[] { "password", "token", "access_token", "refresh_token", "client_secret", "api_key", "cardnumber", "cvv", "pin" }, StringComparer.OrdinalIgnoreCase); + public IReadOnlySet SensitiveHeaderNames { get; init; } = new HashSet(new[] { "Authorization", "Proxy-Authorization", "Cookie", "Set-Cookie", "X-API-Key" }, StringComparer.OrdinalIgnoreCase); + 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/ResponseLoggingMemoryStream.cs b/Shared/Middleware/ResponseLoggingMemoryStream.cs index 1a9482e4..02ef0e01 100644 --- a/Shared/Middleware/ResponseLoggingMemoryStream.cs +++ b/Shared/Middleware/ResponseLoggingMemoryStream.cs @@ -1,19 +1,55 @@ +using System; using System.Diagnostics.CodeAnalysis; using System.IO; +using System.Threading; +using System.Threading.Tasks; namespace Shared.Middleware; [ExcludeFromCodeCoverage] -public class ResponseLoggingMemoryStream : MemoryStream { - public override void Close() { - // Dont close by default - } +public sealed class ResponseLoggingMemoryStream : Stream +{ + private readonly Stream destination; + private readonly MemoryStream captured = new(); + private readonly Int32 maximumBytes; - public void ForceClose() { - base.Close(); + public ResponseLoggingMemoryStream(Stream destination, Int32 maximumBytes) + { + this.destination = destination; + this.maximumBytes = Math.Max(0, maximumBytes); } - public bool IsDisposed() { - return this.CanRead && this.CanSeek && this.CanWrite; + 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 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); } -} \ No newline at end of file + 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(); +} diff --git a/Shared/Middleware/SensitiveDataRedactor.cs b/Shared/Middleware/SensitiveDataRedactor.cs new file mode 100644 index 00000000..d7f9b528 --- /dev/null +++ b/Shared/Middleware/SensitiveDataRedactor.cs @@ -0,0 +1,142 @@ +#nullable enable +namespace Shared.Middleware; + +using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.Primitives; +using System; +using System.Collections.Generic; +using System.IO; +using System.Linq; +using System.Text; +using System.Text.Json; +using System.Xml; + +internal readonly record struct BodyCaptureResult(String? Body, String Status); + +internal static class SensitiveDataRedactor +{ + private const String RedactedValue = "[REDACTED]"; + + public static IReadOnlyDictionary RedactQuery(IQueryCollection query, IReadOnlySet sensitiveFieldNames) + { + Dictionary result = new(StringComparer.OrdinalIgnoreCase); + foreach (KeyValuePair item in query) + result[item.Key] = item.Value.Select(value => sensitiveFieldNames.Contains(item.Key) ? RedactedValue : value ?? String.Empty).ToArray(); + return result; + } + + public static IReadOnlyDictionary FilterHeaders(IHeaderDictionary headers, IReadOnlySet allowlist, IReadOnlySet sensitiveHeaders) + { + Dictionary result = new(StringComparer.OrdinalIgnoreCase); + foreach (KeyValuePair item in headers) + if (allowlist.Contains(item.Key)) result[item.Key] = sensitiveHeaders.Contains(item.Key) ? RedactedValue : item.Value.ToString(); + return result; + } + + public static BodyCaptureResult RedactBody(ReadOnlyMemory body, String? contentType, IReadOnlySet sensitiveFieldNames, Int32 maximumBytes, 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 + { + String text = Encoding.UTF8.GetString(body.Span); + return format switch + { + BodyFormat.Json => RedactJsonBody(text, sensitiveFieldNames), + BodyFormat.Form => RedactFormBody(text, sensitiveFieldNames), + BodyFormat.Xml => RedactXmlBody(text, sensitiveFieldNames), + _ => new(null, "unsupported_content_type") + }; + } + catch { return new(null, "redaction_failed"); } + } + + private static Boolean TryGetBodyFormat(String? contentType, IReadOnlySet supportedContentTypes, out BodyFormat format) + { + format = default; + if (String.IsNullOrWhiteSpace(contentType)) return false; + String mediaType = contentType.Split(';', 2)[0].Trim(); + Boolean json = mediaType.Equals("application/json", StringComparison.OrdinalIgnoreCase) || + (mediaType.StartsWith("application/", StringComparison.OrdinalIgnoreCase) && mediaType.EndsWith("+json", StringComparison.OrdinalIgnoreCase) && supportedContentTypes.Contains("application/*+json")); + Boolean form = mediaType.Equals("application/x-www-form-urlencoded", StringComparison.OrdinalIgnoreCase); + Boolean xml = mediaType.Equals("application/xml", StringComparison.OrdinalIgnoreCase) || mediaType.Equals("text/xml", StringComparison.OrdinalIgnoreCase) || mediaType.Equals("application/soap+xml", StringComparison.OrdinalIgnoreCase); + Boolean allowed = supportedContentTypes.Contains(mediaType) || (json && supportedContentTypes.Contains("application/*+json")); + if (!(json || form || xml) || !allowed) return false; + format = json ? BodyFormat.Json : form ? BodyFormat.Form : BodyFormat.Xml; + return true; + } + + private static BodyCaptureResult RedactJsonBody(String text, IReadOnlySet sensitive) + { + using JsonDocument document = JsonDocument.Parse(text); + using MemoryStream output = new(); + using (Utf8JsonWriter writer = new(output)) WriteJson(document.RootElement, writer, sensitive); + return new(Encoding.UTF8.GetString(output.ToArray()), "captured"); + } + + private static BodyCaptureResult RedactFormBody(String text, IReadOnlySet sensitive) + { + String[] pairs = text.Split('&'); + for (Int32 i = 0; i < pairs.Length; i++) + { + String[] part = pairs[i].Split('=', 2); + String key = Uri.UnescapeDataString(part[0].Replace('+', ' ')); + if (sensitive.Contains(key)) pairs[i] = part[0] + "=" + RedactedValue; + } + return new(String.Join('&', pairs), "captured"); + } + + private static BodyCaptureResult RedactXmlBody(String text, IReadOnlySet sensitive) + { + XmlReaderSettings settings = new() { DtdProcessing = DtdProcessing.Prohibit, XmlResolver = null }; + XmlDocument document = new() { XmlResolver = null }; + using (XmlReader reader = XmlReader.Create(new StringReader(text), settings)) document.Load(reader); + RedactXml(document.DocumentElement, sensitive); + return new(document.OuterXml, "captured"); + } + + private static void WriteJson(JsonElement element, Utf8JsonWriter writer, IReadOnlySet sensitive) + { + switch (element.ValueKind) + { + case JsonValueKind.Object: + writer.WriteStartObject(); + foreach (JsonProperty property in element.EnumerateObject()) + { + writer.WritePropertyName(property.Name); + if (sensitive.Contains(property.Name)) writer.WriteStringValue(RedactedValue); else WriteJson(property.Value, writer, sensitive); + } + writer.WriteEndObject(); + break; + case JsonValueKind.Array: + writer.WriteStartArray(); + foreach (JsonElement child in element.EnumerateArray()) + { + WriteJson(child, writer, sensitive); + } + writer.WriteEndArray(); + break; + default: element.WriteTo(writer); break; + } + } + + private static void RedactXml(XmlNode? node, IReadOnlySet sensitive) + { + if (node is not XmlElement element) return; + foreach (XmlAttribute attribute in element.Attributes) + if (sensitive.Contains(attribute.LocalName)) attribute.Value = RedactedValue; + if (sensitive.Contains(element.LocalName)) + { + element.InnerText = RedactedValue; + return; + } + foreach (XmlNode child in element.ChildNodes) RedactXml(child, sensitive); + } + + private enum BodyFormat + { + Json, + Form, + Xml + } +} From 012e0c115715f4201077c52a433f58ce10f34b33 Mon Sep 17 00:00:00 2001 From: StuartFerguson Date: Fri, 23 Oct 2026 17:10:00 +0100 Subject: [PATCH 2/5] remove MS logger --- Shared.Logger/MicrosoftLogger.cs | 78 -------------------------------- 1 file changed, 78 deletions(-) delete mode 100644 Shared.Logger/MicrosoftLogger.cs diff --git a/Shared.Logger/MicrosoftLogger.cs b/Shared.Logger/MicrosoftLogger.cs deleted file mode 100644 index 51d2cdcf..00000000 --- a/Shared.Logger/MicrosoftLogger.cs +++ /dev/null @@ -1,78 +0,0 @@ -namespace Shared.Logger; - -using System; -using System.Diagnostics.CodeAnalysis; -using Microsoft.Extensions.Logging; - -[ExcludeFromCodeCoverage] -public class MicrosoftLogger : ILogger -{ - - private Microsoft.Extensions.Logging.ILogger LoggerObject; - - - - public Boolean IsInitialised { get; set; } - - - - public void Initialise(Microsoft.Extensions.Logging.ILogger loggerObject) { - this.LoggerObject = loggerObject; - this.IsInitialised = true; - } - - public void LogCritical(Exception exception) { - this.LogMessage(LogLevel.Critical, exception.Message, exception); - } - - public void LogCritical(String message, - Exception exception) { - this.LogMessage(LogLevel.Critical, message, exception); - } - - public void LogDebug(String message) { - this.LogMessage(LogLevel.Debug, message); - } - - public void LogError(Exception exception) { - this.LogMessage(LogLevel.Error, exception.Message, exception); - } - - public void LogError(String message) { - this.LogMessage(LogLevel.Error, message); - } - - public void LogError(String message, - Exception exception) { - this.LogMessage(LogLevel.Error, message, exception); - } - - public void LogInformation(String message) { - this.LogMessage(LogLevel.Information, message); - } - - public void LogTrace(String message) { - this.LogMessage(LogLevel.Trace, message); - } - - public void LogWarning(String message) { - this.LogMessage(LogLevel.Warning, message); - } - - private void LogMessage(LogLevel logLevel, - String message, - Exception exception = null) { - if (this.LoggerObject != null) { - this.LoggerObject.Log(logLevel, - new EventId(), - message, - exception, - (state, - ex) => message); - } - else { - throw new InvalidOperationException("LoggerObject has not been set"); - } - } - -} \ No newline at end of file From 5593aef18c9d37197fed0f9a1662222cb44ae4ac Mon Sep 17 00:00:00 2001 From: StuartFerguson Date: Fri, 23 Oct 2026 17:18:15 +0100 Subject: [PATCH 3/5] Preserve collection values in legacy logger formatting --- Shared.Logger/ILogger.cs | 18 +++++++++++- Shared.Tests/StructuredLoggingTests.cs | 40 ++++++++++++++++++++++++++ 2 files changed, 57 insertions(+), 1 deletion(-) diff --git a/Shared.Logger/ILogger.cs b/Shared.Logger/ILogger.cs index 0b562ec0..451912ba 100644 --- a/Shared.Logger/ILogger.cs +++ b/Shared.Logger/ILogger.cs @@ -1,8 +1,10 @@ namespace Shared.Logger; using System; +using System.Collections; using System.Globalization; using System.Text; +using System.Text.Json; /// /// @@ -83,7 +85,7 @@ private static String FormatMessageTemplate(String messageTemplate, Object?[] ar Int32 end = messageTemplate.IndexOf('}', index + 1); if (end >= 0 && argumentIndex < args.Length) { - result.Append(Convert.ToString(args[argumentIndex++], CultureInfo.InvariantCulture)); + result.Append(FormatArgument(args[argumentIndex++])); index = end + 1; continue; } @@ -93,4 +95,18 @@ private static String FormatMessageTemplate(String messageTemplate, Object?[] ar return result.ToString(); } + private static String FormatArgument(Object? argument) + { + if (argument is IEnumerable && argument is not String) + { + try + { + return JsonSerializer.Serialize(argument, argument.GetType()); + } + catch (NotSupportedException) { } + catch (JsonException) { } + } + return Convert.ToString(argument, CultureInfo.InvariantCulture) ?? String.Empty; + } + } diff --git a/Shared.Tests/StructuredLoggingTests.cs b/Shared.Tests/StructuredLoggingTests.cs index ae3c5c7f..4b40ed01 100644 --- a/Shared.Tests/StructuredLoggingTests.cs +++ b/Shared.Tests/StructuredLoggingTests.cs @@ -102,6 +102,30 @@ public async Task Middleware_RedactsSensitiveQueryHeadersAndJsonBody() allFields.ShouldNotContain("unlisted-secret"); } + [Fact] + public async Task Middleware_PreservesQueryAndHeaderCollectionsWithLegacyLogger() + { + LegacyCapturingLogger logger = new(); + Shared.Logger.Logger.Initialise(logger); + DefaultHttpContext context = CreateContext(String.Empty, null); + context.Request.QueryString = new QueryString("?search=visible&token=query-secret"); + context.Request.Headers.Authorization = "header-secret"; + context.Request.Headers["X-Request-Id"] = "request-123"; + RequestResponseLoggingMiddleware middleware = new(_ => Task.CompletedTask); + + await middleware.Invoke(context, new RequestResponseMiddlewareLoggingConfig(LogLevel.Information, true, false)); + + String log = logger.Entries.ShouldHaveSingleItem(); + log.ShouldContain("search"); + log.ShouldContain("visible"); + log.ShouldContain("X-Request-Id"); + log.ShouldContain("request-123"); + log.ShouldContain("[REDACTED]"); + log.ShouldNotContain("query-secret"); + log.ShouldNotContain("header-secret"); + log.ShouldNotContain("System.Collections.Generic.Dictionary"); + } + [Fact] public async Task Middleware_OmitsBodyWhenRequestExceedsConfiguredLimitAndRestoresRequestStream() { @@ -247,4 +271,20 @@ private sealed class CapturingLogger : Shared.Logger.ILogger private void Add(String template, Object?[] args, LogLevel level) => this.Entries.Add(new(template, args, level)); } + + private sealed class LegacyCapturingLogger : Shared.Logger.ILogger + { + public Boolean IsInitialised { get; set; } = true; + public List Entries { get; } = new(); + + public void LogCritical(Exception exception) => this.Entries.Add(exception.Message); + public void LogCritical(String message, Exception exception) => this.Entries.Add(message); + public void LogDebug(String message) => this.Entries.Add(message); + public void LogError(Exception exception) => this.Entries.Add(exception.Message); + public void LogError(String message) => this.Entries.Add(message); + public void LogError(String message, Exception exception) => this.Entries.Add(message); + public void LogInformation(String message) => this.Entries.Add(message); + public void LogTrace(String message) => this.Entries.Add(message); + public void LogWarning(String message) => this.Entries.Add(message); + } } From 5850e2a7f540e4f21da377a84688db653e304b26 Mon Sep 17 00:00:00 2001 From: StuartFerguson Date: Fri, 23 Oct 2026 17:23:37 +0100 Subject: [PATCH 4/5] Address remaining Codacy findings --- Shared.Logger/ILogger.cs | 10 ++++- .../RequestResponseLoggingMiddleware.cs | 9 ++-- Shared/Middleware/SensitiveDataRedactor.cs | 44 +++++++++++++++---- 3 files changed, 49 insertions(+), 14 deletions(-) diff --git a/Shared.Logger/ILogger.cs b/Shared.Logger/ILogger.cs index 451912ba..cb719894 100644 --- a/Shared.Logger/ILogger.cs +++ b/Shared.Logger/ILogger.cs @@ -103,8 +103,14 @@ private static String FormatArgument(Object? argument) { return JsonSerializer.Serialize(argument, argument.GetType()); } - catch (NotSupportedException) { } - catch (JsonException) { } + catch (NotSupportedException) + { + // Unsupported collection types use the invariant scalar fallback below. + } + catch (JsonException) + { + // Collections that cannot be serialized also use the invariant scalar fallback below. + } } return Convert.ToString(argument, CultureInfo.InvariantCulture) ?? String.Empty; } diff --git a/Shared/Middleware/RequestResponseLoggingMiddleware.cs b/Shared/Middleware/RequestResponseLoggingMiddleware.cs index 12e17894..2b44d8da 100644 --- a/Shared/Middleware/RequestResponseLoggingMiddleware.cs +++ b/Shared/Middleware/RequestResponseLoggingMiddleware.cs @@ -14,6 +14,7 @@ public class RequestResponseLoggingMiddleware { private const String RequestIdField = "requestId"; private const String HeadersField = "headers"; + private const String BodyStatusField = "bodyStatus"; private readonly RequestDelegate next; @@ -43,7 +44,7 @@ public async Task Invoke(HttpContext context, RequestResponseMiddlewareLoggingCo requestFields = new() { [RequestIdField] = requestId, ["method"] = context.Request.Method, ["path"] = path, - ["query"] = query, [HeadersField] = requestHeaders, ["bodyStatus"] = requestCapture.Status, + ["query"] = query, [HeadersField] = requestHeaders, [BodyStatusField] = requestCapture.Status, ["body"] = requestCapture.Body, ["healthCheck"] = healthCheck }; } @@ -71,7 +72,7 @@ public async Task Invoke(HttpContext context, RequestResponseMiddlewareLoggingCo { [RequestIdField] = requestId, ["statusCode"] = context.Response.StatusCode, ["elapsedMs"] = timer.ElapsedMilliseconds, [HeadersField] = SensitiveDataRedactor.FilterHeaders(context.Response.Headers, configuration.AllowedResponseHeaders, configuration.SensitiveHeaderNames), - ["bodyStatus"] = responseCapture.Status, ["body"] = responseCapture.Body, ["healthCheck"] = healthCheck + [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(); @@ -113,8 +114,8 @@ private static void WriteLog(LogLevel level, String template, Dictionary supportedContentTypes) + { + Boolean isJson = mediaType.Equals("application/json", StringComparison.OrdinalIgnoreCase) || + (mediaType.StartsWith("application/", StringComparison.OrdinalIgnoreCase) && + mediaType.EndsWith("+json", StringComparison.OrdinalIgnoreCase) && + supportedContentTypes.Contains("application/*+json")); + return isJson && (supportedContentTypes.Contains(mediaType) || supportedContentTypes.Contains("application/*+json")); + } + + private static Boolean IsSupportedFormMediaType(String mediaType, IReadOnlySet supportedContentTypes) => + mediaType.Equals("application/x-www-form-urlencoded", StringComparison.OrdinalIgnoreCase) && supportedContentTypes.Contains(mediaType); + + private static Boolean IsSupportedXmlMediaType(String mediaType, IReadOnlySet supportedContentTypes) + { + Boolean isXml = mediaType.Equals("application/xml", StringComparison.OrdinalIgnoreCase) || + mediaType.Equals("text/xml", StringComparison.OrdinalIgnoreCase) || + mediaType.Equals("application/soap+xml", StringComparison.OrdinalIgnoreCase); + return isXml && supportedContentTypes.Contains(mediaType); } private static BodyCaptureResult RedactJsonBody(String text, IReadOnlySet sensitive) From 912a8b3ff2bd26d6c493f55ad66911fb3346a8ff Mon Sep 17 00:00:00 2001 From: StuartFerguson Date: Fri, 23 Oct 2026 17:30:11 +0100 Subject: [PATCH 5/5] Suppress intentional logger findings --- Shared.Logger/ILogger.cs | 4 +++- Shared.Logger/Logger.cs | 2 ++ 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/Shared.Logger/ILogger.cs b/Shared.Logger/ILogger.cs index cb719894..91d3fb4f 100644 --- a/Shared.Logger/ILogger.cs +++ b/Shared.Logger/ILogger.cs @@ -24,8 +24,10 @@ public interface ILogger void LogCritical(Exception exception); - void LogCritical(String messageTemplate, // NOSONAR - delegates to the required string-only overload, so it is not recursive. +#pragma warning disable S2190 // This overload delegates to the required string-only overload; it does not call itself. + void LogCritical(String messageTemplate, params Object?[] args) => this.LogCritical(FormatMessageTemplate(messageTemplate, args)); +#pragma warning restore S2190 void LogCritical(Exception exception, String messageTemplate, diff --git a/Shared.Logger/Logger.cs b/Shared.Logger/Logger.cs index 3e07492e..08e8e586 100644 --- a/Shared.Logger/Logger.cs +++ b/Shared.Logger/Logger.cs @@ -85,6 +85,7 @@ public static void LogCritical(Exception exception, } // Compatibility overloads below remain available for existing callers and can be removed only in a breaking release. +#pragma warning disable S1133 // These deprecated APIs are retained for source compatibility until a breaking release. [Obsolete("Use LogCritical(String messageTemplate, params Object?[] args) or the exception-aware structured overload.")] // NOSONAR - retained for source compatibility until a breaking release. public static void LogCritical(Exception exception) { @@ -149,6 +150,7 @@ public static void LogWarning(String message) Logger.ValidateLoggerObject(); Logger.Write(logger => logger.LogWarning(message)); } +#pragma warning restore S1133 [MemberNotNull(nameof(LoggerObject))] private static void ValidateLoggerObject()