Investigate flaky WaitFor* timeouts on CI

src/bunit/Extensions/WaitForHelpers/WaitForElementsHelper.cs

@@ -16,16 +16,27 @@ public WaitForElementsHelper(IRenderedComponent<TComponent> renderedComponent, s
 	}
 }
 
+// Primary constructor, so matchElementCount is captured before the base constructor starts the timeout timer,
+// which reads TimeoutErrorMessage and may fire before a regular constructor body would have assigned the field.
 /// <summary>
 /// Represents an async wait helper, that will wait for a specified time for element(s) of type <typeparamref name="TElement"/> to become available in the DOM.
 /// </summary>
-internal class WaitForElementsHelper<TComponent, TElement> : WaitForHelper<IReadOnlyList<TElement>, TComponent>
+internal class WaitForElementsHelper<TComponent, TElement>(IRenderedComponent<TComponent> renderedComponent, string cssSelector, int? matchElementCount, TimeSpan? timeout = null)
+	: WaitForHelper<IReadOnlyList<TElement>, TComponent>(renderedComponent, () =>
+	{
+		var elements = renderedComponent.FindAll<TComponent, TElement>(cssSelector);
+
+		var checkPassed = matchElementCount is null
+			? elements.Count > 0
+			: elements.Count == matchElementCount;
+
+		return (checkPassed, elements);
+	}, timeout)
 	where TComponent : IComponent
 	where TElement : class, IElement
 {
 	internal const string TimeoutBeforeFoundMessage = "The CSS selector did not result in any matching element(s) before the timeout period passed.";
 	internal static readonly CompositeFormat TimeoutBeforeFoundWithCountMessage = CompositeFormat.Parse("The CSS selector did not result in exactly {0} matching element(s) before the timeout period passed.");
-	private readonly int? matchElementCount;
 
 	/// <inheritdoc/>
 	protected override string? TimeoutErrorMessage => matchElementCount is null
@@ -34,19 +45,4 @@ internal class WaitForElementsHelper<TComponent, TElement> : WaitForHelper<IRead
 
 	/// <inheritdoc/>
 	protected override bool StopWaitingOnCheckException => true;
-
-	public WaitForElementsHelper(IRenderedComponent<TComponent> renderedComponent, string cssSelector, int? matchElementCount, TimeSpan? timeout = null)
-		: base(renderedComponent, () =>
-		{
-			var elements = renderedComponent.FindAll<TComponent, TElement>(cssSelector);
-
-			var checkPassed = matchElementCount is null
-				? elements.Count > 0
-				: elements.Count == matchElementCount;
-
-			return (checkPassed, elements);
-		}, timeout)
-	{
-		this.matchElementCount = matchElementCount;
-	}
 }

src/bunit/Extensions/WaitForHelpers/WaitForHelper.cs

@@ -16,7 +16,8 @@ internal abstract class WaitForHelper<T, TComponent> : IDisposable
 	private readonly IRenderedComponent<TComponent> renderedComponent;
 	private readonly ILogger<WaitForHelper<T, TComponent>> logger;
 	private readonly BunitRenderer renderer;
-	private readonly Timer? timer;
+	private readonly TimeSpan runtimeTimeout;
+	private Timer? timer;
 	private bool isDisposed;
 	private bool isChecking;
 	private bool isDirty;
@@ -82,37 +83,14 @@ protected WaitForHelper(
 			.Renderer;
 		checkPassedCompletionSource = new TaskCompletionSource<T>(TaskCreationOptions.RunContinuationsAsynchronously);
 
-		// Create the wait task and run the initial check
-		// and subscribe to the OnAfterRender event.
-		// This must happen before the timer is started,
-		// as the check happens inside the renderers synchronization context,
-		// and that may be blocked longer than the timeout on overloaded systems,
-		// resulting in the timer completing before a single check has
-		// has a chance to complete.
+		runtimeTimeout = GetRuntimeTimeout(timeout);
+
+		// Create the wait task, run the initial check and subscribe to the OnAfterRender event.
+		// The timer is only started after the initial check ran on the renderers synchronization context,
+		// as that may be blocked longer than the timeout on overloaded systems,
+		// resulting in the timer completing before a single check has had a chance to run.
 		WaitTask = CreateWaitTask();
 		CheckAndInitializeWaiting();
-
-		// If the initial check did not complete successfully,
-		// start the timer and recheck after every render until the timer expires.
-		if (!WaitTask.IsCompleted)
-		{
-			timer = new Timer(
-				static (state) =>
-				{
-					var @this = (WaitForHelper<T, TComponent>)state!;
-					@this.logger.LogWaiterTimedOut(@this.renderedComponent.ComponentId);
-					@this.checkPassedCompletionSource.TrySetException(
-						new WaitForFailedException(
-							@this.TimeoutErrorMessage ?? string.Empty,
-							@this.checkCount,
-							@this.renderedComponent.RenderCount,
-							@this.renderer.RenderCount,
-							@this.capturedException));
-				},
-				this,
-				GetRuntimeTimeout(timeout),
-				Timeout.InfiniteTimeSpan);
-		}
 	}
 
 	/// <summary>
@@ -138,8 +116,12 @@ protected virtual void Dispose(bool disposing)
 		if (isDisposed || !disposing)
 			return;
 
-		isDisposed = true;
-		timer?.Dispose();
+		lock (checkPassedCompletionSource)
+		{
+			isDisposed = true;
+			timer?.Dispose();
+		}
+
 		checkPassedCompletionSource.TrySetCanceled();
 		renderedComponent.OnAfterRender -= OnAfterRender;
 		logger.LogWaiterDisposed(renderedComponent.ComponentId);
@@ -159,12 +141,50 @@ private void CheckAndInitializeWaiting()
 			{
 				// Before subscribing to renderedFragment.OnAfterRender,
 				// we need to make sure that the desired state has not already been reached.
-				OnAfterRender(this, EventArgs.Empty);
-				SubscribeToOnAfterRender();
+				// The returned task is discarded, so failures, e.g. an invalid timeout, must be forwarded to the WaitTask,
+				// otherwise the waiter would hang without a timer.
+				try
+				{
+					OnAfterRender(this, EventArgs.Empty);
+					SubscribeToOnAfterRender();
+					StartTimer();
+				}
+				catch (Exception ex)
+				{
+					checkPassedCompletionSource.TrySetException(ex);
+					Dispose();
+				}
 			});
 		}
 	}
 
+	private void StartTimer()
+	{
+		lock (checkPassedCompletionSource)
+		{
+			if (isDisposed || WaitTask.IsCompleted)
+				return;
+
+			var started = Stopwatch.StartNew();
+			timer = new Timer(
+				static (state) =>
+				{
+					var (@this, started) = ((WaitForHelper<T, TComponent>, Stopwatch))state!;
+					@this.logger.LogWaiterTimedOut(@this.renderedComponent.ComponentId, @this.runtimeTimeout.TotalMilliseconds, started.ElapsedMilliseconds, ThreadPool.ThreadCount, ThreadPool.PendingWorkItemCount);
+					@this.checkPassedCompletionSource.TrySetException(
+						new WaitForFailedException(
+							@this.TimeoutErrorMessage ?? string.Empty,
+							@this.checkCount,
+							@this.renderedComponent.RenderCount,
+							@this.renderer.RenderCount,
+							@this.capturedException));
+				},
+				(this, started),
+				runtimeTimeout,
+				Timeout.InfiniteTimeSpan);
+		}
+	}
+
 	private Task<T> CreateWaitTask()
 	{
 		// Two to failure conditions, that the renderer captures an unhandled

src/bunit/Extensions/WaitForHelpers/WaitForHelperLoggerExtensions.cs

@@ -37,8 +37,8 @@ internal static partial class WaitForHelperLoggerExtensions
 		EventId = 10,
 		EventName = "WaiterTimedOut",
 		Level = LogLevel.Debug,
-		Message = "The waiter for component {ComponentId} timed out.")]
-	internal static partial void LogWaiterTimedOut(this ILogger logger, int componentId);
+		Message = "The waiter for component {ComponentId} timed out. Configured: {ConfiguredMs}ms, actual: {ElapsedMs}ms, pool threads: {PoolThreads}, pending pool items: {PendingItems}.")]
+	internal static partial void LogWaiterTimedOut(this ILogger logger, int componentId, double configuredMs, long elapsedMs, int poolThreads, long pendingItems);
 
 	[LoggerMessage(
 		EventId = 20,

tests/bunit.tests/Assembly.cs

@@ -1 +1,17 @@
+using System.Runtime.CompilerServices;
+
 [assembly: System.Diagnostics.CodeAnalysis.ExcludeFromCodeCoverage]
+
+namespace Bunit;
+
+internal static class ThreadPoolSetup
+{
+	// Many tests block a pool thread synchronously (WaitFor*, Click) while xunit runs 2x processor count in parallel,
+	// so the default pool floor starves the continuations those tests wait on, causing sporadic WaitFor* timeouts on CI.
+	[ModuleInitializer]
+	internal static void RaiseMinThreads()
+	{
+		ThreadPool.GetMinThreads(out var workers, out var io);
+		ThreadPool.SetMinThreads(Math.Max(workers, Environment.ProcessorCount * 4), io);
+	}
+}

tests/bunit.tests/Extensions/WaitForHelpers/RenderedComponentWaitForHelperExtensions.cs

@@ -240,6 +240,45 @@ await cut.WaitForAssertionAsync(async () =>
 		expected.Message.ShouldStartWith(WaitForAssertionHelper<Simple1>.TimeoutMessage);
 	}
 
+	[Fact(DisplayName = "WaitForElementAsync runs the initial check before the timeout starts when the dispatcher is busy")]
+	public async Task Test500()
+	{
+		var cut = Render<Simple1>();
+		var cancellationToken = Xunit.TestContext.Current.CancellationToken;
+		using var dispatcherEntered = new ManualResetEventSlim();
+		using var releaseDispatcher = new ManualResetEventSlim();
+		var blocker = Task.Run(() => cut.InvokeAsync(() =>
+		{
+			dispatcherEntered.Set();
+			releaseDispatcher.Wait();
+		}), cancellationToken);
+
+		Task<IElement> waitTask;
+		try
+		{
+			dispatcherEntered.Wait(cancellationToken);
+			waitTask = cut.WaitForElementAsync("#notHere", TimeSpan.FromMilliseconds(5));
+			await Task.Delay(50, cancellationToken);
+		}
+		finally
+		{
+			releaseDispatcher.Set();
+			await blocker;
+		}
+
+		var expected = await Should.ThrowAsync<WaitForFailedException>(waitTask);
+		expected.InnerException.ShouldBeOfType<ElementNotFoundException>();
+	}
+
+	[Fact(DisplayName = "WaitForStateAsync throws instead of hanging when the timeout is invalid")]
+	public async Task Test501()
+	{
+		var cut = Render<Simple1>();
+
+		await Should.ThrowAsync<ArgumentOutOfRangeException>(
+			cut.WaitForStateAsync(() => false, TimeSpan.FromMilliseconds(-2)).WaitAsync(TimeSpan.FromSeconds(5), Xunit.TestContext.Current.CancellationToken));
+	}
+
 	private sealed class ThrowsAfterAsyncOperation : ComponentBase
 	{
 		protected override async Task OnInitializedAsync()