diff --git a/.gitignore b/.gitignore index 740dafc6d7..01a7753946 100644 --- a/.gitignore +++ b/.gitignore @@ -438,4 +438,4 @@ doc/plans/ *.nettrace # Git worktrees -.worktrees/.worktrees/ +.worktrees/ diff --git a/TUnit.Core/Logging/DefaultLogger.cs b/TUnit.Core/Logging/DefaultLogger.cs index 9479873ec2..17a8b9d78f 100644 --- a/TUnit.Core/Logging/DefaultLogger.cs +++ b/TUnit.Core/Logging/DefaultLogger.cs @@ -124,16 +124,13 @@ protected virtual string GenerateMessage(string message, Exception? exception, L /// True if this is an error-level message. protected virtual void WriteToOutput(string message, bool isError) { - if (isError) - { - context.ErrorOutputWriter.WriteLine(message); - GlobalContext.Current.OriginalConsoleError.WriteLine(message); - } - else - { - context.OutputWriter.WriteLine(message); - GlobalContext.Current.OriginalConsoleOut.WriteLine(message); - } + var level = isError ? LogLevel.Error : LogLevel.Information; + + // Route to registered log sinks - they handle output destinations: + // - TestOutputSink: accumulates to context for test results + // - ConsoleOutputSink: writes to console (if --output Detailed) + // - RealTimeOutputSink: streams to IDEs + LogSinkRouter.RouteToSinks(level, message, null, context); } /// @@ -145,15 +142,12 @@ protected virtual void WriteToOutput(string message, bool isError) /// A task representing the async operation. protected virtual async ValueTask WriteToOutputAsync(string message, bool isError) { - if (isError) - { - await context.ErrorOutputWriter.WriteLineAsync(message); - await GlobalContext.Current.OriginalConsoleError.WriteLineAsync(message); - } - else - { - await context.OutputWriter.WriteLineAsync(message); - await GlobalContext.Current.OriginalConsoleOut.WriteLineAsync(message); - } + var level = isError ? LogLevel.Error : LogLevel.Information; + + // Route to registered log sinks - they handle output destinations: + // - TestOutputSink: accumulates to context for test results + // - ConsoleOutputSink: writes to console (if --output Detailed) + // - RealTimeOutputSink: streams to IDEs + await LogSinkRouter.RouteToSinksAsync(level, message, null, context); } } diff --git a/TUnit.Core/Logging/ILogSink.cs b/TUnit.Core/Logging/ILogSink.cs new file mode 100644 index 0000000000..8a0161689b --- /dev/null +++ b/TUnit.Core/Logging/ILogSink.cs @@ -0,0 +1,108 @@ +namespace TUnit.Core.Logging; + +/// +/// Represents a destination for log messages. Implement this interface +/// to create custom log sinks that receive output from tests. +/// +/// +/// +/// Log sinks receive all output from: +/// +/// Console.WriteLine() calls during test execution +/// Console.Error.WriteLine() calls (with ) +/// TUnit logger output via TestContext.Current.GetDefaultLogger() +/// +/// +/// +/// Register your sink in a [Before(Assembly)] hook or before tests run using +/// . +/// +/// +/// +/// +/// // Example: File logging sink +/// public class FileLogSink : ILogSink, IAsyncDisposable +/// { +/// private readonly StreamWriter _writer; +/// +/// public FileLogSink(string path) +/// { +/// _writer = new StreamWriter(path, append: true); +/// } +/// +/// public bool IsEnabled(LogLevel level) => level >= LogLevel.Information; +/// +/// public void Log(LogLevel level, string message, Exception? exception, Context? context) +/// { +/// var testName = context is TestContext tc ? tc.TestDetails.TestName : "Unknown"; +/// _writer.WriteLine($"[{DateTime.Now:HH:mm:ss}] [{level}] [{testName}] {message}"); +/// if (exception != null) +/// _writer.WriteLine(exception.ToString()); +/// } +/// +/// public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) +/// { +/// Log(level, message, exception, context); +/// return ValueTask.CompletedTask; +/// } +/// +/// public async ValueTask DisposeAsync() +/// { +/// await _writer.FlushAsync(); +/// await _writer.DisposeAsync(); +/// } +/// } +/// +/// // Register in assembly hook: +/// [Before(Assembly)] +/// public static void SetupLogging() +/// { +/// TUnitLoggerFactory.AddSink(new FileLogSink("test-output.log")); +/// } +/// +/// +public interface ILogSink +{ + /// + /// Determines if this sink should receive messages at the specified level. + /// Return false to skip processing for performance. + /// + /// The log level to check. + /// true if messages at this level should be logged; otherwise false. + bool IsEnabled(LogLevel level); + + /// + /// Synchronously logs a message to this sink. + /// + /// The log level (Information, Warning, Error, etc.). + /// The formatted message to log. + /// Optional exception associated with this log entry. + /// + /// The current execution context, which may be: + /// + /// - during test execution + /// - during class hooks + /// - during assembly hooks + /// null - if outside test execution + /// + /// + void Log(LogLevel level, string message, Exception? exception, Context? context); + + /// + /// Asynchronously logs a message to this sink. + /// + /// The log level (Information, Warning, Error, etc.). + /// The formatted message to log. + /// Optional exception associated with this log entry. + /// + /// The current execution context, which may be: + /// + /// - during test execution + /// - during class hooks + /// - during assembly hooks + /// null - if outside test execution + /// + /// + /// A representing the asynchronous operation. + ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context); +} diff --git a/TUnit.Core/Logging/LogSinkRouter.cs b/TUnit.Core/Logging/LogSinkRouter.cs new file mode 100644 index 0000000000..526c623c0b --- /dev/null +++ b/TUnit.Core/Logging/LogSinkRouter.cs @@ -0,0 +1,63 @@ +namespace TUnit.Core.Logging; + +/// +/// Internal helper for routing log messages to all registered sinks. +/// +internal static class LogSinkRouter +{ + public static void RouteToSinks(LogLevel level, string message, Exception? exception, Context? context) + { + var sinks = TUnitLoggerFactory.GetSinks(); + if (sinks.Count == 0) + { + return; + } + + foreach (var sink in sinks) + { + if (!sink.IsEnabled(level)) + { + continue; + } + + try + { + sink.Log(level, message, exception, context); + } + catch (Exception ex) + { + // Write to original console to avoid recursion + GlobalContext.Current.OriginalConsoleError.WriteLine( + $"[TUnit] Log sink {sink.GetType().Name} failed: {ex.Message}"); + } + } + } + + public static async ValueTask RouteToSinksAsync(LogLevel level, string message, Exception? exception, Context? context) + { + var sinks = TUnitLoggerFactory.GetSinks(); + if (sinks.Count == 0) + { + return; + } + + foreach (var sink in sinks) + { + if (!sink.IsEnabled(level)) + { + continue; + } + + try + { + await sink.LogAsync(level, message, exception, context).ConfigureAwait(false); + } + catch (Exception ex) + { + // Write to original console to avoid recursion + await GlobalContext.Current.OriginalConsoleError.WriteLineAsync( + $"[TUnit] Log sink {sink.GetType().Name} failed: {ex.Message}").ConfigureAwait(false); + } + } + } +} diff --git a/TUnit.Core/Logging/TUnitLoggerFactory.cs b/TUnit.Core/Logging/TUnitLoggerFactory.cs new file mode 100644 index 0000000000..1eaab9adda --- /dev/null +++ b/TUnit.Core/Logging/TUnitLoggerFactory.cs @@ -0,0 +1,174 @@ +namespace TUnit.Core.Logging; + +/// +/// Factory for configuring and managing log sinks in TUnit. +/// Use this class to register custom sinks that receive test output. +/// +/// +/// +/// TUnit uses a sink-based logging architecture where all test output +/// (Console.WriteLine, logger calls, etc.) is routed through registered sinks. +/// Each sink can handle the output differently - write to files, stream to IDEs, +/// send to external services, etc. +/// +/// +/// Built-in sinks (registered automatically): +/// +/// TestOutputSink - Captures output for test results +/// ConsoleOutputSink - Real-time console output (when --output Detailed) +/// RealTimeOutputSink - Streams to IDE test explorers +/// +/// +/// +/// Register custom sinks in a [Before(Assembly)] hook: +/// +/// +/// +/// +/// // Register a custom sink in an assembly hook +/// public class TestSetup +/// { +/// [Before(Assembly)] +/// public static void SetupLogging() +/// { +/// // Register by instance (for sinks needing configuration) +/// TUnitLoggerFactory.AddSink(new FileLogSink("test-output.log")); +/// +/// // Or register by type (for simple sinks) +/// TUnitLoggerFactory.AddSink<DebugLogSink>(); +/// } +/// } +/// +/// // Simple sink that writes to Debug output +/// public class DebugLogSink : ILogSink +/// { +/// public bool IsEnabled(LogLevel level) => true; +/// +/// public void Log(LogLevel level, string message, Exception? exception, Context? context) +/// { +/// System.Diagnostics.Debug.WriteLine($"[{level}] {message}"); +/// } +/// +/// public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) +/// { +/// Log(level, message, exception, context); +/// return ValueTask.CompletedTask; +/// } +/// } +/// +/// +public static class TUnitLoggerFactory +{ + private static readonly List _sinks = []; + private static readonly Lock _lock = new(); + + /// + /// Registers a log sink instance to receive log messages from all tests. + /// + /// The sink instance to register. + /// + /// + /// Call this method in a [Before(Assembly)] hook to ensure the sink + /// is registered before any tests run. + /// + /// + /// If your sink implements or , + /// it will be automatically disposed when the test session ends. + /// + /// + /// + /// + /// [Before(Assembly)] + /// public static void SetupLogging() + /// { + /// TUnitLoggerFactory.AddSink(new FileLogSink("test-output.log")); + /// } + /// + /// + public static void AddSink(ILogSink sink) + { + lock (_lock) + { + _sinks.Add(sink); + } + } + + /// + /// Registers a log sink by type. TUnit will create a new instance using the parameterless constructor. + /// + /// + /// The sink type to register. Must implement and have a parameterless constructor. + /// + /// + /// Use this overload for simple sinks that don't require constructor parameters. + /// For sinks that need configuration, use instead. + /// + /// + /// + /// [Before(Assembly)] + /// public static void SetupLogging() + /// { + /// TUnitLoggerFactory.AddSink<DebugLogSink>(); + /// } + /// + /// + public static void AddSink() where TSink : ILogSink, new() + { + AddSink(new TSink()); + } + + /// + /// Gets all registered sinks. For internal use. + /// + internal static IReadOnlyList GetSinks() + { + lock (_lock) + { + return _sinks.ToArray(); + } + } + + /// + /// Disposes all sinks that implement IAsyncDisposable or IDisposable. + /// Called at end of test session. + /// + internal static async ValueTask DisposeAllAsync() + { + ILogSink[] sinksToDispose; + lock (_lock) + { + sinksToDispose = _sinks.ToArray(); + _sinks.Clear(); + } + + foreach (var sink in sinksToDispose) + { + try + { + if (sink is IAsyncDisposable asyncDisposable) + { + await asyncDisposable.DisposeAsync().ConfigureAwait(false); + } + else if (sink is IDisposable disposable) + { + disposable.Dispose(); + } + } + catch + { + // Swallow disposal errors + } + } + } + + /// + /// Clears all registered sinks. For testing purposes. + /// + internal static void Clear() + { + lock (_lock) + { + _sinks.Clear(); + } + } +} diff --git a/TUnit.Engine/Framework/TUnitServiceProvider.cs b/TUnit.Engine/Framework/TUnitServiceProvider.cs index bff64d228a..66e3822a51 100644 --- a/TUnit.Engine/Framework/TUnitServiceProvider.cs +++ b/TUnit.Engine/Framework/TUnitServiceProvider.cs @@ -11,6 +11,7 @@ using TUnit.Core; using TUnit.Core.Helpers; using TUnit.Core.Interfaces; +using TUnit.Core.Logging; using TUnit.Core.Tracking; using TUnit.Engine.Building; using TUnit.Engine.Building.Collectors; @@ -25,6 +26,8 @@ using TUnit.Engine.Services; using TUnit.Engine.Services.TestExecution; +#pragma warning disable TPEXP // Experimental API - GetClientInfo + namespace TUnit.Engine.Framework; internal class TUnitServiceProvider : IServiceProvider, IAsyncDisposable @@ -136,6 +139,19 @@ public TUnitServiceProvider(IExtension extension, frameworkServiceProvider, context)); + // Register log sinks based on output mode + + // TestOutputSink: Always registered - accumulates to Context.OutputWriter/ErrorOutputWriter for test results + TUnitLoggerFactory.AddSink(new TestOutputSink()); + + // ConsoleOutputSink: For --output Detailed mode - real-time console output + if (VerbosityService.IsDetailedOutput) + { + TUnitLoggerFactory.AddSink(new ConsoleOutputSink( + StandardOutConsoleInterceptor.DefaultOut, + StandardErrorConsoleInterceptor.DefaultError)); + } + CancellationToken = Register(new EngineCancellationToken()); EventReceiverOrchestrator = Register(new EventReceiverOrchestrator(Logger)); @@ -269,8 +285,8 @@ public TUnitServiceProvider(IExtension extension, private void InitializeConsoleInterceptors() { - var outInterceptor = new StandardOutConsoleInterceptor(VerbosityService); - var errorInterceptor = new StandardErrorConsoleInterceptor(VerbosityService); + var outInterceptor = new StandardOutConsoleInterceptor(); + var errorInterceptor = new StandardErrorConsoleInterceptor(); outInterceptor.Initialize(); errorInterceptor.Initialize(); @@ -307,6 +323,9 @@ public async ValueTask DisposeAsync() _services.Clear(); + // Dispose all log sinks (flushes any remaining logs) + await TUnitLoggerFactory.DisposeAllAsync().ConfigureAwait(false); + TestExtensions.ClearCaches(); } } diff --git a/TUnit.Engine/Logging/AsyncConsoleWriter.cs b/TUnit.Engine/Logging/AsyncConsoleWriter.cs deleted file mode 100644 index cdeffb7408..0000000000 --- a/TUnit.Engine/Logging/AsyncConsoleWriter.cs +++ /dev/null @@ -1,395 +0,0 @@ -using System.Text; -using System.Threading.Channels; - -namespace TUnit.Engine.Logging; - -/// -/// Lock-free asynchronous console writer that maintains message order -/// while eliminating contention between parallel tests -/// -internal sealed class AsyncConsoleWriter : TextWriter -{ - private readonly TextWriter _target; - private readonly Channel _writeChannel; - private readonly Task _processorTask; - private readonly CancellationTokenSource _shutdownCts = new(); - private volatile bool _disposed; - - // Command types for the queue - private enum CommandType - { - Write, - WriteLine, - Flush - } - - private readonly struct WriteCommand - { - public CommandType Type { get; } - public string? Text { get; } - - public WriteCommand(CommandType type, string? text = null) - { - Type = type; - Text = text; - } - - public static WriteCommand Write(string text) => new(CommandType.Write, text); - public static WriteCommand WriteLine(string text) => new(CommandType.WriteLine, text); - public static WriteCommand FlushCommand => new(CommandType.Flush); - } - - public AsyncConsoleWriter(TextWriter target) - { - _target = target ?? throw new ArgumentNullException(nameof(target)); - - // Create an unbounded channel for maximum throughput - // Order is guaranteed by the channel - _writeChannel = Channel.CreateUnbounded(new UnboundedChannelOptions - { - SingleWriter = false, // Multiple threads can write - SingleReader = true, // Single background task reads - AllowSynchronousContinuations = false // Don't block writers - }); - - // Start the background processor - _processorTask = Task.Run(ProcessWritesAsync); - } - - public override Encoding Encoding => _target.Encoding; - - public override void Write(char value) - { - if (_disposed) - { - return; - } - Write(value.ToString()); - } - - public override void Write(string? value) - { - if (_disposed || string.IsNullOrEmpty(value)) - { - return; - } - - // Non-blocking write to channel - if (!_writeChannel.Writer.TryWrite(WriteCommand.Write(value!))) - { - // Channel is closed, write directly - try - { - _target.Write(value); - } - catch - { - // Ignore write errors - } - } - } - - public override void Write(char[]? buffer) - { - if (_disposed || buffer == null) - { - return; - } - Write(new string(buffer)); - } - - public override void Write(char[] buffer, int index, int count) - { - if (_disposed || buffer == null || count <= 0) - { - return; - } - Write(new string(buffer, index, count)); - } - - public override void WriteLine() - { - if (_disposed) - { - return; - } - WriteLine(string.Empty); - } - - public override void WriteLine(string? value) - { - if (_disposed) - { - return; - } - - // Non-blocking write to channel - if (!_writeChannel.Writer.TryWrite(WriteCommand.WriteLine(value ?? string.Empty))) - { - // Channel is closed, write directly - try - { - _target.WriteLine(value); - } - catch - { - // Ignore write errors - } - } - } - - public override void Flush() - { - if (_disposed) - { - return; - } - - // Queue a flush command - if (!_writeChannel.Writer.TryWrite(WriteCommand.FlushCommand)) - { - // Channel is closed, flush directly - try - { - _target.Flush(); - } - catch - { - // Ignore flush errors - } - } - } - - public override async Task FlushAsync() - { - if (_disposed) - { - return; - } - - // Queue a flush and wait a bit for it to process - _writeChannel.Writer.TryWrite(WriteCommand.FlushCommand); - await Task.Delay(10); // Small delay to allow flush to process - } - - /// - /// Background task that processes all writes in order - /// Optimized to drain the channel in batches to reduce async overhead - /// - private async Task ProcessWritesAsync() - { - var buffer = new StringBuilder(4096); - var lastFlush = DateTime.UtcNow; - const int flushIntervalMs = 50; - - try - { - // Drain-loop pattern: reduces async state machine overhead by processing all available items in one go - while (await _writeChannel.Reader.WaitToReadAsync(_shutdownCts.Token).ConfigureAwait(false)) - { - // Drain all immediately available items from the channel - while (_writeChannel.Reader.TryRead(out var command)) - { - switch (command.Type) - { - case CommandType.Write: - buffer.Append(command.Text); - break; - - case CommandType.WriteLine: - buffer.AppendLine(command.Text); - break; - - case CommandType.Flush: - FlushBuffer(buffer); - lastFlush = DateTime.UtcNow; - continue; - } - - // Check if we should flush mid-drain (for large buffers) - if (buffer.Length > 4096) - { - FlushBuffer(buffer); - lastFlush = DateTime.UtcNow; - } - } - - // Flush after draining batch if time-based threshold met - if (buffer.Length > 0 && (DateTime.UtcNow - lastFlush).TotalMilliseconds > flushIntervalMs) - { - FlushBuffer(buffer); - lastFlush = DateTime.UtcNow; - } - } - } - catch (OperationCanceledException) - { - // Normal shutdown - } - finally - { - // Final flush on shutdown - if (buffer.Length > 0) - { - FlushBuffer(buffer); - } - } - } - - private void FlushBuffer(StringBuilder buffer) - { - if (buffer.Length == 0) - { - return; - } - - try - { - _target.Write(buffer.ToString()); - _target.Flush(); - } - catch - { - // Ignore write errors - } - finally - { - buffer.Clear(); - } - } - - protected override void Dispose(bool disposing) - { - if (_disposed) - { - return; - } - _disposed = true; - - if (disposing) - { - // Signal shutdown - _writeChannel.Writer.TryComplete(); - _shutdownCts.Cancel(); - - // Don't block on disposal - it can cause deadlocks - // Just give the processor task a brief moment to complete naturally - // The cancellation token will signal it to stop anyway - try - { - // Use a very short non-blocking wait to see if it's already done - _processorTask.Wait(1); - } - catch - { - // Ignore - the task might still be running, but we've signaled shutdown - // and it will complete on its own - } - - _shutdownCts.Dispose(); - } - - base.Dispose(disposing); - } - - // Formatted write methods to match BufferedTextWriter interface - public void WriteFormatted(string format, object? arg0) - { - if (_disposed) - { - return; - } - Write(string.Format(format, arg0)); - } - - public void WriteFormatted(string format, object? arg0, object? arg1) - { - if (_disposed) - { - return; - } - Write(string.Format(format, arg0, arg1)); - } - - public void WriteFormatted(string format, object? arg0, object? arg1, object? arg2) - { - if (_disposed) - { - return; - } - Write(string.Format(format, arg0, arg1, arg2)); - } - - public void WriteFormatted(string format, params object?[] args) - { - if (_disposed) - { - return; - } - Write(string.Format(format, args)); - } - - public void WriteLineFormatted(string format, object? arg0) - { - if (_disposed) - { - return; - } - WriteLine(string.Format(format, arg0)); - } - - public void WriteLineFormatted(string format, object? arg0, object? arg1) - { - if (_disposed) - { - return; - } - WriteLine(string.Format(format, arg0, arg1)); - } - - public void WriteLineFormatted(string format, object? arg0, object? arg1, object? arg2) - { - if (_disposed) - { - return; - } - WriteLine(string.Format(format, arg0, arg1, arg2)); - } - - public void WriteLineFormatted(string format, params object?[] args) - { - if (_disposed) - { - return; - } - WriteLine(string.Format(format, args)); - } - -#if NET - public override async ValueTask DisposeAsync() - { - if (_disposed) - { - return; - } - _disposed = true; - - // Signal shutdown - _writeChannel.Writer.TryComplete(); - _shutdownCts.Cancel(); - - // Wait for processor to finish - try - { - await _processorTask.ConfigureAwait(false); - } - catch - { - // Ignore - } - - _shutdownCts.Dispose(); - await base.DisposeAsync().ConfigureAwait(false); - } -#endif -} \ No newline at end of file diff --git a/TUnit.Engine/Logging/BufferedTextWriter.cs b/TUnit.Engine/Logging/BufferedTextWriter.cs deleted file mode 100644 index 230c3d9f7f..0000000000 --- a/TUnit.Engine/Logging/BufferedTextWriter.cs +++ /dev/null @@ -1,510 +0,0 @@ -using System.Collections.Concurrent; -using System.Text; - -#pragma warning disable CS8765 // Nullability of type of parameter doesn't match overridden member - -namespace TUnit.Engine.Logging; - -/// -/// A thread-safe buffered text writer that reduces allocation overhead -/// Uses per-thread buffers to minimize lock contention -/// -internal sealed class BufferedTextWriter : TextWriter, IDisposable -{ - private readonly TextWriter _target; - private readonly ReaderWriterLockSlim _lock = new(); - private readonly int _bufferSize; - private readonly ThreadLocal _threadLocalBuffer; - private readonly ConcurrentQueue _flushQueue = new(); - private volatile bool _disposed; - private readonly Timer _flushTimer; - - public BufferedTextWriter(TextWriter target, int bufferSize = 4096) - { - _target = target ?? throw new ArgumentNullException(nameof(target)); - _bufferSize = bufferSize; - _threadLocalBuffer = new ThreadLocal(() => new StringBuilder(bufferSize)); - - // Auto-flush every 100ms to prevent data loss - _flushTimer = new Timer(AutoFlush, null, TimeSpan.FromMilliseconds(100), TimeSpan.FromMilliseconds(100)); - } - - public override Encoding Encoding => _target.Encoding; - - public override IFormatProvider FormatProvider => _target.FormatProvider; - - public override string NewLine - { - get => _target.NewLine; - set - { - _lock.EnterWriteLock(); - try - { - _target.NewLine = value ?? Environment.NewLine; - } - finally - { - _lock.ExitWriteLock(); - } - } - } - - public override void Write(char value) - { - if (_disposed) - { - return; - } - - var buffer = _threadLocalBuffer.Value; - if (buffer == null) - { - return; - } - - buffer.Append(value); - CheckFlush(buffer); - } - - public override void Write(string? value) - { - if (string.IsNullOrEmpty(value) || _disposed) - { - return; - } - - var buffer = _threadLocalBuffer.Value; - if (buffer == null) - { - return; - } - - buffer.Append(value); - CheckFlush(buffer); - } - - public override void Write(char[] buffer, int index, int count) - { - if (buffer == null || count <= 0 || _disposed) - { - return; - } - - var localBuffer = _threadLocalBuffer.Value; - if (localBuffer == null) - { - return; - } - - localBuffer.Append(buffer, index, count); - CheckFlush(localBuffer); - } - - public override void WriteLine() - { - if (_disposed) - { - return; - } - - var buffer = _threadLocalBuffer.Value; - if (buffer == null) - { - return; - } - - buffer.AppendLine(); - FlushBuffer(buffer); - } - - public override void WriteLine(string? value) - { - if (_disposed) - { - return; - } - - var buffer = _threadLocalBuffer.Value; - if (buffer == null) - { - return; - } - - buffer.AppendLine(value); - FlushBuffer(buffer); - } - - // Optimized Write methods to avoid boxing and tuple allocations - public void WriteFormatted(string format, object? arg0) - { - if (_disposed) - { - return; - } - - var buffer = _threadLocalBuffer.Value; - if (buffer == null) - { - return; - } - - buffer.AppendFormat(format, arg0); - CheckFlush(buffer); - } - - public void WriteFormatted(string format, object? arg0, object? arg1) - { - if (_disposed) - { - return; - } - - var buffer = _threadLocalBuffer.Value; - if (buffer == null) - { - return; - } - - buffer.AppendFormat(format, arg0, arg1); - CheckFlush(buffer); - } - - public void WriteFormatted(string format, object? arg0, object? arg1, object? arg2) - { - if (_disposed) - { - return; - } - - var buffer = _threadLocalBuffer.Value; - if (buffer == null) - { - return; - } - - buffer.AppendFormat(format, arg0, arg1, arg2); - CheckFlush(buffer); - } - - public void WriteFormatted(string format, params object?[] args) - { - if (_disposed) - { - return; - } - - var buffer = _threadLocalBuffer.Value; - if (buffer == null) - { - return; - } - - buffer.AppendFormat(format, args); - CheckFlush(buffer); - } - - public void WriteLineFormatted(string format, object? arg0) - { - if (_disposed) - { - return; - } - - var buffer = _threadLocalBuffer.Value; - if (buffer == null) - { - return; - } - - buffer.AppendFormat(format, arg0); - buffer.AppendLine(); - FlushBuffer(buffer); - } - - public void WriteLineFormatted(string format, object? arg0, object? arg1) - { - if (_disposed) - { - return; - } - - var buffer = _threadLocalBuffer.Value; - if (buffer == null) - { - return; - } - - buffer.AppendFormat(format, arg0, arg1); - buffer.AppendLine(); - FlushBuffer(buffer); - } - - public void WriteLineFormatted(string format, object? arg0, object? arg1, object? arg2) - { - if (_disposed) - { - return; - } - - var buffer = _threadLocalBuffer.Value; - if (buffer == null) - { - return; - } - - buffer.AppendFormat(format, arg0, arg1, arg2); - buffer.AppendLine(); - FlushBuffer(buffer); - } - - public void WriteLineFormatted(string format, params object?[] args) - { - if (_disposed) - { - return; - } - - var buffer = _threadLocalBuffer.Value; - if (buffer == null) - { - return; - } - - buffer.AppendFormat(format, args); - buffer.AppendLine(); - FlushBuffer(buffer); - } - - public override void Flush() - { - // Flush all thread-local buffers - FlushAllThreadBuffers(); - - // Collect content to write without holding the lock - var contentToWrite = new List(); - - _lock.EnterWriteLock(); - try - { - // Dequeue all content while holding the lock - while (_flushQueue.TryDequeue(out var content)) - { - contentToWrite.Add(content); - } - } - finally - { - _lock.ExitWriteLock(); - } - - // Write content and flush outside the lock to avoid deadlock - foreach (var content in contentToWrite) - { - _target.Write(content); - } - _target.Flush(); - } - - public override async Task FlushAsync() - { - // Flush all thread-local buffers - FlushAllThreadBuffers(); - - var contentToWrite = new List(); - - _lock.EnterWriteLock(); - try - { - // Get all queued content - while (_flushQueue.TryDequeue(out var content)) - { - contentToWrite.Add(content); - } - } - finally - { - _lock.ExitWriteLock(); - } - - // Write all content asynchronously - foreach (var content in contentToWrite) - { - await _target.WriteAsync(content); - } - - await _target.FlushAsync(); - } - - private void CheckFlush(StringBuilder buffer) - { - // Flush if buffer is getting large - if (buffer.Length >= _bufferSize) - { - FlushBuffer(buffer); - } - } - - private void FlushBuffer(StringBuilder buffer) - { - if (buffer.Length == 0) - { - return; - } - - var content = buffer.ToString(); - buffer.Clear(); - - // Queue content for batch writing - _flushQueue.Enqueue(content); - - // Process queue if it's getting large - if (_flushQueue.Count > 10) - { - // Collect content to write without holding the lock - var contentToWrite = new List(); - - _lock.EnterWriteLock(); - try - { - // Dequeue content while holding the lock - while (_flushQueue.TryDequeue(out var queuedContent) && contentToWrite.Count < 20) - { - contentToWrite.Add(queuedContent); - } - } - finally - { - _lock.ExitWriteLock(); - } - - // Write content outside the lock to avoid deadlock - foreach (var contentItem in contentToWrite) - { - _target.Write(contentItem); - } - } - } - - private void FlushAllThreadBuffers() - { - // This forces all thread-local buffers to be flushed - // by accessing them from the current thread context - var currentBuffer = _threadLocalBuffer.Value; - if (currentBuffer?.Length > 0) - { - FlushBuffer(currentBuffer); - } - } - - private void ProcessFlushQueue() - { - // Process all queued content - while (_flushQueue.TryDequeue(out var content)) - { - _target.Write(content); - } - } - - private void AutoFlush(object? state) - { - if (_disposed) - { - return; - } - - try - { - FlushAllThreadBuffers(); - - // Collect content to write without holding the lock - var contentToWrite = new List(); - - _lock.EnterWriteLock(); - try - { - // Dequeue all content while holding the lock - while (_flushQueue.TryDequeue(out var content)) - { - contentToWrite.Add(content); - } - } - finally - { - _lock.ExitWriteLock(); - } - - // Write content outside the lock to avoid deadlock - foreach (var content in contentToWrite) - { - _target.Write(content); - } - } - catch - { - // Ignore errors in auto-flush to prevent crashes - } - } - - protected override void Dispose(bool disposing) - { - if (!_disposed && disposing) - { - _flushTimer?.Dispose(); - FlushAllThreadBuffers(); - - // Collect content to write without holding the lock - var contentToWrite = new List(); - - _lock.EnterWriteLock(); - try - { - // Dequeue all content while holding the lock - while (_flushQueue.TryDequeue(out var content)) - { - contentToWrite.Add(content); - } - _disposed = true; - } - finally - { - _lock.ExitWriteLock(); - } - - // Write content outside the lock - foreach (var content in contentToWrite) - { - _target.Write(content); - } - - _threadLocalBuffer?.Dispose(); - _lock?.Dispose(); - } - base.Dispose(disposing); - } - -#if NET - public override async ValueTask DisposeAsync() - { - if (!_disposed) - { - _flushTimer?.Dispose(); - await FlushAsync(); - - _lock.EnterWriteLock(); - try - { - _disposed = true; - } - finally - { - _lock.ExitWriteLock(); - } - - _threadLocalBuffer?.Dispose(); - _lock?.Dispose(); - } - await base.DisposeAsync().ConfigureAwait(false); - } -#endif -} \ No newline at end of file diff --git a/TUnit.Engine/Logging/ConsoleOutputSink.cs b/TUnit.Engine/Logging/ConsoleOutputSink.cs new file mode 100644 index 0000000000..ed05254333 --- /dev/null +++ b/TUnit.Engine/Logging/ConsoleOutputSink.cs @@ -0,0 +1,34 @@ +using TUnit.Core; +using TUnit.Core.Logging; + +namespace TUnit.Engine.Logging; + +/// +/// A log sink that writes output to the actual console (stdout/stderr). +/// Only registered when --output Detailed is specified. +/// +internal sealed class ConsoleOutputSink : ILogSink +{ + private readonly TextWriter _stdout; + private readonly TextWriter _stderr; + + public ConsoleOutputSink(TextWriter stdout, TextWriter stderr) + { + _stdout = stdout; + _stderr = stderr; + } + + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + var writer = level >= LogLevel.Error ? _stderr : _stdout; + writer.WriteLine(message); + } + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + Log(level, message, exception, context); + return ValueTask.CompletedTask; + } +} diff --git a/TUnit.Engine/Logging/OptimizedConsoleInterceptor.cs b/TUnit.Engine/Logging/OptimizedConsoleInterceptor.cs index 86239ace6f..3ba2bc37d2 100644 --- a/TUnit.Engine/Logging/OptimizedConsoleInterceptor.cs +++ b/TUnit.Engine/Logging/OptimizedConsoleInterceptor.cs @@ -1,596 +1,199 @@ using System.Text; -using TUnit.Engine.Services; +using TUnit.Core; +using TUnit.Core.Logging; #pragma warning disable CS8765 // Nullability of type of parameter doesn't match overridden member (possibly because of nullability attributes). namespace TUnit.Engine.Logging; /// -/// Optimized console interceptor that eliminates tuple allocations and uses buffered output +/// Console interceptor that captures output and routes it to registered sinks. +/// The interceptor itself doesn't write anywhere - it only routes to sinks: +/// - TestOutputSink: accumulates to Context.OutputWriter/ErrorOutputWriter +/// - ConsoleOutputSink: writes to actual console +/// - RealTimeOutputSink: streams to IDEs /// internal abstract class OptimizedConsoleInterceptor : TextWriter { - private readonly VerbosityService _verbosityService; - private readonly BufferedTextWriter? _originalOutBuffer; + private readonly StringBuilder _lineBuffer = new(); - protected OptimizedConsoleInterceptor(VerbosityService verbosityService) - { - _verbosityService = verbosityService; - - var originalOut = GetOriginalOut(); - - // Wrap outputs with buffered writers for better performance - _originalOutBuffer = originalOut != null ? new BufferedTextWriter(originalOut, 2048) : null; - } - - public override Encoding Encoding => RedirectedOut?.Encoding ?? _originalOutBuffer?.Encoding ?? Encoding.UTF8; + public override Encoding Encoding => Encoding.UTF8; - protected abstract TextWriter? RedirectedOut { get; } + /// + /// Gets the log level to use when routing console output to sinks. + /// + protected abstract LogLevel SinkLogLevel { get; } private protected abstract TextWriter GetOriginalOut(); private protected abstract void ResetDefault(); -#if NET - public override ValueTask DisposeAsync() + /// + /// Routes the message to registered log sinks. + /// + private void RouteToSinks(string? message) { - ResetDefault(); - _originalOutBuffer?.Dispose(); - // Don't dispose RedirectedOut as it's not owned by us - return ValueTask.CompletedTask; - } -#endif - - public override void Flush() - { - _originalOutBuffer?.Flush(); - RedirectedOut?.Flush(); - } - - public override async Task FlushAsync() - { - if (_originalOutBuffer != null) + if (message is not null && message.Length > 0) { - await _originalOutBuffer.FlushAsync(); + LogSinkRouter.RouteToSinks(SinkLogLevel, message, null, Context.Current); } - if (RedirectedOut != null) - { - await RedirectedOut.FlushAsync(); - } - } - - // Optimized Write methods - no tuple allocations - - public override void Write(bool value) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.Write(value.ToString()); - } - RedirectedOut?.Write(value.ToString()); - } - - public override void Write(char value) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.Write(value); - } - RedirectedOut?.Write(value); } - public override void Write(char[]? buffer) + /// + /// Routes the message to registered log sinks asynchronously. + /// + private async ValueTask RouteToSinksAsync(string? message) { - if (buffer == null) + if (message is not null && message.Length > 0) { - return; + await LogSinkRouter.RouteToSinksAsync(SinkLogLevel, message, null, Context.Current).ConfigureAwait(false); } - - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.Write(buffer); - } - RedirectedOut?.Write(buffer); } - public override void Write(decimal value) - { - var str = value.ToString(); - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.Write(str); - } - RedirectedOut?.Write(str); - } - - public override void Write(double value) - { - var str = value.ToString(); - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.Write(str); - } - RedirectedOut?.Write(str); - } - - public override void Write(int value) +#if NET + public override ValueTask DisposeAsync() { - var str = value.ToString(); - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.Write(str); - } - RedirectedOut?.Write(str); + ResetDefault(); + return ValueTask.CompletedTask; } +#endif - public override void Write(long value) + public override void Flush() { - var str = value.ToString(); - if (!_verbosityService.HideTestOutput) + // Flush any buffered partial line + if (_lineBuffer.Length > 0) { - _originalOutBuffer?.Write(str); + RouteToSinks(_lineBuffer.ToString()); + _lineBuffer.Clear(); } - RedirectedOut?.Write(str); } - public override void Write(object? value) + public override async Task FlushAsync() { - var str = value?.ToString() ?? string.Empty; - if (!_verbosityService.HideTestOutput) + if (_lineBuffer.Length > 0) { - _originalOutBuffer?.Write(str); + await RouteToSinksAsync(_lineBuffer.ToString()).ConfigureAwait(false); + _lineBuffer.Clear(); } - RedirectedOut?.Write(str); } - public override void Write(float value) + // Write methods - buffer partial writes until we get a complete line + public override void Write(bool value) => Write(value.ToString()); + public override void Write(char value) => BufferChar(value); + public override void Write(char[]? buffer) { - var str = value.ToString(); - if (!_verbosityService.HideTestOutput) + if (buffer != null) { - _originalOutBuffer?.Write(str); + BufferChars(buffer, 0, buffer.Length); } - RedirectedOut?.Write(str); } - + public override void Write(decimal value) => Write(value.ToString()); + public override void Write(double value) => Write(value.ToString()); + public override void Write(int value) => Write(value.ToString()); + public override void Write(long value) => Write(value.ToString()); + public override void Write(object? value) => Write(value?.ToString() ?? string.Empty); + public override void Write(float value) => Write(value.ToString()); public override void Write(string? value) { - if (value == null) - { - return; - } - - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.Write(value); - } - RedirectedOut?.Write(value); - } - - public override void Write(uint value) - { - var str = value.ToString(); - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.Write(str); - } - RedirectedOut?.Write(str); - } - - public override void Write(ulong value) - { - var str = value.ToString(); - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.Write(str); - } - RedirectedOut?.Write(str); + if (value == null) return; + _lineBuffer.Append(value); } + public override void Write(uint value) => Write(value.ToString()); + public override void Write(ulong value) => Write(value.ToString()); + public override void Write(char[] buffer, int index, int count) => BufferChars(buffer, index, count); + public override void Write(string format, object? arg0) => Write(string.Format(format, arg0)); + public override void Write(string format, object? arg0, object? arg1) => Write(string.Format(format, arg0, arg1)); + public override void Write(string format, object? arg0, object? arg1, object? arg2) => Write(string.Format(format, arg0, arg1, arg2)); + public override void Write(string format, params object?[] arg) => Write(string.Format(format, arg)); - public override void Write(char[] buffer, int index, int count) + private void BufferChar(char value) { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.Write(buffer, index, count); - } - RedirectedOut?.Write(buffer, index, count); + _lineBuffer.Append(value); } - // Optimized formatted Write methods - no tuple allocations - public override void Write(string format, object? arg0) + private void BufferChars(char[] buffer, int index, int count) { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteFormatted(format, arg0); - } - RedirectedOut?.Write(format, arg0); - } - - public override void Write(string format, object? arg0, object? arg1) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteFormatted(format, arg0, arg1); - } - RedirectedOut?.Write(format, arg0, arg1); - } - - public override void Write(string format, object? arg0, object? arg1, object? arg2) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteFormatted(format, arg0, arg1, arg2); - } - RedirectedOut?.Write(format, arg0, arg1, arg2); + _lineBuffer.Append(buffer, index, count); } - public override void Write(string format, params object?[] arg) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteFormatted(format, arg); - } - RedirectedOut?.Write(format, arg); - } - - // WriteLine methods + // WriteLine methods - flush buffer and route complete line to sinks public override void WriteLine() { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(); - } - RedirectedOut?.WriteLine(); - } - - public override void WriteLine(bool value) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(value.ToString()); - } - RedirectedOut?.WriteLine(value.ToString()); + var line = _lineBuffer.ToString(); + _lineBuffer.Clear(); + RouteToSinks(line); } - public override void WriteLine(char value) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(value.ToString()); - } - RedirectedOut?.WriteLine(value.ToString()); - } - - public override void WriteLine(char[]? buffer) - { - if (buffer == null) - { - return; - } - - var str = new string(buffer); - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(str); - } - RedirectedOut?.WriteLine(str); - } - - public override void WriteLine(char[] buffer, int index, int count) - { - var str = new string(buffer, index, count); - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(str); - } - RedirectedOut?.WriteLine(str); - } - - public override void WriteLine(decimal value) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(value.ToString()); - } - RedirectedOut?.WriteLine(value.ToString()); - } - - public override void WriteLine(double value) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(value.ToString()); - } - RedirectedOut?.WriteLine(value.ToString()); - } - - public override void WriteLine(int value) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(value.ToString()); - } - RedirectedOut?.WriteLine(value.ToString()); - } - - public override void WriteLine(long value) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(value.ToString()); - } - RedirectedOut?.WriteLine(value.ToString()); - } - - public override void WriteLine(object? value) - { - var str = value?.ToString() ?? string.Empty; - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(str); - } - RedirectedOut?.WriteLine(str); - } - - public override void WriteLine(float value) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(value.ToString()); - } - RedirectedOut?.WriteLine(value.ToString()); - } + public override void WriteLine(bool value) => WriteLine(value.ToString()); + public override void WriteLine(char value) => WriteLine(value.ToString()); + public override void WriteLine(char[]? buffer) => WriteLine(buffer != null ? new string(buffer) : string.Empty); + public override void WriteLine(char[] buffer, int index, int count) => WriteLine(new string(buffer, index, count)); + public override void WriteLine(decimal value) => WriteLine(value.ToString()); + public override void WriteLine(double value) => WriteLine(value.ToString()); + public override void WriteLine(int value) => WriteLine(value.ToString()); + public override void WriteLine(long value) => WriteLine(value.ToString()); + public override void WriteLine(object? value) => WriteLine(value?.ToString() ?? string.Empty); + public override void WriteLine(float value) => WriteLine(value.ToString()); public override void WriteLine(string? value) { - if (!_verbosityService.HideTestOutput) + // Prepend any buffered content + if (_lineBuffer.Length > 0) { - _originalOutBuffer?.WriteLine(value); + _lineBuffer.Append(value); + value = _lineBuffer.ToString(); + _lineBuffer.Clear(); } - RedirectedOut?.WriteLine(value); + RouteToSinks(value); } - public override void WriteLine(uint value) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(value.ToString()); - } - RedirectedOut?.WriteLine(value.ToString()); - } - - public override void WriteLine(ulong value) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(value.ToString()); - } - RedirectedOut?.WriteLine(value.ToString()); - } - - // Optimized formatted WriteLine methods - no tuple allocations - public override void WriteLine(string format, object? arg0) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLineFormatted(format, arg0); - } - RedirectedOut?.WriteLine(format, arg0); - } - - public override void WriteLine(string format, object? arg0, object? arg1) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLineFormatted(format, arg0, arg1); - } - RedirectedOut?.WriteLine(format, arg0, arg1); - } - - public override void WriteLine(string format, object? arg0, object? arg1, object? arg2) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLineFormatted(format, arg0, arg1, arg2); - } - RedirectedOut?.WriteLine(format, arg0, arg1, arg2); - } - - public override void WriteLine(string format, params object?[] arg) - { - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLineFormatted(format, arg); - } - RedirectedOut?.WriteLine(format, arg); - } + public override void WriteLine(uint value) => WriteLine(value.ToString()); + public override void WriteLine(ulong value) => WriteLine(value.ToString()); + public override void WriteLine(string format, object? arg0) => WriteLine(string.Format(format, arg0)); + public override void WriteLine(string format, object? arg0, object? arg1) => WriteLine(string.Format(format, arg0, arg1)); + public override void WriteLine(string format, object? arg0, object? arg1, object? arg2) => WriteLine(string.Format(format, arg0, arg1, arg2)); + public override void WriteLine(string format, params object?[] arg) => WriteLine(string.Format(format, arg)); // Async methods - public override async Task WriteLineAsync() - { - if (!_verbosityService.HideTestOutput && _originalOutBuffer != null) - { - await _originalOutBuffer.WriteAsync(Environment.NewLine); - } - if (RedirectedOut != null) - { - await RedirectedOut.WriteAsync(Environment.NewLine); - } - } - - public override async Task WriteAsync(char value) - { - if (!_verbosityService.HideTestOutput && _originalOutBuffer != null) - { - await _originalOutBuffer.WriteAsync(value.ToString()); - } - if (RedirectedOut != null) - { - await RedirectedOut.WriteAsync(value.ToString()); - } - } - - public override async Task WriteAsync(char[] buffer, int index, int count) - { - var str = new string(buffer, index, count); - if (!_verbosityService.HideTestOutput && _originalOutBuffer != null) - { - await _originalOutBuffer.WriteAsync(str); - } - if (RedirectedOut != null) - { - await RedirectedOut.WriteAsync(str); - } - } - - public override async Task WriteAsync(string? value) - { - if (value == null) - { - return; - } - - if (!_verbosityService.HideTestOutput && _originalOutBuffer != null) - { - await _originalOutBuffer.WriteAsync(value); - } - if (RedirectedOut != null) - { - await RedirectedOut.WriteAsync(value); - } - } + public override Task WriteLineAsync() => WriteLineAsync(string.Empty); + public override Task WriteAsync(char value) { Write(value); return Task.CompletedTask; } + public override Task WriteAsync(char[] buffer, int index, int count) { Write(buffer, index, count); return Task.CompletedTask; } + public override Task WriteAsync(string? value) { Write(value); return Task.CompletedTask; } public override async Task WriteLineAsync(char value) { - var str = value + Environment.NewLine; - if (!_verbosityService.HideTestOutput && _originalOutBuffer != null) - { - await _originalOutBuffer.WriteAsync(str); - } - if (RedirectedOut != null) - { - await RedirectedOut.WriteAsync(str); - } + await WriteLineAsync(value.ToString()).ConfigureAwait(false); } public override async Task WriteLineAsync(char[] buffer, int index, int count) { - var str = new string(buffer, index, count) + Environment.NewLine; - if (!_verbosityService.HideTestOutput && _originalOutBuffer != null) - { - await _originalOutBuffer.WriteAsync(str); - } - if (RedirectedOut != null) - { - await RedirectedOut.WriteAsync(str); - } + await WriteLineAsync(new string(buffer, index, count)).ConfigureAwait(false); } public override async Task WriteLineAsync(string? value) { - var str = (value ?? string.Empty) + Environment.NewLine; - if (!_verbosityService.HideTestOutput && _originalOutBuffer != null) - { - await _originalOutBuffer.WriteAsync(str); - } - if (RedirectedOut != null) + if (_lineBuffer.Length > 0) { - await RedirectedOut.WriteAsync(str); + _lineBuffer.Append(value); + value = _lineBuffer.ToString(); + _lineBuffer.Clear(); } + await RouteToSinksAsync(value).ConfigureAwait(false); } #if NET - public override void Write(ReadOnlySpan buffer) - { - var str = new string(buffer); - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.Write(str); - } - RedirectedOut?.Write(str); - } - - public override void Write(StringBuilder? value) - { - var str = value?.ToString() ?? string.Empty; - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.Write(str); - } - RedirectedOut?.Write(str); - } - - public override async Task WriteAsync(ReadOnlyMemory buffer, CancellationToken cancellationToken = new()) - { - var str = new string(buffer.Span); - if (!_verbosityService.HideTestOutput && _originalOutBuffer != null) - { - await _originalOutBuffer.WriteAsync(str); - } - if (RedirectedOut != null) - { - await RedirectedOut.WriteAsync(str); - } - } - - public override async Task WriteAsync(StringBuilder? value, CancellationToken cancellationToken = new()) - { - var str = value?.ToString() ?? string.Empty; - if (!_verbosityService.HideTestOutput && _originalOutBuffer != null) - { - await _originalOutBuffer.WriteAsync(str); - } - if (RedirectedOut != null) - { - await RedirectedOut.WriteAsync(str); - } - } - - public override void WriteLine(ReadOnlySpan buffer) - { - var str = new string(buffer); - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(str); - } - RedirectedOut?.WriteLine(str); - } - - public override void WriteLine(StringBuilder? value) - { - var str = value?.ToString() ?? string.Empty; - if (!_verbosityService.HideTestOutput) - { - _originalOutBuffer?.WriteLine(str); - } - RedirectedOut?.WriteLine(str); - } - - public override async Task WriteLineAsync(ReadOnlyMemory buffer, CancellationToken cancellationToken = new()) - { - var str = new string(buffer.Span) + Environment.NewLine; - if (!_verbosityService.HideTestOutput && _originalOutBuffer != null) - { - await _originalOutBuffer.WriteAsync(str); - } - if (RedirectedOut != null) - { - await RedirectedOut.WriteAsync(str); - } - } - - public override async Task WriteLineAsync(StringBuilder? value, CancellationToken cancellationToken = new()) - { - var str = (value?.ToString() ?? string.Empty) + Environment.NewLine; - if (!_verbosityService.HideTestOutput && _originalOutBuffer != null) - { - await _originalOutBuffer.WriteAsync(str); - } - if (RedirectedOut != null) - { - await RedirectedOut.WriteAsync(str); - } - } + public override void Write(ReadOnlySpan buffer) => Write(new string(buffer)); + public override void Write(StringBuilder? value) => Write(value?.ToString() ?? string.Empty); + public override Task WriteAsync(ReadOnlyMemory buffer, CancellationToken cancellationToken = new()) + => WriteAsync(new string(buffer.Span)); + public override Task WriteAsync(StringBuilder? value, CancellationToken cancellationToken = new()) + => WriteAsync(value?.ToString() ?? string.Empty); + public override void WriteLine(ReadOnlySpan buffer) => WriteLine(new string(buffer)); + public override void WriteLine(StringBuilder? value) => WriteLine(value?.ToString() ?? string.Empty); + public override Task WriteLineAsync(ReadOnlyMemory buffer, CancellationToken cancellationToken = new()) + => WriteLineAsync(new string(buffer.Span)); + public override Task WriteLineAsync(StringBuilder? value, CancellationToken cancellationToken = new()) + => WriteLineAsync(value?.ToString() ?? string.Empty); #endif public override IFormatProvider FormatProvider => GetOriginalOut().FormatProvider; @@ -598,21 +201,12 @@ public override void WriteLine(StringBuilder? value) public override string NewLine { get => GetOriginalOut().NewLine; - set - { - GetOriginalOut().NewLine = value; - if (RedirectedOut != null) - { - RedirectedOut.NewLine = value; - } - } + set => GetOriginalOut().NewLine = value; } public override void Close() { Flush(); - _originalOutBuffer?.Dispose(); - // Don't dispose RedirectedOut as it's not owned by us ResetDefault(); } @@ -620,9 +214,8 @@ protected override void Dispose(bool disposing) { if (disposing) { - _originalOutBuffer?.Dispose(); - // Don't dispose RedirectedOut as it's not owned by us + Flush(); } base.Dispose(disposing); } -} \ No newline at end of file +} diff --git a/TUnit.Engine/Logging/StandardErrorConsoleInterceptor.cs b/TUnit.Engine/Logging/StandardErrorConsoleInterceptor.cs index 2d3080bcae..ba1e4fd0a6 100644 --- a/TUnit.Engine/Logging/StandardErrorConsoleInterceptor.cs +++ b/TUnit.Engine/Logging/StandardErrorConsoleInterceptor.cs @@ -1,7 +1,4 @@ -using TUnit.Core; -using TUnit.Engine.Services; - -#pragma warning disable CS8765 // Nullability of type of parameter doesn't match overridden member (possibly because of nullability attributes). +using TUnit.Core.Logging; namespace TUnit.Engine.Logging; @@ -11,19 +8,17 @@ internal class StandardErrorConsoleInterceptor : OptimizedConsoleInterceptor public static TextWriter DefaultError { get; } - protected override TextWriter RedirectedOut => Context.Current.ErrorOutputWriter; + protected override LogLevel SinkLogLevel => LogLevel.Error; static StandardErrorConsoleInterceptor() { - // Get the raw stream without SyncTextWriter synchronization wrapper - // BufferedTextWriter already provides thread safety, so we avoid double-locking DefaultError = new StreamWriter(Console.OpenStandardError()) { AutoFlush = true }; } - public StandardErrorConsoleInterceptor(VerbosityService verbosityService) : base(verbosityService) + public StandardErrorConsoleInterceptor() { Instance = this; } @@ -33,13 +28,7 @@ public void Initialize() Console.SetError(this); } - private protected override TextWriter GetOriginalOut() - { - return DefaultError; - } + private protected override TextWriter GetOriginalOut() => DefaultError; - private protected override void ResetDefault() - { - Console.SetError(DefaultError); - } + private protected override void ResetDefault() => Console.SetError(DefaultError); } diff --git a/TUnit.Engine/Logging/StandardOutConsoleInterceptor.cs b/TUnit.Engine/Logging/StandardOutConsoleInterceptor.cs index d494fee6aa..075054faa2 100644 --- a/TUnit.Engine/Logging/StandardOutConsoleInterceptor.cs +++ b/TUnit.Engine/Logging/StandardOutConsoleInterceptor.cs @@ -1,7 +1,4 @@ -using TUnit.Core; -using TUnit.Engine.Services; - -#pragma warning disable CS8765 // Nullability of type of parameter doesn't match overridden member (possibly because of nullability attributes). +using TUnit.Core.Logging; namespace TUnit.Engine.Logging; @@ -11,19 +8,17 @@ internal class StandardOutConsoleInterceptor : OptimizedConsoleInterceptor public static TextWriter DefaultOut { get; } - protected override TextWriter RedirectedOut => Context.Current.OutputWriter; + protected override LogLevel SinkLogLevel => LogLevel.Information; static StandardOutConsoleInterceptor() { - // Get the raw stream without SyncTextWriter synchronization wrapper - // BufferedTextWriter already provides thread safety, so we avoid double-locking DefaultOut = new StreamWriter(Console.OpenStandardOutput()) { AutoFlush = true }; } - public StandardOutConsoleInterceptor(VerbosityService verbosityService) : base(verbosityService) + public StandardOutConsoleInterceptor() { Instance = this; } @@ -33,13 +28,7 @@ public void Initialize() Console.SetOut(this); } - private protected override TextWriter GetOriginalOut() - { - return DefaultOut; - } + private protected override TextWriter GetOriginalOut() => DefaultOut; - private protected override void ResetDefault() - { - Console.SetOut(DefaultOut); - } + private protected override void ResetDefault() => Console.SetOut(DefaultOut); } diff --git a/TUnit.Engine/Logging/TestOutputSink.cs b/TUnit.Engine/Logging/TestOutputSink.cs new file mode 100644 index 0000000000..7f7426e843 --- /dev/null +++ b/TUnit.Engine/Logging/TestOutputSink.cs @@ -0,0 +1,31 @@ +using TUnit.Core; +using TUnit.Core.Logging; + +namespace TUnit.Engine.Logging; + +/// +/// A log sink that accumulates output to the test context's output writers. +/// Routes to OutputWriter for non-error levels and ErrorOutputWriter for error levels. +/// This captured output is included in test results. +/// +internal sealed class TestOutputSink : ILogSink +{ + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + if (context == null) + { + return; + } + + var writer = level >= LogLevel.Error ? context.ErrorOutputWriter : context.OutputWriter; + writer.WriteLine(message); + } + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + Log(level, message, exception, context); + return ValueTask.CompletedTask; + } +} diff --git a/TUnit.Engine/NullLogger.cs b/TUnit.Engine/MtpNullLogger.cs similarity index 73% rename from TUnit.Engine/NullLogger.cs rename to TUnit.Engine/MtpNullLogger.cs index aa54c78501..a04e1564ae 100644 --- a/TUnit.Engine/NullLogger.cs +++ b/TUnit.Engine/MtpNullLogger.cs @@ -2,7 +2,10 @@ namespace TUnit.Engine; -internal class NullLogger : ILogger +/// +/// Null logger implementation for Microsoft Testing Platform's ILogger interface. +/// +internal class MtpNullLogger : ILogger { public Task LogAsync(LogLevel logLevel, TState state, Exception? exception, Func formatter) => Task.CompletedTask; diff --git a/TUnit.Engine/NullLoggerFactory.cs b/TUnit.Engine/NullLoggerFactory.cs index 105c7e7679..79e6c1f5fd 100644 --- a/TUnit.Engine/NullLoggerFactory.cs +++ b/TUnit.Engine/NullLoggerFactory.cs @@ -7,6 +7,6 @@ namespace TUnit.Engine; /// internal class NullLoggerFactory : ILoggerFactory { - public ILogger CreateLogger() => new NullLogger(); - public ILogger CreateLogger(string categoryName) => new NullLogger(); + public ILogger CreateLogger() => new MtpNullLogger(); + public ILogger CreateLogger(string categoryName) => new MtpNullLogger(); } diff --git a/TUnit.Engine/Services/LogLevelProvider.cs b/TUnit.Engine/Services/LogLevelProvider.cs index fd13eeae5a..72e13b3910 100644 --- a/TUnit.Engine/Services/LogLevelProvider.cs +++ b/TUnit.Engine/Services/LogLevelProvider.cs @@ -1,15 +1,21 @@ -using Microsoft.Testing.Platform.CommandLine; +using Microsoft.Testing.Platform.CommandLine; using TUnit.Core.Logging; using TUnit.Engine.CommandLineProviders; namespace TUnit.Engine.Services; -public class LogLevelProvider(ICommandLineOptions commandLineOptions) +public class LogLevelProvider { - internal static LogLevel? _logLevel; - public LogLevel LogLevel => _logLevel ??= GetLogLevel(); + private readonly LogLevel _logLevel; - private LogLevel GetLogLevel() + public LogLevelProvider(ICommandLineOptions commandLineOptions) + { + _logLevel = GetLogLevel(commandLineOptions); + } + + public LogLevel LogLevel => _logLevel; + + private static LogLevel GetLogLevel(ICommandLineOptions commandLineOptions) { if (commandLineOptions.TryGetOptionArgumentList(LogLevelCommandProvider.LogLevelOption, out var values)) { diff --git a/TUnit.Engine/Services/VerbosityService.cs b/TUnit.Engine/Services/VerbosityService.cs index 0dc093289d..71f8db580f 100644 --- a/TUnit.Engine/Services/VerbosityService.cs +++ b/TUnit.Engine/Services/VerbosityService.cs @@ -8,7 +8,9 @@ namespace TUnit.Engine.Services; /// -/// Centralized service for managing TUnit output and diagnostic settings +/// Centralized service for managing TUnit output and diagnostic settings. +/// Controls whether output goes to console vs real-time streaming, and manages +/// stack trace verbosity based on log levels and command-line options. /// public sealed class VerbosityService { @@ -19,8 +21,14 @@ public VerbosityService(ICommandLineOptions commandLineOptions, IServiceProvider { _isDetailedOutput = GetOutputLevel(commandLineOptions, serviceProvider); _logLevel = GetLogLevel(commandLineOptions); + IsIdeClient = !IsConsoleEnvironment(serviceProvider); } + /// + /// Whether running in an IDE (Rider, VS, etc.) vs console. + /// + public bool IsIdeClient { get; } + /// /// Whether to show detailed stack traces (enabled with Debug/Trace log level) /// @@ -32,18 +40,21 @@ public VerbosityService(ICommandLineOptions commandLineOptions, IServiceProvider public bool IsDetailedOutput => _isDetailedOutput; /// - /// Whether to hide real-time test output (hidden with --output Normal, unless log level is Debug/Trace) + /// Whether to hide real-time test output from the console. + /// For IDE clients, we hide console output because we stream via TestNodeUpdateMessage instead. + /// For console clients, we hide if --output Normal and log level is not Debug/Trace. /// - public bool HideTestOutput => !_isDetailedOutput && _logLevel > LogLevel.Debug; + public bool HideTestOutput => IsIdeClient || (!_isDetailedOutput && _logLevel > LogLevel.Debug); /// - /// Creates a summary of current output and diagnostic settings + /// Creates a summary of current output and diagnostic settings. /// public string CreateVerbositySummary() { var outputMode = _isDetailedOutput ? "Detailed" : "Normal"; - return $"Output: {outputMode}, Log Level: {_logLevel} " + - $"(Stack traces: {ShowDetailedStackTrace}, "; + var clientType = IsIdeClient ? "IDE" : "Console"; + return $"Output: {outputMode}, Log Level: {_logLevel}, Client: {clientType} " + + $"(Stack traces: {ShowDetailedStackTrace}, Hide output: {HideTestOutput})"; } private static bool GetOutputLevel(ICommandLineOptions commandLineOptions, IServiceProvider serviceProvider) diff --git a/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.DotNet10_0.verified.txt b/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.DotNet10_0.verified.txt index d14c5dd60b..54302afe11 100644 --- a/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.DotNet10_0.verified.txt +++ b/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.DotNet10_0.verified.txt @@ -2616,6 +2616,12 @@ namespace .Logging protected virtual void WriteToOutput(string message, bool isError) { } protected virtual . WriteToOutputAsync(string message, bool isError) { } } + public interface ILogSink + { + bool IsEnabled(. level); + void Log(. level, string message, ? exception, .Context? context); + . LogAsync(. level, string message, ? exception, .Context? context); + } public interface ILogger { bool IsEnabled(. logLevel); @@ -2659,6 +2665,12 @@ namespace .Logging public abstract void Log(. logLevel, TState state, ? exception, formatter); public abstract . LogAsync(. logLevel, TState state, ? exception, formatter); } + public static class TUnitLoggerFactory + { + public static void AddSink(. sink) { } + public static void AddSink() + where TSink : ., new () { } + } } namespace .Models { diff --git a/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.DotNet8_0.verified.txt b/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.DotNet8_0.verified.txt index 855998a426..285eebc8eb 100644 --- a/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.DotNet8_0.verified.txt +++ b/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.DotNet8_0.verified.txt @@ -2616,6 +2616,12 @@ namespace .Logging protected virtual void WriteToOutput(string message, bool isError) { } protected virtual . WriteToOutputAsync(string message, bool isError) { } } + public interface ILogSink + { + bool IsEnabled(. level); + void Log(. level, string message, ? exception, .Context? context); + . LogAsync(. level, string message, ? exception, .Context? context); + } public interface ILogger { bool IsEnabled(. logLevel); @@ -2659,6 +2665,12 @@ namespace .Logging public abstract void Log(. logLevel, TState state, ? exception, formatter); public abstract . LogAsync(. logLevel, TState state, ? exception, formatter); } + public static class TUnitLoggerFactory + { + public static void AddSink(. sink) { } + public static void AddSink() + where TSink : ., new () { } + } } namespace .Models { diff --git a/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.DotNet9_0.verified.txt b/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.DotNet9_0.verified.txt index 3f9990e990..27799ffefb 100644 --- a/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.DotNet9_0.verified.txt +++ b/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.DotNet9_0.verified.txt @@ -2616,6 +2616,12 @@ namespace .Logging protected virtual void WriteToOutput(string message, bool isError) { } protected virtual . WriteToOutputAsync(string message, bool isError) { } } + public interface ILogSink + { + bool IsEnabled(. level); + void Log(. level, string message, ? exception, .Context? context); + . LogAsync(. level, string message, ? exception, .Context? context); + } public interface ILogger { bool IsEnabled(. logLevel); @@ -2659,6 +2665,12 @@ namespace .Logging public abstract void Log(. logLevel, TState state, ? exception, formatter); public abstract . LogAsync(. logLevel, TState state, ? exception, formatter); } + public static class TUnitLoggerFactory + { + public static void AddSink(. sink) { } + public static void AddSink() + where TSink : ., new () { } + } } namespace .Models { diff --git a/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.Net4_7.verified.txt b/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.Net4_7.verified.txt index 03a16f9ba2..08b1e25e4b 100644 --- a/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.Net4_7.verified.txt +++ b/TUnit.PublicAPI/Tests.Core_Library_Has_No_API_Changes.Net4_7.verified.txt @@ -2538,6 +2538,12 @@ namespace .Logging protected virtual void WriteToOutput(string message, bool isError) { } protected virtual . WriteToOutputAsync(string message, bool isError) { } } + public interface ILogSink + { + bool IsEnabled(. level); + void Log(. level, string message, ? exception, .Context? context); + . LogAsync(. level, string message, ? exception, .Context? context); + } public interface ILogger { bool IsEnabled(. logLevel); @@ -2581,6 +2587,12 @@ namespace .Logging public abstract void Log(. logLevel, TState state, ? exception, formatter); public abstract . LogAsync(. logLevel, TState state, ? exception, formatter); } + public static class TUnitLoggerFactory + { + public static void AddSink(. sink) { } + public static void AddSink() + where TSink : ., new () { } + } } namespace .Models { diff --git a/TUnit.TestProject/ConsoleTests.cs b/TUnit.TestProject/ConsoleTests.cs index 520f9ac8ef..14c4848e64 100644 --- a/TUnit.TestProject/ConsoleTests.cs +++ b/TUnit.TestProject/ConsoleTests.cs @@ -11,4 +11,15 @@ public async Task Write_Source_Gen_Information() Console.WriteLine(TestContext.Current!.Metadata.TestDetails.MethodMetadata); await Assert.That(TestContext.Current.GetStandardOutput()).Contains(TestContext.Current.Metadata.TestDetails.MethodMetadata.ToString()!); } + + [Test] + [Explicit] + public async Task StreamsToIde() + { + for (var i = 0; i < 10; i++) + { + Console.WriteLine(@$"{i}..."); + await Task.Delay(TimeSpan.FromSeconds(2)); + } + } } diff --git a/TUnit.UnitTests/LogSinkIntegrationTests.cs b/TUnit.UnitTests/LogSinkIntegrationTests.cs new file mode 100644 index 0000000000..f3b4f2cb8b --- /dev/null +++ b/TUnit.UnitTests/LogSinkIntegrationTests.cs @@ -0,0 +1,198 @@ +using TUnit.Core.Logging; + +namespace TUnit.UnitTests; + +/// +/// Integration tests that verify the end-to-end flow from DefaultLogger through LogSinkRouter to registered sinks. +/// +[NotInParallel] +public class LogSinkIntegrationTests +{ + private RecordingSink _sink = null!; + + [Before(Test)] + public void SetUp() + { + TUnitLoggerFactory.Clear(); + _sink = new RecordingSink(); + TUnitLoggerFactory.AddSink(_sink); + } + + [After(Test)] + public async Task TearDown() + { + await TUnitLoggerFactory.DisposeAllAsync(); + } + + [Test] + public async Task DefaultLogger_RoutesToRegisteredSink() + { + // Act + TestContext.Current!.GetDefaultLogger().LogInformation("test message"); + + // Assert + await Assert.That(_sink.Logs).Count().IsEqualTo(1); + await Assert.That(_sink.Logs[0].Message).Contains("test message"); + } + + [Test] + public async Task DefaultLogger_RoutesMultipleMessages() + { + // Act + var logger = TestContext.Current!.GetDefaultLogger(); + logger.LogInformation("message 1"); + logger.LogWarning("message 2"); + logger.LogError("message 3"); + + // Assert + await Assert.That(_sink.Logs).Count().IsEqualTo(3); + } + + [Test] + public async Task DefaultLogger_PassesCorrectLogLevels() + { + // Act + var logger = TestContext.Current!.GetDefaultLogger(); + logger.LogInformation("info message"); + logger.LogWarning("warning message"); + logger.LogError("error message"); + + // Assert - DefaultLogger converts to Information or Error based on level + // LogLevel.Information and LogLevel.Warning both become LogLevel.Information in WriteToOutput + // LogLevel.Error and above become LogLevel.Error + await Assert.That(_sink.Logs).Count().IsEqualTo(3); + await Assert.That(_sink.Logs[0].Level).IsEqualTo(LogLevel.Information); + await Assert.That(_sink.Logs[1].Level).IsEqualTo(LogLevel.Information); + await Assert.That(_sink.Logs[2].Level).IsEqualTo(LogLevel.Error); + } + + [Test] + public async Task DefaultLogger_IncludesLogLevelInMessage() + { + // Act + TestContext.Current!.GetDefaultLogger().LogWarning("warning test"); + + // Assert + await Assert.That(_sink.Logs).Count().IsEqualTo(1); + await Assert.That(_sink.Logs[0].Message).Contains("Warning:"); + await Assert.That(_sink.Logs[0].Message).Contains("warning test"); + } + + [Test] + public async Task DefaultLogger_PassesContextToSink() + { + // Act + TestContext.Current!.GetDefaultLogger().LogInformation("context test"); + + // Assert + await Assert.That(_sink.Logs).Count().IsEqualTo(1); + await Assert.That(_sink.Logs[0].Context).IsNotNull(); + await Assert.That(_sink.Logs[0].Context).IsSameReferenceAs(TestContext.Current); + } + + [Test] + public async Task DefaultLogger_AsyncLogging_RoutesToSink() + { + // Act + await TestContext.Current!.GetDefaultLogger().LogInformationAsync("async message"); + + // Assert + await Assert.That(_sink.Logs).Count().IsEqualTo(1); + await Assert.That(_sink.Logs[0].Message).Contains("async message"); + } + + [Test] + public async Task DefaultLogger_MultipleSinks_AllReceiveMessages() + { + // Arrange - add a second sink + var secondSink = new RecordingSink(); + TUnitLoggerFactory.AddSink(secondSink); + + // Act + TestContext.Current!.GetDefaultLogger().LogInformation("broadcast message"); + + // Assert + await Assert.That(_sink.Logs).Count().IsEqualTo(1); + await Assert.That(secondSink.Logs).Count().IsEqualTo(1); + await Assert.That(_sink.Logs[0].Message).Contains("broadcast message"); + await Assert.That(secondSink.Logs[0].Message).Contains("broadcast message"); + } + + [Test] + public async Task DefaultLogger_DisabledSink_DoesNotReceiveMessages() + { + // Arrange - add a disabled sink + var disabledSink = new RecordingSink { Enabled = false }; + TUnitLoggerFactory.AddSink(disabledSink); + + // Act + TestContext.Current!.GetDefaultLogger().LogInformation("enabled only message"); + + // Assert + await Assert.That(_sink.Logs).Count().IsEqualTo(1); // Enabled sink receives it + await Assert.That(disabledSink.Logs).IsEmpty(); // Disabled sink does not + } + + [Test] + public async Task DefaultLogger_LevelFilteredSink_OnlyReceivesMatchingLevels() + { + // Arrange - add a sink that only accepts Error or higher + var errorOnlySink = new LevelFilteredSink(LogLevel.Error); + TUnitLoggerFactory.AddSink(errorOnlySink); + + // Act + var logger = TestContext.Current!.GetDefaultLogger(); + logger.LogInformation("info message"); + logger.LogWarning("warning message"); + logger.LogError("error message"); + + // Assert + await Assert.That(_sink.Logs).Count().IsEqualTo(3); // Default sink receives all + await Assert.That(errorOnlySink.Logs).Count().IsEqualTo(1); // Filtered sink only receives error + await Assert.That(errorOnlySink.Logs[0].Message).Contains("error message"); + } + + #region Recording Sinks + + private class RecordingSink : ILogSink + { + public List<(LogLevel Level, string Message, Exception? Exception, Context? Context)> Logs { get; } = []; + public bool Enabled { get; set; } = true; + + public bool IsEnabled(LogLevel level) => Enabled; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + => Logs.Add((level, message, exception, context)); + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + Logs.Add((level, message, exception, context)); + return ValueTask.CompletedTask; + } + } + + private class LevelFilteredSink : ILogSink + { + private readonly LogLevel _minimumLevel; + + public LevelFilteredSink(LogLevel minimumLevel) + { + _minimumLevel = minimumLevel; + } + + public List<(LogLevel Level, string Message, Exception? Exception, Context? Context)> Logs { get; } = []; + + public bool IsEnabled(LogLevel level) => level >= _minimumLevel; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + => Logs.Add((level, message, exception, context)); + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + Logs.Add((level, message, exception, context)); + return ValueTask.CompletedTask; + } + } + + #endregion +} diff --git a/TUnit.UnitTests/LogSinkRouterTests.cs b/TUnit.UnitTests/LogSinkRouterTests.cs new file mode 100644 index 0000000000..ea99363f62 --- /dev/null +++ b/TUnit.UnitTests/LogSinkRouterTests.cs @@ -0,0 +1,262 @@ +using TUnit.Core.Logging; + +namespace TUnit.UnitTests; + +[NotInParallel] +public class LogSinkRouterTests +{ + [Before(Test)] + public void SetUp() + { + // Ensure clean state before each test + TUnitLoggerFactory.Clear(); + } + + [After(Test)] + public async Task TearDown() + { + // Ensure clean state after each test + await TUnitLoggerFactory.DisposeAllAsync(); + } + + [Test] + public async Task RouteToSinks_CallsAllEnabledSinks() + { + var sink1 = new RecordingSink(); + var sink2 = new RecordingSink(); + TUnitLoggerFactory.AddSink(sink1); + TUnitLoggerFactory.AddSink(sink2); + + LogSinkRouter.RouteToSinks(LogLevel.Information, "Test message", null, null); + + await Assert.That(sink1.Logs).Count().IsEqualTo(1); + await Assert.That(sink2.Logs).Count().IsEqualTo(1); + await Assert.That(sink1.Logs[0].Message).IsEqualTo("Test message"); + await Assert.That(sink1.Logs[0].Level).IsEqualTo(LogLevel.Information); + await Assert.That(sink2.Logs[0].Message).IsEqualTo("Test message"); + } + + [Test] + public async Task RouteToSinks_SkipsDisabledSinks() + { + var enabledSink = new RecordingSink { Enabled = true }; + var disabledSink = new RecordingSink { Enabled = false }; + TUnitLoggerFactory.AddSink(enabledSink); + TUnitLoggerFactory.AddSink(disabledSink); + + LogSinkRouter.RouteToSinks(LogLevel.Information, "Test message", null, null); + + await Assert.That(enabledSink.Logs).Count().IsEqualTo(1); + await Assert.That(disabledSink.Logs).IsEmpty(); + } + + [Test] + public async Task RouteToSinks_ContinuesOnSinkFailure() + { + var faultySink = new FaultySink(); + var goodSink = new RecordingSink(); + TUnitLoggerFactory.AddSink(faultySink); + TUnitLoggerFactory.AddSink(goodSink); + + // Should not throw + LogSinkRouter.RouteToSinks(LogLevel.Information, "Test message", null, null); + + // Good sink should still receive the message + await Assert.That(goodSink.Logs).Count().IsEqualTo(1); + await Assert.That(goodSink.Logs[0].Message).IsEqualTo("Test message"); + } + + [Test] + public async Task RouteToSinks_PassesExceptionToSinks() + { + var sink = new RecordingSink(); + TUnitLoggerFactory.AddSink(sink); + var exception = new InvalidOperationException("Test exception"); + + LogSinkRouter.RouteToSinks(LogLevel.Error, "Error occurred", exception, null); + + await Assert.That(sink.Logs).Count().IsEqualTo(1); + await Assert.That(sink.Logs[0].Exception).IsSameReferenceAs(exception); + } + + [Test] + public async Task RouteToSinks_DoesNothingWhenNoSinksRegistered() + { + // Should not throw when no sinks are registered + LogSinkRouter.RouteToSinks(LogLevel.Information, "Test message", null, null); + + // Just verify no exception was thrown - test passes if we get here + await Assert.That(true).IsTrue(); + } + + [Test] + public async Task RouteToSinksAsync_CallsAllEnabledSinks() + { + var sink1 = new RecordingSink(); + var sink2 = new RecordingSink(); + TUnitLoggerFactory.AddSink(sink1); + TUnitLoggerFactory.AddSink(sink2); + + await LogSinkRouter.RouteToSinksAsync(LogLevel.Information, "Test message", null, null); + + await Assert.That(sink1.Logs).Count().IsEqualTo(1); + await Assert.That(sink2.Logs).Count().IsEqualTo(1); + await Assert.That(sink1.Logs[0].Message).IsEqualTo("Test message"); + await Assert.That(sink1.Logs[0].Level).IsEqualTo(LogLevel.Information); + await Assert.That(sink2.Logs[0].Message).IsEqualTo("Test message"); + } + + [Test] + public async Task RouteToSinksAsync_SkipsDisabledSinks() + { + var enabledSink = new RecordingSink { Enabled = true }; + var disabledSink = new RecordingSink { Enabled = false }; + TUnitLoggerFactory.AddSink(enabledSink); + TUnitLoggerFactory.AddSink(disabledSink); + + await LogSinkRouter.RouteToSinksAsync(LogLevel.Information, "Test message", null, null); + + await Assert.That(enabledSink.Logs).Count().IsEqualTo(1); + await Assert.That(disabledSink.Logs).IsEmpty(); + } + + [Test] + public async Task RouteToSinksAsync_ContinuesOnSinkFailure() + { + var faultySink = new FaultySink(); + var goodSink = new RecordingSink(); + TUnitLoggerFactory.AddSink(faultySink); + TUnitLoggerFactory.AddSink(goodSink); + + // Should not throw + await LogSinkRouter.RouteToSinksAsync(LogLevel.Information, "Test message", null, null); + + // Good sink should still receive the message + await Assert.That(goodSink.Logs).Count().IsEqualTo(1); + await Assert.That(goodSink.Logs[0].Message).IsEqualTo("Test message"); + } + + [Test] + public async Task RouteToSinksAsync_PassesExceptionToSinks() + { + var sink = new RecordingSink(); + TUnitLoggerFactory.AddSink(sink); + var exception = new InvalidOperationException("Test exception"); + + await LogSinkRouter.RouteToSinksAsync(LogLevel.Error, "Error occurred", exception, null); + + await Assert.That(sink.Logs).Count().IsEqualTo(1); + await Assert.That(sink.Logs[0].Exception).IsSameReferenceAs(exception); + } + + [Test] + public async Task RouteToSinksAsync_DoesNothingWhenNoSinksRegistered() + { + // Should not throw when no sinks are registered + await LogSinkRouter.RouteToSinksAsync(LogLevel.Information, "Test message", null, null); + + // Just verify no exception was thrown - test passes if we get here + await Assert.That(true).IsTrue(); + } + + [Test] + public async Task RouteToSinks_PassesCorrectLogLevel() + { + var sink = new RecordingSink(); + TUnitLoggerFactory.AddSink(sink); + + LogSinkRouter.RouteToSinks(LogLevel.Warning, "Warning message", null, null); + LogSinkRouter.RouteToSinks(LogLevel.Error, "Error message", null, null); + LogSinkRouter.RouteToSinks(LogLevel.Debug, "Debug message", null, null); + + await Assert.That(sink.Logs).Count().IsEqualTo(3); + await Assert.That(sink.Logs[0].Level).IsEqualTo(LogLevel.Warning); + await Assert.That(sink.Logs[1].Level).IsEqualTo(LogLevel.Error); + await Assert.That(sink.Logs[2].Level).IsEqualTo(LogLevel.Debug); + } + + [Test] + public async Task RouteToSinks_SinkCanFilterByLogLevel() + { + var errorOnlySink = new LevelFilteredSink(LogLevel.Error); + TUnitLoggerFactory.AddSink(errorOnlySink); + + LogSinkRouter.RouteToSinks(LogLevel.Information, "Info message", null, null); + LogSinkRouter.RouteToSinks(LogLevel.Warning, "Warning message", null, null); + LogSinkRouter.RouteToSinks(LogLevel.Error, "Error message", null, null); + + // Only error message should be logged + await Assert.That(errorOnlySink.Logs).Count().IsEqualTo(1); + await Assert.That(errorOnlySink.Logs[0].Level).IsEqualTo(LogLevel.Error); + } + + [Test] + public async Task RouteToSinksAsync_SinkCanFilterByLogLevel() + { + var errorOnlySink = new LevelFilteredSink(LogLevel.Error); + TUnitLoggerFactory.AddSink(errorOnlySink); + + await LogSinkRouter.RouteToSinksAsync(LogLevel.Information, "Info message", null, null); + await LogSinkRouter.RouteToSinksAsync(LogLevel.Warning, "Warning message", null, null); + await LogSinkRouter.RouteToSinksAsync(LogLevel.Error, "Error message", null, null); + + // Only error message should be logged + await Assert.That(errorOnlySink.Logs).Count().IsEqualTo(1); + await Assert.That(errorOnlySink.Logs[0].Level).IsEqualTo(LogLevel.Error); + } + + #region Mock Sinks + + private class RecordingSink : ILogSink + { + public List<(LogLevel Level, string Message, Exception? Exception, Context? Context)> Logs { get; } = []; + public bool Enabled { get; set; } = true; + + public bool IsEnabled(LogLevel level) => Enabled; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + => Logs.Add((level, message, exception, context)); + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + Logs.Add((level, message, exception, context)); + return ValueTask.CompletedTask; + } + } + + private class FaultySink : ILogSink + { + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + => throw new InvalidOperationException("Sink failure"); + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + => throw new InvalidOperationException("Sink failure"); + } + + private class LevelFilteredSink : ILogSink + { + private readonly LogLevel _minimumLevel; + + public LevelFilteredSink(LogLevel minimumLevel) + { + _minimumLevel = minimumLevel; + } + + public List<(LogLevel Level, string Message, Exception? Exception, Context? Context)> Logs { get; } = []; + + public bool IsEnabled(LogLevel level) => level >= _minimumLevel; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + => Logs.Add((level, message, exception, context)); + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + Logs.Add((level, message, exception, context)); + return ValueTask.CompletedTask; + } + } + + #endregion +} diff --git a/TUnit.UnitTests/TUnitLoggerFactoryTests.cs b/TUnit.UnitTests/TUnitLoggerFactoryTests.cs new file mode 100644 index 0000000000..7a3c18c4ca --- /dev/null +++ b/TUnit.UnitTests/TUnitLoggerFactoryTests.cs @@ -0,0 +1,281 @@ +using TUnit.Core.Logging; + +namespace TUnit.UnitTests; + +[NotInParallel] +public class TUnitLoggerFactoryTests +{ + [Before(Test)] + public void SetUp() + { + // Ensure clean state before each test + TUnitLoggerFactory.Clear(); + } + + [After(Test)] + public async Task TearDown() + { + // Ensure clean state after each test + await TUnitLoggerFactory.DisposeAllAsync(); + } + + [Test] + public async Task AddSink_RegistersSink() + { + var sink = new MockLogSink(); + + TUnitLoggerFactory.AddSink(sink); + + var sinks = TUnitLoggerFactory.GetSinks(); + await Assert.That(sinks).Count().IsEqualTo(1); + await Assert.That(sinks[0]).IsSameReferenceAs(sink); + } + + [Test] + public async Task AddSink_Generic_InstantiatesAndRegisters() + { + TUnitLoggerFactory.AddSink(); + + var sinks = TUnitLoggerFactory.GetSinks(); + await Assert.That(sinks).Count().IsEqualTo(1); + await Assert.That(sinks[0]).IsTypeOf(); + } + + [Test] + public async Task GetSinks_ReturnsEmptyList_WhenNoSinksRegistered() + { + var sinks = TUnitLoggerFactory.GetSinks(); + + await Assert.That(sinks).IsEmpty(); + } + + [Test] + public async Task Clear_RemovesAllSinks() + { + var sink1 = new MockLogSink(); + var sink2 = new MockLogSink(); + TUnitLoggerFactory.AddSink(sink1); + TUnitLoggerFactory.AddSink(sink2); + + TUnitLoggerFactory.Clear(); + + var sinks = TUnitLoggerFactory.GetSinks(); + await Assert.That(sinks).IsEmpty(); + } + + [Test] + public async Task Clear_DoesNotDisposeSinks() + { + var disposableSink = new DisposableMockSink(); + TUnitLoggerFactory.AddSink(disposableSink); + + TUnitLoggerFactory.Clear(); + + await Assert.That(disposableSink.Disposed).IsFalse(); + } + + [Test] + public async Task DisposeAllAsync_DisposesAsyncDisposable() + { + var asyncDisposableSink = new AsyncDisposableMockSink(); + TUnitLoggerFactory.AddSink(asyncDisposableSink); + + await TUnitLoggerFactory.DisposeAllAsync(); + + await Assert.That(asyncDisposableSink.Disposed).IsTrue(); + } + + [Test] + public async Task DisposeAllAsync_DisposesDisposable() + { + var disposableSink = new DisposableMockSink(); + TUnitLoggerFactory.AddSink(disposableSink); + + await TUnitLoggerFactory.DisposeAllAsync(); + + await Assert.That(disposableSink.Disposed).IsTrue(); + } + + [Test] + public async Task DisposeAllAsync_ClearsSinksList() + { + var sink = new MockLogSink(); + TUnitLoggerFactory.AddSink(sink); + + await TUnitLoggerFactory.DisposeAllAsync(); + + var sinks = TUnitLoggerFactory.GetSinks(); + await Assert.That(sinks).IsEmpty(); + } + + [Test] + public async Task DisposeAllAsync_ContinuesOnError() + { + var faultySink = new FaultyDisposableSink(); + var goodSink = new AsyncDisposableMockSink(); + TUnitLoggerFactory.AddSink(faultySink); + TUnitLoggerFactory.AddSink(goodSink); + + // Should not throw even though faultySink throws + await TUnitLoggerFactory.DisposeAllAsync(); + + // Verify the second sink was still disposed despite first one failing + await Assert.That(goodSink.Disposed).IsTrue(); + } + + [Test] + public async Task DisposeAllAsync_PrefersAsyncDisposableOverDisposable() + { + var dualDisposableSink = new DualDisposableMockSink(); + TUnitLoggerFactory.AddSink(dualDisposableSink); + + await TUnitLoggerFactory.DisposeAllAsync(); + + // Should use async dispose, not sync dispose + await Assert.That(dualDisposableSink.AsyncDisposed).IsTrue(); + await Assert.That(dualDisposableSink.SyncDisposed).IsFalse(); + } + + [Test] + public async Task AddSink_MultipleSinks_AllAreRegistered() + { + var sink1 = new MockLogSink(); + var sink2 = new MockLogSink(); + var sink3 = new MockLogSink(); + + TUnitLoggerFactory.AddSink(sink1); + TUnitLoggerFactory.AddSink(sink2); + TUnitLoggerFactory.AddSink(sink3); + + var sinks = TUnitLoggerFactory.GetSinks(); + await Assert.That(sinks).Count().IsEqualTo(3); + } + + [Test] + public async Task GetSinks_ReturnsSnapshot_NotLiveList() + { + var sink1 = new MockLogSink(); + TUnitLoggerFactory.AddSink(sink1); + + var sinks = TUnitLoggerFactory.GetSinks(); + + // Add another sink after getting the snapshot + var sink2 = new MockLogSink(); + TUnitLoggerFactory.AddSink(sink2); + + // Original snapshot should not be affected + await Assert.That(sinks).Count().IsEqualTo(1); + + // New call should show both + var newSinks = TUnitLoggerFactory.GetSinks(); + await Assert.That(newSinks).Count().IsEqualTo(2); + } + + #region Mock Sinks + + private class MockLogSink : ILogSink + { + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + } + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + return ValueTask.CompletedTask; + } + } + + private class DisposableMockSink : ILogSink, IDisposable + { + public bool Disposed { get; private set; } + + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + } + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + return ValueTask.CompletedTask; + } + + public void Dispose() + { + Disposed = true; + } + } + + private class AsyncDisposableMockSink : ILogSink, IAsyncDisposable + { + public bool Disposed { get; private set; } + + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + } + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + return ValueTask.CompletedTask; + } + + public ValueTask DisposeAsync() + { + Disposed = true; + return ValueTask.CompletedTask; + } + } + + private class DualDisposableMockSink : ILogSink, IAsyncDisposable, IDisposable + { + public bool AsyncDisposed { get; private set; } + public bool SyncDisposed { get; private set; } + + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + } + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + return ValueTask.CompletedTask; + } + + public ValueTask DisposeAsync() + { + AsyncDisposed = true; + return ValueTask.CompletedTask; + } + + public void Dispose() + { + SyncDisposed = true; + } + } + + private class FaultyDisposableSink : ILogSink, IAsyncDisposable + { + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + } + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + return ValueTask.CompletedTask; + } + + public ValueTask DisposeAsync() + { + throw new InvalidOperationException("Simulated disposal failure"); + } + } + + #endregion +} diff --git a/docs/docs/customization-extensibility/logging.md b/docs/docs/customization-extensibility/logging.md index 8dddaee561..4376664ff1 100644 --- a/docs/docs/customization-extensibility/logging.md +++ b/docs/docs/customization-extensibility/logging.md @@ -1,106 +1,252 @@ # Logging -By default, TUnit will intercept any logs to the `Console`, and attempt to correlate them to the test that triggered that log by the current async context that it is in. +TUnit provides a flexible logging system that captures all test output and routes it to configurable destinations called "log sinks". -So for most scenarios, you can just rely on `Console.WriteLine(...)`. +## Basic Usage -## Logger Objects -If you want a logger object, you can call `TestContext.Current.GetDefaultLogger()`, which will give you a logger that will write output to that test's output writer. +By default, TUnit intercepts any logs to `Console.WriteLine()` and correlates them to the test that triggered the log using the current async context. -This logger can also be used to map to other logging interfaces (e.g. Microsoft.Extensions.Logging), so that for example, Asp.NET web apps can log to your test's context, so that you have a cleaner, more isolated log output. +```csharp +[Test] +public async Task MyTest() +{ + Console.WriteLine("This output is captured and associated with this test"); +} +``` -## Log Level -TUnit will use the same log level as provided to the Microsoft.Testing.Platform, which is set on the command line when invoking the test suite. If not defined, the default log level should be `Trace`. +### Logger Objects -If you want to override this, you can inherit from `TUnitLogger` or `DefaultLogger` and override the `IsEnabled` method: +For more control, use `TestContext.Current.GetDefaultLogger()` to get a logger instance: ```csharp - public override bool IsEnabled(LogLevel logLevel) +[Test] +public async Task MyTest() { - return logLevel >= LogLevel.Error; + var logger = TestContext.Current!.GetDefaultLogger(); + logger.LogInformation("Information message"); + logger.LogWarning("Warning message"); + logger.LogError("Error message"); } ``` -## Log Level Command Line -If you are executing tests via the command line, you can set the log level via the `--log-level` argument: - -``` -dotnet run --log-level Warning -``` +This logger can integrate with other logging frameworks like Microsoft.Extensions.Logging for ASP.NET applications. -The above will show only logs that are `Warning` or higher (e.g. `Error`, `Critical`) while executing the test. +## Log Sinks -## Custom Loggers +TUnit uses a sink-based architecture where all output is routed through registered log sinks. Each sink decides how to handle the messages - write to files, stream to IDEs, send to external services, etc. -The `DefaultLogger` class is designed to be extensible. You can inherit from it to customize message formatting and output behavior. +### Built-in Sinks -### Available Extension Points +TUnit automatically registers these sinks based on your execution context: -- `Context` - Protected property to access the associated context -- `GenerateMessage(string message, Exception? exception, LogLevel logLevel)` - Override to customize message formatting -- `WriteToOutput(string message, bool isError)` - Override to customize how messages are written -- `WriteToOutputAsync(string message, bool isError)` - Async version of WriteToOutput +| Sink | When Registered | Purpose | +|------|-----------------|---------| +| **TestOutputSink** | Always | Captures output for test results shown after execution | +| **ConsoleOutputSink** | `--output Detailed` | Writes real-time output to the console | +| **RealTimeOutputSink** | IDE clients (VS, Rider) | Streams output to IDE test explorers | -### Example: Adding Test Headers +### Creating Custom Log Sinks -Here's an example of a custom logger that prepends a test identifier header before the first log message: +Implement the `ILogSink` interface to create a custom sink: ```csharp -public class TestHeaderLogger : DefaultLogger +using TUnit.Core; +using TUnit.Core.Logging; + +public class FileLogSink : ILogSink, IAsyncDisposable { - private bool _hasOutputHeader; + private readonly StreamWriter _writer; - public TestHeaderLogger(Context context) : base(context) { } + public FileLogSink(string filePath) + { + _writer = new StreamWriter(filePath, append: true); + } - protected override string GenerateMessage(string message, Exception? exception, LogLevel logLevel) + public bool IsEnabled(LogLevel level) { - var baseMessage = base.GenerateMessage(message, exception, logLevel); + // Return false to skip processing for performance + return level >= LogLevel.Information; + } - if (!_hasOutputHeader && Context is TestContext testContext) + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + // Get test name from context if available + var testName = context is TestContext tc + ? tc.TestDetails.TestName + : "Unknown"; + + _writer.WriteLine($"[{DateTime.Now:HH:mm:ss}] [{level}] [{testName}] {message}"); + + if (exception != null) { - _hasOutputHeader = true; - var testId = $"{testContext.TestDetails.ClassType.Name}.{testContext.TestDetails.TestName}"; - return $"--- {testId} ---\n{baseMessage}"; + _writer.WriteLine(exception.ToString()); } + } - return baseMessage; + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + Log(level, message, exception, context); + return ValueTask.CompletedTask; + } + + public async ValueTask DisposeAsync() + { + await _writer.FlushAsync(); + await _writer.DisposeAsync(); } } ``` -### Using Custom Loggers +### Registering Custom Sinks -Create an instance of your custom logger and use it directly: +Register your sink in a `[Before(Assembly)]` hook so it's active before any tests run: ```csharp -[Test] -public async Task MyTest() +public class TestSetup +{ + [Before(Assembly)] + public static void SetupLogging() + { + // Register by instance (for sinks needing configuration) + TUnitLoggerFactory.AddSink(new FileLogSink("test-output.log")); + + // Or register by type (for simple sinks) + TUnitLoggerFactory.AddSink(); + } +} +``` + +Sinks that implement `IDisposable` or `IAsyncDisposable` are automatically disposed when the test session ends. + +### Context Information + +The `context` parameter provides information about where the log originated: + +```csharp +public void Log(LogLevel level, string message, Exception? exception, Context? context) { - var logger = new TestHeaderLogger(TestContext.Current!); - logger.LogInformation("This message will have a test header"); - logger.LogInformation("Subsequent messages won't repeat the header"); + switch (context) + { + case TestContext tc: + // During test execution + var testName = tc.TestDetails.TestName; + var className = tc.TestDetails.ClassType.Name; + break; + + case ClassHookContext chc: + // During [Before(Class)] or [After(Class)] hooks + var classType = chc.ClassType; + break; + + case AssemblyHookContext ahc: + // During [Before(Assembly)] or [After(Assembly)] hooks + var assembly = ahc.Assembly; + break; + + case null: + // Outside test execution + break; + } } ``` -### Example: Custom Output Destinations +### Example: Seq/Serilog Integration -You can override the write methods to send output to additional destinations: +Here's an example sink that sends logs to Seq: ```csharp -public class MultiDestinationLogger : DefaultLogger +public class SeqLogSink : ILogSink, IDisposable { - private readonly TextWriter _additionalOutput; + private readonly Serilog.ILogger _logger; + + public SeqLogSink(string seqUrl) + { + _logger = new LoggerConfiguration() + .WriteTo.Seq(seqUrl) + .CreateLogger(); + } + + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + var serilogLevel = level switch + { + LogLevel.Trace => Serilog.Events.LogEventLevel.Verbose, + LogLevel.Debug => Serilog.Events.LogEventLevel.Debug, + LogLevel.Information => Serilog.Events.LogEventLevel.Information, + LogLevel.Warning => Serilog.Events.LogEventLevel.Warning, + LogLevel.Error => Serilog.Events.LogEventLevel.Error, + LogLevel.Critical => Serilog.Events.LogEventLevel.Fatal, + _ => Serilog.Events.LogEventLevel.Information + }; + + var testName = context is TestContext tc ? tc.TestDetails.TestName : "Unknown"; + + _logger + .ForContext("TestName", testName) + .Write(serilogLevel, exception, message); + } - public MultiDestinationLogger(Context context, TextWriter additionalOutput) - : base(context) + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) { - _additionalOutput = additionalOutput; + Log(level, message, exception, context); + return ValueTask.CompletedTask; } - protected override void WriteToOutput(string message, bool isError) + public void Dispose() + { + (_logger as IDisposable)?.Dispose(); + } +} +``` + +## Log Levels + +TUnit uses the same log level as provided to the Microsoft.Testing.Platform via command line: + +```bash +dotnet run --log-level Warning +``` + +Available levels (from least to most severe): +- `Trace` +- `Debug` +- `Information` (default) +- `Warning` +- `Error` +- `Critical` + +## Custom Loggers + +You can also create custom loggers by inheriting from `DefaultLogger`: + +```csharp +public class TestHeaderLogger : DefaultLogger +{ + private bool _hasOutputHeader; + + public TestHeaderLogger(Context context) : base(context) { } + + protected override string GenerateMessage(string message, Exception? exception, LogLevel logLevel) { - base.WriteToOutput(message, isError); - _additionalOutput.WriteLine(message); + var baseMessage = base.GenerateMessage(message, exception, logLevel); + + if (!_hasOutputHeader && Context is TestContext testContext) + { + _hasOutputHeader = true; + var testId = $"{testContext.TestDetails.ClassType.Name}.{testContext.TestDetails.TestName}"; + return $"--- {testId} ---\n{baseMessage}"; + } + + return baseMessage; } } ``` + +### Available Extension Points + +- `Context` - Protected property to access the associated context +- `GenerateMessage(message, exception, logLevel)` - Override to customize message formatting +- `WriteToOutput(message, isError)` - Override to customize synchronous output +- `WriteToOutputAsync(message, isError)` - Override for asynchronous output diff --git a/docs/plans/2026-01-17-log-streaming-design.md b/docs/plans/2026-01-17-log-streaming-design.md new file mode 100644 index 0000000000..7e9fd53c30 --- /dev/null +++ b/docs/plans/2026-01-17-log-streaming-design.md @@ -0,0 +1,407 @@ +# Log Streaming Plugin System Design + +**Date:** 2026-01-17 +**Issue:** [#4478 - Stream logs](https://github.com/thomhurst/TUnit/issues/4478) +**Status:** Draft + +## Problem Statement + +Currently, when using TUnit's logging with `TestContext.GetDefaultLogger()`, log output only appears in the IDE (e.g., Rider) after test completion. Users expect real-time log streaming during test execution, similar to NUnit's behavior. + +```csharp +[Test] +public async Task X() +{ + for (int i = 0; i < 3; i += 1) + { + TestContext.Current!.GetDefaultLogger().LogInformation(i.ToString()); + await Task.Delay(1000); + } +} +``` + +**Current behavior:** All 3 log messages appear after the test completes. +**Expected behavior:** Each log message appears as it's written. + +## Root Cause + +Microsoft Testing Platform has two output channels: +1. **Real-time:** `IOutputDevice.DisplayAsync()` - streams directly to IDEs during execution +2. **Historical:** `StandardOutputProperty` on `TestNodeUpdateMessage` - bundled at test completion + +`DefaultLogger` writes to `context.OutputWriter` (historical) and `OriginalConsoleOut` (console), but never uses `IOutputDevice.DisplayAsync()` for real-time IDE streaming. + +## Solution: Plugin-Based Log Sink System + +Inspired by ASP.NET Core's logging architecture, we'll introduce a plugin system that: +1. Allows multiple log destinations (sinks) +2. Enables real-time streaming via `IOutputDevice` +3. Maintains backward compatibility with historical capture +4. Opens extensibility for custom sinks (Seq, file, etc.) + +## Design + +### Core Interfaces (TUnit.Core) + +#### ILogSink + +```csharp +namespace TUnit.Core.Logging; + +/// +/// Represents a destination for log messages. Implement this interface +/// to create custom log sinks (e.g., file, Seq, Application Insights). +/// +public interface ILogSink +{ + /// + /// Asynchronously logs a message. + /// + /// The log level. + /// The formatted message. + /// Optional exception. + /// The current context (TestContext, ClassHookContext, etc.), or null if outside test execution. + ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context); + + /// + /// Synchronously logs a message. + /// + void Log(LogLevel level, string message, Exception? exception, Context? context); + + /// + /// Determines if this sink should receive messages at the specified level. + /// + bool IsEnabled(LogLevel level); +} +``` + +**Design notes:** +- Both sync and async methods match existing `ILogger` pattern +- `Context?` is nullable for console output outside test execution +- Sinks can cast to `TestContext` when they need test-specific info (test name, class, etc.) +- `IsEnabled` allows sinks to filter by level for performance +- If sink implements `IAsyncDisposable`, TUnit calls it at session end + +#### TUnitLoggerFactory + +```csharp +namespace TUnit.Core.Logging; + +/// +/// Factory for configuring and managing log sinks. +/// +public static class TUnitLoggerFactory +{ + private static readonly List Sinks = new(); + private static readonly object Lock = new(); + + /// + /// Registers a log sink to receive log messages. + /// Call this in [Before(Assembly)] or before tests run. + /// + public static void AddSink(ILogSink sink) + { + lock (Lock) + { + Sinks.Add(sink); + } + } + + /// + /// Registers a log sink by type. TUnit will instantiate it. + /// + public static void AddSink() where TSink : ILogSink, new() + { + AddSink(new TSink()); + } + + internal static IReadOnlyList GetSinks() => Sinks; + + internal static async ValueTask DisposeAllAsync() + { + foreach (var sink in Sinks) + { + if (sink is IAsyncDisposable disposable) + { + try + { + await disposable.DisposeAsync(); + } + catch + { + // Swallow disposal errors + } + } + } + Sinks.Clear(); + } +} +``` + +### Routing Changes + +#### DefaultLogger Modifications + +```csharp +// In DefaultLogger.WriteToOutput / WriteToOutputAsync: + +protected virtual void WriteToOutput(string message, bool isError) +{ + var level = isError ? LogLevel.Error : LogLevel.Information; + + // Historical capture (unchanged) + if (isError) + context.ErrorOutputWriter.WriteLine(message); + else + context.OutputWriter.WriteLine(message); + + // Real-time streaming to sinks (new) + foreach (var sink in TUnitLoggerFactory.GetSinks()) + { + if (!sink.IsEnabled(level)) + continue; + + try + { + sink.Log(level, message, exception: null, context); + } + catch (Exception ex) + { + GlobalContext.Current.OriginalConsoleError.WriteLine( + $"[TUnit] Log sink {sink.GetType().Name} failed: {ex.Message}"); + } + } +} + +protected virtual async ValueTask WriteToOutputAsync(string message, bool isError) +{ + var level = isError ? LogLevel.Error : LogLevel.Information; + + // Historical capture (unchanged) + if (isError) + await context.ErrorOutputWriter.WriteLineAsync(message); + else + await context.OutputWriter.WriteLineAsync(message); + + // Real-time streaming to sinks (new) + foreach (var sink in TUnitLoggerFactory.GetSinks()) + { + if (!sink.IsEnabled(level)) + continue; + + try + { + await sink.LogAsync(level, message, exception: null, context); + } + catch (Exception ex) + { + await GlobalContext.Current.OriginalConsoleError.WriteLineAsync( + $"[TUnit] Log sink {sink.GetType().Name} failed: {ex.Message}"); + } + } +} +``` + +#### Console Interceptor Modifications + +Route `Console.WriteLine` through sinks for real-time streaming: + +```csharp +// In StandardOutConsoleInterceptor, after writing to context: + +private void RouteToSinks(string? value) +{ + if (string.IsNullOrEmpty(value)) + return; + + var sinks = TUnitLoggerFactory.GetSinks(); + if (sinks.Count == 0) + return; + + var context = Context.Current; // may be null outside test execution + + foreach (var sink in sinks) + { + if (!sink.IsEnabled(LogLevel.Information)) + continue; + + try + { + sink.Log(LogLevel.Information, value, exception: null, context); + } + catch (Exception ex) + { + // Write to original console to avoid recursion + GlobalContext.Current.OriginalConsoleError.WriteLine( + $"[TUnit] Log sink {sink.GetType().Name} failed: {ex.Message}"); + } + } +} +``` + +### Engine's Built-in Sink (TUnit.Engine) + +```csharp +namespace TUnit.Engine.Logging; + +/// +/// Built-in sink that streams logs to IDEs via Microsoft Testing Platform's IOutputDevice. +/// Automatically registered by TUnit.Engine at startup. +/// +internal class OutputDeviceLogSink : ILogSink +{ + private readonly IOutputDevice _outputDevice; + private readonly LogLevel _minLevel; + + public OutputDeviceLogSink(IOutputDevice outputDevice, LogLevel minLevel = LogLevel.Information) + { + _outputDevice = outputDevice; + _minLevel = minLevel; + } + + public bool IsEnabled(LogLevel level) => level >= _minLevel; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + // Fire and forget for sync path - IOutputDevice is async-only + _ = LogAsync(level, message, exception, context); + } + + public async ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + if (!IsEnabled(level)) + return; + + var color = GetConsoleColor(level); + + await _outputDevice.DisplayAsync( + this, + new FormattedTextOutputDeviceData(message) + { + ForegroundColor = new SystemConsoleColor { ConsoleColor = color } + }, + CancellationToken.None); + } + + private static ConsoleColor GetConsoleColor(LogLevel level) => level switch + { + LogLevel.Error => ConsoleColor.Red, + LogLevel.Warning => ConsoleColor.Yellow, + LogLevel.Debug => ConsoleColor.Gray, + _ => ConsoleColor.White + }; +} +``` + +**Registration during test session initialization:** + +```csharp +// In TUnitTestFramework or test session initialization: +var outputDevice = serviceProvider.GetRequiredService(); +TUnitLoggerFactory.AddSink(new OutputDeviceLogSink(outputDevice)); +``` + +## Data Flow + +``` +┌─────────────────────────────────────────────────────────────────┐ +│ Test Code │ +│ - TestContext.GetDefaultLogger().LogInformation("...") │ +│ - Console.WriteLine("...") │ +└──────────────────────────┬──────────────────────────────────────┘ + │ + ▼ +┌─────────────────────────────────────────────────────────────────┐ +│ DefaultLogger / Console Interceptor │ +│ 1. Write to context.OutputWriter (historical capture) │ +│ 2. Route to all registered ILogSink instances │ +└──────────────────────────┬──────────────────────────────────────┘ + │ + ┌───────────────┼───────────────┐ + ▼ ▼ ▼ +┌─────────────────┐ ┌─────────────┐ ┌─────────────────┐ +│ OutputDevice │ │ User's Seq │ │ User's File │ +│ LogSink │ │ LogSink │ │ LogSink │ +│ (built-in) │ │ (custom) │ │ (custom) │ +└────────┬────────┘ └──────┬──────┘ └────────┬────────┘ + │ │ │ + ▼ ▼ ▼ + IDE Real-time Seq Server Log File +``` + +## User Registration Example + +```csharp +[assembly: Before(Assembly)] +public static class LoggingSetup +{ + public static Task BeforeAssembly() + { + // Add custom sinks + TUnitLoggerFactory.AddSink(new SeqLogSink("http://localhost:5341")); + TUnitLoggerFactory.AddSink(); + return Task.CompletedTask; + } +} + +// Example custom sink +public class FileLogSink : ILogSink, IAsyncDisposable +{ + private readonly StreamWriter _writer; + + public FileLogSink() + { + _writer = new StreamWriter("test-log.txt", append: true); + } + + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + var testName = (context as TestContext)?.TestDetails.TestName ?? "N/A"; + _writer.WriteLine($"[{DateTime.Now:HH:mm:ss}] [{level}] [{testName}] {message}"); + } + + public async ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + var testName = (context as TestContext)?.TestDetails.TestName ?? "N/A"; + await _writer.WriteLineAsync($"[{DateTime.Now:HH:mm:ss}] [{level}] [{testName}] {message}"); + } + + public async ValueTask DisposeAsync() + { + await _writer.DisposeAsync(); + } +} +``` + +## Files to Create/Modify + +| File | Action | Description | +|------|--------|-------------| +| `TUnit.Core/Logging/ILogSink.cs` | Create | New sink interface | +| `TUnit.Core/Logging/TUnitLoggerFactory.cs` | Create | Sink registration | +| `TUnit.Core/Logging/DefaultLogger.cs` | Modify | Route to sinks | +| `TUnit.Core/Logging/StandardOutConsoleInterceptor.cs` | Modify | Route console to sinks | +| `TUnit.Engine/Logging/OutputDeviceLogSink.cs` | Create | Built-in IDE streaming sink | +| `TUnit.Engine/Services/TUnitTestFramework.cs` | Modify | Register OutputDeviceLogSink | + +## Error Handling + +- Sink failures are caught and logged to `OriginalConsoleError` +- Failures do not break tests or stop other sinks from receiving messages +- Disposal errors are swallowed during cleanup + +## Backward Compatibility + +- No breaking changes to existing APIs +- Historical capture via `context.OutputWriter` unchanged +- Existing behavior preserved if no custom sinks registered +- `OutputDeviceLogSink` registered automatically by Engine + +## Future Considerations + +- Built-in sinks package (file, JSON, etc.) +- Structured logging support with semantic properties +- Log level configuration per sink +- Async batching for high-throughput scenarios diff --git a/docs/plans/2026-01-17-log-streaming-implementation.md b/docs/plans/2026-01-17-log-streaming-implementation.md new file mode 100644 index 0000000000..ff08669d03 --- /dev/null +++ b/docs/plans/2026-01-17-log-streaming-implementation.md @@ -0,0 +1,999 @@ +# Log Streaming Plugin System Implementation Plan + +> **For Claude:** REQUIRED SUB-SKILL: Use superpowers:executing-plans to implement this plan task-by-task. + +**Goal:** Enable real-time log streaming to IDEs during test execution via a plugin-based ILogSink system. + +**Architecture:** Introduce `ILogSink` interface in TUnit.Core that receives log messages. `TUnitLoggerFactory` manages sink registration. `DefaultLogger` and console interceptors route to all registered sinks. TUnit.Engine registers `OutputDeviceLogSink` at startup which uses `IOutputDevice.DisplayAsync()` for real-time IDE streaming. + +**Tech Stack:** .NET, Microsoft Testing Platform, IOutputDevice + +**Design Document:** `docs/plans/2026-01-17-log-streaming-design.md` + +--- + +## Task 1: Create ILogSink Interface + +**Files:** +- Create: `TUnit.Core/Logging/ILogSink.cs` + +**Step 1: Create the interface file** + +```csharp +namespace TUnit.Core.Logging; + +/// +/// Represents a destination for log messages. Implement this interface +/// to create custom log sinks (e.g., file, Seq, Application Insights). +/// +public interface ILogSink +{ + /// + /// Asynchronously logs a message. + /// + /// The log level. + /// The formatted message. + /// Optional exception. + /// The current context (TestContext, ClassHookContext, etc.), or null if outside test execution. + ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context); + + /// + /// Synchronously logs a message. + /// + void Log(LogLevel level, string message, Exception? exception, Context? context); + + /// + /// Determines if this sink should receive messages at the specified level. + /// + bool IsEnabled(LogLevel level); +} +``` + +**Step 2: Verify it compiles** + +Run: `dotnet build TUnit.Core/TUnit.Core.csproj -c Release` +Expected: Build succeeded + +**Step 3: Commit** + +```bash +git add TUnit.Core/Logging/ILogSink.cs +git commit -m "feat(logging): add ILogSink interface for log destinations" +``` + +--- + +## Task 2: Create TUnitLoggerFactory + +**Files:** +- Create: `TUnit.Core/Logging/TUnitLoggerFactory.cs` + +**Step 1: Create the factory class** + +```csharp +namespace TUnit.Core.Logging; + +/// +/// Factory for configuring and managing log sinks. +/// +public static class TUnitLoggerFactory +{ + private static readonly List _sinks = []; + private static readonly Lock _lock = new(); + + /// + /// Registers a log sink to receive log messages. + /// Call this in [Before(Assembly)] or before tests run. + /// + public static void AddSink(ILogSink sink) + { + lock (_lock) + { + _sinks.Add(sink); + } + } + + /// + /// Registers a log sink by type. TUnit will instantiate it. + /// + public static void AddSink() where TSink : ILogSink, new() + { + AddSink(new TSink()); + } + + /// + /// Gets all registered sinks. For internal use. + /// + internal static IReadOnlyList GetSinks() + { + lock (_lock) + { + return _sinks.ToArray(); + } + } + + /// + /// Disposes all sinks that implement IAsyncDisposable. + /// Called at end of test session. + /// + internal static async ValueTask DisposeAllAsync() + { + ILogSink[] sinksToDispose; + lock (_lock) + { + sinksToDispose = _sinks.ToArray(); + _sinks.Clear(); + } + + foreach (var sink in sinksToDispose) + { + if (sink is IAsyncDisposable disposable) + { + try + { + await disposable.DisposeAsync(); + } + catch + { + // Swallow disposal errors + } + } + } + } + + /// + /// Clears all registered sinks. For testing purposes. + /// + internal static void Clear() + { + lock (_lock) + { + _sinks.Clear(); + } + } +} +``` + +**Step 2: Verify it compiles** + +Run: `dotnet build TUnit.Core/TUnit.Core.csproj -c Release` +Expected: Build succeeded + +**Step 3: Commit** + +```bash +git add TUnit.Core/Logging/TUnitLoggerFactory.cs +git commit -m "feat(logging): add TUnitLoggerFactory for sink registration" +``` + +--- + +## Task 3: Add Internal Sink Routing Helper + +**Files:** +- Create: `TUnit.Core/Logging/LogSinkRouter.cs` + +**Step 1: Create router helper to avoid code duplication** + +```csharp +namespace TUnit.Core.Logging; + +/// +/// Internal helper for routing log messages to all registered sinks. +/// +internal static class LogSinkRouter +{ + public static void RouteToSinks(LogLevel level, string message, Exception? exception, Context? context) + { + var sinks = TUnitLoggerFactory.GetSinks(); + if (sinks.Count == 0) + { + return; + } + + foreach (var sink in sinks) + { + if (!sink.IsEnabled(level)) + { + continue; + } + + try + { + sink.Log(level, message, exception, context); + } + catch (Exception ex) + { + // Write to original console to avoid recursion + GlobalContext.Current.OriginalConsoleError.WriteLine( + $"[TUnit] Log sink {sink.GetType().Name} failed: {ex.Message}"); + } + } + } + + public static async ValueTask RouteToSinksAsync(LogLevel level, string message, Exception? exception, Context? context) + { + var sinks = TUnitLoggerFactory.GetSinks(); + if (sinks.Count == 0) + { + return; + } + + foreach (var sink in sinks) + { + if (!sink.IsEnabled(level)) + { + continue; + } + + try + { + await sink.LogAsync(level, message, exception, context); + } + catch (Exception ex) + { + // Write to original console to avoid recursion + await GlobalContext.Current.OriginalConsoleError.WriteLineAsync( + $"[TUnit] Log sink {sink.GetType().Name} failed: {ex.Message}"); + } + } + } +} +``` + +**Step 2: Verify it compiles** + +Run: `dotnet build TUnit.Core/TUnit.Core.csproj -c Release` +Expected: Build succeeded + +**Step 3: Commit** + +```bash +git add TUnit.Core/Logging/LogSinkRouter.cs +git commit -m "feat(logging): add LogSinkRouter helper for sink dispatch" +``` + +--- + +## Task 4: Modify DefaultLogger to Route to Sinks + +**Files:** +- Modify: `TUnit.Core/Logging/DefaultLogger.cs` + +**Step 1: Update WriteToOutput to route to sinks** + +Find the `WriteToOutput` method (around line 125) and replace with: + +```csharp +/// +/// Writes the message to the output. +/// Override this method to customize how messages are written. +/// +/// The formatted message to write. +/// True if this is an error-level message. +protected virtual void WriteToOutput(string message, bool isError) +{ + var level = isError ? LogLevel.Error : LogLevel.Information; + + // Historical capture + if (isError) + { + context.ErrorOutputWriter.WriteLine(message); + } + else + { + context.OutputWriter.WriteLine(message); + } + + // Real-time streaming to sinks + LogSinkRouter.RouteToSinks(level, message, null, context); +} +``` + +**Step 2: Update WriteToOutputAsync to route to sinks** + +Find the `WriteToOutputAsync` method (around line 146) and replace with: + +```csharp +/// +/// Asynchronously writes the message to the output. +/// Override this method to customize how messages are written. +/// +/// The formatted message to write. +/// True if this is an error-level message. +/// A task representing the async operation. +protected virtual async ValueTask WriteToOutputAsync(string message, bool isError) +{ + var level = isError ? LogLevel.Error : LogLevel.Information; + + // Historical capture + if (isError) + { + await context.ErrorOutputWriter.WriteLineAsync(message); + } + else + { + await context.OutputWriter.WriteLineAsync(message); + } + + // Real-time streaming to sinks + await LogSinkRouter.RouteToSinksAsync(level, message, null, context); +} +``` + +**Step 3: Verify it compiles** + +Run: `dotnet build TUnit.Core/TUnit.Core.csproj -c Release` +Expected: Build succeeded + +**Step 4: Commit** + +```bash +git add TUnit.Core/Logging/DefaultLogger.cs +git commit -m "feat(logging): route DefaultLogger output to registered sinks" +``` + +--- + +## Task 5: Modify Console Interceptor to Route to Sinks + +**Files:** +- Modify: `TUnit.Engine/Logging/StandardOutConsoleInterceptor.cs` + +**Step 1: Find the interceptor and understand its structure** + +Read the file first to understand how it intercepts console output. + +Run: Read `TUnit.Engine/Logging/StandardOutConsoleInterceptor.cs` + +**Step 2: Add sink routing after console capture** + +The interceptor likely has Write/WriteLine methods that capture output. Add routing to sinks after capturing. The exact modification depends on the file structure, but the pattern is: + +After any line that writes to the context's output (like `Context.Current?.OutputWriter?.WriteLine(value)`), add: + +```csharp +// Route to sinks for real-time streaming +LogSinkRouter.RouteToSinks(LogLevel.Information, value?.ToString() ?? string.Empty, null, Context.Current); +``` + +**Step 3: Add using statement if needed** + +Add at top of file: +```csharp +using TUnit.Core.Logging; +``` + +**Step 4: Verify it compiles** + +Run: `dotnet build TUnit.Engine/TUnit.Engine.csproj -c Release` +Expected: Build succeeded + +**Step 5: Commit** + +```bash +git add TUnit.Engine/Logging/StandardOutConsoleInterceptor.cs +git commit -m "feat(logging): route Console.WriteLine to registered sinks" +``` + +--- + +## Task 6: Modify Console Error Interceptor (if separate) + +**Files:** +- Modify: `TUnit.Engine/Logging/StandardErrorConsoleInterceptor.cs` (if exists) + +**Step 1: Check if file exists and apply same pattern** + +If there's a separate error interceptor, apply the same changes as Task 5 but use `LogLevel.Error`: + +```csharp +LogSinkRouter.RouteToSinks(LogLevel.Error, value?.ToString() ?? string.Empty, null, Context.Current); +``` + +**Step 2: Verify it compiles** + +Run: `dotnet build TUnit.Engine/TUnit.Engine.csproj -c Release` +Expected: Build succeeded + +**Step 3: Commit (if changes made)** + +```bash +git add TUnit.Engine/Logging/StandardErrorConsoleInterceptor.cs +git commit -m "feat(logging): route Console.Error to registered sinks" +``` + +--- + +## Task 7: Create OutputDeviceLogSink in TUnit.Engine + +**Files:** +- Create: `TUnit.Engine/Logging/OutputDeviceLogSink.cs` + +**Step 1: Create the sink that streams to IDEs** + +```csharp +using Microsoft.Testing.Platform.OutputDevice; +using TUnit.Core; +using TUnit.Core.Logging; + +namespace TUnit.Engine.Logging; + +/// +/// Built-in sink that streams logs to IDEs via Microsoft Testing Platform's IOutputDevice. +/// Automatically registered by TUnit.Engine at startup. +/// +internal class OutputDeviceLogSink : ILogSink, IOutputDeviceDataProducer +{ + private readonly IOutputDevice _outputDevice; + private readonly LogLevel _minLevel; + + public OutputDeviceLogSink(IOutputDevice outputDevice, LogLevel minLevel = LogLevel.Information) + { + _outputDevice = outputDevice; + _minLevel = minLevel; + } + + public string Uid => "TUnit.OutputDeviceLogSink"; + public string Version => typeof(OutputDeviceLogSink).Assembly.GetName().Version?.ToString() ?? "1.0.0"; + public string DisplayName => "TUnit Log Sink"; + public string Description => "Streams test logs to IDE in real-time"; + + public Task IsEnabledAsync() => Task.FromResult(true); + + public bool IsEnabled(LogLevel level) => level >= _minLevel; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + if (!IsEnabled(level)) + { + return; + } + + // Fire and forget for sync path - IOutputDevice is async-only + _ = LogAsync(level, message, exception, context); + } + + public async ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + if (!IsEnabled(level)) + { + return; + } + + try + { + var color = GetConsoleColor(level); + + await _outputDevice.DisplayAsync( + this, + new FormattedTextOutputDeviceData(message) + { + ForegroundColor = new SystemConsoleColor { ConsoleColor = color } + }, + CancellationToken.None); + } + catch + { + // Swallow errors - logging should not break tests + } + } + + private static ConsoleColor GetConsoleColor(LogLevel level) => level switch + { + LogLevel.Error => ConsoleColor.Red, + LogLevel.Warning => ConsoleColor.Yellow, + LogLevel.Debug => ConsoleColor.Gray, + LogLevel.Trace => ConsoleColor.DarkGray, + _ => ConsoleColor.White + }; +} +``` + +**Step 2: Verify it compiles** + +Run: `dotnet build TUnit.Engine/TUnit.Engine.csproj -c Release` +Expected: Build succeeded + +**Step 3: Commit** + +```bash +git add TUnit.Engine/Logging/OutputDeviceLogSink.cs +git commit -m "feat(logging): add OutputDeviceLogSink for real-time IDE streaming" +``` + +--- + +## Task 8: Register OutputDeviceLogSink at Startup + +**Files:** +- Modify: Find the test framework initialization (likely `TUnit.Engine/Services/TUnitTestFramework.cs` or similar) + +**Step 1: Find where IOutputDevice is available** + +Search for where `IOutputDevice` is injected or retrieved from the service provider. + +Run: `grep -r "IOutputDevice" TUnit.Engine/ --include="*.cs"` + +**Step 2: Register the sink during initialization** + +At the point where `IOutputDevice` is available (likely in a constructor or initialization method), add: + +```csharp +// Register the built-in sink for real-time IDE streaming +var outputDeviceSink = new OutputDeviceLogSink(outputDevice); +TUnitLoggerFactory.AddSink(outputDeviceSink); +``` + +Add using statement: +```csharp +using TUnit.Core.Logging; +``` + +**Step 3: Verify it compiles** + +Run: `dotnet build TUnit.Engine/TUnit.Engine.csproj -c Release` +Expected: Build succeeded + +**Step 4: Commit** + +```bash +git add TUnit.Engine/Services/*.cs +git commit -m "feat(logging): register OutputDeviceLogSink at test session startup" +``` + +--- + +## Task 9: Dispose Sinks at Session End + +**Files:** +- Modify: Find session cleanup code (likely `TUnit.Engine/Services/TUnitTestFramework.cs` or `OnTestSessionFinishing` handler) + +**Step 1: Find session end hook** + +Search for cleanup or disposal code: + +Run: `grep -r "OnTestSessionFinishing\|Dispose\|Cleanup" TUnit.Engine/Services/ --include="*.cs"` + +**Step 2: Add sink disposal** + +At session end, add: + +```csharp +await TUnitLoggerFactory.DisposeAllAsync(); +``` + +**Step 3: Verify it compiles** + +Run: `dotnet build TUnit.Engine/TUnit.Engine.csproj -c Release` +Expected: Build succeeded + +**Step 4: Commit** + +```bash +git add TUnit.Engine/Services/*.cs +git commit -m "feat(logging): dispose sinks at test session end" +``` + +--- + +## Task 10: Write Unit Tests for TUnitLoggerFactory + +**Files:** +- Create: `TUnit.UnitTests/LogSinkTests.cs` + +**Step 1: Create test file with basic tests** + +```csharp +using TUnit.Core.Logging; + +namespace TUnit.UnitTests; + +public class LogSinkTests +{ + [Before(Test)] + public void Setup() + { + TUnitLoggerFactory.Clear(); + } + + [After(Test)] + public void Cleanup() + { + TUnitLoggerFactory.Clear(); + } + + [Test] + public void AddSink_RegistersSink() + { + // Arrange + var sink = new TestLogSink(); + + // Act + TUnitLoggerFactory.AddSink(sink); + + // Assert + var sinks = TUnitLoggerFactory.GetSinks(); + await Assert.That(sinks).Contains(sink); + } + + [Test] + public void AddSink_Generic_CreatesSinkInstance() + { + // Act + TUnitLoggerFactory.AddSink(); + + // Assert + var sinks = TUnitLoggerFactory.GetSinks(); + await Assert.That(sinks).HasCount().EqualTo(1); + await Assert.That(sinks[0]).IsTypeOf(); + } + + [Test] + public async Task DisposeAllAsync_DisposesAsyncDisposableSinks() + { + // Arrange + var sink = new DisposableTestLogSink(); + TUnitLoggerFactory.AddSink(sink); + + // Act + await TUnitLoggerFactory.DisposeAllAsync(); + + // Assert + await Assert.That(sink.WasDisposed).IsTrue(); + await Assert.That(TUnitLoggerFactory.GetSinks()).IsEmpty(); + } + + [Test] + public void Clear_RemovesAllSinks() + { + // Arrange + TUnitLoggerFactory.AddSink(new TestLogSink()); + TUnitLoggerFactory.AddSink(new TestLogSink()); + + // Act + TUnitLoggerFactory.Clear(); + + // Assert + await Assert.That(TUnitLoggerFactory.GetSinks()).IsEmpty(); + } + + private class TestLogSink : ILogSink + { + public List Messages { get; } = []; + + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + Messages.Add(message); + } + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + Messages.Add(message); + return ValueTask.CompletedTask; + } + } + + private class DisposableTestLogSink : TestLogSink, IAsyncDisposable + { + public bool WasDisposed { get; private set; } + + public ValueTask DisposeAsync() + { + WasDisposed = true; + return ValueTask.CompletedTask; + } + } +} +``` + +**Step 2: Run tests** + +Run: `dotnet run --project TUnit.UnitTests/TUnit.UnitTests.csproj -c Release --no-build -f net8.0 -- --treenode-filter "/*/*/LogSinkTests/*"` +Expected: All tests pass + +**Step 3: Commit** + +```bash +git add TUnit.UnitTests/LogSinkTests.cs +git commit -m "test(logging): add unit tests for TUnitLoggerFactory" +``` + +--- + +## Task 11: Write Unit Tests for LogSinkRouter + +**Files:** +- Modify: `TUnit.UnitTests/LogSinkTests.cs` + +**Step 1: Add router tests to the test file** + +```csharp +public class LogSinkRouterTests +{ + [Before(Test)] + public void Setup() + { + TUnitLoggerFactory.Clear(); + } + + [After(Test)] + public void Cleanup() + { + TUnitLoggerFactory.Clear(); + } + + [Test] + public void RouteToSinks_SendsMessageToAllEnabledSinks() + { + // Arrange + var sink1 = new TestLogSink(); + var sink2 = new TestLogSink(); + TUnitLoggerFactory.AddSink(sink1); + TUnitLoggerFactory.AddSink(sink2); + + // Act + LogSinkRouter.RouteToSinks(LogLevel.Information, "test message", null, null); + + // Assert + await Assert.That(sink1.Messages).Contains("test message"); + await Assert.That(sink2.Messages).Contains("test message"); + } + + [Test] + public void RouteToSinks_SkipsDisabledSinks() + { + // Arrange + var enabledSink = new TestLogSink(); + var disabledSink = new TestLogSink { MinLevel = LogLevel.Error }; + TUnitLoggerFactory.AddSink(enabledSink); + TUnitLoggerFactory.AddSink(disabledSink); + + // Act + LogSinkRouter.RouteToSinks(LogLevel.Information, "test message", null, null); + + // Assert + await Assert.That(enabledSink.Messages).Contains("test message"); + await Assert.That(disabledSink.Messages).IsEmpty(); + } + + [Test] + public void RouteToSinks_ContinuesAfterSinkFailure() + { + // Arrange + var failingSink = new FailingLogSink(); + var workingSink = new TestLogSink(); + TUnitLoggerFactory.AddSink(failingSink); + TUnitLoggerFactory.AddSink(workingSink); + + // Act - should not throw + LogSinkRouter.RouteToSinks(LogLevel.Information, "test message", null, null); + + // Assert - working sink still received message + await Assert.That(workingSink.Messages).Contains("test message"); + } + + private class TestLogSink : ILogSink + { + public List Messages { get; } = []; + public LogLevel MinLevel { get; set; } = LogLevel.Trace; + + public bool IsEnabled(LogLevel level) => level >= MinLevel; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + Messages.Add(message); + } + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + Messages.Add(message); + return ValueTask.CompletedTask; + } + } + + private class FailingLogSink : ILogSink + { + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + throw new InvalidOperationException("Sink failed"); + } + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + throw new InvalidOperationException("Sink failed"); + } + } +} +``` + +**Step 2: Run tests** + +Run: `dotnet run --project TUnit.UnitTests/TUnit.UnitTests.csproj -c Release -f net8.0 -- --treenode-filter "/*/*/LogSinkRouterTests/*"` +Expected: All tests pass + +**Step 3: Commit** + +```bash +git add TUnit.UnitTests/LogSinkTests.cs +git commit -m "test(logging): add unit tests for LogSinkRouter" +``` + +--- + +## Task 12: Integration Test - End to End + +**Files:** +- Create: `TUnit.UnitTests/LogStreamingIntegrationTests.cs` + +**Step 1: Create integration test** + +```csharp +using TUnit.Core.Logging; + +namespace TUnit.UnitTests; + +public class LogStreamingIntegrationTests +{ + [Before(Test)] + public void Setup() + { + TUnitLoggerFactory.Clear(); + } + + [After(Test)] + public void Cleanup() + { + TUnitLoggerFactory.Clear(); + } + + [Test] + public async Task DefaultLogger_RoutesToRegisteredSinks() + { + // Arrange + var captureSink = new CapturingLogSink(); + TUnitLoggerFactory.AddSink(captureSink); + + var testContext = TestContext.Current; + var logger = testContext!.GetDefaultLogger(); + + // Act + await logger.LogInformationAsync("Hello from test"); + + // Assert + await Assert.That(captureSink.Messages).Contains(m => m.Contains("Hello from test")); + } + + private class CapturingLogSink : ILogSink + { + public List Messages { get; } = []; + + public bool IsEnabled(LogLevel level) => true; + + public void Log(LogLevel level, string message, Exception? exception, Context? context) + { + Messages.Add(message); + } + + public ValueTask LogAsync(LogLevel level, string message, Exception? exception, Context? context) + { + Messages.Add(message); + return ValueTask.CompletedTask; + } + } +} +``` + +**Step 2: Run test** + +Run: `dotnet run --project TUnit.UnitTests/TUnit.UnitTests.csproj -c Release -f net8.0 -- --treenode-filter "/*/*/LogStreamingIntegrationTests/*"` +Expected: Test passes + +**Step 3: Commit** + +```bash +git add TUnit.UnitTests/LogStreamingIntegrationTests.cs +git commit -m "test(logging): add integration test for log streaming" +``` + +--- + +## Task 13: Run Full Test Suite + +**Files:** None (verification only) + +**Step 1: Build entire solution** + +Run: `dotnet build TUnit.sln -c Release` +Expected: Build succeeded + +**Step 2: Run unit tests** + +Run: `dotnet run --project TUnit.UnitTests/TUnit.UnitTests.csproj -c Release --no-build -f net8.0` +Expected: All tests pass + +**Step 3: Run analyzer tests** + +Run: `dotnet run --project TUnit.Analyzers.Tests/TUnit.Analyzers.Tests.csproj -c Release -f net8.0` +Expected: All tests pass + +--- + +## Task 14: Update Public API Surface (if using PublicAPI analyzers) + +**Files:** +- Modify: `TUnit.Core/PublicAPI.Shipped.txt` or `PublicAPI.Unshipped.txt` + +**Step 1: Check if public API tracking is used** + +Run: `ls TUnit.Core/PublicAPI*.txt 2>/dev/null || echo "No PublicAPI files"` + +**Step 2: If files exist, add new public types** + +Add to `PublicAPI.Unshipped.txt`: +``` +TUnit.Core.Logging.ILogSink +TUnit.Core.Logging.ILogSink.IsEnabled(TUnit.Core.Logging.LogLevel) -> bool +TUnit.Core.Logging.ILogSink.Log(TUnit.Core.Logging.LogLevel, string!, System.Exception?, TUnit.Core.Context?) -> void +TUnit.Core.Logging.ILogSink.LogAsync(TUnit.Core.Logging.LogLevel, string!, System.Exception?, TUnit.Core.Context?) -> System.Threading.Tasks.ValueTask +TUnit.Core.Logging.TUnitLoggerFactory +TUnit.Core.Logging.TUnitLoggerFactory.AddSink(TUnit.Core.Logging.ILogSink!) -> void +TUnit.Core.Logging.TUnitLoggerFactory.AddSink() -> void +``` + +**Step 3: Commit** + +```bash +git add TUnit.Core/PublicAPI*.txt +git commit -m "docs: update public API surface for log sink types" +``` + +--- + +## Task 15: Final Verification and Squash (Optional) + +**Step 1: Verify all tests pass** + +Run: `dotnet run --project TUnit.UnitTests/TUnit.UnitTests.csproj -c Release -f net8.0` +Expected: All tests pass including new log sink tests + +**Step 2: Review git log** + +Run: `git log --oneline -15` + +**Step 3: Create final summary commit or squash if desired** + +If keeping granular commits: +```bash +git push -u origin feature/log-streaming +``` + +If squashing: +```bash +git rebase -i main +# Squash commits as desired +git push -u origin feature/log-streaming +``` + +--- + +## Summary + +| Task | Description | Files | +|------|-------------|-------| +| 1 | Create ILogSink interface | `TUnit.Core/Logging/ILogSink.cs` | +| 2 | Create TUnitLoggerFactory | `TUnit.Core/Logging/TUnitLoggerFactory.cs` | +| 3 | Create LogSinkRouter helper | `TUnit.Core/Logging/LogSinkRouter.cs` | +| 4 | Modify DefaultLogger | `TUnit.Core/Logging/DefaultLogger.cs` | +| 5-6 | Modify Console Interceptors | `TUnit.Engine/Logging/Standard*ConsoleInterceptor.cs` | +| 7 | Create OutputDeviceLogSink | `TUnit.Engine/Logging/OutputDeviceLogSink.cs` | +| 8 | Register sink at startup | `TUnit.Engine/Services/*.cs` | +| 9 | Dispose sinks at session end | `TUnit.Engine/Services/*.cs` | +| 10-12 | Write tests | `TUnit.UnitTests/LogSink*.cs` | +| 13 | Full test suite verification | - | +| 14 | Update public API | `TUnit.Core/PublicAPI*.txt` | +| 15 | Final verification | - |