fix: improve logging output

Author: egil

src/bunit.core/Extensions/WaitForHelpers/WaitForHelperLoggerExtensions.cs

@@ -5,22 +5,22 @@ namespace Bunit.Extensions.WaitForHelpers;
 internal static class WaitForHelperLoggerExtensions
 {
 	private static readonly Action<ILogger, int, Exception?> CheckingWaitCondition
-		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(1, "OnAfterRender"), "Checking the wait condition for component {Id}.");
+		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(1, "CheckingWaitCondition"), "Checking the wait condition for component {Id}.");
 
 	private static readonly Action<ILogger, int, Exception?> CheckCompleted
-		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(2, "OnAfterRender"), "The check completed successfully for component {Id}.");
+		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(2, "CheckCompleted"), "The check completed successfully for component {Id}.");
 
 	private static readonly Action<ILogger, int, Exception?> CheckFailed
-		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(3, "OnAfterRender"), "The check failed for component {Id}.");
+		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(3, "CheckFailed"), "The check failed for component {Id}.");
 
 	private static readonly Action<ILogger, int, Exception> CheckThrow
-		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(4, "OnAfterRender"), "The checker for component {Id} throw an exception.");
+		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(4, "CheckThrow"), "The checker for component {Id} throw an exception.");
 
 	private static readonly Action<ILogger, int, Exception?> WaiterTimedOut
-		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(10, "OnTimeout"), "The waiter for component {Id} timed out.");
+		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(10, "WaiterTimedOut"), "The waiter for component {Id} timed out.");
 
 	private static readonly Action<ILogger, int, Exception?> WaiterDisposed
-		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(20, "OnTimeout"), "The waiter for component {Id} disposed.");
+		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(20, "WaiterDisposed"), "The waiter for component {Id} disposed.");
 
 	internal static void LogCheckingWaitCondition<T>(this ILogger<WaitForHelper<T>> logger, int componentId)
 	{

src/bunit.core/Rendering/TestRenderer.cs

@@ -233,32 +233,35 @@ protected override Task UpdateDisplayAsync(in RenderBatch renderBatch)
 	{
 		if (disposed)
 		{
-			logger.LogRenderCycleActiveAfterDispose();
 			return Task.CompletedTask;
 		}
 
 		var renderEvent = new RenderEvent();
 
-		for (var i = 0; i < renderBatch.DisposedComponentIDs.Count; i++)
-		{
-			var id = renderBatch.DisposedComponentIDs.Array[i];
-			renderEvent.SetDisposed(id);
-		}
+		PrepareRenderEvent(renderBatch);
+		InvokeApplyRenderEvent();
 
-		for (int i = 0; i < renderBatch.UpdatedComponents.Count; i++)
-		{
-			ref var update = ref renderBatch.UpdatedComponents.Array[i];
-			renderEvent.SetUpdated(update.ComponentId, update.Edits.Count > 0);
-		}
+		return Task.CompletedTask;
 
-		foreach (var (key, rc) in renderedComponents)
+		void PrepareRenderEvent(in RenderBatch renderBatch)
 		{
-			LoadChangesIntoRenderEvent(rc.ComponentId);
-		}
+			for (var i = 0; i < renderBatch.DisposedComponentIDs.Count; i++)
+			{
+				var id = renderBatch.DisposedComponentIDs.Array[i];
+				renderEvent.SetDisposed(id);
+			}
 
-		InvokeApplyRenderEvent();
+			for (int i = 0; i < renderBatch.UpdatedComponents.Count; i++)
+			{
+				ref var update = ref renderBatch.UpdatedComponents.Array[i];
+				renderEvent.SetUpdated(update.ComponentId, update.Edits.Count > 0);
+			}
 
-		return Task.CompletedTask;
+			foreach (var (key, rc) in renderedComponents)
+			{
+				LoadChangesIntoRenderEvent(rc.ComponentId);
+			}
+		}
 
 		void LoadChangesIntoRenderEvent(int componentId)
 		{

src/bunit.core/Rendering/TestRendererLoggerExtensions.cs

@@ -4,51 +4,27 @@ namespace Bunit.Rendering;
 
 internal static class TestRendererLoggerExtensions
 {
-	private static readonly Action<ILogger, Exception?> ProcessingPendingRenders
-		= LoggerMessage.Define(LogLevel.Debug, new EventId(1, "ProcessPendingRender"), "Processing pending renders.");
-
-	private static readonly Action<ILogger, Exception?> NewRenderBatchReceived
-		= LoggerMessage.Define(LogLevel.Debug, new EventId(10, "UpdateDisplayAsync"), "New render batch received.");
-
 	private static readonly Action<ILogger, int, Exception?> ComponentDisposed
-		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(11, "UpdateDisplayAsync"), "Component {Id} has been disposed.");
+		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(11, "ComponentDisposed"), "Component {Id} has been disposed.");
 
 	private static readonly Action<ILogger, int, Exception?> ComponentRendered
-		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(12, "UpdateDisplayAsync"), "Component {Id} has been rendered.");
-
-	private static readonly Action<ILogger, Exception?> ChangedComponentsMarkupUpdated
-		= LoggerMessage.Define(LogLevel.Debug, new EventId(13, "UpdateDisplayAsync"), "Finished updating the markup of changed components.");
+		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(12, "ComponentRendered"), "Component {Id} has been rendered.");
 
 	private static readonly Action<ILogger, int, int, Exception?> DisposedChildInRenderTreeFrame
-		= LoggerMessage.Define<int, int>(LogLevel.Warning, new EventId(14, "UpdateDisplayAsync"), "A parent components {ParentComponentId} has a disposed component {ComponentId} as its child.");
+		= LoggerMessage.Define<int, int>(LogLevel.Warning, new EventId(14, "DisposedChildInRenderTreeFrame"), "A parent components {ParentComponentId} has a disposed component {ComponentId} as its child.");
 
 	private static readonly Action<ILogger, Exception?> AsyncInitialRender
-		= LoggerMessage.Define(LogLevel.Debug, new EventId(20, "Render"), "The initial render task did not complete immediately.");
+		= LoggerMessage.Define(LogLevel.Debug, new EventId(20, "AsyncInitialRender"), "The initial render task did not complete immediately.");
 
 	private static readonly Action<ILogger, int, Exception?> InitialRenderCompleted
-		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(21, "UpdateDisplayAsync"), "The initial render of component {Id} is completed.");
+		= LoggerMessage.Define<int>(LogLevel.Debug, new EventId(21, "InitialRenderCompleted"), "The initial render of component {Id} is completed.");
 
 	private static readonly Action<ILogger, string, string, Exception> UnhandledException
-		= LoggerMessage.Define<string, string>(LogLevel.Error, new EventId(30, "LogUnhandledException"), "An unhandled exception happened during rendering: {Message}" + Environment.NewLine + "{StackTrace}");
+		= LoggerMessage.Define<string, string>(LogLevel.Error, new EventId(30, "UnhandledException"), "An unhandled exception happened during rendering: {Message}" + Environment.NewLine + "{StackTrace}");
 
 	private static readonly Action<ILogger, Exception?> RenderCycleActiveAfterDispose
-		= LoggerMessage.Define(LogLevel.Warning, new EventId(31, "LogRenderCycleActiveAfterDispose"), "A component attempted to update the render tree after the renderer was disposed.");
-
-	internal static void LogProcessingPendingRenders(this ILogger<TestRenderer> logger)
-	{
-		if (logger.IsEnabled(LogLevel.Debug))
-		{
-			ProcessingPendingRenders(logger, null);
-		}
-	}
+		= LoggerMessage.Define(LogLevel.Warning, new EventId(31, "RenderCycleActiveAfterDispose"), "A component attempted to update the render tree after the renderer was disposed.");
 
-	internal static void LogNewRenderBatchReceived(this ILogger<TestRenderer> logger)
-	{
-		if (logger.IsEnabled(LogLevel.Debug))
-		{
-			NewRenderBatchReceived(logger, null);
-		}
-	}
 
 	internal static void LogComponentDisposed(this ILogger<TestRenderer> logger, int componentId)
 	{
@@ -66,14 +42,6 @@ internal static void LogComponentRendered(this ILogger<TestRenderer> logger, int
 		}
 	}
 
-	internal static void LogChangedComponentsMarkupUpdated(this ILogger<TestRenderer> logger)
-	{
-		if (logger.IsEnabled(LogLevel.Debug))
-		{
-			ChangedComponentsMarkupUpdated(logger, null);
-		}
-	}
-
 	internal static void LogAsyncInitialRender(this ILogger<TestRenderer> logger)
 	{
 		if (logger.IsEnabled(LogLevel.Debug))

src/bunit.web/TestDoubles/ErrorBoundary/BunitErrorBoundaryLogger.cs

@@ -1,7 +1,4 @@
 #if NET6_0_OR_GREATER
-using System;
-using System.Threading.Tasks;
-using Microsoft.AspNetCore.Components.Web;
 using Microsoft.Extensions.Logging;
 
 namespace Bunit.TestDoubles;
@@ -12,10 +9,8 @@ namespace Bunit.TestDoubles;
 /// </summary>
 internal class BunitErrorBoundaryLogger : IErrorBoundaryLogger
 {
-	private static readonly Action<ILogger, string, Exception> ExceptionCaughtByErrorBoundary = LoggerMessage.Define<string>(
-		LogLevel.Warning,
-		100,
-		"Unhandled exception rendering component: {Message}");
+	private static readonly Action<ILogger, string, Exception> ExceptionCaughtByErrorBoundary
+		= LoggerMessage.Define<string>(LogLevel.Warning, new EventId(100, "ExceptionCaughtByErrorBoundary"), "Unhandled exception rendering component: {Message}");
 
 	private readonly ILogger logger;
 

tests/bunit.testassets/ServiceCollectionLoggingExtensions.cs

@@ -1,40 +1,25 @@
-using System.Globalization;
 using Microsoft.Extensions.Logging;
 using Serilog;
-using Serilog.Core;
 using Serilog.Events;
+using Serilog.Templates;
 using Xunit.Abstractions;
 
 namespace Xunit;
 
 public static class ServiceCollectionLoggingExtensions
 {
-	[SuppressMessage("Reliability", "CA2000:Dispose objects before losing scope", Justification = "Serilog should dispose of its logger itself")]
 	public static IServiceCollection AddXunitLogger(this IServiceCollection services, ITestOutputHelper outputHelper)
 	{
 		var serilogLogger = new LoggerConfiguration()
 			.MinimumLevel.Verbose()
-			.Enrich.With(new ThreadIDEnricher())
 			.WriteTo.TestOutput(
 				testOutputHelper: outputHelper,
-				restrictedToMinimumLevel: LogEventLevel.Verbose,
-				outputTemplate: ThreadIDEnricher.DefaultConsoleOutputTemplate,
-				formatProvider: CultureInfo.InvariantCulture)
+				formatter: new ExpressionTemplate("[{UtcDateTime(@t):mm:ss.ffffff} | {@l:u3} | {Substring(SourceContext, LastIndexOf(SourceContext, '.') + 1)} | {Coalesce(EventId.Name, '<none>')}] {@m}\n{@x}"),
+				restrictedToMinimumLevel: LogEventLevel.Verbose)
 			.CreateLogger();
 
-		services.AddSingleton<ILoggerFactory>(new LoggerFactory().AddSerilog(serilogLogger, dispose: true));
+		services.AddSingleton<ILoggerFactory>(_ => new LoggerFactory().AddSerilog(serilogLogger, dispose: true));
 		services.AddSingleton(typeof(ILogger<>), typeof(Logger<>));
 		return services;
 	}
-
-	private sealed class ThreadIDEnricher : ILogEventEnricher
-	{
-		internal const string DefaultConsoleOutputTemplate = "{Timestamp:yyyy-MM-dd HH:mm:ss} ({ThreadID}) [{Level}] {Message}{NewLine}{Exception}";
-
-		public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
-		{
-			logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
-			  "ThreadID", Environment.CurrentManagedThreadId.ToString("D4", CultureInfo.InvariantCulture)));
-		}
-	}
 }

tests/bunit.testassets/bunit.testassets.csproj

@@ -14,6 +14,7 @@
 
 	<ItemGroup>
 		<PackageReference Include="Serilog" Version="3.0.1" />
+		<PackageReference Include="Serilog.Expressions" Version="3.4.1" />
 	</ItemGroup>
 
 	<ItemGroup Condition="'$(TargetFramework)' == 'netstandard2.1'">