feat: improve event dispatching logging

src/bunit.core/Rendering/TestRenderer.cs

@@ -119,6 +119,7 @@ public Task DispatchEventAsync(
 
 				try
 				{
+					logger.LogDispatchingEvent(eventHandlerId, fieldInfo, eventArgs);
 					return base.DispatchEventAsync(eventHandlerId, fieldInfo, eventArgs);
 				}
 				catch (ArgumentException ex) when (string.Equals(ex.Message, $"There is no event handler associated with this event. EventId: '{eventHandlerId}'. (Parameter 'eventHandlerId')", StringComparison.Ordinal))
@@ -142,7 +143,7 @@ public Task DispatchEventAsync(
 
 			return result;
 		}
-	}
+	}	
 
 	/// <inheritdoc/>
 	public IRenderedComponentBase<TComponent> FindComponent<TComponent>(IRenderedFragmentBase parentComponent)

src/bunit.core/Rendering/TestRendererLoggerExtensions.cs

@@ -1,30 +1,15 @@
 using Microsoft.Extensions.Logging;
+using System.Text.Json;
 
 namespace Bunit.Rendering;
 
 internal static class TestRendererLoggerExtensions
 {
 	private static readonly Action<ILogger, int, Exception?> ComponentDisposed
-		= 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, "ComponentRendered"), "Component {Id} has been rendered.");
-
-	private static readonly Action<ILogger, int, int, Exception?> DisposedChildInRenderTreeFrame
-		= 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, "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, "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, "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, "RenderCycleActiveAfterDispose"), "A component attempted to update the render tree after the renderer was disposed.");
-
+		= LoggerMessage.Define<int>(
+			LogLevel.Debug,
+			new EventId(11, "ComponentDisposed"),
+			"Component {Id} has been disposed.");
 
 	internal static void LogComponentDisposed(this ILogger<TestRenderer> logger, int componentId)
 	{
@@ -34,6 +19,12 @@ internal static void LogComponentDisposed(this ILogger<TestRenderer> logger, int
 		}
 	}
 
+	private static readonly Action<ILogger, int, Exception?> ComponentRendered
+		= LoggerMessage.Define<int>(
+			LogLevel.Debug,
+			new EventId(12, "ComponentRendered"),
+			"Component {ComponentId} has been rendered.");
+
 	internal static void LogComponentRendered(this ILogger<TestRenderer> logger, int componentId)
 	{
 		if (logger.IsEnabled(LogLevel.Debug))
@@ -42,6 +33,26 @@ internal static void LogComponentRendered(this ILogger<TestRenderer> logger, int
 		}
 	}
 
+	private static readonly Action<ILogger, int, int, Exception?> DisposedChildInRenderTreeFrame
+		= LoggerMessage.Define<int, int>(
+			LogLevel.Warning,
+			new EventId(14, "DisposedChildInRenderTreeFrame"),
+			"A parent components {ParentComponentId} has a disposed component {ComponentId} as its child.");
+
+	internal static void LogDisposedChildInRenderTreeFrame(this ILogger<TestRenderer> logger, int parentComponentId, int componentId)
+	{
+		if (logger.IsEnabled(LogLevel.Warning))
+		{
+			DisposedChildInRenderTreeFrame(logger, parentComponentId, componentId, null);
+		}
+	}
+
+	private static readonly Action<ILogger, Exception?> AsyncInitialRender
+		= LoggerMessage.Define(
+			LogLevel.Debug,
+			new EventId(20, "AsyncInitialRender"),
+			"The initial render task did not complete immediately.");
+
 	internal static void LogAsyncInitialRender(this ILogger<TestRenderer> logger)
 	{
 		if (logger.IsEnabled(LogLevel.Debug))
@@ -50,6 +61,12 @@ internal static void LogAsyncInitialRender(this ILogger<TestRenderer> logger)
 		}
 	}
 
+	private static readonly Action<ILogger, int, Exception?> InitialRenderCompleted
+		= LoggerMessage.Define<int>(
+			LogLevel.Debug,
+			new EventId(21, "InitialRenderCompleted"),
+			"The initial render of component {ComponentId} is completed.");
+
 	internal static void LogInitialRenderCompleted(this ILogger<TestRenderer> logger, int componentId)
 	{
 		if (logger.IsEnabled(LogLevel.Debug))
@@ -58,6 +75,12 @@ internal static void LogInitialRenderCompleted(this ILogger<TestRenderer> logger
 		}
 	}
 
+	private static readonly Action<ILogger, string, string, Exception> UnhandledException
+		= LoggerMessage.Define<string, string>(
+			LogLevel.Error,
+			new EventId(30, "UnhandledException"),
+			"An unhandled exception happened during rendering: {Message}" + Environment.NewLine + "{StackTrace}");
+
 	internal static void LogUnhandledException(this ILogger<TestRenderer> logger, Exception exception)
 	{
 		if (logger.IsEnabled(LogLevel.Error))
@@ -66,6 +89,12 @@ internal static void LogUnhandledException(this ILogger<TestRenderer> logger, Ex
 		}
 	}
 
+	private static readonly Action<ILogger, Exception?> RenderCycleActiveAfterDispose
+		= LoggerMessage.Define(
+			LogLevel.Warning,
+			new EventId(31, "RenderCycleActiveAfterDispose"),
+			"A component attempted to update the render tree after the renderer was disposed.");
+
 	internal static void LogRenderCycleActiveAfterDispose(this ILogger<TestRenderer> logger)
 	{
 		if (logger.IsEnabled(LogLevel.Warning))
@@ -74,11 +103,42 @@ internal static void LogRenderCycleActiveAfterDispose(this ILogger<TestRenderer>
 		}
 	}
 
-	internal static void LogDisposedChildInRenderTreeFrame(this ILogger<TestRenderer> logger, int parentComponentId, int componentId)
+	private static readonly Action<ILogger, string, string, ulong, int, Exception?> DispatchingEventWithFieldValue
+		= LoggerMessage.Define<string, string, ulong, int>(
+			LogLevel.Debug,
+			new EventId(40, "DispatchingEvent"),
+			"Dispatching {EventArgs} to {FieldValue} handler (id = {EventHandlerId}) on component {ComponentId}.");
+
+	private static readonly Action<ILogger, string, ulong, int, Exception?> DispatchingEvent
+		= LoggerMessage.Define<string, ulong, int>(
+			LogLevel.Debug,
+			new EventId(40, "DispatchingEvent"),
+			"Dispatching {EventArgs} to handler (id = {EventHandlerId}) on component {ComponentId}.");
+
+	internal static void LogDispatchingEvent(this ILogger<TestRenderer> logger, ulong eventHandlerId, EventFieldInfo fieldInfo, EventArgs eventArgs)
 	{
-		if (logger.IsEnabled(LogLevel.Warning))
+		if (logger.IsEnabled(LogLevel.Debug))
 		{
-			DisposedChildInRenderTreeFrame(logger, parentComponentId, componentId, null);
+			var eventType = eventArgs.GetType();
+			var eventArgsText = eventType.Name;
+			if (eventArgsText != nameof(EventArgs))
+			{
+				var eventArgsContent = JsonSerializer.Serialize(eventArgs, eventType);
+				eventArgsText = eventArgsContent == "{}"
+					? eventArgsText
+					: $"{eventArgsText} = {eventArgsContent}";
+			}
+
+			if (fieldInfo.FieldValue is not null)
+			{
+				var fieldValueText = JsonSerializer.Serialize(fieldInfo.FieldValue, fieldInfo.FieldValue.GetType());
+				DispatchingEventWithFieldValue(logger, eventArgsText, fieldValueText, eventHandlerId, fieldInfo.ComponentId, null);
+			}
+			else
+			{
+				DispatchingEvent(logger, eventArgsText, eventHandlerId, fieldInfo.ComponentId, null);
+			}
 		}
 	}
+
 }

tests/Directory.Build.props

@@ -42,6 +42,7 @@
 		<Using Include="Moq" />
 		<Using Include="Shouldly" />
 		<Using Include="Xunit" />
+		<Using Include="Xunit.Abstractions" />
 	</ItemGroup>
 
 </Project>

tests/bunit.web.tests/EventDispatchExtensions/ClipboardEventDispatchExtensionsTest.cs

@@ -1,7 +1,13 @@
+using Xunit.Abstractions;
+
 namespace Bunit;
 
 public class ClipboardEventDispatchExtensionsTest : EventDispatchExtensionsTest<ClipboardEventArgs>
 {
+	public ClipboardEventDispatchExtensionsTest(ITestOutputHelper outputHelper) : base(outputHelper)
+	{
+	}
+
 	protected override string ElementName => "textarea";
 
 	[Theory(DisplayName = "Clipboard events are raised correctly through helpers")]

tests/bunit.web.tests/EventDispatchExtensions/DetailsElementEventDispatcherExtensionsTest.cs

@@ -1,7 +1,4 @@
 #if !NETCOREAPP3_1
-using Bunit.TestAssets.SampleComponents;
-using Shouldly;
-using Xunit;
 
 namespace Bunit.EventDispatchExtensions;
 

tests/bunit.web.tests/EventDispatchExtensions/DragEventDispatchExtensionsTest.cs

@@ -2,6 +2,10 @@ namespace Bunit;
 
 public class DragEventDispatchExtensionsTest : EventDispatchExtensionsTest<DragEventArgs>
 {
+	public DragEventDispatchExtensionsTest(ITestOutputHelper outputHelper) : base(outputHelper)
+	{
+	}
+
 	protected override string ElementName => "textarea";
 
 	[Theory(DisplayName = "Drag events are raised correctly through helpers")]

tests/bunit.web.tests/EventDispatchExtensions/EventDispatchExtensionsTest.cs

@@ -1,4 +1,5 @@
 using AngleSharp.Dom;
+using Xunit.Abstractions;
 
 namespace Bunit;
 
@@ -9,6 +10,11 @@ public abstract class EventDispatchExtensionsTest<TEventArgs> : TestContext
 
 	protected abstract string ElementName { get; }
 
+	protected EventDispatchExtensionsTest(ITestOutputHelper outputHelper)
+	{
+		Services.AddXunitLogger(outputHelper);
+	}
+
 	protected TriggerEventSpy<EventArgs> CreateTriggerSpy(string element, string eventName)
 		=> new(p => RenderComponent<TriggerTester<EventArgs>>(p), element, eventName);
 

tests/bunit.web.tests/EventDispatchExtensions/FocusEventDispatchExtensionsTest.cs

@@ -2,6 +2,10 @@ namespace Bunit;
 
 public class FocusEventDispatchExtensionsTest : EventDispatchExtensionsTest<FocusEventArgs>
 {
+	public FocusEventDispatchExtensionsTest(ITestOutputHelper outputHelper) : base(outputHelper)
+	{
+	}
+
 	protected override string ElementName => "p";
 
 	[Theory(DisplayName = "Focus events are raised correctly through helpers")]

tests/bunit.web.tests/EventDispatchExtensions/GeneralEventDispatchExtensionsTest.cs

@@ -1,7 +1,6 @@
 using AngleSharp;
 using AngleSharp.Dom;
 using Bunit.Rendering;
-using Xunit.Abstractions;
 
 namespace Bunit;
 
@@ -10,9 +9,9 @@ public class GeneralEventDispatchExtensionsTest : EventDispatchExtensionsTest<Ev
 	protected override string ElementName => "p";
 
 	public GeneralEventDispatchExtensionsTest(ITestOutputHelper outputHelper)
+		: base(outputHelper)
 	{
 		TestContext.DefaultWaitTimeout = TimeSpan.FromSeconds(30);
-		Services.AddXunitLogger(outputHelper);
 	}
 
 	[Theory(DisplayName = "General events are raised correctly through helpers")]
@@ -342,8 +341,8 @@ public async Task Test400(int repeatCount)
 	// reliably.
 	[SuppressMessage("Style", "IDE0060:Remove unused parameter", Justification = "Needed to trigger multiple reruns of test.")]
 	[Theory(DisplayName = "TriggerEventAsync avoids race condition with DOM tree updates")]
-    [Repeat(10)]
-    [Trait("Category", "sync")]
+	[Repeat(10)]
+	[Trait("Category", "sync")]
 	public async Task Test400_Sync(int repeatCount)
 	{
 		var cut = RenderComponent<CounterComponentDynamic>();

tests/bunit.web.tests/EventDispatchExtensions/InputEventDispatchExtensionsTest.cs

@@ -11,6 +11,10 @@ public class InputEventDispatchExtensionsTest : EventDispatchExtensionsTest<Chan
 
 	protected override string ElementName => "input";
 
+	public InputEventDispatchExtensionsTest(ITestOutputHelper outputHelper) : base(outputHelper)
+	{
+	}
+
 	[Theory(DisplayName = "Input events are raised correctly through helpers")]
 	[MemberData(nameof(Helpers))]
 	public void CanRaiseEvents(MethodInfo helper)

tests/bunit.web.tests/EventDispatchExtensions/KeyboardEventDispatchExtensionsTest.cs

@@ -2,6 +2,10 @@ namespace Bunit;
 
 public class KeyboardEventDispatchExtensionsTest : EventDispatchExtensionsTest<KeyboardEventArgs>
 {
+	public KeyboardEventDispatchExtensionsTest(ITestOutputHelper outputHelper) : base(outputHelper)
+	{
+	}
+
 	public static IEnumerable<object[]> Helpers { get; }
 		= GetEventHelperMethods(
 			typeof(KeyboardEventDispatchExtensions),

tests/bunit.web.tests/EventDispatchExtensions/MediaEventDispatchExtensionsTest.cs

@@ -2,6 +2,10 @@ namespace Bunit;
 
 public class MediaEventDispatchExtensionsTest : EventDispatchExtensionsTest<EventArgs>
 {
+	public MediaEventDispatchExtensionsTest(ITestOutputHelper outputHelper) : base(outputHelper)
+	{
+	}
+
 	protected override string ElementName => "audio";
 
 	[Theory(DisplayName = "Media events are raised correctly through helpers")]

tests/bunit.web.tests/EventDispatchExtensions/MouseEventDispatchExtensionsTest.cs

@@ -2,6 +2,10 @@ namespace Bunit;
 
 public class MouseEventDispatchExtensionsTest : EventDispatchExtensionsTest<MouseEventArgs>
 {
+	public MouseEventDispatchExtensionsTest(ITestOutputHelper outputHelper) : base(outputHelper)
+	{
+	}
+
 	public static IEnumerable<object[]> Helpers { get; }
 		= GetEventHelperMethods(
 			typeof(MouseEventDispatchExtensions),

tests/bunit.web.tests/EventDispatchExtensions/PointerEventDispatchExtensionsTest.cs

@@ -2,6 +2,10 @@ namespace Bunit;
 
 public class PointerEventDispatchExtensionsTest : EventDispatchExtensionsTest<PointerEventArgs>
 {
+	public PointerEventDispatchExtensionsTest(ITestOutputHelper outputHelper) : base(outputHelper)
+	{
+	}
+
 	protected override string ElementName => "div";
 
 	[Theory(DisplayName = "Pointer events are raised correctly through helpers")]

tests/bunit.web.tests/EventDispatchExtensions/ProgressEventDispatchExtensionsTest.cs

@@ -2,6 +2,10 @@ namespace Bunit;
 
 public class ProgressEventDispatchExtensionsTest : EventDispatchExtensionsTest<ProgressEventArgs>
 {
+	public ProgressEventDispatchExtensionsTest(ITestOutputHelper outputHelper) : base(outputHelper)
+	{
+	}
+
 	protected override string ElementName => "div";
 
 	[Theory(DisplayName = "Progress events are raised correctly through helpers")]

tests/bunit.web.tests/EventDispatchExtensions/TouchEventDispatchExtensionsTest.cs

@@ -2,6 +2,10 @@ namespace Bunit;
 
 public class TouchEventDispatchExtensionsTest : EventDispatchExtensionsTest<TouchEventArgs>
 {
+	public TouchEventDispatchExtensionsTest(ITestOutputHelper outputHelper) : base(outputHelper)
+	{
+	}
+
 	protected override string ElementName => "p";
 
 	[Theory(DisplayName = "Touch events are raised correctly through helpers")]

tests/bunit.web.tests/EventDispatchExtensions/WheelEventDispatchExtensionsTest.cs

@@ -2,6 +2,10 @@ namespace Bunit;
 
 public class WheelEventDispatchExtensionsTest : EventDispatchExtensionsTest<WheelEventArgs>
 {
+	public WheelEventDispatchExtensionsTest(ITestOutputHelper outputHelper) : base(outputHelper)
+	{
+	}
+
 	public static IEnumerable<object[]> Helpers { get; }
 		= GetEventHelperMethods(typeof(MouseEventDispatchExtensions), x => x.Name.Contains("Wheel", StringComparison.OrdinalIgnoreCase));