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

Update System.Net.Security Telemetry tests #55910

Merged
3 commits merged into from
Jul 22, 2021
Merged

Update System.Net.Security Telemetry tests #55910

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
bdc41ca
Update System.Net.Security Telemetry tests
MihaZupan Jul 19, 2021
97f42d6
Always return Task from ProcessAuthenticationAsync
MihaZupan Jul 20, 2021
9440a45
Name bool arguments
MihaZupan Jul 22, 2021
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
71 changes: 21 additions & 50 deletions src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -194,7 +194,17 @@ private SecurityStatusPal EncryptData(ReadOnlyMemory<byte> buffer, ref byte[] ou

if (NetSecurityTelemetry.Log.IsEnabled())
{
return ProcessAuthenticationWithTelemetry(isAsync, isApm, cancellationToken);
ValueTask task = ProcessAuthenticationWithTelemetryAsync(isAsync, isApm, cancellationToken);
if (isAsync)
{
return task.AsTask();
}
else
{
Debug.Assert(task.IsCompleted);
task.GetAwaiter().GetResult();
return null;
}
}
else
{
Expand All @@ -210,7 +220,7 @@ private SecurityStatusPal EncryptData(ReadOnlyMemory<byte> buffer, ref byte[] ou
}
}

private Task? ProcessAuthenticationWithTelemetry(bool isAsync, bool isApm, CancellationToken cancellationToken)
private async ValueTask ProcessAuthenticationWithTelemetryAsync(bool isAsync, bool isApm, CancellationToken cancellationToken)
{
NetSecurityTelemetry.Log.HandshakeStart(_context!.IsServer, _sslAuthenticationOptions!.TargetHost);
ValueStopwatch stopwatch = ValueStopwatch.StartNew();
Expand All @@ -219,62 +229,23 @@ private SecurityStatusPal EncryptData(ReadOnlyMemory<byte> buffer, ref byte[] ou
{
if (isAsync)
{
Task task = ForceAuthenticationAsync(new AsyncReadWriteAdapter(InnerStream, cancellationToken), _context.IsServer, null, isApm);

return task.ContinueWith((t, s) =>
{
var tuple = ((SslStream, ValueStopwatch))s!;
SslStream thisRef = tuple.Item1;
ValueStopwatch stopwatch = tuple.Item2;

if (t.IsCompletedSuccessfully)
{
LogSuccess(thisRef, stopwatch);
}
else
{
LogFailure(thisRef._context!.IsServer, stopwatch, t.Exception?.Message ?? "Operation canceled.");

// Throw the same exception we would if not using Telemetry
t.GetAwaiter().GetResult();
}
},
state: (this, stopwatch),
cancellationToken: default,
TaskContinuationOptions.ExecuteSynchronously,
TaskScheduler.Current);
await ForceAuthenticationAsync(new AsyncReadWriteAdapter(InnerStream, cancellationToken), _context.IsServer, null, isApm).ConfigureAwait(false);
}
else
{
ForceAuthenticationAsync(new SyncReadWriteAdapter(InnerStream), _context.IsServer, null).GetAwaiter().GetResult();
LogSuccess(this, stopwatch);
return null;
ForceAuthenticationAsync(new SyncReadWriteAdapter(InnerStream), _context!.IsServer, null).GetAwaiter().GetResult();
}
}
catch (Exception ex) when (LogFailure(_context.IsServer, stopwatch, ex.Message))
{
Debug.Fail("LogFailure should return false");
throw;
}

static bool LogFailure(bool isServer, ValueStopwatch stopwatch, string exceptionMessage)
{
NetSecurityTelemetry.Log.HandshakeFailed(isServer, stopwatch, exceptionMessage);
return false;
}

static void LogSuccess(SslStream thisRef, ValueStopwatch stopwatch)
{
// SslStream could already have been disposed at this point, in which case _connectionOpenedStatus == 2
// Make sure that we increment the open connection counter only if it is guaranteed to be decremented in dispose/finalize
bool connectionOpen = Interlocked.CompareExchange(ref _connectionOpenedStatus, 1, 0) == 0;

// Using a field of a marshal-by-reference class as a ref or out value or taking its address may cause a runtime exception
// Justification: thisRef is a reference to 'this', not a proxy object
#pragma warning disable CS0197
bool connectionOpen = Interlocked.CompareExchange(ref thisRef._connectionOpenedStatus, 1, 0) == 0;
#pragma warning restore CS0197

NetSecurityTelemetry.Log.HandshakeCompleted(thisRef.GetSslProtocolInternal(), stopwatch, connectionOpen);
NetSecurityTelemetry.Log.HandshakeCompleted(GetSslProtocolInternal(), stopwatch, connectionOpen);
}
catch (Exception ex)
{
NetSecurityTelemetry.Log.HandshakeFailed(_context.IsServer, stopwatch, ex.Message);
throw;
}
}

Expand Down
118 changes: 90 additions & 28 deletions 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 @@ -33,28 +33,44 @@ public static void EventSource_SuccessfulHandshake_LogsStartStop()
RemoteExecutor.Invoke(async () =>
{
using var listener = new TestEventListener("System.Net.Security", EventLevel.Verbose, eventCounterInterval: 0.1d);
listener.AddActivityTracking();

var events = new ConcurrentQueue<EventWrittenEventArgs>();
await listener.RunWithCallbackAsync(events.Enqueue, async () =>
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () =>
{
// Invoke tests that'll cause some events to be generated
var test = new SslStreamStreamToStreamTest_Async();
await test.SslStream_StreamToStream_Authentication_Success();
await Task.Delay(300);
await WaitForEventCountersAsync(events);
});
Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself
Assert.DoesNotContain(events, ev => ev.Event.EventId == 0); // errors from the EventSource itself

EventWrittenEventArgs[] starts = events.Where(e => e.EventName == "HandshakeStart").ToArray();
(EventWrittenEventArgs Event, Guid ActivityId)[] starts = events.Where(e => e.Event.EventName == "HandshakeStart").ToArray();
Assert.Equal(2, starts.Length);
Assert.All(starts, s => Assert.Equal(2, s.Payload.Count));
Assert.Single(starts, s => s.Payload[0] is bool isServer && isServer);
Assert.Single(starts, s => s.Payload[1] is string targetHost && targetHost.Length == 0);
Assert.All(starts, s => Assert.Equal(2, s.Event.Payload.Count));
Assert.All(starts, s => Assert.NotEqual(Guid.Empty, s.ActivityId));

EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "HandshakeStop").ToArray();
// isServer
(EventWrittenEventArgs Event, Guid ActivityId) serverStart = Assert.Single(starts, s => (bool)s.Event.Payload[0]);
(EventWrittenEventArgs Event, Guid ActivityId) clientStart = Assert.Single(starts, s => !(bool)s.Event.Payload[0]);

// targetHost
Assert.Empty(Assert.IsType<string>(serverStart.Event.Payload[1]));
Assert.NotEmpty(Assert.IsType<string>(clientStart.Event.Payload[1]));

Assert.NotEqual(serverStart.ActivityId, clientStart.ActivityId);

(EventWrittenEventArgs Event, Guid ActivityId)[] stops = events.Where(e => e.Event.EventName == "HandshakeStop").ToArray();
Assert.Equal(2, stops.Length);
Assert.All(stops, s => ValidateHandshakeStopEventPayload(s, failure: false));

Assert.DoesNotContain(events, e => e.EventName == "HandshakeFailed");
EventWrittenEventArgs serverStop = Assert.Single(stops, s => s.ActivityId == serverStart.ActivityId).Event;
EventWrittenEventArgs clientStop = Assert.Single(stops, s => s.ActivityId == clientStart.ActivityId).Event;

SslProtocols serverProtocol = ValidateHandshakeStopEventPayload(serverStop);
SslProtocols clientProtocol = ValidateHandshakeStopEventPayload(clientStop);
Assert.Equal(serverProtocol, clientProtocol);

Assert.DoesNotContain(events, e => e.Event.EventName == "HandshakeFailed");

VerifyEventCounters(events, shouldHaveFailures: false);
}).Dispose();
Expand All @@ -67,38 +83,57 @@ public static void EventSource_UnsuccessfulHandshake_LogsStartFailureStop()
RemoteExecutor.Invoke(async () =>
{
using var listener = new TestEventListener("System.Net.Security", EventLevel.Verbose, eventCounterInterval: 0.1d);
listener.AddActivityTracking();

var events = new ConcurrentQueue<EventWrittenEventArgs>();
await listener.RunWithCallbackAsync(events.Enqueue, async () =>
var events = new ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)>();
await listener.RunWithCallbackAsync(e => events.Enqueue((e, e.ActivityId)), async () =>
{
// Invoke tests that'll cause some events to be generated
var test = new SslStreamStreamToStreamTest_Async();
await test.SslStream_ServerLocalCertificateSelectionCallbackReturnsNull_Throw();
await Task.Delay(300);
await WaitForEventCountersAsync(events);
});
Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself
Assert.DoesNotContain(events, ev => ev.Event.EventId == 0); // errors from the EventSource itself

EventWrittenEventArgs[] starts = events.Where(e => e.EventName == "HandshakeStart").ToArray();
(EventWrittenEventArgs Event, Guid ActivityId)[] starts = events.Where(e => e.Event.EventName == "HandshakeStart").ToArray();
Assert.Equal(2, starts.Length);
Assert.All(starts, s => Assert.Equal(2, s.Payload.Count));
Assert.Single(starts, s => s.Payload[0] is bool isServer && isServer);
Assert.Single(starts, s => s.Payload[1] is string targetHost && targetHost.Length == 0);
Assert.All(starts, s => Assert.Equal(2, s.Event.Payload.Count));
Assert.All(starts, s => Assert.NotEqual(Guid.Empty, s.ActivityId));

EventWrittenEventArgs[] failures = events.Where(e => e.EventName == "HandshakeFailed").ToArray();
Assert.Equal(2, failures.Length);
Assert.All(failures, f => Assert.Equal(3, f.Payload.Count));
Assert.Single(failures, f => f.Payload[0] is bool isServer && isServer);
Assert.All(failures, f => Assert.NotEmpty(f.Payload[2] as string)); // exceptionMessage
// isServer
(EventWrittenEventArgs Event, Guid ActivityId) serverStart = Assert.Single(starts, s => (bool)s.Event.Payload[0]);
(EventWrittenEventArgs Event, Guid ActivityId) clientStart = Assert.Single(starts, s => !(bool)s.Event.Payload[0]);

// targetHost
Assert.Empty(Assert.IsType<string>(serverStart.Event.Payload[1]));
Assert.NotEmpty(Assert.IsType<string>(clientStart.Event.Payload[1]));

EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "HandshakeStop").ToArray();
Assert.NotEqual(serverStart.ActivityId, clientStart.ActivityId);

(EventWrittenEventArgs Event, Guid ActivityId)[] stops = events.Where(e => e.Event.EventName == "HandshakeStop").ToArray();
Assert.Equal(2, stops.Length);
Assert.All(stops, s => ValidateHandshakeStopEventPayload(s, failure: true));
Assert.All(stops, s => ValidateHandshakeStopEventPayload(s.Event, failure: true));

EventWrittenEventArgs serverStop = Assert.Single(stops, s => s.ActivityId == serverStart.ActivityId).Event;
EventWrittenEventArgs clientStop = Assert.Single(stops, s => s.ActivityId == clientStart.ActivityId).Event;

(EventWrittenEventArgs Event, Guid ActivityId)[] failures = events.Where(e => e.Event.EventName == "HandshakeFailed").ToArray();
Assert.Equal(2, failures.Length);
Assert.All(failures, f => Assert.Equal(3, f.Event.Payload.Count));
Assert.All(failures, f => Assert.NotEmpty(f.Event.Payload[2] as string)); // exceptionMessage

EventWrittenEventArgs serverFailure = Assert.Single(failures, f => f.ActivityId == serverStart.ActivityId).Event;
EventWrittenEventArgs clientFailure = Assert.Single(failures, f => f.ActivityId == clientStart.ActivityId).Event;

// isServer
Assert.Equal(true, serverFailure.Payload[0]);
Assert.Equal(false, clientFailure.Payload[0]);

VerifyEventCounters(events, shouldHaveFailures: true);
}).Dispose();
}

private static void ValidateHandshakeStopEventPayload(EventWrittenEventArgs stopEvent, bool failure)
private static SslProtocols ValidateHandshakeStopEventPayload(EventWrittenEventArgs stopEvent, bool failure = false)
{
Assert.Equal("HandshakeStop", stopEvent.EventName);
Assert.Equal(1, stopEvent.Payload.Count);
Expand All @@ -114,11 +149,14 @@ private static void ValidateHandshakeStopEventPayload(EventWrittenEventArgs stop
{
Assert.NotEqual(SslProtocols.None, protocol);
}

return protocol;
}

private static void VerifyEventCounters(ConcurrentQueue<EventWrittenEventArgs> events, bool shouldHaveFailures)
private static void VerifyEventCounters(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events, bool shouldHaveFailures)
{
Dictionary<string, double[]> eventCounters = events
.Select(e => e.Event)
.Where(e => e.EventName == "EventCounters")
.Select(e => (IDictionary<string, object>)e.Payload.Single())
.GroupBy(d => (string)d["Name"], d => (double)(d.ContainsKey("Mean") ? d["Mean"] : d["Increment"]))
Expand Down Expand Up @@ -174,5 +212,29 @@ private static void VerifyEventCounters(ConcurrentQueue<EventWrittenEventArgs> e
Assert.Contains(allHandshakeDurations, d => d > 0);
}
}

private static async Task WaitForEventCountersAsync(ConcurrentQueue<(EventWrittenEventArgs Event, Guid ActivityId)> events)
{
DateTime startTime = DateTime.UtcNow;
int startCount = events.Count;

while (events.Skip(startCount).Count(e => IsTlsHandshakeRateEventCounter(e.Event)) < 3)
{
if (DateTime.UtcNow.Subtract(startTime) > TimeSpan.FromSeconds(30))
throw new TimeoutException($"Timed out waiting for EventCounters");

await Task.Delay(100);
}

static bool IsTlsHandshakeRateEventCounter(EventWrittenEventArgs e)
{
if (e.EventName != "EventCounters")
return false;

var dictionary = (IDictionary<string, object>)e.Payload.Single();

return (string)dictionary["Name"] == "tls-handshake-rate";
}
}
}
}
2 changes: 1 addition & 1 deletion src/libraries/System.Net.Sockets/tests/FunctionalTests/TelemetryTest.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -357,7 +357,7 @@ private static async Task WaitForEventCountersAsync(ConcurrentQueue<(EventWritte
DateTime startTime = DateTime.UtcNow;
int startCount = events.Count;

while (events.Skip(startCount).Count(e => IsBytesSentEventCounter(e.Event)) < 2)
while (events.Skip(startCount).Count(e => IsBytesSentEventCounter(e.Event)) < 3)
{
if (DateTime.UtcNow.Subtract(startTime) > TimeSpan.FromSeconds(30))
throw new TimeoutException($"Timed out waiting for EventCounters");
Expand Down