From 4af8275e9d8a4f3b887b31a2eb4edf52b0358bd1 Mon Sep 17 00:00:00 2001 From: James Newton-King Date: Sat, 25 Jan 2025 19:35:58 +0800 Subject: [PATCH] Attempted fix on flaky counter tests (#59892) --- .../HostingApplicationDiagnosticsTests.cs | 35 +++++++++++-------- .../test/Internal/HostingEventSourceTests.cs | 35 +++++++++++-------- .../Microsoft.AspNetCore.Hosting.Tests.csproj | 1 + .../ConcurrencyLimiterEventSourceTests.cs | 35 ++++++++----------- ...AspNetCore.ConcurrencyLimiter.Tests.csproj | 1 + .../AsyncEnumerableExtensions.cs | 30 ++++------------ .../TestCounterListener.cs | 11 ++++-- 7 files changed, 71 insertions(+), 77 deletions(-) rename src/{Hosting/Hosting/test/Internal => Shared}/AsyncEnumerableExtensions.cs (51%) diff --git a/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs b/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs index c3de0c334a73..08aa85210973 100644 --- a/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs +++ b/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs @@ -40,9 +40,9 @@ public async Task EventCountersAndMetricsValues() using CancellationTokenSource timeoutTokenSource = new CancellationTokenSource(timeout); timeoutTokenSource.Token.Register(() => Logger.LogError("Timeout while waiting for counter value.")); - var totalRequestValues = eventListener.GetCounterValues("total-requests", timeoutTokenSource.Token).GetAsyncEnumerator(); - var currentRequestValues = eventListener.GetCounterValues("current-requests", timeoutTokenSource.Token).GetAsyncEnumerator(); - var failedRequestValues = eventListener.GetCounterValues("failed-requests", timeoutTokenSource.Token).GetAsyncEnumerator(); + var totalRequestValues = eventListener.GetCounterValues("total-requests", timeoutTokenSource.Token); + var currentRequestValues = eventListener.GetCounterValues("current-requests", timeoutTokenSource.Token); + var failedRequestValues = eventListener.GetCounterValues("failed-requests", timeoutTokenSource.Token); eventListener.EnableEvents(hostingEventSource, EventLevel.Informational, EventKeywords.None, new Dictionary @@ -69,18 +69,18 @@ public async Task EventCountersAndMetricsValues() var context1 = hostingApplication1.CreateContext(features1); var context2 = hostingApplication2.CreateContext(features2); - await totalRequestValues.WaitForSumValueAsync(2); - await currentRequestValues.WaitForValueAsync(2); - await failedRequestValues.WaitForValueAsync(0); + await WaitForCounterValue(totalRequestValues, expectedValue: 2, Logger); + await WaitForCounterValue(currentRequestValues, expectedValue: 2, Logger); + await WaitForCounterValue(failedRequestValues, expectedValue: 0, Logger); Logger.LogInformation(nameof(HostingApplication.DisposeContext)); hostingApplication1.DisposeContext(context1, null); hostingApplication2.DisposeContext(context2, null); - await totalRequestValues.WaitForSumValueAsync(2); - await currentRequestValues.WaitForValueAsync(0); - await failedRequestValues.WaitForValueAsync(0); + await WaitForCounterValue(totalRequestValues, expectedValue: 2, Logger); + await WaitForCounterValue(currentRequestValues, expectedValue: 0, Logger); + await WaitForCounterValue(failedRequestValues, expectedValue: 0, Logger); Assert.Collection(activeRequestsCollector1.GetMeasurementSnapshot(), m => Assert.Equal(1, m.Value), @@ -100,9 +100,9 @@ public async Task EventCountersAndMetricsValues() context1 = hostingApplication1.CreateContext(features1); context2 = hostingApplication2.CreateContext(features2); - await totalRequestValues.WaitForSumValueAsync(4); - await currentRequestValues.WaitForValueAsync(2); - await failedRequestValues.WaitForValueAsync(0); + await WaitForCounterValue(totalRequestValues, expectedValue: 4, Logger); + await WaitForCounterValue(currentRequestValues, expectedValue: 2, Logger); + await WaitForCounterValue(failedRequestValues, expectedValue: 0, Logger); context1.HttpContext.Response.StatusCode = StatusCodes.Status500InternalServerError; context2.HttpContext.Response.StatusCode = StatusCodes.Status500InternalServerError; @@ -112,9 +112,9 @@ public async Task EventCountersAndMetricsValues() hostingApplication1.DisposeContext(context1, null); hostingApplication2.DisposeContext(context2, null); - await totalRequestValues.WaitForSumValueAsync(4); - await currentRequestValues.WaitForValueAsync(0); - await failedRequestValues.WaitForValueAsync(2); + await WaitForCounterValue(totalRequestValues, expectedValue: 4, Logger); + await WaitForCounterValue(currentRequestValues, expectedValue: 0, Logger); + await WaitForCounterValue(failedRequestValues, expectedValue: 2, Logger); Assert.Collection(activeRequestsCollector1.GetMeasurementSnapshot(), m => Assert.Equal(1, m.Value), @@ -134,6 +134,11 @@ public async Task EventCountersAndMetricsValues() m => Assert.True(m.Value > 0)); } + private static async Task WaitForCounterValue(CounterValues values, double expectedValue, ILogger logger) + { + await values.Values.WaitForValueAsync(expectedValue, values.CounterName, logger); + } + [Fact] public void EventCountersEnabled() { diff --git a/src/Hosting/Hosting/test/Internal/HostingEventSourceTests.cs b/src/Hosting/Hosting/test/Internal/HostingEventSourceTests.cs index e0ed1e587071..441607fc75be 100644 --- a/src/Hosting/Hosting/test/Internal/HostingEventSourceTests.cs +++ b/src/Hosting/Hosting/test/Internal/HostingEventSourceTests.cs @@ -193,9 +193,9 @@ public async Task VerifyCountersFireWithCorrectValues() using var timeoutTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(30)); timeoutTokenSource.Token.Register(() => Logger.LogError("Timeout while waiting for counter value.")); - var totalRequestValues = eventListener.GetCounterValues("total-requests", timeoutTokenSource.Token).GetAsyncEnumerator(); - var currentRequestValues = eventListener.GetCounterValues("current-requests", timeoutTokenSource.Token).GetAsyncEnumerator(); - var failedRequestValues = eventListener.GetCounterValues("failed-requests", timeoutTokenSource.Token).GetAsyncEnumerator(); + var totalRequestValues = eventListener.GetCounterValues("total-requests", timeoutTokenSource.Token); + var currentRequestValues = eventListener.GetCounterValues("current-requests", timeoutTokenSource.Token); + var failedRequestValues = eventListener.GetCounterValues("failed-requests", timeoutTokenSource.Token); eventListener.EnableEvents(hostingEventSource, EventLevel.Informational, EventKeywords.None, new Dictionary @@ -207,32 +207,37 @@ public async Task VerifyCountersFireWithCorrectValues() Logger.LogInformation(nameof(HostingEventSource.RequestStart)); hostingEventSource.RequestStart("GET", "/"); - await totalRequestValues.WaitForSumValueAsync(1); - await currentRequestValues.WaitForValueAsync(1); - await failedRequestValues.WaitForValueAsync(0); + await WaitForCounterValue(totalRequestValues, expectedValue: 1, Logger); + await WaitForCounterValue(currentRequestValues, expectedValue: 1, Logger); + await WaitForCounterValue(failedRequestValues, expectedValue: 0, Logger); Logger.LogInformation(nameof(HostingEventSource.RequestStop)); hostingEventSource.RequestStop(); - await totalRequestValues.WaitForSumValueAsync(1); - await currentRequestValues.WaitForValueAsync(0); - await failedRequestValues.WaitForValueAsync(0); + await WaitForCounterValue(totalRequestValues, expectedValue: 1, Logger); + await WaitForCounterValue(currentRequestValues, expectedValue: 0, Logger); + await WaitForCounterValue(failedRequestValues, expectedValue: 0, Logger); Logger.LogInformation(nameof(HostingEventSource.RequestStart)); hostingEventSource.RequestStart("POST", "/"); - await totalRequestValues.WaitForSumValueAsync(2); - await currentRequestValues.WaitForValueAsync(1); - await failedRequestValues.WaitForValueAsync(0); + await WaitForCounterValue(totalRequestValues, expectedValue: 2, Logger); + await WaitForCounterValue(currentRequestValues, expectedValue: 1, Logger); + await WaitForCounterValue(failedRequestValues, expectedValue: 0, Logger); Logger.LogInformation(nameof(HostingEventSource.RequestFailed)); hostingEventSource.RequestFailed(); Logger.LogInformation(nameof(HostingEventSource.RequestStop)); hostingEventSource.RequestStop(); - await totalRequestValues.WaitForSumValueAsync(2); - await currentRequestValues.WaitForValueAsync(0); - await failedRequestValues.WaitForValueAsync(1); + await WaitForCounterValue(totalRequestValues, expectedValue: 2, Logger); + await WaitForCounterValue(currentRequestValues, expectedValue: 0, Logger); + await WaitForCounterValue(failedRequestValues, expectedValue: 1, Logger); + } + + private static async Task WaitForCounterValue(CounterValues values, double expectedValue, ILogger logger) + { + await values.Values.WaitForValueAsync(expectedValue, values.CounterName, logger); } private static HostingEventSource GetHostingEventSource() diff --git a/src/Hosting/Hosting/test/Microsoft.AspNetCore.Hosting.Tests.csproj b/src/Hosting/Hosting/test/Microsoft.AspNetCore.Hosting.Tests.csproj index 19c3179c3d0a..d1175fe212a4 100644 --- a/src/Hosting/Hosting/test/Microsoft.AspNetCore.Hosting.Tests.csproj +++ b/src/Hosting/Hosting/test/Microsoft.AspNetCore.Hosting.Tests.csproj @@ -11,6 +11,7 @@ + diff --git a/src/Middleware/ConcurrencyLimiter/test/ConcurrencyLimiterEventSourceTests.cs b/src/Middleware/ConcurrencyLimiter/test/ConcurrencyLimiterEventSourceTests.cs index b556899a79c5..61b5b99b9d87 100644 --- a/src/Middleware/ConcurrencyLimiter/test/ConcurrencyLimiterEventSourceTests.cs +++ b/src/Middleware/ConcurrencyLimiter/test/ConcurrencyLimiterEventSourceTests.cs @@ -5,6 +5,7 @@ using System.Diagnostics.Tracing; using Microsoft.AspNetCore.Internal; using Microsoft.AspNetCore.InternalTesting; +using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.ConcurrencyLimiter.Tests; @@ -55,7 +56,7 @@ public async Task TracksQueueLength() using var timeoutTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(30)); - var lengthValues = eventListener.GetCounterValues("queue-length", timeoutTokenSource.Token).GetAsyncEnumerator(); + var lengthValues = eventListener.GetCounterValues("queue-length", timeoutTokenSource.Token); eventListener.EnableEvents(eventSource, EventLevel.Informational, EventKeywords.None, new Dictionary @@ -66,20 +67,20 @@ public async Task TracksQueueLength() // Act eventSource.RequestRejected(); - Assert.True(await UntilValueMatches(lengthValues, 0)); + await WaitForCounterValue(lengthValues, expectedValue: 0, Logger); using (eventSource.QueueTimer()) { - Assert.True(await UntilValueMatches(lengthValues, 1)); + await WaitForCounterValue(lengthValues, expectedValue: 1, Logger); using (eventSource.QueueTimer()) { - Assert.True(await UntilValueMatches(lengthValues, 2)); + await WaitForCounterValue(lengthValues, expectedValue: 2, Logger); } - Assert.True(await UntilValueMatches(lengthValues, 1)); + await WaitForCounterValue(lengthValues, expectedValue: 1, Logger); } - Assert.True(await UntilValueMatches(lengthValues, 0)); + await WaitForCounterValue(lengthValues, expectedValue: 0, Logger); } [Fact] @@ -96,7 +97,7 @@ public async Task TracksDurationSpentInQueue() using var timeoutTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(5)); - var durationValues = eventListener.GetCounterValues("queue-duration", timeoutTokenSource.Token).GetAsyncEnumerator(); + var durationValues = eventListener.GetCounterValues("queue-duration", timeoutTokenSource.Token); eventListener.EnableEvents(eventSource, EventLevel.Informational, EventKeywords.None, new Dictionary @@ -105,17 +106,17 @@ public async Task TracksDurationSpentInQueue() }); // Act - Assert.True(await UntilValueMatches(durationValues, 0)); + await WaitForCounterValue(durationValues, expectedValue: 0, Logger); using (eventSource.QueueTimer()) { - Assert.True(await UntilValueMatches(durationValues, 0)); + await WaitForCounterValue(durationValues, expectedValue: 0, Logger); } // check that something (anything!) has been written - while (await durationValues.MoveNextAsync()) + while (await durationValues.Values.MoveNextAsync()) { - if (durationValues.Current > 0) + if (durationValues.Values.Current > 0) { return; } @@ -124,17 +125,9 @@ public async Task TracksDurationSpentInQueue() throw new TimeoutException(); } - private async Task UntilValueMatches(IAsyncEnumerator enumerator, int value) + private static async Task WaitForCounterValue(CounterValues values, double expectedValue, ILogger logger) { - while (await enumerator.MoveNextAsync()) - { - if (enumerator.Current == value) - { - return true; - } - } - - return false; + await values.Values.WaitForValueAsync(expectedValue, values.CounterName, logger); } private static ConcurrencyLimiterEventSource GetConcurrencyLimiterEventSource() diff --git a/src/Middleware/ConcurrencyLimiter/test/Microsoft.AspNetCore.ConcurrencyLimiter.Tests.csproj b/src/Middleware/ConcurrencyLimiter/test/Microsoft.AspNetCore.ConcurrencyLimiter.Tests.csproj index 5bb19e39bebf..ad2734d58177 100644 --- a/src/Middleware/ConcurrencyLimiter/test/Microsoft.AspNetCore.ConcurrencyLimiter.Tests.csproj +++ b/src/Middleware/ConcurrencyLimiter/test/Microsoft.AspNetCore.ConcurrencyLimiter.Tests.csproj @@ -7,6 +7,7 @@ + diff --git a/src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs b/src/Shared/AsyncEnumerableExtensions.cs similarity index 51% rename from src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs rename to src/Shared/AsyncEnumerableExtensions.cs index 2c520cdac00b..353440b39cb6 100644 --- a/src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs +++ b/src/Shared/AsyncEnumerableExtensions.cs @@ -2,12 +2,13 @@ // The .NET Foundation licenses this file to you under the MIT license. using System.Numerics; +using Microsoft.Extensions.Logging; -namespace System.Collections.Generic; +namespace Microsoft.AspNetCore.InternalTesting; internal static class AsyncEnumerableExtensions { - public static async Task WaitForValueAsync(this IAsyncEnumerator values, T expectedValue) where T : INumber + public static async Task WaitForValueAsync(this IAsyncEnumerator values, T expectedValue, string operationName, ILogger logger) where T : INumber { T value = T.Zero; try @@ -17,37 +18,18 @@ public static async Task WaitForValueAsync(this IAsyncEnumerator values, T value = values.Current; if (value == expectedValue) { + logger.LogDebug("Operation {OperationName} completed with value {Value}.", operationName, value); return; } - } - - throw new InvalidOperationException("Data ended without match."); - } - catch (Exception ex) - { - throw new InvalidOperationException($"Results ended with final value of {value}. Expected value of {expectedValue}.", ex); - } - } - public static async Task WaitForSumValueAsync(this IAsyncEnumerator values, T expectedValue) where T: INumber - { - T value = T.Zero; - try - { - while (await values.MoveNextAsync()) - { - value += values.Current; - if (value == expectedValue) - { - return; - } + logger.LogDebug("Operation {OperationName} expected {ExpectedValue} but got {Value}.", operationName, expectedValue, value); } throw new InvalidOperationException("Data ended without match."); } catch (Exception ex) { - throw new InvalidOperationException($"Results ended with final sum value of {value}. Expected sum value of {expectedValue}.", ex); + throw new InvalidOperationException($"Results ended with final value of {value}. Expected value of {expectedValue}.", ex); } } } diff --git a/src/Shared/EventSource.Testing/TestCounterListener.cs b/src/Shared/EventSource.Testing/TestCounterListener.cs index 6dbcab1fbb56..34de12abae66 100644 --- a/src/Shared/EventSource.Testing/TestCounterListener.cs +++ b/src/Shared/EventSource.Testing/TestCounterListener.cs @@ -9,6 +9,12 @@ namespace Microsoft.AspNetCore.Internal; +internal sealed class CounterValues(string counterName, IAsyncEnumerator values) +{ + public string CounterName { get; } = counterName; + public IAsyncEnumerator Values { get; } = values; +} + internal sealed class TestCounterListener : EventListener { private readonly Dictionary> _counters = new Dictionary>(); @@ -30,9 +36,10 @@ public TestCounterListener(ILoggerFactory loggerFactory, string eventSourceName, _eventSourceName = eventSourceName; } - public IAsyncEnumerable GetCounterValues(string counterName, CancellationToken cancellationToken = default) + public CounterValues GetCounterValues(string counterName, CancellationToken cancellationToken = default) { - return _counters[counterName].Reader.ReadAllAsync(cancellationToken); + var values = _counters[counterName].Reader.ReadAllAsync(cancellationToken).GetAsyncEnumerator(cancellationToken); + return new CounterValues(counterName, values); } protected override void OnEventWritten(EventWrittenEventArgs eventData)