Skip to content

Commit 6a69493

Browse files
MihaZupanMihaZupan
authored
Workaround EventSource counters race condition in networking tests (#106294)
1 parent c788546 commit 6a69493

File tree

2 files changed

+80
-6
lines changed

2 files changed

+80
-6
lines changed

‎src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs‎

Lines changed: 54 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -81,6 +81,8 @@ await RemoteExecutor.Invoke(static async (useVersionString, testMethod) =>
8181
using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d);
8282
listener.AddActivityTracking();
8383

84+
await PrepareEventCountersAsync(listener);
85+
8486
bool buffersResponse = false;
8587
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
8688
Uri expectedUri = null;
@@ -222,6 +224,8 @@ await RemoteExecutor.Invoke(static async (useVersionString, testMethod) =>
222224
using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d);
223225
listener.AddActivityTracking();
224226

227+
await PrepareEventCountersAsync(listener);
228+
225229
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
226230
Uri expectedUri = null;
227231
await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () =>
@@ -335,6 +339,8 @@ await RemoteExecutor.Invoke(static async (useVersionString, testMethod) =>
335339
using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d);
336340
listener.AddActivityTracking();
337341

342+
await PrepareEventCountersAsync(listener);
343+
338344
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
339345
Uri expectedUri = null;
340346
await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () =>
@@ -436,6 +442,8 @@ await RemoteExecutor.Invoke(static async (useVersionString, uriTail, expectedPat
436442
using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d);
437443
listener.AddActivityTracking();
438444

445+
await PrepareEventCountersAsync(listener);
446+
439447
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
440448
Uri expectedUri = null;
441449
await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () =>
@@ -540,7 +548,7 @@ private static void ValidateStartFailedStopEvents(ConcurrentQueue<(EventWrittenE
540548
}
541549
}
542550

543-
// The validation assumes that the connection id's are in range 0..(connectionCount-1)
551+
// The validation assumes that the connection id's are in range 1..connectionCount
544552
protected static void ValidateConnectionEstablishedClosed(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events, Version version, Uri uri, int connectionCount = 1)
545553
{
546554
EventWrittenEventArgs[] connectionsEstablished = events.Select(e => e.Event).Where(e => e.EventName == "ConnectionEstablished").ToArray();
@@ -564,7 +572,7 @@ protected static void ValidateConnectionEstablishedClosed(ConcurrentQueue<(Event
564572
ip.Equals(IPAddress.Loopback) ||
565573
ip.Equals(IPAddress.IPv6Loopback));
566574
}
567-
Assert.True(connectionIds.SetEquals(Enumerable.Range(0, connectionCount).Select(i => (long)i)), "ConnectionEstablished has logged an unexpected connectionId.");
575+
Assert.True(connectionIds.SetEquals(Enumerable.Range(1, connectionCount).Select(i => (long)i)), "ConnectionEstablished has logged an unexpected connectionId.");
568576

569577
EventWrittenEventArgs[] connectionsClosed = events.Select(e => e.Event).Where(e => e.EventName == "ConnectionClosed").ToArray();
570578
Assert.Equal(connectionCount, connectionsClosed.Length);
@@ -580,7 +588,7 @@ protected static void ValidateConnectionEstablishedClosed(ConcurrentQueue<(Event
580588
Assert.Empty(connectionIds);
581589
}
582590

583-
private static void ValidateRequestResponseStartStopEvents(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events, int? requestContentLength, int? responseContentLength, int count, long connectionId = 0)
591+
private static void ValidateRequestResponseStartStopEvents(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events, int? requestContentLength, int? responseContentLength, int count)
584592
{
585593
(EventWrittenEventArgs Event, Guid ActivityId)[] requestHeadersStarts = events.Where(e => e.Event.EventName == "RequestHeadersStart").ToArray();
586594
Assert.Equal(count, requestHeadersStarts.Length);
@@ -589,7 +597,8 @@ private static void ValidateRequestResponseStartStopEvents(ConcurrentQueue<(Even
589597
EventWrittenEventArgs e = r.Event;
590598
Assert.Equal(1, e.Payload.Count);
591599
Assert.Equal("connectionId", e.PayloadNames.Single());
592-
Assert.Equal(connectionId, (long)e.Payload[0]);
600+
// 1 instead of 0 to account for the request we made in PrepareEventCountersAsync.
601+
Assert.Equal(1, (long)e.Payload[0]);
593602
});
594603

595604
(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
652661

653662
private static void ValidateEventCounters(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events, int requestCount, bool shouldHaveFailures, int versionMajor, bool requestLeftQueue = false)
654663
{
664+
// Account for the request we made in PrepareEventCountersAsync.
665+
requestCount++;
666+
655667
Dictionary<string, double[]> eventCounters = events
656668
.Select(e => e.Event)
657669
.Where(e => e.EventName == "EventCounters")
@@ -758,6 +770,8 @@ await RemoteExecutor.Invoke(static async (useVersionString) =>
758770
using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d);
759771
listener.AddActivityTracking();
760772

773+
await PrepareEventCountersAsync(listener);
774+
761775
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
762776
Uri expectedUri = null;
763777
await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () =>
@@ -871,6 +885,9 @@ await RemoteExecutor.Invoke(static async (string useVersionString) =>
871885
Version version = Version.Parse(useVersionString);
872886

873887
using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d);
888+
889+
await PrepareEventCountersAsync(listener);
890+
874891
listener.AddActivityTracking();
875892
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
876893
Uri expectedUri = null;
@@ -932,6 +949,9 @@ await RemoteExecutor.Invoke(static async (useVersionString, uriTail, expectedUri
932949

933950
using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d);
934951
listener.AddActivityTracking();
952+
953+
await PrepareEventCountersAsync(listener);
954+
935955
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
936956
Uri expectedUri = null;
937957

@@ -986,6 +1006,9 @@ public void EventSource_Proxy_LogsIPAddress(bool useSsl)
9861006
{
9871007
using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d);
9881008
listener.AddActivityTracking();
1009+
1010+
await PrepareEventCountersAsync(listener);
1011+
9891012
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
9901013

9911014
await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () =>
@@ -1040,6 +1063,30 @@ static bool IsRequestsStartedEventCounter(EventWrittenEventArgs e)
10401063
return (string)dictionary["Name"] == "requests-started";
10411064
}
10421065
}
1066+
1067+
internal static async Task PrepareEventCountersAsync(TestEventListener listener)
1068+
{
1069+
// There is a race condition in EventSource where counters using IncrementingPollingCounter
1070+
// will drop increments that happened before the background timer thread first runs.
1071+
// See https://github.com/dotnet/runtime/issues/106268#issuecomment-2284626183.
1072+
// To workaround this issue, we ensure that the EventCounters timer is running before
1073+
// executing any of the interesting logic under test.
1074+
1075+
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
1076+
1077+
await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () =>
1078+
{
1079+
await LoopbackServer.CreateClientAndServerAsync(
1080+
async uri =>
1081+
{
1082+
using var client = new HttpClient();
1083+
await client.GetStringAsync(uri);
1084+
},
1085+
server => server.HandleRequestAsync());
1086+
1087+
await WaitForEventCountersAsync(events);
1088+
});
1089+
}
10431090
}
10441091

10451092
public sealed class TelemetryTest_Http11 : TelemetryTest
@@ -1057,6 +1104,8 @@ await RemoteExecutor.Invoke(async () =>
10571104
using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d);
10581105
listener.AddActivityTracking();
10591106

1107+
await PrepareEventCountersAsync(listener);
1108+
10601109
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
10611110
Uri expectedUri = null;
10621111
await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () =>
@@ -1107,7 +1156,7 @@ async Task HandleConnectionAsync(GenericLoopbackConnection connection)
11071156

11081157
EventWrittenEventArgs[] requestHeadersStart = events.Select(e => e.Event).Where(e => e.EventName == "RequestHeadersStart").ToArray();
11091158
Assert.Equal(NumParallelRequests, requestHeadersStart.Length);
1110-
HashSet<long> connectionIds = new(Enumerable.Range(0, NumParallelRequests).Select(i => (long)i));
1159+
HashSet<long> connectionIds = new(Enumerable.Range(1, NumParallelRequests).Select(i => (long)i));
11111160
foreach (EventWrittenEventArgs e in requestHeadersStart)
11121161
{
11131162
long connectionId = (long)e.Payload.Single();

‎src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs‎

Lines changed: 26 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -126,6 +126,8 @@ await RemoteExecutor.Invoke(async () =>
126126
using var listener = new TestEventListener("System.Net.Security", EventLevel.Verbose, eventCounterInterval: 0.1d);
127127
listener.AddActivityTracking();
128128

129+
await PrepareEventCountersAsync(listener);
130+
129131
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
130132
await listener.RunWithCallbackAsync(e =>
131133
{
@@ -184,13 +186,16 @@ await listener.RunWithCallbackAsync(e =>
184186

185187
[OuterLoop]
186188
[ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))]
189+
[SkipOnPlatform(TestPlatforms.iOS | TestPlatforms.tvOS, "X509 certificate store is not supported on iOS or tvOS.")] // Match SslStream_StreamToStream_Authentication_Success
187190
public static async Task EventSource_UnsuccessfulHandshake_LogsStartFailureStop()
188191
{
189192
await RemoteExecutor.Invoke(async () =>
190193
{
191194
using var listener = new TestEventListener("System.Net.Security", EventLevel.Verbose, eventCounterInterval: 0.1d);
192195
listener.AddActivityTracking();
193196

197+
await PrepareEventCountersAsync(listener);
198+
194199
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
195200
await listener.RunWithCallbackAsync(e =>
196201
{
@@ -279,7 +284,8 @@ private static void VerifyEventCounters(ConcurrentQueue<(EventWrittenEventArgs E
279284
.ToDictionary(p => p.Key, p => p.ToArray());
280285

281286
Assert.True(eventCounters.TryGetValue("total-tls-handshakes", out double[] totalHandshakes));
282-
Assert.Equal(2, totalHandshakes[^1]);
287+
// 4 instead of 2 to account for the handshake we made in PrepareEventCountersAsync.
288+
Assert.Equal(4, totalHandshakes[^1]);
283289

284290
Assert.True(eventCounters.TryGetValue("tls-handshake-rate", out double[] handshakeRate));
285291
Assert.Contains(handshakeRate, r => r > 0);
@@ -352,5 +358,24 @@ static bool IsTlsHandshakeRateEventCounter(EventWrittenEventArgs e)
352358
return (string)dictionary["Name"] == "tls-handshake-rate";
353359
}
354360
}
361+
362+
private static async Task PrepareEventCountersAsync(TestEventListener listener)
363+
{
364+
// There is a race condition in EventSource where counters using IncrementingPollingCounter
365+
// will drop increments that happened before the background timer thread first runs.
366+
// See https://github.com/dotnet/runtime/issues/106268#issuecomment-2284626183.
367+
// To workaround this issue, we ensure that the EventCounters timer is running before
368+
// executing any of the interesting logic under test.
369+
370+
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
371+
372+
await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () =>
373+
{
374+
var test = new SslStreamStreamToStreamTest_Async();
375+
await test.SslStream_StreamToStream_Authentication_Success();
376+
377+
await WaitForEventCountersAsync(events);
378+
});
379+
}
355380
}
356381
}

0 commit comments

Comments
 (0)