diff --git a/src/ModularPipelines/Console/ModuleOutputBuffer.cs b/src/ModularPipelines/Console/ModuleOutputBuffer.cs index 41b510e6cf..1aaac3423b 100644 --- a/src/ModularPipelines/Console/ModuleOutputBuffer.cs +++ b/src/ModularPipelines/Console/ModuleOutputBuffer.cs @@ -5,6 +5,7 @@ using Microsoft.Extensions.Logging; using ModularPipelines.Engine; using ModularPipelines.Helpers; +using ModularPipelines.Logging; using Spectre.Console; namespace ModularPipelines.Console; @@ -761,20 +762,45 @@ internal sealed class BufferedLogEvent( LogLevel level, EventId eventId, TState originalState, - object obfuscatedState, + object? obfuscatedState, Exception? exception, Func formatter, ISecretObfuscator secretObfuscator) : IBufferedLogEvent { + private readonly Exception? _obfuscatedException = + ObfuscatedLogException.Create(exception, secretObfuscator); + public LogLevel Level => level; public void WriteTo(ILogger logger) { + if (obfuscatedState is null && originalState is null) + { + logger.Log( + level, + eventId, + originalState, + _obfuscatedException, + FormatTyped); + return; + } + + if (obfuscatedState is TState typedState) + { + logger.Log( + level, + eventId, + typedState, + _obfuscatedException, + FormatTyped); + return; + } + logger.Log( level, eventId, obfuscatedState, - exception, + _obfuscatedException, Format); } @@ -785,12 +811,15 @@ public void WriteTo(ILogger logger) ? null : secretObfuscator.Obfuscate(exception.ToString(), null); - private string Format(object state, Exception? logException) + private string Format(object? state, Exception? logException) { - var formatted = formatter(originalState, logException); + var formatted = formatter(originalState, exception); return secretObfuscator.Obfuscate(formatted, null) ?? string.Empty; } + private string FormatTyped(TState state, Exception? logException) + => Format(state!, logException); + private static string FormatLevel(LogLevel logLevel) => logLevel switch { diff --git a/src/ModularPipelines/Logging/CommandLogger.cs b/src/ModularPipelines/Logging/CommandLogger.cs index 86d145eb44..499d8f1f49 100644 --- a/src/ModularPipelines/Logging/CommandLogger.cs +++ b/src/ModularPipelines/Logging/CommandLogger.cs @@ -85,14 +85,15 @@ private CommandLoggingOptions GetEffectiveLoggingOptions(CommandLineToolOptions? private void LogDryRunCommand(CommandLoggingOptions options, string workingDirectory, string? input) { - if (!ShouldShowInput(options)) + var logger = Logger; + if (!ShouldShowInput(options) || !logger.IsEnabled(LogLevel.Information)) { return; } - Logger.LogInformation("{WorkingDirectory}> {Input} [DRY-RUN]", + logger.LogInformation("{WorkingDirectory}> {Input} [DRY-RUN]", workingDirectory, - input); + _secretObfuscator.Obfuscate(input, null)); } private void LogOutputLine( diff --git a/src/ModularPipelines/Logging/FormattedLogValuesObfuscator.cs b/src/ModularPipelines/Logging/FormattedLogValuesObfuscator.cs index ac1571c3fe..b66b566343 100644 --- a/src/ModularPipelines/Logging/FormattedLogValuesObfuscator.cs +++ b/src/ModularPipelines/Logging/FormattedLogValuesObfuscator.cs @@ -33,7 +33,7 @@ public object TryObfuscateValues(object state) { if (state is not IReadOnlyList> values) { - return state; + return ObfuscateValue(state); } KeyValuePair[]? obfuscatedValues = null; @@ -46,9 +46,8 @@ public object TryObfuscateValues(object state) continue; } - var originalValue = property.Value.ToString() ?? string.Empty; - var obfuscatedValue = _secretObfuscator.Obfuscate(originalValue, null); - if (obfuscatedValue.Equals(originalValue, StringComparison.Ordinal)) + var obfuscatedValue = ObfuscateValue(property.Value); + if (ReferenceEquals(obfuscatedValue, property.Value)) { continue; } @@ -59,6 +58,24 @@ public object TryObfuscateValues(object state) return obfuscatedValues ?? state; } + + private object ObfuscateValue(object value) + { + string originalValue; + try + { + originalValue = value.ToString() ?? string.Empty; + } + catch (Exception) + { + return value; + } + + var obfuscatedValue = _secretObfuscator.Obfuscate(originalValue, null); + return obfuscatedValue.Equals(originalValue, StringComparison.Ordinal) + ? value + : obfuscatedValue; + } } /// diff --git a/src/ModularPipelines/Logging/ModuleLogger.cs b/src/ModularPipelines/Logging/ModuleLogger.cs index ba0b4a2a46..42b84425dd 100644 --- a/src/ModularPipelines/Logging/ModuleLogger.cs +++ b/src/ModularPipelines/Logging/ModuleLogger.cs @@ -119,7 +119,9 @@ public override void Log(LogLevel logLevel, EventId eventId, TState stat return; } - var obfuscatedState = _formattedLogValuesObfuscator.TryObfuscateValues(state!); + var obfuscatedState = state is null + ? null + : _formattedLogValuesObfuscator.TryObfuscateValues(state); var logEvent = new BufferedLogEvent( logLevel, eventId, diff --git a/src/ModularPipelines/Logging/ModuleLoggerProvider.cs b/src/ModularPipelines/Logging/ModuleLoggerProvider.cs index 8f9ee8223c..fb598c580c 100644 --- a/src/ModularPipelines/Logging/ModuleLoggerProvider.cs +++ b/src/ModularPipelines/Logging/ModuleLoggerProvider.cs @@ -20,6 +20,8 @@ internal class ModuleLoggerProvider : IInternalModuleLoggerProvider private readonly IServiceProvider _serviceProvider; private readonly IStackTraceModuleDetector _stackTraceDetector; private readonly ILoggerFactory _loggerFactory; + private readonly ISecretObfuscator _secretObfuscator; + private readonly IFormattedLogValuesObfuscator _formattedLogValuesObfuscator; private readonly object _lock = new(); private IModuleLogger? _moduleLogger; @@ -28,11 +30,15 @@ internal class ModuleLoggerProvider : IInternalModuleLoggerProvider public ModuleLoggerProvider( IServiceProvider serviceProvider, IStackTraceModuleDetector stackTraceDetector, - ILoggerFactory loggerFactory) + ILoggerFactory loggerFactory, + ISecretObfuscator secretObfuscator, + IFormattedLogValuesObfuscator formattedLogValuesObfuscator) { _serviceProvider = serviceProvider; _stackTraceDetector = stackTraceDetector; _loggerFactory = loggerFactory; + _secretObfuscator = secretObfuscator; + _formattedLogValuesObfuscator = formattedLogValuesObfuscator; } /// @@ -83,7 +89,10 @@ public IModuleLogger GetLogger() { // No module context - return a pipeline-level logger that doesn't create a separate output section // This handles logging during initialization (e.g., GitInformation), condition evaluation, etc. - return _pipelineLevelLogger ??= new PipelineLevelLogger(_loggerFactory.CreateLogger("ModularPipelines.Pipeline")); + return _pipelineLevelLogger ??= new PipelineLevelLogger( + _loggerFactory.CreateLogger("ModularPipelines.Pipeline"), + _secretObfuscator, + _formattedLogValuesObfuscator); } return _moduleLogger = GetLogger(detectedType); diff --git a/src/ModularPipelines/Logging/ObfuscatedLogException.cs b/src/ModularPipelines/Logging/ObfuscatedLogException.cs new file mode 100644 index 0000000000..8a2e6173e4 --- /dev/null +++ b/src/ModularPipelines/Logging/ObfuscatedLogException.cs @@ -0,0 +1,244 @@ +using System.Collections; +using System.Diagnostics.CodeAnalysis; +using System.Reflection; +using System.Runtime.CompilerServices; +using ModularPipelines.Constants; +using ModularPipelines.Engine; + +namespace ModularPipelines.Logging; + +/// +/// Provides downstream loggers with an exception whose public text is safe to render. +/// +/// +/// Wrapping intentionally replaces the original exception type identity. +/// +internal sealed class ObfuscatedLogException : Exception +{ + private readonly string? _obfuscatedStackTrace; + private readonly string _obfuscatedText; + + private ObfuscatedLogException(Exception exception, ISecretObfuscator secretObfuscator) + : base( + GetObfuscatedMessage(exception, secretObfuscator), + Create(exception.InnerException, secretObfuscator)) + { + _obfuscatedStackTrace = GetObfuscatedDiagnostic( + () => exception.StackTrace, + secretObfuscator); + _obfuscatedText = GetObfuscatedText(exception, secretObfuscator); + CopyDiagnostics(this, exception, secretObfuscator); + } + + public static Exception? Create(Exception? exception, ISecretObfuscator secretObfuscator) + => exception switch + { + null => null, + AggregateException aggregateException => + new ObfuscatedAggregateLogException(aggregateException, secretObfuscator), + _ => new ObfuscatedLogException(exception, secretObfuscator), + }; + + public override string? StackTrace => _obfuscatedStackTrace; + + public override string ToString() => _obfuscatedText; + + private static string? ObfuscateNullable( + string? value, + ISecretObfuscator secretObfuscator) => + value is null ? null : secretObfuscator.Obfuscate(value, null); + + private static string GetObfuscatedMessage( + Exception exception, + ISecretObfuscator secretObfuscator) + { + try + { + return secretObfuscator.Obfuscate(exception.Message, null); + } + catch (Exception) + { + return LoggingConstants.SecretMask; + } + } + + private static string GetObfuscatedText( + Exception exception, + ISecretObfuscator secretObfuscator) + { + try + { + return secretObfuscator.Obfuscate(exception.ToString(), null); + } + catch (Exception) + { + return $"{exception.GetType().FullName}: {GetObfuscatedMessage(exception, secretObfuscator)}"; + } + } + + private static string? GetObfuscatedDiagnostic( + Func getValue, + ISecretObfuscator secretObfuscator) + { + try + { + return ObfuscateNullable(getValue(), secretObfuscator); + } + catch (Exception) + { + return null; + } + } + + private static void CopyDiagnostics( + Exception destination, + Exception source, + ISecretObfuscator secretObfuscator) + { + TryCopyTargetSite(destination, source); + destination.HResult = source.HResult; + destination.HelpLink = GetObfuscatedDiagnostic( + () => source.HelpLink, + secretObfuscator); + destination.Source = GetObfuscatedDiagnostic( + () => source.Source, + secretObfuscator); + CopyData(destination, source, secretObfuscator); + } + + private static void TryCopyTargetSite(Exception destination, Exception source) + { + if (!RuntimeFeature.IsDynamicCodeSupported) + { + TryCopyNativeAotTargetSiteState(destination, source); + return; + } + + try + { + GetExceptionMethod(destination) = GetTargetSite(source); + } + catch (MissingFieldException) + { + // The private runtime field is unavailable under some runtimes. + } + } + + private static void TryCopyNativeAotTargetSiteState(Exception destination, Exception source) + { + try + { + GetNativeAotStackTrace(destination) = GetNativeAotStackTrace(source)?.ToArray(); + GetNativeAotStackTraceCount(destination) = GetNativeAotStackTraceCount(source); + } + catch (MissingFieldException) + { + // The private runtime fields are unavailable under some runtimes. + } + } + + private static void CopyData( + Exception destination, + Exception source, + ISecretObfuscator secretObfuscator) + { + try + { + foreach (DictionaryEntry entry in source.Data) + { + var key = SanitizeDataValue(entry.Key, secretObfuscator); + if (key is null) + { + continue; + } + + destination.Data[GetUniqueDataKey(destination.Data, key)] = + SanitizeDataValue(entry.Value, secretObfuscator); + } + } + catch (Exception) + { + // Diagnostic data must never make logging fail. + } + } + + private static object GetUniqueDataKey(IDictionary data, object key) + { + if (!data.Contains(key)) + { + return key; + } + + var baseKey = key.ToString() ?? string.Empty; + for (var suffix = 2; ; suffix++) + { + var candidate = $"{baseKey} ({suffix})"; + if (!data.Contains(candidate)) + { + return candidate; + } + } + } + + private static object? SanitizeDataValue( + object? value, + ISecretObfuscator secretObfuscator) + { + if (value is null) + { + return null; + } + + try + { + var text = value.ToString() ?? string.Empty; + var obfuscated = secretObfuscator.Obfuscate(text, null); + return obfuscated.Equals(text, StringComparison.Ordinal) ? value : obfuscated; + } + catch (Exception) + { + return LoggingConstants.SecretMask; + } + } + + [UnconditionalSuppressMessage( + "Trimming", + "IL2026", + Justification = "TargetSite is copied as an optional diagnostic; missing trimmed metadata is acceptable.")] + private static MethodBase? GetTargetSite(Exception exception) => exception.TargetSite; + + // TargetSite is non-virtual and has no public copy API; this is its .NET 10 backing field. + [UnsafeAccessor(UnsafeAccessorKind.Field, Name = "_exceptionMethod")] + private static extern ref MethodBase? GetExceptionMethod(Exception exception); + + // NativeAOT computes TargetSite from the first captured native stack trace entry. + [UnsafeAccessor(UnsafeAccessorKind.Field, Name = "_corDbgStackTrace")] + private static extern ref IntPtr[]? GetNativeAotStackTrace(Exception exception); + + [UnsafeAccessor(UnsafeAccessorKind.Field, Name = "_idxFirstFreeStackTraceEntry")] + private static extern ref int GetNativeAotStackTraceCount(Exception exception); + + private sealed class ObfuscatedAggregateLogException : AggregateException + { + private readonly string? _obfuscatedStackTrace; + private readonly string _obfuscatedText; + + public ObfuscatedAggregateLogException( + AggregateException exception, + ISecretObfuscator secretObfuscator) + : base( + GetObfuscatedMessage(exception, secretObfuscator), + exception.InnerExceptions.Select(inner => Create(inner, secretObfuscator)!)) + { + _obfuscatedStackTrace = GetObfuscatedDiagnostic( + () => exception.StackTrace, + secretObfuscator); + _obfuscatedText = GetObfuscatedText(exception, secretObfuscator); + CopyDiagnostics(this, exception, secretObfuscator); + } + + public override string? StackTrace => _obfuscatedStackTrace; + + public override string ToString() => _obfuscatedText; + } +} diff --git a/src/ModularPipelines/Logging/PipelineLevelLogger.cs b/src/ModularPipelines/Logging/PipelineLevelLogger.cs index 9774242f15..6b78e8bd8c 100644 --- a/src/ModularPipelines/Logging/PipelineLevelLogger.cs +++ b/src/ModularPipelines/Logging/PipelineLevelLogger.cs @@ -1,4 +1,8 @@ +using System.Collections; using Microsoft.Extensions.Logging; +using ModularPipelines.Console; +using ModularPipelines.Constants; +using ModularPipelines.Engine; namespace ModularPipelines.Logging; @@ -14,16 +18,57 @@ namespace ModularPipelines.Logging; internal sealed class PipelineLevelLogger : IModuleLogger { private readonly ILogger _logger; + private readonly ISecretObfuscator _secretObfuscator; + private readonly IFormattedLogValuesObfuscator _formattedLogValuesObfuscator; - public PipelineLevelLogger(ILogger logger) + public PipelineLevelLogger( + ILogger logger, + ISecretObfuscator secretObfuscator, + IFormattedLogValuesObfuscator formattedLogValuesObfuscator) { _logger = logger; + _secretObfuscator = secretObfuscator; + _formattedLogValuesObfuscator = formattedLogValuesObfuscator; } /// public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) { - _logger.Log(logLevel, eventId, state, exception, formatter); + if (!IsEnabled(logLevel)) + { + return; + } + + object? obfuscatedState; + try + { + obfuscatedState = state is null + ? null + : _formattedLogValuesObfuscator.TryObfuscateValues(state); + } + catch (Exception) + { + new BufferedLogEvent( + logLevel, + eventId, + LoggingConstants.SecretMask, + LoggingConstants.SecretMask, + exception, + static (message, _) => message, + _secretObfuscator) + .WriteTo(_logger); + return; + } + + new BufferedLogEvent( + logLevel, + eventId, + state, + obfuscatedState, + exception, + formatter, + _secretObfuscator) + .WriteTo(_logger); } /// @@ -36,7 +81,10 @@ public bool IsEnabled(LogLevel logLevel) public IDisposable? BeginScope(TState state) where TState : notnull { - return _logger.BeginScope(state); + var obfuscatedState = TryObfuscateScopeState(state); + return obfuscatedState is TState typedState + ? _logger.BeginScope(typedState) + : _logger.BeginScope(obfuscatedState); } /// @@ -44,4 +92,54 @@ public void Dispose() { // Nothing to dispose - the underlying logger is managed by the LoggerFactory } + + private object TryObfuscateScopeState(TState state) + where TState : notnull + { + try + { + var obfuscatedState = _formattedLogValuesObfuscator.TryObfuscateValues(state); + if (!ReferenceEquals(obfuscatedState, state) + && obfuscatedState is IReadOnlyList> obfuscatedValues + && state is IReadOnlyList>) + { + return new ObfuscatedScopeState( + obfuscatedValues, + TryRenderScope(state)); + } + + return obfuscatedState; + } + catch (Exception) + { + return LoggingConstants.SecretMask; + } + } + + private string TryRenderScope(TState state) + { + try + { + return _secretObfuscator.Obfuscate(state?.ToString(), null); + } + catch (Exception) + { + return LoggingConstants.SecretMask; + } + } + + private sealed class ObfuscatedScopeState( + IReadOnlyList> values, + string formattedValue) : IReadOnlyList> + { + public int Count => values.Count; + + public KeyValuePair this[int index] => values[index]; + + public IEnumerator> GetEnumerator() => values.GetEnumerator(); + + IEnumerator IEnumerable.GetEnumerator() => GetEnumerator(); + + public override string ToString() => formattedValue; + } } diff --git a/test/ModularPipelines.UnitTests/Commands/CommandLoggerTests.cs b/test/ModularPipelines.UnitTests/Commands/CommandLoggerTests.cs index fbecb89513..ce27bfa689 100644 --- a/test/ModularPipelines.UnitTests/Commands/CommandLoggerTests.cs +++ b/test/ModularPipelines.UnitTests/Commands/CommandLoggerTests.cs @@ -35,6 +35,35 @@ await result.T.ExecuteCommandLineToolAsync( await Assert.That(logFile).Contains("********"); } + [Test] + public async Task Masks_Secret_Values_From_Dry_Run_Command() + { + const string secret = "dry-run-command-secret"; + var file = Path.Combine(TestContext.WorkingDirectory, Guid.NewGuid().ToString("N") + ".txt"); + var result = await GetService((_, collection) => + { + collection.Configure(options => options.MinLevel = LogLevel.Information); + collection.AddLogging(builder => builder.AddFile(file)); + }); + + await result.T.ExecuteCommandLineToolAsync( + new SecretCommandOptions { Secret = secret }, + new CommandExecutionOptions + { + InternalDryRun = true, + LogSettings = new CommandLoggingOptions + { + ShowCommandArguments = true, + }, + }); + await result.Host.DisposeAsync(); + + var logFile = await File.ReadAllTextAsync(file); + await Assert.That(logFile).Contains("[DRY-RUN]"); + await Assert.That(logFile).DoesNotContain(secret); + await Assert.That(logFile).Contains("********"); + } + [Test] public async Task OutputLoggingManipulator_Does_Not_Change_Command_Result() { @@ -284,7 +313,7 @@ public async Task Diagnostic_Verbosity_Logs_Everything_Including_WorkingDirector } [Test] - public async Task Fast_Command_Logs_Complete_Output_When_Result_Is_Truncated() + public async Task Command_Logs_Complete_Output_When_Result_Is_Truncated() { const string output = "complete-output"; var file = await RunPowershellCommandWithLoggingOptions( @@ -293,7 +322,7 @@ public async Task Fast_Command_Logs_Complete_Output_When_Result_Is_Truncated() maxCapturedOutputLength: 4); var logFile = await File.ReadAllTextAsync(file); - await Assert.That(logFile).Contains($"→ {output}"); + await Assert.That(Regex.Matches(logFile, $"(?:→|↳) {output}").Count).IsEqualTo(1); await Assert.That(logFile).DoesNotContain("truncated"); } diff --git a/test/ModularPipelines.UnitTests/Console/ModuleOutputBufferTests.cs b/test/ModularPipelines.UnitTests/Console/ModuleOutputBufferTests.cs index 0818b6ce75..97531f7e76 100644 --- a/test/ModularPipelines.UnitTests/Console/ModuleOutputBufferTests.cs +++ b/test/ModularPipelines.UnitTests/Console/ModuleOutputBufferTests.cs @@ -179,6 +179,24 @@ public async Task LogEventAddedAfterCompletion_IsIgnored() await Assert.That(buffer.NeedsCompletionFlush).IsFalse(); } + [Test] + public async Task BufferedLogEvent_PreservesGenericTypeForNullState() + { + var logger = new RecordingLogger(); + var logEvent = new BufferedLogEvent( + LogLevel.Information, + default, + null, + null, + null, + static (state, _) => state ?? "null-state", + new PassthroughSecretObfuscator()); + + logEvent.WriteTo(logger); + + await Assert.That(logger.StateTypes).HasSingleItem().And.IsEquivalentTo([typeof(string)]); + } + [Test] public async Task ConsoleOutputAddedAfterCompletion_IsRetained() { @@ -551,7 +569,7 @@ public async Task Flush_LockTimeout_WritesBufferedOutputDirectly() var writer = new StringWriter(); var loggerControl = new SynchronousLoggerControl(writer); var fallbackLogger = new RecordingLogger(); - var logException = new InvalidOperationException("structured failure"); + var logException = new InvalidOperationException("structured secret failure"); var buffer = CreateBufferWithStructuredLog( TimeSpan.FromMilliseconds(50), "structured secret", @@ -595,11 +613,12 @@ public async Task Flush_LockTimeout_WritesBufferedOutputDirectly() await Assert.That(output).Contains("[WARN] structured ***"); await Assert.That(output).DoesNotContain("structured secret"); await Assert.That(output).Contains(nameof(InvalidOperationException)); - await Assert.That(output).Contains("structured failure"); + await Assert.That(output).Contains("structured *** failure"); await Assert.That(output).Contains("direct output"); await Assert.That(loggerControl.LogCallCount).IsEqualTo(0); await Assert.That(fallbackLogger.Entries).HasSingleItem(); - await Assert.That(fallbackLogger.Entries[0].Exception).IsSameReferenceAs(logException); + await Assert.That(fallbackLogger.Entries[0].Exception).IsNotSameReferenceAs(logException); + await Assert.That(fallbackLogger.Entries[0].Exception?.ToString()).DoesNotContain("secret"); await Assert.That(buffer.HasOutput).IsFalse(); } @@ -759,6 +778,8 @@ private sealed class RecordingLogger : ILogger { public List<(string Message, Exception? Exception)> Entries { get; } = []; + public List StateTypes { get; } = []; + public Exception? LogException { get; set; } public IDisposable? BeginScope(TState state) @@ -779,6 +800,7 @@ public void Log( throw LogException; } + StateTypes.Add(typeof(TState)); Entries.Add((formatter(state, exception), exception)); } } diff --git a/test/ModularPipelines.UnitTests/Logging/FormattedLogValuesObfuscatorTests.cs b/test/ModularPipelines.UnitTests/Logging/FormattedLogValuesObfuscatorTests.cs index f8da674d5e..bc310578fc 100644 --- a/test/ModularPipelines.UnitTests/Logging/FormattedLogValuesObfuscatorTests.cs +++ b/test/ModularPipelines.UnitTests/Logging/FormattedLogValuesObfuscatorTests.cs @@ -92,4 +92,40 @@ public async Task TryObfuscateValues_MasksCustomStructuredLogStates() await Assert.That(properties["ModuleName"]).IsEqualTo("********"); } + + [Test] + public async Task TryObfuscateValues_MasksUnstructuredState() + { + const string secret = "plain-state-secret"; + var secretObfuscator = new Mock(); + secretObfuscator + .Setup(x => x.Obfuscate(It.IsAny(), null)) + .Returns((string? value, object? _) => + (value ?? string.Empty).Replace(secret, "********", StringComparison.Ordinal)); + + var obfuscatedState = new FormattedLogValuesObfuscator(secretObfuscator.Object) + .TryObfuscateValues($"Value: {secret}"); + + await Assert.That(obfuscatedState).IsEqualTo("Value: ********"); + } + + [Test] + public async Task TryObfuscateValues_PreservesStateWhenToStringThrows() + { + var state = new ThrowingToStringState(); + var secretObfuscator = new Mock(); + + var obfuscatedState = new FormattedLogValuesObfuscator(secretObfuscator.Object) + .TryObfuscateValues(state); + + await Assert.That(obfuscatedState).IsSameReferenceAs(state); + secretObfuscator.Verify( + x => x.Obfuscate(It.IsAny(), It.IsAny()), + Times.Never); + } + + private sealed class ThrowingToStringState + { + public override string ToString() => throw new InvalidOperationException("Cannot format state."); + } } diff --git a/test/ModularPipelines.UnitTests/Logging/PipelineLevelLoggerTests.cs b/test/ModularPipelines.UnitTests/Logging/PipelineLevelLoggerTests.cs index f4722ab157..7831be28de 100644 --- a/test/ModularPipelines.UnitTests/Logging/PipelineLevelLoggerTests.cs +++ b/test/ModularPipelines.UnitTests/Logging/PipelineLevelLoggerTests.cs @@ -1,4 +1,7 @@ +using System.Collections; using Microsoft.Extensions.Logging; +using ModularPipelines.Constants; +using ModularPipelines.Engine; using ModularPipelines.Logging; using Moq; @@ -14,7 +17,8 @@ public void Log_DelegatesToUnderlyingLogger() { // Arrange var mockLogger = new Mock(); - var pipelineLevelLogger = new PipelineLevelLogger(mockLogger.Object); + mockLogger.Setup(x => x.IsEnabled(LogLevel.Information)).Returns(true); + var pipelineLevelLogger = CreateLogger(mockLogger.Object); var eventId = new EventId(1, "TestEvent"); const string message = "Test message"; @@ -30,6 +34,54 @@ public void Log_DelegatesToUnderlyingLogger() It.IsAny>()), Times.Once); } + [Test] + public void Log_DoesNotObfuscateWhenDisabled() + { + var mockLogger = new Mock(); + var secretObfuscator = new Mock(); + var pipelineLevelLogger = new PipelineLevelLogger( + mockLogger.Object, + secretObfuscator.Object, + new FormattedLogValuesObfuscator(secretObfuscator.Object)); + + pipelineLevelLogger.LogError( + new InvalidOperationException("secret"), + "Token {Token}", + "secret"); + + secretObfuscator.Verify( + x => x.Obfuscate(It.IsAny(), It.IsAny()), + Times.Never); + mockLogger.Verify( + x => x.Log( + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny>()), + Times.Never); + } + + [Test] + public async Task Log_PreservesNullState() + { + var underlyingLogger = new RecordingLogger(); + var pipelineLevelLogger = CreateLogger(underlyingLogger); + + pipelineLevelLogger.Log( + LogLevel.Information, + new EventId(2, "NullState"), + null, + null, + static (state, _) => state ?? "null-state"); + + using (Assert.Multiple()) + { + await Assert.That(underlyingLogger.State).IsNull(); + await Assert.That(underlyingLogger.Message).IsEqualTo("null-state"); + } + } + [Test] public async Task IsEnabled_DelegatesToUnderlyingLogger() { @@ -37,7 +89,7 @@ public async Task IsEnabled_DelegatesToUnderlyingLogger() var mockLogger = new Mock(); mockLogger.Setup(x => x.IsEnabled(LogLevel.Warning)).Returns(true); mockLogger.Setup(x => x.IsEnabled(LogLevel.Trace)).Returns(false); - var pipelineLevelLogger = new PipelineLevelLogger(mockLogger.Object); + var pipelineLevelLogger = CreateLogger(mockLogger.Object); // Act & Assert await Assert.That(pipelineLevelLogger.IsEnabled(LogLevel.Warning)).IsTrue(); @@ -51,7 +103,7 @@ public async Task BeginScope_DelegatesToUnderlyingLogger() var mockLogger = new Mock(); var expectedScope = new Mock(); mockLogger.Setup(x => x.BeginScope("test scope")).Returns(expectedScope.Object); - var pipelineLevelLogger = new PipelineLevelLogger(mockLogger.Object); + var pipelineLevelLogger = CreateLogger(mockLogger.Object); // Act var scope = pipelineLevelLogger.BeginScope("test scope"); @@ -65,9 +117,323 @@ public void Dispose_DoesNotThrow() { // Arrange var mockLogger = new Mock(); - var pipelineLevelLogger = new PipelineLevelLogger(mockLogger.Object); + var pipelineLevelLogger = CreateLogger(mockLogger.Object); // Act & Assert - should not throw pipelineLevelLogger.Dispose(); } + + [Test] + public async Task Log_ObfuscatesStateMessageAndExceptionBeforeDelegating() + { + const string secret = "pipeline-secret"; + var underlyingLogger = new RecordingLogger(); + var originalException = new InvalidOperationException($"Failure: {secret}"); + var pipelineLevelLogger = CreateLogger( + underlyingLogger, + value => value?.Replace(secret, "********", StringComparison.Ordinal) ?? string.Empty); + + pipelineLevelLogger.LogError( + originalException, + "Token {Token}", + secret); + + await Assert.That(underlyingLogger.State?.ToString()).DoesNotContain(secret); + await Assert.That(underlyingLogger.Message).DoesNotContain(secret); + await Assert.That(underlyingLogger.Exception).IsNotSameReferenceAs(originalException); + await Assert.That(underlyingLogger.Exception?.ToString()).DoesNotContain(secret); + } + + [Test] + public async Task Log_PreservesSanitizedExceptionDiagnostics() + { + const string secret = "pipeline-secret"; + var underlyingLogger = new RecordingLogger(); + var innerException = new ArgumentException($"Inner: {secret}"); + var originalException = CaptureException( + new InvalidOperationException($"Outer: {secret}", innerException)); + originalException.HelpLink = $"https://example.invalid/{secret}"; + originalException.Source = $"source-{secret}"; + originalException.Data[$"key-{secret}"] = $"value-{secret}"; + originalException.Data["number"] = 42; + originalException.Data["hostile"] = new ThrowingToStringValue(); + var pipelineLevelLogger = CreateLogger( + underlyingLogger, + value => value?.Replace(secret, "********", StringComparison.Ordinal) ?? string.Empty); + + pipelineLevelLogger.LogError(originalException, "Failure"); + + var exception = underlyingLogger.Exception; + using (Assert.Multiple()) + { + await Assert.That(exception?.StackTrace).Contains(nameof(CaptureException)); + await Assert.That(exception?.StackTrace).DoesNotContain(secret); + await Assert.That(exception?.TargetSite).IsEqualTo(originalException.TargetSite); + await Assert.That(exception?.InnerException).IsNotNull(); + await Assert.That(exception?.InnerException?.Message).IsEqualTo("Inner: ********"); + await Assert.That(exception?.InnerException).IsNotSameReferenceAs(innerException); + await Assert.That(exception?.HelpLink).IsEqualTo("https://example.invalid/********"); + await Assert.That(exception?.Source).IsEqualTo("source-********"); + await Assert.That(exception?.Data["key-********"]).IsEqualTo("value-********"); + await Assert.That(exception?.Data["number"]).IsEqualTo(42); + await Assert.That(exception?.Data["hostile"]).IsEqualTo(LoggingConstants.SecretMask); + } + } + + [Test] + public async Task Log_GuardsHostileExceptionDiagnostics() + { + var underlyingLogger = new RecordingLogger(); + var pipelineLevelLogger = CreateLogger(underlyingLogger); + + await Assert.That( + () => pipelineLevelLogger.LogError(new ThrowingDiagnosticException(), "Failure")) + .ThrowsNothing(); + + using (Assert.Multiple()) + { + await Assert.That(underlyingLogger.Exception?.Message) + .IsEqualTo(LoggingConstants.SecretMask); + await Assert.That(underlyingLogger.Exception?.ToString()) + .Contains(nameof(ThrowingDiagnosticException)); + } + } + + [Test] + public async Task Log_GuardsHostileStructuredTraversal() + { + var underlyingLogger = new RecordingLogger(); + var pipelineLevelLogger = CreateLogger(underlyingLogger); + + await Assert.That(() => pipelineLevelLogger.Log( + LogLevel.Information, + new EventId(3, "HostileState"), + new ThrowingCountStructuredState(), + null, + static (_, _) => throw new InvalidOperationException("Cannot format state."))) + .ThrowsNothing(); + + using (Assert.Multiple()) + { + await Assert.That(underlyingLogger.State).IsEqualTo(LoggingConstants.SecretMask); + await Assert.That(underlyingLogger.Message).IsEqualTo(LoggingConstants.SecretMask); + } + } + + [Test] + public async Task Log_PreservesEverySanitizedAggregateExceptionBranch() + { + const string secret = "pipeline-secret"; + var underlyingLogger = new RecordingLogger(); + var firstException = new InvalidOperationException($"First: {secret}"); + var secondException = new ArgumentException($"Second: {secret}"); + var originalException = new AggregateException( + $"Aggregate: {secret}", + firstException, + secondException); + var pipelineLevelLogger = CreateLogger( + underlyingLogger, + value => value?.Replace(secret, "********", StringComparison.Ordinal) ?? string.Empty); + + pipelineLevelLogger.LogError(originalException, "Failure"); + + var aggregateException = underlyingLogger.Exception as AggregateException; + using (Assert.Multiple()) + { + await Assert.That(aggregateException).IsNotNull(); + await Assert.That(aggregateException!.InnerExceptions).Count().IsEqualTo(2); + await Assert.That(aggregateException.InnerExceptions[0].Message).IsEqualTo("First: ********"); + await Assert.That(aggregateException.InnerExceptions[1].Message).IsEqualTo("Second: ********"); + await Assert.That(aggregateException.InnerExceptions[0]).IsNotSameReferenceAs(firstException); + await Assert.That(aggregateException.InnerExceptions[1]).IsNotSameReferenceAs(secondException); + } + } + + [Test] + public async Task BeginScope_ObfuscatesStateBeforeDelegating() + { + const string secret = "scope-secret"; + var underlyingLogger = new RecordingLogger(); + var pipelineLevelLogger = CreateLogger( + underlyingLogger, + value => value?.Replace(secret, "********", StringComparison.Ordinal) ?? string.Empty); + + pipelineLevelLogger.BeginScope($"Scope: {secret}"); + + await Assert.That(underlyingLogger.Scope?.ToString()).IsEqualTo("Scope: ********"); + } + + [Test] + public async Task BeginScope_PreservesStructuredFormattedRenderingAfterObfuscation() + { + const string secret = "scope-secret"; + var underlyingLogger = new RecordingLogger(); + var pipelineLevelLogger = CreateLogger( + underlyingLogger, + value => value?.Replace(secret, "********", StringComparison.Ordinal) ?? string.Empty); + + pipelineLevelLogger.BeginScope("Token {Token}", secret); + + await Assert.That(underlyingLogger.Scope?.ToString()).IsEqualTo("Token ********"); + var structuredScope = underlyingLogger.Scope + as IReadOnlyList>; + await Assert.That(structuredScope).IsNotNull(); + await Assert.That(structuredScope![0].Value?.ToString()).IsEqualTo("********"); + } + + [Test] + public async Task BeginScope_PreservesStructuredStateWhenRenderingThrows() + { + const string secret = "scope-secret"; + var underlyingLogger = new RecordingLogger(); + var pipelineLevelLogger = CreateLogger( + underlyingLogger, + value => value?.Replace(secret, "********", StringComparison.Ordinal) ?? string.Empty); + var state = new ThrowingStructuredScopeState("Token", secret); + + await Assert.That(() => pipelineLevelLogger.BeginScope(state)).ThrowsNothing(); + + var structuredScope = underlyingLogger.Scope + as IReadOnlyList>; + await Assert.That(structuredScope).IsNotNull(); + await Assert.That(structuredScope![0].Value).IsEqualTo("********"); + await Assert.That(underlyingLogger.Scope?.ToString()).IsEqualTo(LoggingConstants.SecretMask); + } + + [Test] + public async Task BeginScope_GuardsHostileStructuredTraversal() + { + var underlyingLogger = new RecordingLogger(); + var pipelineLevelLogger = CreateLogger(underlyingLogger); + + await Assert.That( + () => pipelineLevelLogger.BeginScope(new ThrowingCountStructuredState())) + .ThrowsNothing(); + + await Assert.That(underlyingLogger.Scope).IsEqualTo(LoggingConstants.SecretMask); + } + + private static PipelineLevelLogger CreateLogger( + ILogger logger, + Func? obfuscate = null) + { + var secretObfuscator = new Mock(); + secretObfuscator + .Setup(x => x.Obfuscate(It.IsAny(), null)) + .Returns((string? value, object? _) => obfuscate?.Invoke(value) ?? value ?? string.Empty); + + return new PipelineLevelLogger( + logger, + secretObfuscator.Object, + new FormattedLogValuesObfuscator(secretObfuscator.Object)); + } + + private static Exception CaptureException(Exception exception) + { + try + { + throw exception; + } + catch (Exception captured) + { + return captured; + } + } + + private sealed class ThrowingStructuredScopeState( + string key, + object? value) : IReadOnlyList> + { + private readonly KeyValuePair[] _values = + [ + new(key, value), + ]; + + public int Count => _values.Length; + + public KeyValuePair this[int index] => _values[index]; + + public IEnumerator> GetEnumerator() => + ((IEnumerable>) _values).GetEnumerator(); + + System.Collections.IEnumerator System.Collections.IEnumerable.GetEnumerator() => + GetEnumerator(); + + public override string ToString() => throw new InvalidOperationException("Cannot format scope."); + } + + private sealed class ThrowingCountStructuredState + : IReadOnlyList> + { + public int Count => throw new InvalidOperationException("Cannot count scope values."); + + public KeyValuePair this[int index] => + throw new InvalidOperationException("Cannot read scope value."); + + public IEnumerator> GetEnumerator() => + throw new InvalidOperationException("Cannot enumerate scope values."); + + IEnumerator IEnumerable.GetEnumerator() => GetEnumerator(); + } + + private sealed class ThrowingToStringValue + { + public override string ToString() => throw new InvalidOperationException("Cannot format value."); + } + + private sealed class ThrowingDiagnosticException : Exception + { + public override string Message => throw new InvalidOperationException("Cannot read message."); + + public override IDictionary Data => throw new InvalidOperationException("Cannot read data."); + + public override string? HelpLink + { + get => throw new InvalidOperationException("Cannot read help link."); + set => base.HelpLink = value; + } + + public override string? Source + { + get => throw new InvalidOperationException("Cannot read source."); + set => base.Source = value; + } + + public override string? StackTrace => + throw new InvalidOperationException("Cannot read stack trace."); + + public override string ToString() => throw new InvalidOperationException("Cannot format exception."); + } + + private sealed class RecordingLogger : ILogger + { + public object? State { get; private set; } + + public object? Scope { get; private set; } + + public string? Message { get; private set; } + + public Exception? Exception { get; private set; } + + public IDisposable? BeginScope(TState state) + where TState : notnull + { + Scope = state; + return null; + } + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + State = state; + Exception = exception; + Message = formatter(state, exception); + } + } }