Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Workaround EventSource counters race condition in networking tests #106294

Merged
merged 2 commits into from
Aug 13, 2024
Merged

Workaround EventSource counters race condition in networking tests #106294

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
3b05a0a
Workaround EventSource counters race condition in networking tests
MihaZupan Aug 12, 2024
f10d38e
Merge branch 'main' into http-eventsourcetestrace
MihaZupan Aug 13, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
59 changes: 54 additions & 5 deletions src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs
View file
Open in desktop
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
Open in desktop
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);
});
}
}
}
Loading