Skip to content

Commit

Permalink
Workaround EventSource counters race condition in networking tests (d…
Browse files Browse the repository at this point in the history 
…otnet#106294)
  • Loading branch information
@MihaZupan
MihaZupan authored Aug 13, 2024
1 parent c788546 commit 6a69493
Show file tree
Hide file tree
Showing 2 changed files with 80 additions and 6 deletions.
59 changes: 54 additions & 5 deletions src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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 () =>
Expand Down Expand Up @@ -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 () =>
Expand Down Expand Up @@ -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 () =>
Expand Down Expand Up @@ -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();
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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();
Expand Down Expand Up @@ -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<string, double[]> eventCounters = events
.Select(e => e.Event)
.Where(e => e.EventName == "EventCounters")
Expand Down Expand Up @@ -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 () =>
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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;

Expand Down Expand Up @@ -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 () =>
Expand Down Expand Up @@ -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
Expand All @@ -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 () =>
Expand Down Expand Up @@ -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<long> connectionIds = new(Enumerable.Range(0, NumParallelRequests).Select(i => (long)i));
HashSet<long> connectionIds = new(Enumerable.Range(1, NumParallelRequests).Select(i => (long)i));
foreach (EventWrittenEventArgs e in requestHeadersStart)
{
long connectionId = (long)e.Payload.Single();
Expand Down
27 changes: 26 additions & 1 deletion src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 =>
{
Expand Down Expand Up @@ -184,13 +186,16 @@ 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 () =>
{
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 =>
{
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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);
});
}
}
}

0 comments on commit 6a69493

Please sign in to comment.