From f5641d4c5c170bc0b71cb3aa8566e05db729661f Mon Sep 17 00:00:00 2001 From: skwasjer <11424653+skwasjer@users.noreply.github.com> Date: Wed, 2 Oct 2024 02:34:48 +0200 Subject: [PATCH] test: simplify request logging --- .../Fixtures/CapturingLoggerFactoryFixture.cs | 230 ------------------ .../Fixtures/FakeLogRecordSerialization.cs | 53 ++++ .../Fixtures/LoggerFactoryFixture.cs | 46 ++-- .../Fixtures/MockHttpServerFixture.cs | 53 ++-- .../MockHttp.Server.Tests.csproj | 2 +- 5 files changed, 106 insertions(+), 278 deletions(-) delete mode 100644 test/MockHttp.Server.Tests/Fixtures/CapturingLoggerFactoryFixture.cs create mode 100644 test/MockHttp.Server.Tests/Fixtures/FakeLogRecordSerialization.cs diff --git a/test/MockHttp.Server.Tests/Fixtures/CapturingLoggerFactoryFixture.cs b/test/MockHttp.Server.Tests/Fixtures/CapturingLoggerFactoryFixture.cs deleted file mode 100644 index 2ff20365..00000000 --- a/test/MockHttp.Server.Tests/Fixtures/CapturingLoggerFactoryFixture.cs +++ /dev/null @@ -1,230 +0,0 @@ -using System.Text; -using Microsoft.Extensions.DependencyInjection; -using Microsoft.Extensions.Logging; -using Microsoft.Extensions.Logging.Abstractions; -using Microsoft.Extensions.Logging.Console; -using Microsoft.Extensions.Options; - -namespace MockHttp.Fixtures; - -public delegate void CaptureDelegate(string message); - -public class CapturingLoggerFactoryFixture : LoggerFactoryFixture -{ - private static readonly AsyncLocal LogContextLocal = new(); - - public CapturingLoggerFactoryFixture() - : base(configure => configure - .AddConsole(opts => opts.FormatterName = ConsoleCapture.NameKey) - .AddConsoleFormatter(opts => opts.IncludeScopes = true) - .Services.AddSingleton((CaptureDelegate)(message => LogContextLocal.Value?.Events.Add(message))) - ) - { - } - - public static LogContext CreateContext() - { - return LogContextLocal.Value = new LogContext(() => LogContextLocal.Value = null); - } - - public sealed class LogContext(Action dispose) : IDisposable - { - public List Events { get; } = new(); - - public void Dispose() - { - dispose(); - } - } - - private class ConsoleCapture : ConsoleFormatter - { - internal const string NameKey = "console-capture"; - private const string LogLevelPadding = ": "; - private static readonly string MessagePadding = new(' ', GetLogLevelString(LogLevel.Information).Length + LogLevelPadding.Length); - private static readonly string NewLineWithMessagePadding = Environment.NewLine + MessagePadding; - - private readonly CaptureDelegate _onWrite; - - private readonly ConsoleCaptureOptions _options; - - public ConsoleCapture - ( - CaptureDelegate onWrite, - IOptions options - ) : base(NameKey) - { - _onWrite = onWrite ?? throw new ArgumentNullException(nameof(onWrite)); - _options = options.Value; - } - - public override void Write(in LogEntry logEntry, IExternalScopeProvider? scopeProvider, TextWriter textWriter) - { - var sb = new StringBuilder(); - textWriter = new StringWriter(sb); - - string? message = logEntry.Formatter(logEntry.State, logEntry.Exception); - if (logEntry.Exception is null && message is null) - { - return; - } - - LogLevel logLevel = logEntry.LogLevel; - string logLevelString = GetLogLevelString(logLevel); - - string? timestamp = null; - string? timestampFormat = _options.TimestampFormat; - if (timestampFormat is not null) - { - DateTimeOffset dateTimeOffset = GetCurrentDateTime(); - timestamp = dateTimeOffset.ToString(timestampFormat); - } - - if (!string.IsNullOrEmpty(timestamp)) - { - textWriter.Write(timestamp); - } - - if (!string.IsNullOrEmpty(logLevelString)) - { - textWriter.Write(logLevelString); - } - - CreateDefaultLogMessage(textWriter, in logEntry, message, scopeProvider); - - _onWrite(sb.ToString()); - } - - private void CreateDefaultLogMessage(TextWriter textWriter, in LogEntry logEntry, string message, IExternalScopeProvider? scopeProvider) - { - bool singleLine = _options.SingleLine; - int eventId = logEntry.EventId.Id; - Exception? exception = logEntry.Exception; - - // Example: - // info: ConsoleApp.Program[10] - // Request received - - // category and event id - textWriter.Write(LogLevelPadding); - textWriter.Write(logEntry.Category); - textWriter.Write('['); - -#if NETCOREAPP - Span span = stackalloc char[10]; - if (eventId.TryFormat(span, out int charsWritten)) - { - textWriter.Write(span.Slice(0, charsWritten)); - } - else -#endif - { - textWriter.Write(eventId.ToString()); - } - - textWriter.Write(']'); - if (!singleLine) - { - textWriter.Write(Environment.NewLine); - } - - // scope information - WriteScopeInformation(textWriter, scopeProvider, singleLine); - WriteMessage(textWriter, message, singleLine); - - // Example: - // System.InvalidOperationException - // at Namespace.Class.Function() in File:line X - if (exception is not null) - { - // exception message - WriteMessage(textWriter, exception.ToString(), singleLine); - } - - if (singleLine) - { - textWriter.Write(Environment.NewLine); - } - } - - private static void WriteMessage(TextWriter textWriter, string message, bool singleLine) - { - if (!string.IsNullOrEmpty(message)) - { - if (singleLine) - { - textWriter.Write(' '); - WriteReplacing(textWriter, Environment.NewLine, " ", message); - } - else - { - textWriter.Write(MessagePadding); - WriteReplacing(textWriter, Environment.NewLine, NewLineWithMessagePadding, message); - textWriter.Write(Environment.NewLine); - } - } - - static void WriteReplacing(TextWriter writer, string oldValue, string newValue, string message) - { - string newMessage = message.Replace(oldValue, newValue); - writer.Write(newMessage); - } - } - - private void WriteScopeInformation(TextWriter textWriter, IExternalScopeProvider? scopeProvider, bool singleLine) - { - if (_options.IncludeScopes && scopeProvider is not null) - { - bool paddingNeeded = !singleLine; - scopeProvider.ForEachScope((scope, state) => - { - if (paddingNeeded) - { - paddingNeeded = false; - state.Write(MessagePadding); - state.Write("=> "); - } - else - { - state.Write(" => "); - } - - state.Write(scope); - }, - textWriter); - - if (!paddingNeeded && !singleLine) - { - textWriter.Write(Environment.NewLine); - } - } - } - - private static string GetLogLevelString(LogLevel logLevel) - { - return logLevel switch - { - LogLevel.Trace => "trce", - LogLevel.Debug => "dbug", - LogLevel.Information => "info", - LogLevel.Warning => "warn", - LogLevel.Error => "fail", - LogLevel.Critical => "crit", - _ => throw new ArgumentOutOfRangeException(nameof(logLevel)) - }; - } - - private DateTimeOffset GetCurrentDateTime() - { - return _options.UseUtcTimestamp ? DateTimeOffset.UtcNow : DateTimeOffset.Now; - } - } - - private class ConsoleCaptureOptions : ConsoleFormatterOptions - { - /// - /// When , the entire message gets logged in a single line. - /// - public bool SingleLine { get; set; } - } -} diff --git a/test/MockHttp.Server.Tests/Fixtures/FakeLogRecordSerialization.cs b/test/MockHttp.Server.Tests/Fixtures/FakeLogRecordSerialization.cs new file mode 100644 index 00000000..7754fe78 --- /dev/null +++ b/test/MockHttp.Server.Tests/Fixtures/FakeLogRecordSerialization.cs @@ -0,0 +1,53 @@ +using System.Text; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Testing; + +namespace MockHttp.Fixtures; + +internal static class FakeLogRecordSerialization +{ + internal static string Serialize(FakeLogRecord e) + { + var sb = new StringBuilder(); + const int len = 4; + string indent = new(' ', len + 2); + + sb.AppendLine($"{GetLogLevelString(e.Level)}: {e.Category}[{e.Id.Id}]"); + foreach (IEnumerable> scope in e.Scopes.OfType>>()) + { + sb.Append(indent); + // ReSharper disable once UsageOfDefaultStructEquality + foreach (KeyValuePair kvp in scope) + { + sb.Append($"=> {kvp} "); + } + + sb.AppendLine(); + } + + sb.Append(indent); + sb.AppendLine(e.Message); + + if (e.Exception is not null) + { + sb.Append(indent); + sb.AppendLine(e.Exception.ToString()); + } + + return sb.ToString(); + } + + private static string GetLogLevelString(LogLevel logLevel) + { + return logLevel switch + { + LogLevel.Trace => "trce", + LogLevel.Debug => "dbug", + LogLevel.Information => "info", + LogLevel.Warning => "warn", + LogLevel.Error => "fail", + LogLevel.Critical => "crit", + _ => throw new ArgumentOutOfRangeException(nameof(logLevel)) + }; + } +} diff --git a/test/MockHttp.Server.Tests/Fixtures/LoggerFactoryFixture.cs b/test/MockHttp.Server.Tests/Fixtures/LoggerFactoryFixture.cs index 1f4dccee..97f73a50 100644 --- a/test/MockHttp.Server.Tests/Fixtures/LoggerFactoryFixture.cs +++ b/test/MockHttp.Server.Tests/Fixtures/LoggerFactoryFixture.cs @@ -1,50 +1,44 @@ using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Testing; namespace MockHttp.Fixtures; -public abstract class LoggerFactoryFixture : IAsyncLifetime, IAsyncDisposable +internal sealed class LoggerFactoryFixture : IAsyncDisposable, IDisposable { private readonly ServiceProvider _services; - protected LoggerFactoryFixture(Action? configure = null) + public LoggerFactoryFixture(Action? configure = null) { _services = new ServiceCollection() - .AddLogging(builder => - { - builder.SetMinimumLevel(LogLevel.Trace); - - builder - .AddDebug() - .AddSimpleConsole(opts => opts.IncludeScopes = true) - ; - - configure?.Invoke(builder); - }) + .AddLogging( + builder => + { + builder.SetMinimumLevel(LogLevel.Trace); + + builder + .AddFakeLogging() + .AddDebug(); + + configure?.Invoke(builder); + } + ) .BuildServiceProvider(); Factory = _services.GetRequiredService(); + FakeLogCollector = _services.GetRequiredService(); } public ILoggerFactory Factory { get; } - public async ValueTask DisposeAsync() - { - await DisposeAsyncCore(); - GC.SuppressFinalize(this); - } + public FakeLogCollector FakeLogCollector { get; } - Task IAsyncLifetime.InitializeAsync() + public void Dispose() { - return Task.CompletedTask; + _services.Dispose(); } - Task IAsyncLifetime.DisposeAsync() - { - return DisposeAsync().AsTask(); - } - - protected virtual async ValueTask DisposeAsyncCore() + public async ValueTask DisposeAsync() { await _services.DisposeAsync(); } diff --git a/test/MockHttp.Server.Tests/Fixtures/MockHttpServerFixture.cs b/test/MockHttp.Server.Tests/Fixtures/MockHttpServerFixture.cs index 5c864da3..0a1f822b 100644 --- a/test/MockHttp.Server.Tests/Fixtures/MockHttpServerFixture.cs +++ b/test/MockHttp.Server.Tests/Fixtures/MockHttpServerFixture.cs @@ -1,13 +1,15 @@ using System.Net.NetworkInformation; using Microsoft.AspNetCore.Builder; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; using Xunit.Abstractions; namespace MockHttp.Fixtures; public class MockHttpServerFixture : IDisposable, IAsyncLifetime { - private readonly CapturingLoggerFactoryFixture _loggerFactoryFixture; - private CapturingLoggerFactoryFixture.LogContext? _loggerCtx; + private readonly Guid _logRequestScope = Guid.NewGuid(); + private readonly LoggerFactoryFixture _loggerFactoryFixture; public MockHttpServerFixture() : this("http") @@ -16,7 +18,7 @@ public MockHttpServerFixture() protected MockHttpServerFixture(string scheme) { - _loggerFactoryFixture = new CapturingLoggerFactoryFixture(); + _loggerFactoryFixture = new LoggerFactoryFixture(); Handler = new MockHttpHandler(); Server = new MockHttpServer( Handler, @@ -28,12 +30,16 @@ protected MockHttpServerFixture(string scheme) ) ); Server - .Configure(builder => builder - .Use((_, next) => - { - _loggerCtx ??= CapturingLoggerFactoryFixture.CreateContext(); - return next(); - }) + .Configure( + builder => builder.Use( + async (context, func) => + { + ILogger + logger = context.RequestServices.GetRequiredService>(); + using IDisposable? scope = logger.BeginScope(_logRequestScope); + await func(context); + } + ) ); } @@ -48,33 +54,38 @@ public Task InitializeAsync() public async Task DisposeAsync() { - await _loggerFactoryFixture.DisposeAsync(); await Server.DisposeAsync(); + Handler.Dispose(); + await _loggerFactoryFixture.DisposeAsync(); } public void Dispose() { - _loggerCtx?.Dispose(); - Server.Dispose(); - Handler.Dispose(); + Dispose(true); GC.SuppressFinalize(this); } + protected virtual void Dispose(bool disposing) + { + if (disposing) + { + Server.Dispose(); + Handler.Dispose(); + _loggerFactoryFixture.Dispose(); + } + } + private static bool SupportsIpv6() { NetworkInterface[] networkInterfaces = NetworkInterface.GetAllNetworkInterfaces(); return networkInterfaces.Any(ni => ni.Supports(NetworkInterfaceComponent.IPv6)); } - // ReSharper disable once MemberCanBeMadeStatic.Global public void LogServerTrace(ITestOutputHelper testOutputHelper) { - if (_loggerCtx is null) - { - return; - } - - foreach (string msg in _loggerCtx.Events) + foreach (string msg in _loggerFactoryFixture.FakeLogCollector.GetSnapshot() + .Where(e => e.Scopes.Contains(_logRequestScope)) + .Select(FakeLogRecordSerialization.Serialize)) { testOutputHelper.WriteLine(msg); } @@ -83,6 +94,6 @@ public void LogServerTrace(ITestOutputHelper testOutputHelper) public void Reset() { Handler.Reset(); - _loggerCtx = null; + _loggerFactoryFixture.FakeLogCollector.Clear(); } } diff --git a/test/MockHttp.Server.Tests/MockHttp.Server.Tests.csproj b/test/MockHttp.Server.Tests/MockHttp.Server.Tests.csproj index 4e92a423..acd249a5 100644 --- a/test/MockHttp.Server.Tests/MockHttp.Server.Tests.csproj +++ b/test/MockHttp.Server.Tests/MockHttp.Server.Tests.csproj @@ -13,7 +13,7 @@ - +