From 3b05a0a7793cdc81645e91cb1f3545dd518e43d3 Mon Sep 17 00:00:00 2001 From: Miha Zupan Date: Mon, 12 Aug 2024 22:36:33 +0200 Subject: [PATCH] Workaround EventSource counters race condition in networking tests --- .../tests/FunctionalTests/TelemetryTest.cs | 59 +++++++++++++++++-- .../tests/FunctionalTests/TelemetryTest.cs | 27 ++++++++- 2 files changed, 80 insertions(+), 6 deletions(-) diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs index e5e1889b051d7..6aaf96d07e1c2 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs @@ -81,6 +81,8 @@ await RemoteExecutor.Invoke(static async (useVersionString, testMethod) => using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); listener.AddActivityTracking(); + await PrepareEventCountersAsync(listener); + bool buffersResponse = false; var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); Uri expectedUri = null; @@ -222,6 +224,8 @@ await RemoteExecutor.Invoke(static async (useVersionString, testMethod) => using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); listener.AddActivityTracking(); + await PrepareEventCountersAsync(listener); + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); Uri expectedUri = null; await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => @@ -335,6 +339,8 @@ await RemoteExecutor.Invoke(static async (useVersionString, testMethod) => using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); listener.AddActivityTracking(); + await PrepareEventCountersAsync(listener); + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); Uri expectedUri = null; await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => @@ -436,6 +442,8 @@ await RemoteExecutor.Invoke(static async (useVersionString, uriTail, expectedPat using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); listener.AddActivityTracking(); + await PrepareEventCountersAsync(listener); + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); Uri expectedUri = null; await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => @@ -540,7 +548,7 @@ private static void ValidateStartFailedStopEvents(ConcurrentQueue<(EventWrittenE } } - // The validation assumes that the connection id's are in range 0..(connectionCount-1) + // The validation assumes that the connection id's are in range 1..connectionCount protected static void ValidateConnectionEstablishedClosed(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events, Version version, Uri uri, int connectionCount = 1) { EventWrittenEventArgs[] connectionsEstablished = events.Select(e => e.Event).Where(e => e.EventName == "ConnectionEstablished").ToArray(); @@ -564,7 +572,7 @@ protected static void ValidateConnectionEstablishedClosed(ConcurrentQueue<(Event ip.Equals(IPAddress.Loopback) || ip.Equals(IPAddress.IPv6Loopback)); } - Assert.True(connectionIds.SetEquals(Enumerable.Range(0, connectionCount).Select(i => (long)i)), "ConnectionEstablished has logged an unexpected connectionId."); + Assert.True(connectionIds.SetEquals(Enumerable.Range(1, connectionCount).Select(i => (long)i)), "ConnectionEstablished has logged an unexpected connectionId."); EventWrittenEventArgs[] connectionsClosed = events.Select(e => e.Event).Where(e => e.EventName == "ConnectionClosed").ToArray(); Assert.Equal(connectionCount, connectionsClosed.Length); @@ -580,7 +588,7 @@ protected static void ValidateConnectionEstablishedClosed(ConcurrentQueue<(Event Assert.Empty(connectionIds); } - private static void ValidateRequestResponseStartStopEvents(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events, int? requestContentLength, int? responseContentLength, int count, long connectionId = 0) + private static void ValidateRequestResponseStartStopEvents(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events, int? requestContentLength, int? responseContentLength, int count) { (EventWrittenEventArgs Event, Guid ActivityId)[] requestHeadersStarts = events.Where(e => e.Event.EventName == "RequestHeadersStart").ToArray(); Assert.Equal(count, requestHeadersStarts.Length); @@ -589,7 +597,8 @@ private static void ValidateRequestResponseStartStopEvents(ConcurrentQueue<(Even EventWrittenEventArgs e = r.Event; Assert.Equal(1, e.Payload.Count); Assert.Equal("connectionId", e.PayloadNames.Single()); - Assert.Equal(connectionId, (long)e.Payload[0]); + // 1 instead of 0 to account for the request we made in PrepareEventCountersAsync. + Assert.Equal(1, (long)e.Payload[0]); }); (EventWrittenEventArgs Event, Guid ActivityId)[] requestHeadersStops = events.Where(e => e.Event.EventName == "RequestHeadersStop").ToArray(); @@ -652,6 +661,9 @@ private static void ValidateSameActivityIds((EventWrittenEventArgs Event, Guid A private static void ValidateEventCounters(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events, int requestCount, bool shouldHaveFailures, int versionMajor, bool requestLeftQueue = false) { + // Account for the request we made in PrepareEventCountersAsync. + requestCount++; + Dictionary eventCounters = events .Select(e => e.Event) .Where(e => e.EventName == "EventCounters") @@ -758,6 +770,8 @@ await RemoteExecutor.Invoke(static async (useVersionString) => using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); listener.AddActivityTracking(); + await PrepareEventCountersAsync(listener); + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); Uri expectedUri = null; await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => @@ -871,6 +885,9 @@ await RemoteExecutor.Invoke(static async (string useVersionString) => Version version = Version.Parse(useVersionString); using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); + + await PrepareEventCountersAsync(listener); + listener.AddActivityTracking(); var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); Uri expectedUri = null; @@ -932,6 +949,9 @@ await RemoteExecutor.Invoke(static async (useVersionString, uriTail, expectedUri using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); listener.AddActivityTracking(); + + await PrepareEventCountersAsync(listener); + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); Uri expectedUri = null; @@ -986,6 +1006,9 @@ public void EventSource_Proxy_LogsIPAddress(bool useSsl) { using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); listener.AddActivityTracking(); + + await PrepareEventCountersAsync(listener); + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => @@ -1040,6 +1063,30 @@ static bool IsRequestsStartedEventCounter(EventWrittenEventArgs e) return (string)dictionary["Name"] == "requests-started"; } } + + internal static async Task PrepareEventCountersAsync(TestEventListener listener) + { + // There is a race condition in EventSource where counters using IncrementingPollingCounter + // will drop increments that happened before the background timer thread first runs. + // See https://github.com/dotnet/runtime/issues/106268#issuecomment-2284626183. + // To workaround this issue, we ensure that the EventCounters timer is running before + // executing any of the interesting logic under test. + + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); + + await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => + { + await LoopbackServer.CreateClientAndServerAsync( + async uri => + { + using var client = new HttpClient(); + await client.GetStringAsync(uri); + }, + server => server.HandleRequestAsync()); + + await WaitForEventCountersAsync(events); + }); + } } public sealed class TelemetryTest_Http11 : TelemetryTest @@ -1057,6 +1104,8 @@ await RemoteExecutor.Invoke(async () => using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); listener.AddActivityTracking(); + await PrepareEventCountersAsync(listener); + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); Uri expectedUri = null; await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => @@ -1107,7 +1156,7 @@ async Task HandleConnectionAsync(GenericLoopbackConnection connection) EventWrittenEventArgs[] requestHeadersStart = events.Select(e => e.Event).Where(e => e.EventName == "RequestHeadersStart").ToArray(); Assert.Equal(NumParallelRequests, requestHeadersStart.Length); - HashSet connectionIds = new(Enumerable.Range(0, NumParallelRequests).Select(i => (long)i)); + HashSet connectionIds = new(Enumerable.Range(1, NumParallelRequests).Select(i => (long)i)); foreach (EventWrittenEventArgs e in requestHeadersStart) { long connectionId = (long)e.Payload.Single(); diff --git a/src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs index 393c62140d55a..667bc13ad3838 100644 --- a/src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs @@ -126,6 +126,8 @@ await RemoteExecutor.Invoke(async () => using var listener = new TestEventListener("System.Net.Security", EventLevel.Verbose, eventCounterInterval: 0.1d); listener.AddActivityTracking(); + await PrepareEventCountersAsync(listener); + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); await listener.RunWithCallbackAsync(e => { @@ -184,6 +186,7 @@ await listener.RunWithCallbackAsync(e => [OuterLoop] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [SkipOnPlatform(TestPlatforms.iOS | TestPlatforms.tvOS, "X509 certificate store is not supported on iOS or tvOS.")] // Match SslStream_StreamToStream_Authentication_Success public static async Task EventSource_UnsuccessfulHandshake_LogsStartFailureStop() { await RemoteExecutor.Invoke(async () => @@ -191,6 +194,8 @@ await RemoteExecutor.Invoke(async () => using var listener = new TestEventListener("System.Net.Security", EventLevel.Verbose, eventCounterInterval: 0.1d); listener.AddActivityTracking(); + await PrepareEventCountersAsync(listener); + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); await listener.RunWithCallbackAsync(e => { @@ -279,7 +284,8 @@ private static void VerifyEventCounters(ConcurrentQueue<(EventWrittenEventArgs E .ToDictionary(p => p.Key, p => p.ToArray()); Assert.True(eventCounters.TryGetValue("total-tls-handshakes", out double[] totalHandshakes)); - Assert.Equal(2, totalHandshakes[^1]); + // 4 instead of 2 to account for the handshake we made in PrepareEventCountersAsync. + Assert.Equal(4, totalHandshakes[^1]); Assert.True(eventCounters.TryGetValue("tls-handshake-rate", out double[] handshakeRate)); Assert.Contains(handshakeRate, r => r > 0); @@ -352,5 +358,24 @@ static bool IsTlsHandshakeRateEventCounter(EventWrittenEventArgs e) return (string)dictionary["Name"] == "tls-handshake-rate"; } } + + private static async Task PrepareEventCountersAsync(TestEventListener listener) + { + // There is a race condition in EventSource where counters using IncrementingPollingCounter + // will drop increments that happened before the background timer thread first runs. + // See https://github.com/dotnet/runtime/issues/106268#issuecomment-2284626183. + // To workaround this issue, we ensure that the EventCounters timer is running before + // executing any of the interesting logic under test. + + var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>(); + + await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () => + { + var test = new SslStreamStreamToStreamTest_Async(); + await test.SslStream_StreamToStream_Authentication_Success(); + + await WaitForEventCountersAsync(events); + }); + } } }