From ee5770d500828533ee61224af799fc0ad04ecfc9 Mon Sep 17 00:00:00 2001 From: Anton Firszov Date: Sat, 13 Jul 2024 12:07:10 +0200 Subject: [PATCH] Activities for Http Connections, Dns, Sockets and SslStream (#103922) Final design: https://github.com/dotnet/runtime/pull/103922#issuecomment-2221811114 --- .../tests/System/Net/ActivityRecorder.cs | 136 ++++++++++ .../src/System.Net.Http.csproj | 1 + .../src/System/Net/Http/DiagnosticsHandler.cs | 35 ++- .../Http/DiagnosticsHandlerLoggingStrings.cs | 18 +- .../src/System/Net/Http/DiagnosticsHelper.cs | 2 +- .../ConnectionSetupDistributedTracing.cs | 98 +++++++ .../HttpConnectionPool.Http1.cs | 8 +- .../HttpConnectionPool.Http2.cs | 16 +- .../HttpConnectionPool.Http3.cs | 27 +- .../ConnectionPool/HttpConnectionPool.cs | 131 +++++---- .../ConnectionPool/HttpConnectionWaiter.cs | 9 +- .../SocketsHttpHandler/Http2Connection.cs | 6 +- .../SocketsHttpHandler/Http3Connection.cs | 19 +- .../Http/SocketsHttpHandler/HttpConnection.cs | 4 +- .../SocketsHttpHandler/HttpConnectionBase.cs | 11 +- .../tests/FunctionalTests/DiagnosticsTests.cs | 249 +++++++++++++++++- .../System.Net.Http.Functional.Tests.csproj | 2 + .../src/System/Net/Dns.cs | 103 ++++---- .../src/System/Net/NameResolutionMetrics.cs | 13 +- .../src/System/Net/NameResolutionTelemetry.cs | 123 ++++++++- .../tests/FunctionalTests/ActivityTest.cs | 170 ++++++++++++ ...Net.NameResolution.Functional.Tests.csproj | 3 + .../src/System.Net.Security.csproj | 1 + .../Net/Security/NetSecurityTelemetry.cs | 58 ++++ .../src/System/Net/Security/SslStream.IO.cs | 40 ++- .../src/System/Net/Security/SslStream.cs | 2 +- .../SslStreamStreamToStreamTest.cs | 16 +- .../System.Net.Security.Tests.csproj | 2 + .../tests/FunctionalTests/TelemetryTest.cs | 87 ++++++ .../src/System.Net.Sockets.csproj | 1 + .../src/System/Net/Sockets/Socket.cs | 16 +- .../Net/Sockets/SocketAsyncEventArgs.cs | 25 +- .../System/Net/Sockets/SocketsTelemetry.cs | 95 ++++++- .../System.Net.Sockets.Tests.csproj | 2 + .../tests/FunctionalTests/TelemetryTest.cs | 131 ++++++++- .../FunctionalTests/UnixDomainSocketTest.cs | 2 +- 36 files changed, 1458 insertions(+), 204 deletions(-) create mode 100644 src/libraries/Common/tests/System/Net/ActivityRecorder.cs create mode 100644 src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/ConnectionSetupDistributedTracing.cs create mode 100644 src/libraries/System.Net.NameResolution/tests/FunctionalTests/ActivityTest.cs diff --git a/src/libraries/Common/tests/System/Net/ActivityRecorder.cs b/src/libraries/Common/tests/System/Net/ActivityRecorder.cs new file mode 100644 index 0000000000000..6647076d4bac5 --- /dev/null +++ b/src/libraries/Common/tests/System/Net/ActivityRecorder.cs @@ -0,0 +1,136 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; +using System.Text; +using Xunit; + +namespace System.Net.Test.Common +{ + internal class ActivityRecorder : IDisposable + { + private string _activitySourceName; + private string _activityName; + + private readonly ActivityListener _listener; + private List _finishedActivities = new(); + + public Predicate Filter { get; set; } = _ => true; + public bool VerifyParent { get; set; } = true; + public Activity ExpectedParent { get; set; } + + public int Started { get; private set; } + public int Stopped { get; private set; } + public Activity LastStartedActivity { get; private set; } + public Activity LastFinishedActivity { get; private set; } + public IEnumerable FinishedActivities => _finishedActivities; + + public ActivityRecorder(string activitySourceName, string activityName) + { + _activitySourceName = activitySourceName; + _activityName = activityName; + _listener = new ActivityListener + { + ShouldListenTo = (activitySource) => activitySource.Name == _activitySourceName, + Sample = (ref ActivityCreationOptions options) => ActivitySamplingResult.AllData, + ActivityStarted = (activity) => { + if (activity.OperationName == _activityName && Filter(activity)) + { + if (VerifyParent) + { + Assert.Same(ExpectedParent, activity.Parent); + } + + Started++; + LastStartedActivity = activity; + } + }, + ActivityStopped = (activity) => { + if (activity.OperationName == _activityName && Filter(activity)) + { + if (VerifyParent) + { + Assert.Same(ExpectedParent, activity.Parent); + } + + Stopped++; + LastFinishedActivity = activity; + _finishedActivities.Add(activity); + } + } + }; + + ActivitySource.AddActivityListener(_listener); + } + + public void Dispose() => _listener.Dispose(); + + public void VerifyActivityRecorded(int times) + { + Assert.Equal(times, Started); + Assert.Equal(times, Stopped); + } + + public Activity VerifyActivityRecordedOnce() + { + VerifyActivityRecorded(1); + return LastFinishedActivity; + } + } + + internal static class ActivityAssert + { + public static KeyValuePair HasTag(Activity activity, string name) + { + KeyValuePair tag = activity.TagObjects.SingleOrDefault(t => t.Key == name); + if (tag.Key is null) + { + Assert.Fail($"The Activity tags should contain {name}."); + } + return tag; + } + + public static void HasTag(Activity activity, string name, T expectedValue) + { + KeyValuePair tag = HasTag(activity, name); + Assert.Equal(expectedValue, (T)tag.Value); + } + + public static void HasTag(Activity activity, string name, Func verifyValue) + { + T? value = (T?)activity.TagObjects.SingleOrDefault(t => t.Key == name).Value; + Assert.False(value is null, $"The Activity tags should contain {name}."); + Assert.True(verifyValue(value)); + } + + public static void HasNoTag(Activity activity, string name) + { + bool contains = activity.TagObjects.Any(t => t.Key == name); + Assert.False(contains, $"The Activity tags should not contain {name}."); + } + + public static void FinishedInOrder(Activity first, Activity second) + { + Assert.True(first.StartTimeUtc + first.Duration < second.StartTimeUtc + second.Duration, $"{first.OperationName} should stop before {second.OperationName}"); + } + + public static string CamelToSnake(string camel) + { + if (string.IsNullOrEmpty(camel)) return camel; + StringBuilder bld = new(); + bld.Append(char.ToLower(camel[0])); + for (int i = 1; i < camel.Length; i++) + { + char c = camel[i]; + if (char.IsUpper(c)) + { + bld.Append('_'); + } + bld.Append(char.ToLower(c)); + } + return bld.ToString(); + } + } +} diff --git a/src/libraries/System.Net.Http/src/System.Net.Http.csproj b/src/libraries/System.Net.Http/src/System.Net.Http.csproj index 477cb08f059a4..5a824c7c5aa7c 100644 --- a/src/libraries/System.Net.Http/src/System.Net.Http.csproj +++ b/src/libraries/System.Net.Http/src/System.Net.Http.csproj @@ -175,6 +175,7 @@ + diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index ed82d0b37d299..6678c5be1de78 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs @@ -16,7 +16,7 @@ namespace System.Net.Http internal sealed class DiagnosticsHandler : HttpMessageHandlerStage { private static readonly DiagnosticListener s_diagnosticListener = new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName); - private static readonly ActivitySource s_activitySource = new ActivitySource(DiagnosticsHandlerLoggingStrings.Namespace); + internal static readonly ActivitySource s_activitySource = new ActivitySource(DiagnosticsHandlerLoggingStrings.RequestNamespace); private readonly HttpMessageHandler _innerHandler; private readonly DistributedContextPropagator _propagator; @@ -58,14 +58,14 @@ private static bool IsEnabled() Activity? activity = null; if (s_activitySource.HasListeners()) { - activity = s_activitySource.StartActivity(DiagnosticsHandlerLoggingStrings.ActivityName, ActivityKind.Client); + activity = s_activitySource.StartActivity(DiagnosticsHandlerLoggingStrings.RequestActivityName, ActivityKind.Client); } if (activity is null && (Activity.Current is not null || - s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityName, request))) + s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestActivityName, request))) { - activity = new Activity(DiagnosticsHandlerLoggingStrings.ActivityName).Start(); + activity = new Activity(DiagnosticsHandlerLoggingStrings.RequestActivityName).Start(); } return activity; @@ -134,9 +134,9 @@ private async ValueTask SendAsyncCore(HttpRequestMessage re } // Only send start event to users who subscribed for it. - if (diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityStartName)) + if (diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestActivityStartName)) { - Write(diagnosticListener, DiagnosticsHandlerLoggingStrings.ActivityStartName, new ActivityStartData(request)); + Write(diagnosticListener, DiagnosticsHandlerLoggingStrings.RequestActivityStartName, new ActivityStartData(request)); } } @@ -214,10 +214,29 @@ await _innerHandler.SendAsync(request, cancellationToken).ConfigureAwait(false) } } + if (activity.IsAllDataRequested) + { + // Add standard tags known at request completion. + if (response is not null) + { + activity.SetTag("http.response.status_code", DiagnosticsHelper.GetBoxedStatusCode((int)response.StatusCode)); + activity.SetTag("network.protocol.version", DiagnosticsHelper.GetProtocolVersionString(response.Version)); + } + + if (DiagnosticsHelper.TryGetErrorType(response, exception, out string? errorType)) + { + activity.SetTag("error.type", errorType); + + // The presence of error.type indicates that the conditions for setting Error status are also met. + // https://github.com/open-telemetry/semantic-conventions/blob/v1.26.0/docs/http/http-spans.md#status + activity.SetStatus(ActivityStatusCode.Error); + } + } + // Only send stop event to users who subscribed for it. - if (diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityStopName)) + if (diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestActivityStopName)) { - Write(diagnosticListener, DiagnosticsHandlerLoggingStrings.ActivityStopName, new ActivityStopData(response, request, taskStatus)); + Write(diagnosticListener, DiagnosticsHandlerLoggingStrings.RequestActivityStopName, new ActivityStopData(response, request, taskStatus)); } activity.Stop(); diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs index 030310f4fdc81..975ab45405631 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs @@ -9,12 +9,16 @@ namespace System.Net.Http internal static class DiagnosticsHandlerLoggingStrings { public const string DiagnosticListenerName = "HttpHandlerDiagnosticListener"; - public const string Namespace = "System.Net.Http"; - public const string RequestWriteNameDeprecated = Namespace + ".Request"; - public const string ResponseWriteNameDeprecated = Namespace + ".Response"; - public const string ExceptionEventName = Namespace + ".Exception"; - public const string ActivityName = Namespace + ".HttpRequestOut"; - public const string ActivityStartName = ActivityName + ".Start"; - public const string ActivityStopName = ActivityName + ".Stop"; + public const string RequestNamespace = "System.Net.Http"; + public const string RequestWriteNameDeprecated = RequestNamespace + ".Request"; + public const string ResponseWriteNameDeprecated = RequestNamespace + ".Response"; + public const string ExceptionEventName = RequestNamespace + ".Exception"; + public const string RequestActivityName = RequestNamespace + ".HttpRequestOut"; + public const string RequestActivityStartName = RequestActivityName + ".Start"; + public const string RequestActivityStopName = RequestActivityName + ".Stop"; + + public const string ConnectionsNamespace = "Experimental.System.Net.Http.Connections"; + public const string ConnectionSetupActivityName = ConnectionsNamespace + ".ConnectionSetup"; + public const string WaitForConnectionActivityName = ConnectionsNamespace + ".WaitForConnection"; } } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHelper.cs b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHelper.cs index ce1a66171fc6e..ca80bda721c40 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHelper.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHelper.cs @@ -67,7 +67,7 @@ public static bool TryGetErrorType(HttpResponseMessage? response, Exception? exc // In case the status code indicates a client or a server error, return the string representation of the status code. // See the paragraph Status and the definition of 'error.type' in - // https://github.com/open-telemetry/semantic-conventions/blob/2bad9afad58fbd6b33cc683d1ad1f006e35e4a5d/docs/http/http-spans.md + // https://github.com/open-telemetry/semantic-conventions/blob/release/v1.23.x/docs/http/http-spans.md#Status if (statusCode >= 400 && statusCode <= 599) { errorType = GetErrorStatusCodeString(statusCode); diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/ConnectionSetupDistributedTracing.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/ConnectionSetupDistributedTracing.cs new file mode 100644 index 0000000000000..aaa60449f410c --- /dev/null +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/ConnectionSetupDistributedTracing.cs @@ -0,0 +1,98 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Collections.Generic; +using System.Diagnostics; +using System.Threading; + +namespace System.Net.Http +{ + // Implements distributed tracing logic for managing the "HTTP connection_setup" and "HTTP wait_for_connection" Activities. + internal static class ConnectionSetupDistributedTracing + { + private static readonly ActivitySource s_connectionsActivitySource = new ActivitySource(DiagnosticsHandlerLoggingStrings.ConnectionsNamespace); + + public static Activity? StartConnectionSetupActivity(bool isSecure, HttpAuthority authority) + { + Activity? activity = null; + if (s_connectionsActivitySource.HasListeners()) + { + // Connection activities should be new roots and not parented under whatever + // request happens to be in progress when the connection is started. + Activity.Current = null; + activity = s_connectionsActivitySource.StartActivity(DiagnosticsHandlerLoggingStrings.ConnectionSetupActivityName); + } + + if (activity is not null) + { + activity.DisplayName = $"HTTP connection_setup {authority.HostValue}:{authority.Port}"; + if (activity.IsAllDataRequested) + { + activity.SetTag("server.address", authority.HostValue); + activity.SetTag("server.port", authority.Port); + activity.SetTag("url.scheme", isSecure ? "https" : "http"); + } + } + + return activity; + } + + public static void StopConnectionSetupActivity(Activity activity, Exception? exception, IPEndPoint? remoteEndPoint) + { + Debug.Assert(activity is not null); + if (exception is not null) + { + ReportError(activity, exception); + } + else + { + if (activity.IsAllDataRequested && remoteEndPoint is not null) + { + activity.SetTag("network.peer.address", remoteEndPoint.Address.ToString()); + } + } + + activity.Stop(); + } + + public static void ReportError(Activity? activity, Exception exception) + { + Debug.Assert(exception is not null); + if (activity is null) return; + activity.SetStatus(ActivityStatusCode.Error); + + if (activity.IsAllDataRequested) + { + DiagnosticsHelper.TryGetErrorType(null, exception, out string? errorType); + Debug.Assert(errorType is not null, "DiagnosticsHelper.TryGetErrorType() should succeed whenever an exception is provided."); + activity.SetTag("error.type", errorType); + } + } + + public static Activity? StartWaitForConnectionActivity(HttpAuthority authority) + { + Activity? activity = s_connectionsActivitySource.StartActivity(DiagnosticsHandlerLoggingStrings.WaitForConnectionActivityName); + if (activity is not null) + { + activity.DisplayName = $"HTTP wait_for_connection {authority.HostValue}:{authority.Port}"; + } + + return activity; + } + + public static void AddConnectionLinkToRequestActivity(Activity connectionSetupActivity) + { + Debug.Assert(connectionSetupActivity is not null); + + // We only support links for request activities created by the "System.Net.Http" ActivitySource. + if (DiagnosticsHandler.s_activitySource.HasListeners()) + { + Activity? requestActivity = Activity.Current; + if (requestActivity?.Source == DiagnosticsHandler.s_activitySource) + { + requestActivity.AddLink(new ActivityLink(connectionSetupActivity.Context)); + } + } + } + } +} diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http1.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http1.cs index 319e119978a85..d65e1b6486de2 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http1.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http1.cs @@ -294,14 +294,14 @@ private async Task InjectNewHttp11ConnectionAsync(RequestQueue.Q internal async ValueTask CreateHttp11ConnectionAsync(HttpRequestMessage request, bool async, CancellationToken cancellationToken) { - (Stream stream, TransportContext? transportContext, IPEndPoint? remoteEndPoint) = await ConnectAsync(request, async, cancellationToken).ConfigureAwait(false); - return await ConstructHttp11ConnectionAsync(async, stream, transportContext, request, remoteEndPoint, cancellationToken).ConfigureAwait(false); + (Stream stream, TransportContext? transportContext, Activity? activity, IPEndPoint? remoteEndPoint) = await ConnectAsync(request, async, cancellationToken).ConfigureAwait(false); + return await ConstructHttp11ConnectionAsync(async, stream, transportContext, request, activity, remoteEndPoint, cancellationToken).ConfigureAwait(false); } - private async ValueTask ConstructHttp11ConnectionAsync(bool async, Stream stream, TransportContext? transportContext, HttpRequestMessage request, IPEndPoint? remoteEndPoint, CancellationToken cancellationToken) + private async ValueTask ConstructHttp11ConnectionAsync(bool async, Stream stream, TransportContext? transportContext, HttpRequestMessage request, Activity? activity, IPEndPoint? remoteEndPoint, CancellationToken cancellationToken) { Stream newStream = await ApplyPlaintextFilterAsync(async, stream, HttpVersion.Version11, request, cancellationToken).ConfigureAwait(false); - return new HttpConnection(this, newStream, transportContext, remoteEndPoint); + return new HttpConnection(this, newStream, transportContext, activity, remoteEndPoint); } private void HandleHttp11ConnectionFailure(HttpConnectionWaiter? requestWaiter, Exception e) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http2.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http2.cs index fb1054165cac1..c3999c520f0f2 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http2.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http2.cs @@ -185,7 +185,7 @@ private async Task InjectNewHttp2ConnectionAsync(RequestQueue. waiter.ConnectionCancellationTokenSource = cts; try { - (Stream stream, TransportContext? transportContext, IPEndPoint? remoteEndPoint) = await ConnectAsync(queueItem.Request, true, cts.Token).ConfigureAwait(false); + (Stream stream, TransportContext? transportContext, Activity? activity, IPEndPoint? remoteEndPoint) = await ConnectAsync(queueItem.Request, true, cts.Token).ConfigureAwait(false); if (IsSecure) { @@ -202,19 +202,19 @@ private async Task InjectNewHttp2ConnectionAsync(RequestQueue. } else { - connection = await ConstructHttp2ConnectionAsync(stream, queueItem.Request, remoteEndPoint, cts.Token).ConfigureAwait(false); + connection = await ConstructHttp2ConnectionAsync(stream, queueItem.Request, activity, remoteEndPoint, cts.Token).ConfigureAwait(false); } } else { // We established an SSL connection, but the server denied our request for HTTP2. - await HandleHttp11Downgrade(queueItem.Request, stream, transportContext, remoteEndPoint, cts.Token).ConfigureAwait(false); + await HandleHttp11Downgrade(queueItem.Request, stream, transportContext, activity, remoteEndPoint, cts.Token).ConfigureAwait(false); return; } } else { - connection = await ConstructHttp2ConnectionAsync(stream, queueItem.Request, remoteEndPoint, cts.Token).ConfigureAwait(false); + connection = await ConstructHttp2ConnectionAsync(stream, queueItem.Request, activity, remoteEndPoint, cts.Token).ConfigureAwait(false); } } catch (Exception e) @@ -244,11 +244,11 @@ private async Task InjectNewHttp2ConnectionAsync(RequestQueue. } } - private async ValueTask ConstructHttp2ConnectionAsync(Stream stream, HttpRequestMessage request, IPEndPoint? remoteEndPoint, CancellationToken cancellationToken) + private async ValueTask ConstructHttp2ConnectionAsync(Stream stream, HttpRequestMessage request, Activity? activity, IPEndPoint? remoteEndPoint, CancellationToken cancellationToken) { stream = await ApplyPlaintextFilterAsync(async: true, stream, HttpVersion.Version20, request, cancellationToken).ConfigureAwait(false); - Http2Connection http2Connection = new Http2Connection(this, stream, remoteEndPoint); + Http2Connection http2Connection = new Http2Connection(this, stream, activity, remoteEndPoint); try { await http2Connection.SetupAsync(cancellationToken).ConfigureAwait(false); @@ -287,7 +287,7 @@ private void HandleHttp2ConnectionFailure(HttpConnectionWaiter } } - private async Task HandleHttp11Downgrade(HttpRequestMessage request, Stream stream, TransportContext? transportContext, IPEndPoint? remoteEndPoint, CancellationToken cancellationToken) + private async Task HandleHttp11Downgrade(HttpRequestMessage request, Stream stream, TransportContext? transportContext, Activity? activity, IPEndPoint? remoteEndPoint, CancellationToken cancellationToken) { if (NetEventSource.Log.IsEnabled()) Trace("Server does not support HTTP2; disabling HTTP2 use and proceeding with HTTP/1.1 connection"); @@ -345,7 +345,7 @@ private async Task HandleHttp11Downgrade(HttpRequestMessage request, Stream stre try { // Note, the same CancellationToken from the original HTTP2 connection establishment still applies here. - http11Connection = await ConstructHttp11ConnectionAsync(true, stream, transportContext, request, remoteEndPoint, cancellationToken).ConfigureAwait(false); + http11Connection = await ConstructHttp11ConnectionAsync(true, stream, transportContext, request, activity, remoteEndPoint, cancellationToken).ConfigureAwait(false); } catch (OperationCanceledException oce) when (oce.CancellationToken == cancellationToken) { diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http3.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http3.cs index b2d17af903c61..bae0ef3895255 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http3.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http3.cs @@ -75,7 +75,7 @@ internal sealed partial class HttpConnectionPool // Loop in case we get a 421 and need to send the request to a different authority. while (true) { - if (!TryGetHttp3Authority(request, out _, out Exception? reasonException)) + if (!TryGetHttp3Authority(request, out HttpAuthority? authority, out Exception? reasonException)) { if (reasonException is null) { @@ -85,10 +85,20 @@ internal sealed partial class HttpConnectionPool } long queueStartingTimestamp = HttpTelemetry.Log.IsEnabled() || Settings._metrics!.RequestsQueueDuration.Enabled ? Stopwatch.GetTimestamp() : 0; + Activity? waitForConnectionActivity = ConnectionSetupDistributedTracing.StartWaitForConnectionActivity(authority); if (!TryGetPooledHttp3Connection(request, out Http3Connection? connection, out HttpConnectionWaiter? http3ConnectionWaiter)) { - connection = await http3ConnectionWaiter.WaitWithCancellationAsync(cancellationToken).ConfigureAwait(false); + try + { + connection = await http3ConnectionWaiter.WaitWithCancellationAsync(cancellationToken).ConfigureAwait(false); + } + catch (Exception ex) + { + ConnectionSetupDistributedTracing.ReportError(waitForConnectionActivity, ex); + waitForConnectionActivity?.Stop(); + throw; + } } // Request cannot be sent over H/3 connection, try downgrade or report failure. @@ -98,7 +108,7 @@ internal sealed partial class HttpConnectionPool return null; } - HttpResponseMessage response = await connection.SendAsync(request, queueStartingTimestamp, cancellationToken).ConfigureAwait(false); + HttpResponseMessage response = await connection.SendAsync(request, queueStartingTimestamp, waitForConnectionActivity, cancellationToken).ConfigureAwait(false); // If an Alt-Svc authority returns 421, it means it can't actually handle the request. // An authority is supposed to be able to handle ALL requests to the origin, so this is a server bug. @@ -245,20 +255,22 @@ private async Task InjectNewHttp3ConnectionAsync(RequestQueue. CancellationTokenSource cts = GetConnectTimeoutCancellationTokenSource(); waiter.ConnectionCancellationTokenSource = cts; + Activity? connectionSetupActivity = null; try { if (TryGetHttp3Authority(queueItem.Request, out authority, out Exception? reasonException)) { + connectionSetupActivity = ConnectionSetupDistributedTracing.StartConnectionSetupActivity(isSecure: true, authority); // If the authority was sent as an option through alt-svc then include alt-used header. connection = new Http3Connection(this, authority, includeAltUsedHeader: _http3Authority == authority); - QuicConnection quicConnection = await ConnectHelper.ConnectQuicAsync(queueItem.Request, new DnsEndPoint(authority.IdnHost, authority.Port), _poolManager.Settings._pooledConnectionIdleTimeout, _sslOptionsHttp3!, connection.StreamCapacityCallback, cts.Token).ConfigureAwait(false); if (quicConnection.NegotiatedApplicationProtocol != SslApplicationProtocol.Http3) { await quicConnection.DisposeAsync().ConfigureAwait(false); throw new HttpRequestException(HttpRequestError.ConnectionError, "QUIC connected but no HTTP/3 indicated via ALPN.", null, RequestRetryType.RetryOnConnectionFailure); } - connection.InitQuicConnection(quicConnection); + if (connectionSetupActivity is not null) ConnectionSetupDistributedTracing.StopConnectionSetupActivity(connectionSetupActivity, null, quicConnection.RemoteEndPoint); + connection.InitQuicConnection(quicConnection, connectionSetupActivity); } else if (reasonException is not null) { @@ -271,6 +283,11 @@ private async Task InjectNewHttp3ConnectionAsync(RequestQueue. CreateConnectTimeoutException(oce) : e; + // On success path connectionSetupActivity is stopped before calling InitQuicConnection(). + // This assertion makes sure that InitQuicConnection() does not throw unexpectedly. + Debug.Assert(connectionSetupActivity?.IsStopped is not true); + if (connectionSetupActivity is not null) ConnectionSetupDistributedTracing.StopConnectionSetupActivity(connectionSetupActivity, connectionException, null); + // If the connection hasn't been initialized with QuicConnection, get rid of it. connection?.Dispose(); connection = null; diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.cs index d4f271acfa681..4770b49203624 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.cs @@ -565,77 +565,96 @@ public async ValueTask SendWithVersionDetectionAndRetryAsyn } } - private async ValueTask<(Stream, TransportContext?, IPEndPoint?)> ConnectAsync(HttpRequestMessage request, bool async, CancellationToken cancellationToken) + private async ValueTask<(Stream, TransportContext?, Activity?, IPEndPoint?)> ConnectAsync(HttpRequestMessage request, bool async, CancellationToken cancellationToken) { Stream? stream = null; IPEndPoint? remoteEndPoint = null; - switch (_kind) - { - case HttpConnectionKind.Http: - case HttpConnectionKind.Https: - case HttpConnectionKind.ProxyConnect: - stream = await ConnectToTcpHostAsync(_originAuthority.IdnHost, _originAuthority.Port, request, async, cancellationToken).ConfigureAwait(false); - // remoteEndPoint is returned for diagnostic purposes. - remoteEndPoint = GetRemoteEndPoint(stream); - if (_kind == HttpConnectionKind.ProxyConnect && _sslOptionsProxy != null) - { - stream = await ConnectHelper.EstablishSslConnectionAsync(_sslOptionsProxy, request, async, stream, cancellationToken).ConfigureAwait(false); - } - break; + Exception? exception = null; + TransportContext? transportContext = null; - case HttpConnectionKind.Proxy: - stream = await ConnectToTcpHostAsync(_proxyUri!.IdnHost, _proxyUri.Port, request, async, cancellationToken).ConfigureAwait(false); - // remoteEndPoint is returned for diagnostic purposes. - remoteEndPoint = GetRemoteEndPoint(stream); - if (_sslOptionsProxy != null) - { - stream = await ConnectHelper.EstablishSslConnectionAsync(_sslOptionsProxy, request, async, stream, cancellationToken).ConfigureAwait(false); - } - break; + Activity? activity = ConnectionSetupDistributedTracing.StartConnectionSetupActivity(IsSecure, OriginAuthority); - case HttpConnectionKind.ProxyTunnel: - case HttpConnectionKind.SslProxyTunnel: - stream = await EstablishProxyTunnelAsync(async, cancellationToken).ConfigureAwait(false); + try + { + switch (_kind) + { + case HttpConnectionKind.Http: + case HttpConnectionKind.Https: + case HttpConnectionKind.ProxyConnect: + stream = await ConnectToTcpHostAsync(_originAuthority.IdnHost, _originAuthority.Port, request, async, cancellationToken).ConfigureAwait(false); + // remoteEndPoint is returned for diagnostic purposes. + remoteEndPoint = GetRemoteEndPoint(stream); + if (_kind == HttpConnectionKind.ProxyConnect && _sslOptionsProxy != null) + { + stream = await ConnectHelper.EstablishSslConnectionAsync(_sslOptionsProxy, request, async, stream, cancellationToken).ConfigureAwait(false); + } + break; - if (stream is HttpContentStream contentStream && contentStream._connection?._stream is Stream innerStream) - { - remoteEndPoint = GetRemoteEndPoint(innerStream); - } + case HttpConnectionKind.Proxy: + stream = await ConnectToTcpHostAsync(_proxyUri!.IdnHost, _proxyUri.Port, request, async, cancellationToken).ConfigureAwait(false); + // remoteEndPoint is returned for diagnostic purposes. + remoteEndPoint = GetRemoteEndPoint(stream); + if (_sslOptionsProxy != null) + { + stream = await ConnectHelper.EstablishSslConnectionAsync(_sslOptionsProxy, request, async, stream, cancellationToken).ConfigureAwait(false); + } + break; - break; + case HttpConnectionKind.ProxyTunnel: + case HttpConnectionKind.SslProxyTunnel: + stream = await EstablishProxyTunnelAsync(async, cancellationToken).ConfigureAwait(false); - case HttpConnectionKind.SocksTunnel: - case HttpConnectionKind.SslSocksTunnel: - stream = await EstablishSocksTunnel(request, async, cancellationToken).ConfigureAwait(false); - // remoteEndPoint is returned for diagnostic purposes. - remoteEndPoint = GetRemoteEndPoint(stream); - break; - } + if (stream is HttpContentStream contentStream && contentStream._connection?._stream is Stream innerStream) + { + remoteEndPoint = GetRemoteEndPoint(innerStream); + } - Debug.Assert(stream != null); + break; - TransportContext? transportContext = null; - if (IsSecure) - { - SslStream? sslStream = stream as SslStream; - if (sslStream == null) - { - sslStream = await ConnectHelper.EstablishSslConnectionAsync(GetSslOptionsForRequest(request), request, async, stream, cancellationToken).ConfigureAwait(false); + case HttpConnectionKind.SocksTunnel: + case HttpConnectionKind.SslSocksTunnel: + stream = await EstablishSocksTunnel(request, async, cancellationToken).ConfigureAwait(false); + // remoteEndPoint is returned for diagnostic purposes. + remoteEndPoint = GetRemoteEndPoint(stream); + break; } - else + + Debug.Assert(stream != null); + + if (IsSecure) { - if (NetEventSource.Log.IsEnabled()) + SslStream? sslStream = stream as SslStream; + if (sslStream == null) { - Trace($"Connected with custom SslStream: alpn='${sslStream.NegotiatedApplicationProtocol}'"); + sslStream = await ConnectHelper.EstablishSslConnectionAsync(GetSslOptionsForRequest(request), request, async, stream, cancellationToken).ConfigureAwait(false); } + else + { + if (NetEventSource.Log.IsEnabled()) + { + Trace($"Connected with custom SslStream: alpn='${sslStream.NegotiatedApplicationProtocol}'"); + } + } + transportContext = sslStream.TransportContext; + stream = sslStream; + } + } + catch (Exception ex) when (activity is not null) + { + exception = ex; + throw; + } + finally + { + if (activity is not null) + { + ConnectionSetupDistributedTracing.StopConnectionSetupActivity(activity, exception, remoteEndPoint); } - transportContext = sslStream.TransportContext; - stream = sslStream; } - static IPEndPoint? GetRemoteEndPoint(Stream stream) => (stream as NetworkStream)?.Socket?.RemoteEndPoint as IPEndPoint; + return (stream, transportContext, activity, remoteEndPoint); - return (stream, transportContext, remoteEndPoint); + static IPEndPoint? GetRemoteEndPoint(Stream stream) => (stream as NetworkStream)?.Socket?.RemoteEndPoint as IPEndPoint; } private async ValueTask ConnectToTcpHostAsync(string host, int port, HttpRequestMessage initialRequest, bool async, CancellationToken cancellationToken) @@ -695,7 +714,7 @@ private async ValueTask ConnectToTcpHostAsync(string host, int port, Htt { throw ex is OperationCanceledException oce && oce.CancellationToken == cancellationToken ? CancellationHelper.CreateOperationCanceledException(innerException: null, cancellationToken) : - ConnectHelper.CreateWrappedException(ex, endPoint.Host, endPoint.Port, cancellationToken); + ConnectHelper.CreateWrappedException(ex, host, port, cancellationToken); } } @@ -799,9 +818,9 @@ private async ValueTask EstablishSocksTunnel(HttpRequestMessage request, { await SocksHelper.EstablishSocksTunnelAsync(stream, _originAuthority.IdnHost, _originAuthority.Port, _proxyUri, ProxyCredentials, async, cancellationToken).ConfigureAwait(false); } - catch (Exception e) when (!(e is OperationCanceledException)) + catch (Exception e) when (e is not OperationCanceledException) { - Debug.Assert(!(e is HttpRequestException)); + Debug.Assert(e is not HttpRequestException); throw new HttpRequestException(HttpRequestError.ProxyTunnelError, SR.net_http_proxy_tunnel_error, e); } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionWaiter.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionWaiter.cs index 3ca1412ebe711..9e1e0f7127d68 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionWaiter.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionWaiter.cs @@ -19,7 +19,7 @@ internal sealed class HttpConnectionWaiter : TaskCompletionSourceWithCancella public ValueTask WaitForConnectionAsync(HttpRequestMessage request, HttpConnectionPool pool, bool async, CancellationToken requestCancellationToken) { - return HttpTelemetry.Log.IsEnabled() || pool.Settings._metrics!.RequestsQueueDuration.Enabled + return HttpTelemetry.Log.IsEnabled() || pool.Settings._metrics!.RequestsQueueDuration.Enabled || Activity.Current?.Source == DiagnosticsHandler.s_activitySource ? WaitForConnectionWithTelemetryAsync(request, pool, async, requestCancellationToken) : WaitWithCancellationAsync(async, requestCancellationToken); } @@ -29,10 +29,17 @@ private async ValueTask WaitForConnectionWithTelemetryAsync(HttpRequestMessag Debug.Assert(typeof(T) == typeof(HttpConnection) || typeof(T) == typeof(Http2Connection)); long startingTimestamp = Stopwatch.GetTimestamp(); + + using Activity? waitForConnectionActivity = ConnectionSetupDistributedTracing.StartWaitForConnectionActivity(pool.OriginAuthority); try { return await WaitWithCancellationAsync(async, requestCancellationToken).ConfigureAwait(false); } + catch (Exception ex) when (waitForConnectionActivity is not null) + { + ConnectionSetupDistributedTracing.ReportError(waitForConnectionActivity, ex); + throw; + } finally { TimeSpan duration = Stopwatch.GetElapsedTime(startingTimestamp); diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs index 8b2c37122e56a..5224adcfa36a6 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs @@ -130,8 +130,8 @@ internal enum KeepAliveState private long _keepAlivePingTimeoutTimestamp; private volatile KeepAliveState _keepAliveState; - public Http2Connection(HttpConnectionPool pool, Stream stream, IPEndPoint? remoteEndPoint) - : base(pool, remoteEndPoint) + public Http2Connection(HttpConnectionPool pool, Stream stream, Activity? connectionSetupActivity, IPEndPoint? remoteEndPoint) + : base(pool, connectionSetupActivity, remoteEndPoint) { _stream = stream; @@ -1844,7 +1844,6 @@ private void FinalTeardown() Debug.Assert(_streamsInUse == 0); GC.SuppressFinalize(this); - _stream.Dispose(); _connectionWindow.Dispose(); @@ -1988,6 +1987,7 @@ public async Task SendAsync(HttpRequestMessage request, boo Debug.Assert(async); Debug.Assert(!_pool.HasSyncObjLock); if (NetEventSource.Log.IsEnabled()) Trace($"Sending request: {request}"); + if (ConnectionSetupActivity is not null) ConnectionSetupDistributedTracing.AddConnectionLinkToRequestActivity(ConnectionSetupActivity); try { diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs index c00071ac3897c..d2f1389ae1207 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs @@ -89,9 +89,9 @@ public Http3Connection(HttpConnectionPool pool, HttpAuthority authority, bool in } } - public void InitQuicConnection(QuicConnection connection) + public void InitQuicConnection(QuicConnection connection, Activity? connectionSetupActivity) { - MarkConnectionAsEstablished(connection.RemoteEndPoint); + MarkConnectionAsEstablished(connectionSetupActivity: connectionSetupActivity, remoteEndPoint: connection.RemoteEndPoint); _connection = connection; @@ -241,7 +241,7 @@ public Task WaitForAvailableStreamsAsync() } } - public async Task SendAsync(HttpRequestMessage request, long queueStartingTimestamp, CancellationToken cancellationToken) + public async Task SendAsync(HttpRequestMessage request, long queueStartingTimestamp, Activity? waitForConnectionActivity, CancellationToken cancellationToken) { // Allocate an active request QuicStream? quicStream = null; @@ -269,10 +269,17 @@ public async Task SendAsync(HttpRequestMessage request, lon } // Swallow any exceptions caused by the connection being closed locally or even disposed due to a race. // Since quicStream will stay `null`, the code below will throw appropriate exception to retry the request. - catch (ObjectDisposedException) { } - catch (QuicException e) when (e.QuicError != QuicError.OperationAborted) { } + catch (ObjectDisposedException e) + { + ConnectionSetupDistributedTracing.ReportError(waitForConnectionActivity, e); + } + catch (QuicException e) when (e.QuicError != QuicError.OperationAborted) + { + ConnectionSetupDistributedTracing.ReportError(waitForConnectionActivity, e); + } finally { + waitForConnectionActivity?.Stop(); if (queueStartingTimestamp != 0) { TimeSpan duration = Stopwatch.GetElapsedTime(queueStartingTimestamp); @@ -304,6 +311,8 @@ public async Task SendAsync(HttpRequestMessage request, lon throw new HttpRequestException(HttpRequestError.Unknown, SR.net_http_request_aborted, null, RequestRetryType.RetryOnConnectionFailure); } + Debug.Assert(waitForConnectionActivity?.IsStopped != false); + if (ConnectionSetupActivity is not null) ConnectionSetupDistributedTracing.AddConnectionLinkToRequestActivity(ConnectionSetupActivity); if (NetEventSource.Log.IsEnabled()) Trace($"Sending request: {request}"); Task responseTask = requestStream.SendAsync(cancellationToken); diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs index c850389203d3d..e71c4c743d631 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs @@ -74,8 +74,9 @@ public HttpConnection( HttpConnectionPool pool, Stream stream, TransportContext? transportContext, + Activity? connectionSetupActivity, IPEndPoint? remoteEndPoint) - : base(pool, remoteEndPoint) + : base(pool, connectionSetupActivity, remoteEndPoint) { Debug.Assert(stream != null); @@ -547,6 +548,7 @@ public async Task SendAsync(HttpRequestMessage request, boo // Send the request. if (NetEventSource.Log.IsEnabled()) Trace($"Sending request: {request}"); + if (ConnectionSetupActivity is not null) ConnectionSetupDistributedTracing.AddConnectionLinkToRequestActivity(ConnectionSetupActivity); CancellationTokenRegistration cancellationRegistration = RegisterCancellation(cancellationToken); try { diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionBase.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionBase.cs index eb4ee5546fd60..c5e578f45b2bc 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionBase.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionBase.cs @@ -1,6 +1,7 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System.Collections.Generic; using System.Diagnostics; using System.Diagnostics.CodeAnalysis; using System.IO; @@ -37,20 +38,24 @@ internal abstract class HttpConnectionBase : IDisposable, IHttpTrace public long Id { get; } = Interlocked.Increment(ref s_connectionCounter); + public Activity? ConnectionSetupActivity { get; private set; } + public HttpConnectionBase(HttpConnectionPool pool) { Debug.Assert(this is HttpConnection or Http2Connection or Http3Connection); Debug.Assert(pool != null); _pool = pool; } - public HttpConnectionBase(HttpConnectionPool pool, IPEndPoint? remoteEndPoint) + + public HttpConnectionBase(HttpConnectionPool pool, Activity? connectionSetupActivity, IPEndPoint? remoteEndPoint) : this(pool) { - MarkConnectionAsEstablished(remoteEndPoint); + MarkConnectionAsEstablished(connectionSetupActivity, remoteEndPoint); } - protected void MarkConnectionAsEstablished(IPEndPoint? remoteEndPoint) + protected void MarkConnectionAsEstablished(Activity? connectionSetupActivity, IPEndPoint? remoteEndPoint) { + ConnectionSetupActivity = connectionSetupActivity; Debug.Assert(_pool.Settings._metrics is not null); SocketsHttpHandlerMetrics metrics = _pool.Settings._metrics; diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs index 77b8893318343..29a03a52d1ab3 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs @@ -8,6 +8,7 @@ using System.IO; using System.Linq; using System.Net.Http.Headers; +using System.Net.Sockets; using System.Net.Test.Common; using System.Reflection; using System.Threading; @@ -457,7 +458,6 @@ await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( }, UseVersion.ToString(), TestAsync.ToString(), statusCode.ToString(), method).DisposeAsync(); } - [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] [InlineData(200, "GET")] [InlineData(404, "GET")] @@ -578,6 +578,243 @@ protected static void VerifyTag(KeyValuePair[] tags, string } } + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData(false)] + [InlineData(true)] + public async Task SendAsync_Success_ConnectionSetupActivityGraphRecorded(bool useTls) + { + if (UseVersion == HttpVersion30 && !useTls) return; + + await RemoteExecutor.Invoke(RunTest, UseVersion.ToString(), TestAsync.ToString(), useTls.ToString()).DisposeAsync(); + static async Task RunTest(string useVersion, string testAsync, string useTlsString) + { + bool useTls = bool.Parse(useTlsString); + + Activity parentActivity = new Activity("parent").Start(); + + using ActivityRecorder requestRecorder = new("System.Net.Http", "System.Net.Http.HttpRequestOut") + { + ExpectedParent = parentActivity + }; + using ActivityRecorder waitForConnectionRecorder = new("Experimental.System.Net.Http.Connections", "Experimental.System.Net.Http.Connections.WaitForConnection") + { + VerifyParent = false + }; + + using ActivityRecorder connectionSetupRecorder = new("Experimental.System.Net.Http.Connections", "Experimental.System.Net.Http.Connections.ConnectionSetup"); + using ActivityRecorder dnsRecorder = new("Experimental.System.Net.NameResolution", "Experimental.System.Net.NameResolution.DnsLookup") { VerifyParent = false }; + using ActivityRecorder socketRecorder = new("Experimental.System.Net.Sockets", "Experimental.System.Net.Sockets.Connect") { VerifyParent = false }; + using ActivityRecorder tlsRecorder = new("Experimental.System.Net.Security", "Experimental.System.Net.Security.TlsHandshake") + { + VerifyParent = false + }; + + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => + { + Version version = Version.Parse(useVersion); + if (version != HttpVersion30) + { + uri = new Uri($"{uri.Scheme}://localhost:{uri.Port}"); + } + + using HttpClient client = new HttpClient(CreateHttpClientHandler(allowAllCertificates: true)); + + await client.SendAsync(bool.Parse(testAsync), CreateRequest(HttpMethod.Get, uri, version, exactVersion: true)); + + Activity req1 = requestRecorder.VerifyActivityRecordedOnce(); + Activity wait1 = waitForConnectionRecorder.VerifyActivityRecordedOnce(); + Activity conn = connectionSetupRecorder.VerifyActivityRecordedOnce(); + + Activity? dns = null; + Activity? sock = null; + Activity? tls = null; + + if (version != HttpVersion30) + { + dns = dnsRecorder.VerifyActivityRecordedOnce(); + Assert.True(socketRecorder.Stopped is 1 or 2); + sock = socketRecorder.LastFinishedActivity; + + if (useTls) + { + tls = tlsRecorder.FinishedActivities.Single(a => a.DisplayName.StartsWith("TLS client")); + } + else + { + tlsRecorder.VerifyActivityRecorded(0); + } + } + + // Verify relationships between request and connection_setup, wait_for_connection: + Assert.Same(parentActivity, req1.Parent); + Assert.Same(req1, wait1.Parent); + + // Verify timing relationships between request, wait_for_connection, connection_setup: + ActivityAssert.FinishedInOrder(conn, wait1); + ActivityAssert.FinishedInOrder(wait1, req1); + + // req1->conn link: + req1.Links.Single(l => l.Context == conn.Context); + + // Verify the connection_setup graph: + Assert.Null(conn.Parent); + + if (version != HttpVersion30) + { + Assert.Same(conn, dns.Parent); + Assert.Same(conn, sock.Parent); + if (useTls) + { + Assert.Same(conn, tls.Parent); + } + + // Verify timing relationships for connection setup: + ActivityAssert.FinishedInOrder(dns, sock); + if (useTls) + { + ActivityAssert.FinishedInOrder(sock, tls); + ActivityAssert.FinishedInOrder(tls, conn); + } + else + { + ActivityAssert.FinishedInOrder(sock, conn); + } + } + + // Verify display names and attributes: + Assert.Equal(ActivityKind.Internal, wait1.Kind); + Assert.Equal(ActivityKind.Internal, conn.Kind); + Assert.Equal($"HTTP wait_for_connection {uri.Host}:{uri.Port}", wait1.DisplayName); + Assert.Equal($"HTTP connection_setup {uri.Host}:{uri.Port}", conn.DisplayName); + ActivityAssert.HasTag(conn, "network.peer.address", + (string a) => a == IPAddress.Loopback.ToString() || + a == IPAddress.Loopback.MapToIPv6().ToString() || + a == IPAddress.IPv6Loopback.ToString()); + ActivityAssert.HasTag(conn, "server.address", uri.Host); + ActivityAssert.HasTag(conn, "server.port", uri.Port); + ActivityAssert.HasTag(conn, "url.scheme", useTls ? "https" : "http"); + + // The second request should reuse the first connection, connection_setup and wait_for_connection should not be recorded again. + await client.SendAsync(CreateRequest(HttpMethod.Get, uri, Version.Parse(useVersion), exactVersion: true)); + requestRecorder.VerifyActivityRecorded(2); + Activity req2 = requestRecorder.LastFinishedActivity; + Assert.NotSame(req1, req2); + waitForConnectionRecorder.VerifyActivityRecorded(version == HttpVersion30 ? 2 : 1); + connectionSetupRecorder.VerifyActivityRecorded(1); + + // The second request should also have a link to the shared connection. + req2.Links.Single(l => l.Context == conn.Context); + }, + async server => + { + await server.AcceptConnectionAsync(async connection => + { + await connection.ReadRequestDataAsync(); + await connection.SendResponseAsync(HttpStatusCode.OK); + connection.CompleteRequestProcessing(); + + await connection.ReadRequestDataAsync(); + await connection.SendResponseAsync(HttpStatusCode.OK); + }); + }, options: new GenericLoopbackOptions() + { + UseSsl = useTls + }); + } + } + + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData("dns")] + [InlineData("socket")] + public async Task SendAsync_ConnectionFailure_RecordsActivitiesWithCorrectErrorInfo(string failureType) + { + await RemoteExecutor.Invoke(RunTest, UseVersion.ToString(), TestAsync.ToString(), failureType).DisposeAsync(); + static async Task RunTest(string useVersion, string testAsync, string failureType) + { + Version version = Version.Parse(useVersion); + + using HttpClientHandler handler = CreateHttpClientHandler(allowAllCertificates: true); + using HttpClient client = new HttpClient(handler); + + Activity parentActivity = new Activity("parent").Start(); + using ActivityRecorder requestRecorder = new("System.Net.Http", "System.Net.Http.HttpRequestOut") + { + ExpectedParent = parentActivity + }; + using ActivityRecorder waitForConnectionRecorder = new("Experimental.System.Net.Http.Connections", "Experimental.System.Net.Http.Connections.WaitForConnection") + { + VerifyParent = false + }; + using ActivityRecorder connectionSetupRecorder = new("Experimental.System.Net.Http.Connections", "Experimental.System.Net.Http.Connections.ConnectionSetup"); + using ActivityRecorder dnsRecorder = new("Experimental.System.Net.NameResolution", "Experimental.System.Net.NameResolution.DnsLookup") { VerifyParent = false }; + using ActivityRecorder socketRecorder = new("Experimental.System.Net.Sockets", "Experimental.System.Net.Sockets.Connect") { VerifyParent = false }; + + Uri uri; + using Socket? notListening = failureType is "socket" + ? (version == HttpVersion30) ? new Socket(AddressFamily.InterNetwork, SocketType.Dgram, ProtocolType.Udp) : new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp) + : null; + + if (failureType is "dns") + { + uri = new Uri("https://does.not.exist.sorry"); + } + else + { + Debug.Assert(notListening is not null); + notListening.Bind(new IPEndPoint(IPAddress.Loopback, 0)); + IPEndPoint ep = (IPEndPoint)notListening.LocalEndPoint; + uri = new Uri($"https://{ep.Address}:{ep.Port}"); + } + + using HttpRequestMessage request = CreateRequest(HttpMethod.Get, uri, version, exactVersion: true); + await Assert.ThrowsAsync(() => client.SendAsync(bool.Parse(testAsync), request)); + + Activity req = requestRecorder.VerifyActivityRecordedOnce(); + Activity wait = waitForConnectionRecorder.VerifyActivityRecordedOnce(); + Activity conn = connectionSetupRecorder.VerifyActivityRecordedOnce(); + + Assert.Same(req, wait.Parent); + Assert.Null(conn.Parent); + + if (failureType == "dns") + { + Assert.Equal(ActivityStatusCode.Error, conn.Status); + Assert.Equal(ActivityStatusCode.Error, wait.Status); + + ActivityAssert.HasTag(conn, "error.type", "name_resolution_error"); + ActivityAssert.HasTag(wait, "error.type", "name_resolution_error"); + + // Whether System.Net.Quic uses System.Net.Dns is an implementation detail. + if (version != HttpVersion30) + { + Activity dns = dnsRecorder.VerifyActivityRecordedOnce(); + Assert.Same(conn, dns.Parent); + Assert.Equal(ActivityStatusCode.Error, dns.Status); + ActivityAssert.HasTag(dns, "error.type", (string t) => t is "host_not_found" or "timed_out"); + } + } + else + { + Debug.Assert(failureType is "socket"); + + Assert.Equal(ActivityStatusCode.Error, conn.Status); + Assert.Equal(ActivityStatusCode.Error, wait.Status); + + ActivityAssert.HasTag(conn, "error.type", "connection_error"); + ActivityAssert.HasTag(wait, "error.type", "connection_error"); + + if (version != HttpVersion30) + { + Activity sock = socketRecorder.VerifyActivityRecordedOnce(); + Assert.Same(conn, sock.Parent); + Assert.Equal(ActivityStatusCode.Error, sock.Status); + ActivityAssert.HasTag(sock, "error.type", (string t) => t is "connection_refused" or "timed_out"); + } + } + } + } + [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public async Task SendAsync_ExpectedDiagnosticSourceActivityLogging_InvalidBaggage() { @@ -1189,7 +1426,7 @@ public static IEnumerable SocketsHttpHandler_ActivityCreation_MemberDa public async Task SendAsync_ActivityIsCreatedIfRequested(bool currentActivitySet, bool? diagnosticListenerActivityEnabled, bool? activitySourceCreatesActivity) { string parameters = $"{currentActivitySet},{diagnosticListenerActivityEnabled},{activitySourceCreatesActivity}"; - await RemoteExecutor.Invoke(async (useVersion, testAsync, parametersString) => + await RemoteExecutor.Invoke(static async (useVersion, testAsync, parametersString) => { bool?[] parameters = parametersString.Split(',').Select(p => p.Length == 0 ? (bool?)null : bool.Parse(p)).ToArray(); bool currentActivitySet = parameters[0].Value; @@ -1201,7 +1438,7 @@ await RemoteExecutor.Invoke(async (useVersion, testAsync, parametersString) => { ActivitySource.AddActivityListener(new ActivityListener { - ShouldListenTo = _ => true, + ShouldListenTo = s => s.Name is "System.Net.Http", Sample = (ref ActivityCreationOptions _) => { madeASamplingDecision = true; @@ -1230,7 +1467,7 @@ await RemoteExecutor.Invoke(async (useVersion, testAsync, parametersString) => // (when a DiagnosticListener forced one to be created) ActivitySource.AddActivityListener(new ActivityListener { - ShouldListenTo = _ => true, + ShouldListenTo = s => s.Name is "System.Net.Http" or "", ActivityStarted = created => { Assert.Null(parent); @@ -1269,8 +1506,8 @@ await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( Assert.Equal(activitySourceCreatesActivity.HasValue, madeASamplingDecision); Assert.Equal(diagnosticListenerActivityEnabled.HasValue, listenerCallbackWasCalled); - }, UseVersion.ToString(), TestAsync.ToString(), parameters).DisposeAsync(); - } + }, UseVersion.ToString(), TestAsync.ToString(), parameters).DisposeAsync(); + } private static T GetProperty(object obj, string propertyName) { diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/System.Net.Http.Functional.Tests.csproj b/src/libraries/System.Net.Http/tests/FunctionalTests/System.Net.Http.Functional.Tests.csproj index e38b4780a34c5..06a51a3f4a55a 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/System.Net.Http.Functional.Tests.csproj +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/System.Net.Http.Functional.Tests.csproj @@ -79,6 +79,8 @@ Link="CommonTest\System\Security\Cryptography\X509Certificates\CertificateAuthority.cs" /> + Gets the host name of the local machine. public static string GetHostName() { - long startingTimestamp = NameResolutionTelemetry.Log.BeforeResolution(string.Empty); + NameResolutionActivity activity = NameResolutionTelemetry.Log.BeforeResolution(string.Empty); string name; try { name = NameResolutionPal.GetHostName(); } - catch (Exception ex) when (LogFailure(string.Empty, startingTimestamp, ex)) + catch (Exception ex) when (LogFailure(string.Empty, activity, ex)) { Debug.Fail("LogFailure should return false"); throw; } - NameResolutionTelemetry.Log.AfterResolution(string.Empty, startingTimestamp); + NameResolutionTelemetry.Log.AfterResolution(string.Empty, activity, answer: name); if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(null, name); return name; @@ -155,8 +155,8 @@ public static Task GetHostEntryAsync(IPAddress address) throw new ArgumentException(SR.net_invalid_ip_addr, nameof(address)); } - return RunAsync(static (s, startingTimestamp) => { - IPHostEntry ipHostEntry = GetHostEntryCore((IPAddress)s, AddressFamily.Unspecified, startingTimestamp); + return RunAsync(static (s, activity) => { + IPHostEntry ipHostEntry = GetHostEntryCore((IPAddress)s, AddressFamily.Unspecified, activity); if (NetEventSource.Log.IsEnabled()) NetEventSource.Info((IPAddress)s, $"{ipHostEntry} with {ipHostEntry.AddressList.Length} entries"); return ipHostEntry; }, address, CancellationToken.None); @@ -361,18 +361,18 @@ public static IPHostEntry EndResolve(IAsyncResult asyncResult) return ipHostEntry; } - private static IPHostEntry GetHostEntryCore(string hostName, AddressFamily addressFamily, long? startingTimestamp = null) => - (IPHostEntry)GetHostEntryOrAddressesCore(hostName, justAddresses: false, addressFamily, startingTimestamp); + private static IPHostEntry GetHostEntryCore(string hostName, AddressFamily addressFamily, NameResolutionActivity? activityOrDefault = default) => + (IPHostEntry)GetHostEntryOrAddressesCore(hostName, justAddresses: false, addressFamily, activityOrDefault); - private static IPAddress[] GetHostAddressesCore(string hostName, AddressFamily addressFamily, long? startingTimestamp = null) => - (IPAddress[])GetHostEntryOrAddressesCore(hostName, justAddresses: true, addressFamily, startingTimestamp); + private static IPAddress[] GetHostAddressesCore(string hostName, AddressFamily addressFamily, NameResolutionActivity? activityOrDefault = default) => + (IPAddress[])GetHostEntryOrAddressesCore(hostName, justAddresses: true, addressFamily, activityOrDefault); - private static object GetHostEntryOrAddressesCore(string hostName, bool justAddresses, AddressFamily addressFamily, long? startingTimestamp = null) + private static object GetHostEntryOrAddressesCore(string hostName, bool justAddresses, AddressFamily addressFamily, NameResolutionActivity? activityOrDefault = default) { ValidateHostName(hostName); - // startingTimestamp may have already been set if we're being called from RunAsync. - startingTimestamp ??= NameResolutionTelemetry.Log.BeforeResolution(hostName); + // NameResolutionActivity may have already been set if we're being called from RunAsync. + NameResolutionActivity activity = activityOrDefault ?? NameResolutionTelemetry.Log.BeforeResolution(hostName); object result; try @@ -394,33 +394,33 @@ private static object GetHostEntryOrAddressesCore(string hostName, bool justAddr Aliases = aliases }; } - catch (Exception ex) when (LogFailure(hostName, startingTimestamp, ex)) + catch (Exception ex) when (LogFailure(hostName, activity, ex)) { Debug.Fail("LogFailure should return false"); throw; } - NameResolutionTelemetry.Log.AfterResolution(hostName, startingTimestamp); + NameResolutionTelemetry.Log.AfterResolution(hostName, activity, answer: result); return result; } - private static IPHostEntry GetHostEntryCore(IPAddress address, AddressFamily addressFamily, long? startingTimestamp = null) => - (IPHostEntry)GetHostEntryOrAddressesCore(address, justAddresses: false, addressFamily, startingTimestamp); + private static IPHostEntry GetHostEntryCore(IPAddress address, AddressFamily addressFamily, NameResolutionActivity? activityOrDefault = default) => + (IPHostEntry)GetHostEntryOrAddressesCore(address, justAddresses: false, addressFamily, activityOrDefault); - private static IPAddress[] GetHostAddressesCore(IPAddress address, AddressFamily addressFamily, long? startingTimestamp = null) => - (IPAddress[])GetHostEntryOrAddressesCore(address, justAddresses: true, addressFamily, startingTimestamp); + private static IPAddress[] GetHostAddressesCore(IPAddress address, AddressFamily addressFamily, NameResolutionActivity? activityOrDefault = default) => + (IPAddress[])GetHostEntryOrAddressesCore(address, justAddresses: true, addressFamily, activityOrDefault); // Does internal IPAddress reverse and then forward lookups (for Legacy and current public methods). - private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAddresses, AddressFamily addressFamily, long? startingTimestamp = null) + private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAddresses, AddressFamily addressFamily, NameResolutionActivity? activityOrDefault = default) { // Try to get the data for the host from its address. // We need to call getnameinfo first, because getaddrinfo w/ the ipaddress string // will only return that address and not the full list. // Do a reverse lookup to get the host name. - // startingTimestamp may have already been set if we're being called from RunAsync. - startingTimestamp ??= NameResolutionTelemetry.Log.BeforeResolution(address); + // NameResolutionActivity may have already been set if we're being called from RunAsync. + NameResolutionActivity activity = activityOrDefault ?? NameResolutionTelemetry.Log.BeforeResolution(address); SocketError errorCode; string? name; @@ -434,16 +434,16 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd } Debug.Assert(name != null); } - catch (Exception ex) when (LogFailure(address, startingTimestamp, ex)) + catch (Exception ex) when (LogFailure(address, activity, ex)) { Debug.Fail("LogFailure should return false"); throw; } - NameResolutionTelemetry.Log.AfterResolution(address, startingTimestamp); + NameResolutionTelemetry.Log.AfterResolution(address, activity, answer: name); // Do the forward lookup to get the IPs for that host name - startingTimestamp = NameResolutionTelemetry.Log.BeforeResolution(name); + activity = NameResolutionTelemetry.Log.BeforeResolution(name); object result; try @@ -464,13 +464,13 @@ private static object GetHostEntryOrAddressesCore(IPAddress address, bool justAd AddressList = addresses }; } - catch (Exception ex) when (LogFailure(name, startingTimestamp, ex)) + catch (Exception ex) when (LogFailure(name, activity, ex)) { Debug.Fail("LogFailure should return false"); throw; } - NameResolutionTelemetry.Log.AfterResolution(name, startingTimestamp); + NameResolutionTelemetry.Log.AfterResolution(name, activity, answer: result); // One of three things happened: // 1. Success. @@ -530,7 +530,7 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR ValidateHostName(hostName); Task? t; - if (NameResolutionTelemetry.Log.IsEnabled() || NameResolutionMetrics.IsEnabled()) + if (NameResolutionTelemetry.AnyDiagnosticsEnabled()) { t = justAddresses ? GetAddrInfoWithTelemetryAsync(hostName, justAddresses, family, cancellationToken) @@ -554,23 +554,23 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR if (justAddresses) { - return RunAsync(static (s, startingTimestamp) => s switch + return RunAsync(static (s, activity) => s switch { - string h => GetHostAddressesCore(h, AddressFamily.Unspecified, startingTimestamp), - KeyValuePair t => GetHostAddressesCore(t.Key, t.Value, startingTimestamp), - IPAddress a => GetHostAddressesCore(a, AddressFamily.Unspecified, startingTimestamp), - KeyValuePair t => GetHostAddressesCore(t.Key, t.Value, startingTimestamp), + string h => GetHostAddressesCore(h, AddressFamily.Unspecified, activity), + KeyValuePair t => GetHostAddressesCore(t.Key, t.Value, activity), + IPAddress a => GetHostAddressesCore(a, AddressFamily.Unspecified, activity), + KeyValuePair t => GetHostAddressesCore(t.Key, t.Value, activity), _ => null }, asyncState, cancellationToken); } else { - return RunAsync(static (s, startingTimestamp) => s switch + return RunAsync(static (s, activity) => s switch { - string h => GetHostEntryCore(h, AddressFamily.Unspecified, startingTimestamp), - KeyValuePair t => GetHostEntryCore(t.Key, t.Value, startingTimestamp), - IPAddress a => GetHostEntryCore(a, AddressFamily.Unspecified, startingTimestamp), - KeyValuePair t => GetHostEntryCore(t.Key, t.Value, startingTimestamp), + string h => GetHostEntryCore(h, AddressFamily.Unspecified, activity), + KeyValuePair t => GetHostEntryCore(t.Key, t.Value, activity), + IPAddress a => GetHostEntryCore(a, AddressFamily.Unspecified, activity), + KeyValuePair t => GetHostEntryCore(t.Key, t.Value, activity), _ => null }, asyncState, cancellationToken); } @@ -591,13 +591,15 @@ private static Task GetHostEntryOrAddressesCoreAsync(string hostName, bool justR // We will retry on thread-pool. return null; - static async Task CompleteAsync(Task task, string hostName, long startingTimestamp) + static async Task CompleteAsync(Task task, string hostName, long startingTimeStamp) { - _ = NameResolutionTelemetry.Log.BeforeResolution(hostName); + NameResolutionActivity activity = NameResolutionTelemetry.Log.BeforeResolution(hostName, startingTimeStamp); Exception? exception = null; + T? result = null; try { - return await ((Task)task).ConfigureAwait(false); + result = await ((Task)task).ConfigureAwait(false); + return result; } catch (Exception ex) { @@ -606,7 +608,7 @@ static async Task CompleteAsync(Task task, string hostName, long startingTime } finally { - NameResolutionTelemetry.Log.AfterResolution(hostName, startingTimestamp, exception); + NameResolutionTelemetry.Log.AfterResolution(hostName, activity, answer: result, exception: exception); } } } @@ -631,9 +633,9 @@ private static void ValidateHostName(string hostName) } } - private static bool LogFailure(object hostNameOrAddress, long? startingTimestamp, Exception exception) + private static bool LogFailure(object hostNameOrAddress, in NameResolutionActivity activity, Exception exception) { - NameResolutionTelemetry.Log.AfterResolution(hostNameOrAddress, startingTimestamp, exception); + NameResolutionTelemetry.Log.AfterResolution(hostNameOrAddress, activity, answer: null, exception: exception); return false; } @@ -651,9 +653,16 @@ private static bool LogFailure(object hostNameOrAddress, long? startingTimestamp /// than having all concurrent requests for the same host share the exact same task, so that any shuffling of the results /// by the OS to enable round robin is still perceived. /// - private static Task RunAsync(Func func, object key, CancellationToken cancellationToken) + private static Task RunAsync(Func func, object key, CancellationToken cancellationToken) { - long startingTimestamp = NameResolutionTelemetry.Log.BeforeResolution(key); + bool tracingEnabled = NameResolutionActivity.IsTracingEnabled(); + Activity? activityToRestore = tracingEnabled ? Activity.Current : null; + NameResolutionActivity activity = NameResolutionTelemetry.Log.BeforeResolution(key); + if (tracingEnabled) + { + // Do not overwrite Activity.Current in the caller's ExecutionContext. + Activity.Current = activityToRestore; + } Task? task = null; @@ -670,7 +679,7 @@ private static Task RunAsync(Func func, Debug.Assert(!Monitor.IsEntered(s_tasks)); try { - return func(key, startingTimestamp); + return func(key, activity); } finally { @@ -695,7 +704,7 @@ private static Task RunAsync(Func func, { ((ICollection>)s_tasks).Remove(new KeyValuePair(key!, task)); // Since it was canceled, func(..) had not executed and call AfterResolution it needs to be called here. - NameResolutionTelemetry.Log.AfterResolution(key!, startingTimestamp, new OperationCanceledException()); + NameResolutionTelemetry.Log.AfterResolution(key!, activity, new OperationCanceledException()); } }, key, CancellationToken.None, TaskContinuationOptions.OnlyOnCanceled | TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default); } diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionMetrics.cs b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionMetrics.cs index 580254289f9f7..7c0857d376f37 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionMetrics.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionMetrics.cs @@ -36,19 +36,10 @@ public static void AfterResolution(TimeSpan duration, string hostName, Exception } else { - var errorTypeTag = KeyValuePair.Create("error.type", (object?)GetErrorType(exception)); + string errorType = NameResolutionTelemetry.GetErrorType(exception); + var errorTypeTag = KeyValuePair.Create("error.type", (object?)errorType); s_lookupDuration.Record(duration.TotalSeconds, hostNameTag, errorTypeTag); } } - - private static string GetErrorType(Exception exception) => (exception as SocketException)?.SocketErrorCode switch - { - SocketError.HostNotFound => "host_not_found", - SocketError.TryAgain => "try_again", - SocketError.AddressFamilyNotSupported => "address_family_not_supported", - SocketError.NoRecovery => "no_recovery", - - _ => exception.GetType().FullName! - }; } } diff --git a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs index 73ed325712ac5..07a252fbd250c 100644 --- a/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs +++ b/src/libraries/System.Net.NameResolution/src/System/Net/NameResolutionTelemetry.cs @@ -58,10 +58,17 @@ protected override void OnEventCommand(EventCommandEventArgs command) [Event(ResolutionFailedEventId, Level = EventLevel.Informational)] private void ResolutionFailed() => WriteEvent(ResolutionFailedEventId); + [NonEvent] + public static bool AnyDiagnosticsEnabled() => Log.IsEnabled() || NameResolutionMetrics.IsEnabled() || NameResolutionActivity.IsTracingEnabled(); [NonEvent] - public long BeforeResolution(object hostNameOrAddress) + public NameResolutionActivity BeforeResolution(object hostNameOrAddress, long startingTimestamp = 0) { + if (!AnyDiagnosticsEnabled()) + { + return default; + } + if (IsEnabled()) { Interlocked.Increment(ref _lookupsRequested); @@ -74,23 +81,22 @@ public long BeforeResolution(object hostNameOrAddress) ResolutionStart(host); } - return Stopwatch.GetTimestamp(); + startingTimestamp = startingTimestamp is not 0 ? startingTimestamp : Stopwatch.GetTimestamp(); } - return NameResolutionMetrics.IsEnabled() ? Stopwatch.GetTimestamp() : 0; + startingTimestamp = startingTimestamp is not 0 ? startingTimestamp : NameResolutionMetrics.IsEnabled() ? Stopwatch.GetTimestamp() : 0; + return new NameResolutionActivity(hostNameOrAddress, startingTimestamp); } [NonEvent] - public void AfterResolution(object hostNameOrAddress, long? startingTimestamp, Exception? exception = null) + public void AfterResolution(object hostNameOrAddress, in NameResolutionActivity activity, object? answer, Exception? exception = null) { - Debug.Assert(startingTimestamp.HasValue); - if (startingTimestamp == 0) + if (!activity.Stop(answer, exception, out TimeSpan duration)) { + // We stopped the System.Diagnostics.Activity at this point and neither metrics nor EventSource is enabled. return; } - TimeSpan duration = Stopwatch.GetElapsedTime(startingTimestamp.Value); - if (IsEnabled()) { Interlocked.Decrement(ref _currentLookups); @@ -114,7 +120,8 @@ public void AfterResolution(object hostNameOrAddress, long? startingTimestamp, E } } - private static string GetHostnameFromStateObject(object hostNameOrAddress) + [NonEvent] + internal static string GetHostnameFromStateObject(object hostNameOrAddress) { Debug.Assert(hostNameOrAddress is not null); @@ -131,5 +138,103 @@ private static string GetHostnameFromStateObject(object hostNameOrAddress) return host; } + + [NonEvent] + internal static string GetErrorType(Exception exception) => (exception as SocketException)?.SocketErrorCode switch + { + SocketError.HostNotFound => "host_not_found", + SocketError.TryAgain => "try_again", + SocketError.AddressFamilyNotSupported => "address_family_not_supported", + SocketError.NoRecovery => "no_recovery", + + _ => exception.GetType().FullName! + }; + } + + /// + /// Encapsulates the starting timestamp together with an optional Activity, to represent the name resolution span for various telemetry pillars. + /// + internal readonly struct NameResolutionActivity + { + private const string ActivitySourceName = "Experimental.System.Net.NameResolution"; + private const string ActivityName = ActivitySourceName + ".DnsLookup"; + private static readonly ActivitySource s_activitySource = new ActivitySource(ActivitySourceName); + + // _startingTimestamp == 0 means NameResolutionTelemetry and NameResolutionMetrics are both disabled. + private readonly long _startingTimestamp; + private readonly Activity? _activity; + + public NameResolutionActivity(object hostNameOrAddress, long startingTimestamp) + { + _startingTimestamp = startingTimestamp; + _activity = s_activitySource.StartActivity(ActivityName); + if (_activity is not null) + { + string host = NameResolutionTelemetry.GetHostnameFromStateObject(hostNameOrAddress); + _activity.DisplayName = hostNameOrAddress is IPAddress ? $"DNS reverse lookup {host}" : $"DNS lookup {host}"; + if (_activity.IsAllDataRequested) + { + _activity.SetTag("dns.question.name", host); + } + } + } + + public static bool IsTracingEnabled() => s_activitySource.HasListeners(); + + // Returns true if either NameResolutionTelemetry or NameResolutionMetrics is enabled. + public bool Stop(object? answer, Exception? exception, out TimeSpan duration) + { + if (_activity is not null) + { + if (_activity.IsAllDataRequested) + { + if (answer is not null) + { + string[]? answerValues = answer switch + { + string h => [h], + IPAddress[] addresses => GetStringValues(addresses), + IPHostEntry entry => GetStringValues(entry.AddressList), + _ => null + }; + + Debug.Assert(answerValues is not null); + _activity.SetTag("dns.answers", answerValues); + } + else + { + Debug.Assert(exception is not null); + string errorType = NameResolutionTelemetry.GetErrorType(exception); + _activity.SetTag("error.type", errorType); + } + } + + if (exception is not null) + { + _activity.SetStatus(ActivityStatusCode.Error); + } + + _activity.Stop(); + } + + if (_startingTimestamp == 0) + { + duration = default; + return false; + } + + duration = Stopwatch.GetElapsedTime(_startingTimestamp); + return true; + + static string[] GetStringValues(IPAddress[] addresses) + { + string[] result = new string[addresses.Length]; + for (int i = 0; i < addresses.Length; i++) + { + result[i] = addresses[i].ToString(); + } + return result; + } + } } } diff --git a/src/libraries/System.Net.NameResolution/tests/FunctionalTests/ActivityTest.cs b/src/libraries/System.Net.NameResolution/tests/FunctionalTests/ActivityTest.cs new file mode 100644 index 0000000000000..13dfeb908942c --- /dev/null +++ b/src/libraries/System.Net.NameResolution/tests/FunctionalTests/ActivityTest.cs @@ -0,0 +1,170 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; +using System.Net.Sockets; +using System.Net.Test.Common; +using System.Threading.Tasks; +using Microsoft.DotNet.RemoteExecutor; +using Xunit; + +namespace System.Net.NameResolution.Tests +{ + public class ActivityTest + { + private const string ActivitySourceName = "Experimental.System.Net.NameResolution"; + private const string ActivityName = ActivitySourceName + ".DnsLookup"; + + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData(false)] + [InlineData(true)] + public async Task ForwardLookup_ValidHostName_ActivityRecorded(bool createParentActivity) + { + await RemoteExecutor.Invoke(static async (createParentActivity) => + { + const string ValidHostName = "localhost"; + using var recorder = new ActivityRecorder(ActivitySourceName, ActivityName) + { + ExpectedParent = bool.Parse(createParentActivity) ? new Activity("parent").Start() : null + }; + + string expected4 = IPAddress.Loopback.ToString(); + string expected6 = IPAddress.IPv6Loopback.ToString(); + + await Dns.GetHostEntryAsync(ValidHostName); + Verify(1); + + await Dns.GetHostAddressesAsync(ValidHostName); + Verify(2); + + Dns.GetHostEntry(ValidHostName); + Verify(3); + + Dns.GetHostAddresses(ValidHostName); + Verify(4); + + Dns.EndGetHostEntry(Dns.BeginGetHostEntry(ValidHostName, null, null)); + Verify(5); + + Dns.EndGetHostAddresses(Dns.BeginGetHostAddresses(ValidHostName, null, null)); + Verify(6); + + void Verify(int timesLookupRecorded) + { + recorder.VerifyActivityRecorded(timesLookupRecorded); + Activity activity = recorder.LastFinishedActivity; + VerifyForwardActivityInfo(activity, ValidHostName); + ActivityAssert.HasTag(activity, "dns.answers", (string[] answers) => answers.Contains(expected4) || answers.Contains(expected6)); + ActivityAssert.HasNoTag(activity, "error.type"); + } + + }, createParentActivity.ToString()).DisposeAsync(); + } + + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData(false)] + [InlineData(true)] + public async Task ReverseLookup_ValidIP_ActivityRecorded(bool createParentActivity) + { + await RemoteExecutor.Invoke(static async (createParentActivity) => + { + string loopbackIPString = IPAddress.Loopback.ToString(); + using var recorder = new ActivityRecorder(ActivitySourceName, ActivityName) + { + ExpectedParent = bool.Parse(createParentActivity) ? new Activity("parent").Start() : null + }; + + IPHostEntry entry = await Dns.GetHostEntryAsync(IPAddress.Loopback); // Also does a forward lookup + Verify(2); + + await Dns.GetHostEntryAsync(loopbackIPString); + Verify(4); + + Dns.GetHostEntry(IPAddress.Loopback); + Verify(6); + + Dns.GetHostEntry(loopbackIPString); + Verify(8); + + Dns.EndGetHostEntry(Dns.BeginGetHostEntry(IPAddress.Loopback, null, null)); + Verify(10); + + Dns.EndGetHostEntry(Dns.BeginGetHostEntry(loopbackIPString, null, null)); + Verify(12); + + void Verify(int timesLookupRecorded) + { + recorder.VerifyActivityRecorded(timesLookupRecorded); + Activity reverseActivity = recorder.FinishedActivities.ToArray()[^2]; + VerifyReverseActivityInfo(reverseActivity, IPAddress.Loopback); + ActivityAssert.HasTag(reverseActivity, "dns.answers", (string[] answers) => answers.Contains(entry.HostName)); + ActivityAssert.HasNoTag(reverseActivity, "error.type"); + VerifyForwardActivityInfo(recorder.LastStartedActivity, entry.HostName); + } + + }, createParentActivity.ToString()).DisposeAsync(); + } + + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData(false)] + [InlineData(true)] + public static async Task ForwardLookup_InvalidHostName_ActivityRecorded(bool createParentActivity) + { + const string InvalidHostName = $"invalid...example.com...{nameof(ForwardLookup_InvalidHostName_ActivityRecorded)}"; + + await RemoteExecutor.Invoke(async (createParentActivity) => + { + using var recorder = new ActivityRecorder(ActivitySourceName, ActivityName) + { + ExpectedParent = bool.Parse(createParentActivity) ? new Activity("parent").Start() : null + }; + + await Assert.ThrowsAnyAsync(async () => await Dns.GetHostEntryAsync(InvalidHostName)); + Verify(1); + + await Assert.ThrowsAnyAsync(async () => await Dns.GetHostAddressesAsync(InvalidHostName)); + Verify(2); + + Assert.ThrowsAny(() => Dns.GetHostEntry(InvalidHostName)); + Verify(3); + + Assert.ThrowsAny(() => Dns.GetHostAddresses(InvalidHostName)); + Verify(4); + + Assert.ThrowsAny(() => Dns.EndGetHostEntry(Dns.BeginGetHostEntry(InvalidHostName, null, null))); + Verify(5); + + Assert.ThrowsAny(() => Dns.EndGetHostAddresses(Dns.BeginGetHostAddresses(InvalidHostName, null, null))); + Verify(6); + + void Verify(int timesLookupRecorded) + { + recorder.VerifyActivityRecorded(timesLookupRecorded); + + Activity activity = recorder.LastFinishedActivity; + Assert.Equal(ActivityStatusCode.Error, activity.Status); + VerifyForwardActivityInfo(activity, InvalidHostName); + ActivityAssert.HasTag(activity, "error.type", "host_not_found"); + } + }, createParentActivity.ToString()).DisposeAsync(); + } + + static void VerifyForwardActivityInfo(Activity activity, string question) + { + Assert.Equal(ActivityKind.Internal, activity.Kind); + Assert.Equal(ActivityName, activity.OperationName); + Assert.Equal($"DNS lookup {question}", activity.DisplayName); + ActivityAssert.HasTag(activity, "dns.question.name", question); + } + + static void VerifyReverseActivityInfo(Activity activity, IPAddress question) + { + Assert.Equal(ActivityKind.Internal, activity.Kind); + Assert.Equal(ActivityName, activity.OperationName); + Assert.Equal($"DNS reverse lookup {question}", activity.DisplayName); + ActivityAssert.HasTag(activity, "dns.question.name", question.ToString()); + } + } +} diff --git a/src/libraries/System.Net.NameResolution/tests/FunctionalTests/System.Net.NameResolution.Functional.Tests.csproj b/src/libraries/System.Net.NameResolution/tests/FunctionalTests/System.Net.NameResolution.Functional.Tests.csproj index ff009e7b84326..182e5d9eba19b 100644 --- a/src/libraries/System.Net.NameResolution/tests/FunctionalTests/System.Net.NameResolution.Functional.Tests.csproj +++ b/src/libraries/System.Net.NameResolution/tests/FunctionalTests/System.Net.NameResolution.Functional.Tests.csproj @@ -6,6 +6,7 @@ true + @@ -20,6 +21,8 @@ + + diff --git a/src/libraries/System.Net.Security/src/System/Net/Security/NetSecurityTelemetry.cs b/src/libraries/System.Net.Security/src/System/Net/Security/NetSecurityTelemetry.cs index c751742175af9..6b425c2891935 100644 --- a/src/libraries/System.Net.Security/src/System/Net/Security/NetSecurityTelemetry.cs +++ b/src/libraries/System.Net.Security/src/System/Net/Security/NetSecurityTelemetry.cs @@ -12,6 +12,11 @@ namespace System.Net.Security [EventSource(Name = "System.Net.Security")] internal sealed class NetSecurityTelemetry : EventSource { + private const string ActivitySourceName = "Experimental.System.Net.Security"; + private const string ActivityName = ActivitySourceName + ".TlsHandshake"; + + private static readonly ActivitySource s_activitySource = new ActivitySource(ActivitySourceName); + private const string EventSourceSuppressMessage = "Parameters to this method are primitive and are trimmer safe"; public static readonly NetSecurityTelemetry Log = new NetSecurityTelemetry(); @@ -39,6 +44,8 @@ internal sealed class NetSecurityTelemetry : EventSource private long _sessionsOpenTls12; private long _sessionsOpenTls13; + public static bool AnyTelemetryEnabled() => Log.IsEnabled() || s_activitySource.HasListeners(); + protected override void OnEventCommand(EventCommandEventArgs command) { if (command.Command == EventCommand.Enable) @@ -304,5 +311,56 @@ private unsafe void WriteEvent(int eventId, bool arg1, double arg2, string? arg3 WriteEventCore(eventId, NumEventDatas, descrs); } } + + [NonEvent] + public static Activity? StartActivity(SslStream stream) + { + using Activity? activity = s_activitySource.StartActivity(ActivityName); + if (activity is not null) + { + activity.DisplayName = stream.IsServer ? "TLS server handshake" : $"TLS client handshake {stream.TargetHostName}"; + if (activity.IsAllDataRequested && !stream.IsServer) + { + activity.SetTag("server.address", stream.TargetHostName); + } + } + return activity; + } + + [NonEvent] + public static void StopActivity(Activity? activity, Exception? exception, SslStream stream) + { + if (activity?.IsAllDataRequested != true) return; + + SslProtocols protocol = stream.GetSslProtocolInternal(); + (string? protocolName, string? protocolVersion) = GetNameAndVersionString(protocol); + + if (protocolName is not null) + { + Debug.Assert(protocolVersion is not null); + activity.SetTag("tls.protocol.name", protocolName); + activity.SetTag("tls.protocol.version", protocolVersion); + } + + if (exception is not null) + { + activity.SetStatus(ActivityStatusCode.Error); + activity.SetTag("error.type", exception.GetType().FullName); + } + + static (string?, string?) GetNameAndVersionString(SslProtocols protocol) => protocol switch + { +#pragma warning disable 0618 // Ssl2, Ssl3 are deprecated. + SslProtocols.Ssl2 => ("ssl", "2"), + SslProtocols.Ssl3 => ("ssl", "3"), +#pragma warning restore 0618 +#pragma warning disable SYSLIB0039 // TLS 1.0 and 1.1 are obsolete. + SslProtocols.Tls => ("tls", "1"), + SslProtocols.Tls12 => ("tls", "1.2"), +#pragma warning restore SYSLIB0039 + SslProtocols.Tls13 => ("tls", "1.3"), + _ => (null, null) + }; + } } } diff --git a/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.IO.cs b/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.IO.cs index 4b876aee9e8ba..0275b8fa5cfea 100644 --- a/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.IO.cs +++ b/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.IO.cs @@ -106,7 +106,7 @@ private Task ProcessAuthenticationAsync(bool isAsync = false, CancellationToken { ThrowIfExceptional(); - if (NetSecurityTelemetry.Log.IsEnabled()) + if (NetSecurityTelemetry.AnyTelemetryEnabled()) { return ProcessAuthenticationWithTelemetryAsync(isAsync, cancellationToken); } @@ -120,9 +120,19 @@ private Task ProcessAuthenticationAsync(bool isAsync = false, CancellationToken private async Task ProcessAuthenticationWithTelemetryAsync(bool isAsync, CancellationToken cancellationToken) { - NetSecurityTelemetry.Log.HandshakeStart(IsServer, _sslAuthenticationOptions.TargetHost); - long startingTimestamp = Stopwatch.GetTimestamp(); + long startingTimestamp; + if (NetSecurityTelemetry.Log.IsEnabled()) + { + NetSecurityTelemetry.Log.HandshakeStart(IsServer, _sslAuthenticationOptions.TargetHost); + startingTimestamp = Stopwatch.GetTimestamp(); + } + else + { + startingTimestamp = 0; + } + Activity? activity = NetSecurityTelemetry.StartActivity(this); + Exception? exception = null; try { Task task = isAsync ? @@ -131,17 +141,29 @@ private async Task ProcessAuthenticationWithTelemetryAsync(bool isAsync, Cancell await task.ConfigureAwait(false); - // 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; - - NetSecurityTelemetry.Log.HandshakeCompleted(GetSslProtocolInternal(), startingTimestamp, connectionOpen); + if (startingTimestamp is not 0) + { + // 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; + SslProtocols protocol = GetSslProtocolInternal(); + NetSecurityTelemetry.Log.HandshakeCompleted(protocol, startingTimestamp, connectionOpen); + } } catch (Exception ex) { - NetSecurityTelemetry.Log.HandshakeFailed(IsServer, startingTimestamp, ex.Message); + exception = ex; + if (startingTimestamp is not 0) + { + NetSecurityTelemetry.Log.HandshakeFailed(IsServer, startingTimestamp, ex.Message); + } + throw; } + finally + { + NetSecurityTelemetry.StopActivity(activity, exception, this); + } } // diff --git a/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.cs b/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.cs index 82ca35d1b0d5f..5b991106dbc3b 100644 --- a/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.cs +++ b/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.cs @@ -486,7 +486,7 @@ public virtual SslProtocols SslProtocol } // Skips the ThrowIfExceptionalOrNotHandshake() check - private SslProtocols GetSslProtocolInternal() + internal SslProtocols GetSslProtocolInternal() { if (_connectionInfo.Protocol == 0) { diff --git a/src/libraries/System.Net.Security/tests/FunctionalTests/SslStreamStreamToStreamTest.cs b/src/libraries/System.Net.Security/tests/FunctionalTests/SslStreamStreamToStreamTest.cs index 13613df3a2479..b6b14b9256cfa 100644 --- a/src/libraries/System.Net.Security/tests/FunctionalTests/SslStreamStreamToStreamTest.cs +++ b/src/libraries/System.Net.Security/tests/FunctionalTests/SslStreamStreamToStreamTest.cs @@ -22,25 +22,27 @@ public abstract class SslStreamStreamToStreamTest { private readonly byte[] _sampleMsg = "Sample Test Message"u8.ToArray(); - protected static async Task WithServerCertificate(X509Certificate serverCertificate, Func func) + internal string Name { get; private set; } + internal SslProtocols SslProtocol { get; private set; } + + protected async Task WithServerCertificate(X509Certificate serverCertificate, Func func) { X509Certificate certificate = serverCertificate ?? Configuration.Certificates.GetServerCertificate(); try { - string name; if (certificate is X509Certificate2 cert2) { - name = cert2.GetNameInfo(X509NameType.SimpleName, forIssuer: false); + Name = cert2.GetNameInfo(X509NameType.SimpleName, forIssuer: false); } else { using (cert2 = new X509Certificate2(certificate)) { - name = cert2.GetNameInfo(X509NameType.SimpleName, forIssuer: false); + Name = cert2.GetNameInfo(X509NameType.SimpleName, forIssuer: false); } } - await func(certificate, name).ConfigureAwait(false); + await func(certificate, Name).ConfigureAwait(false); } finally { @@ -77,6 +79,7 @@ public async Task SslStream_StreamToStream_Authentication_Success(X509Certificat using (var server = new SslStream(stream2, false, delegate { return true; })) { await DoHandshake(client, server, serverCert, clientCert); + SslProtocol = client.SslProtocol; Assert.True(client.IsAuthenticated); Assert.True(server.IsAuthenticated); } @@ -93,7 +96,8 @@ public async Task SslStream_StreamToStream_Authentication_IncorrectServerName_Fa using (var server = new SslStream(stream2)) using (var certificate = Configuration.Certificates.GetServerCertificate()) { - Task t1 = client.AuthenticateAsClientAsync("incorrectServer"); + Name = "incorrectServer"; + Task t1 = client.AuthenticateAsClientAsync(Name); Task t2 = server.AuthenticateAsServerAsync(certificate); await Assert.ThrowsAsync(() => t1.WaitAsync(TestConfiguration.PassingTestTimeout)); diff --git a/src/libraries/System.Net.Security/tests/FunctionalTests/System.Net.Security.Tests.csproj b/src/libraries/System.Net.Security/tests/FunctionalTests/System.Net.Security.Tests.csproj index 11dfd96afb0d6..3d55a2c888a26 100644 --- a/src/libraries/System.Net.Security/tests/FunctionalTests/System.Net.Security.Tests.csproj +++ b/src/libraries/System.Net.Security/tests/FunctionalTests/System.Net.Security.Tests.csproj @@ -55,6 +55,8 @@ Link="Common\System\IO\DelegateStream.cs" /> + + { + using ActivityRecorder recorder = new ActivityRecorder(ActivitySourceName, ActivityName); + + SslStreamStreamToStreamTest test = bool.Parse(synchronousApiStr) + ? new SslStreamStreamToStreamTest_SyncParameters() + : new SslStreamStreamToStreamTest_Async(); + await test.SslStream_StreamToStream_Authentication_Success(); + + recorder.VerifyActivityRecorded(2); // client + server + Activity clientActivity = recorder.FinishedActivities.Single(a => a.DisplayName.StartsWith("TLS client")); + Activity serverActivity = recorder.FinishedActivities.Single(a => a.DisplayName.StartsWith("TLS server")); + Assert.True(Enum.GetValues(typeof(SslProtocols)).Length == 8, "We need to extend the mapping in case new values are added to SslProtocols."); +#pragma warning disable 0618, SYSLIB0039 + (string protocolName, string protocolVersion) = test.SslProtocol switch + { + SslProtocols.Ssl2 => ("ssl", "2"), + SslProtocols.Ssl3 => ("ssl", "3"), + SslProtocols.Tls => ("tls", "1"), + SslProtocols.Tls11 => ("tls", "1.1"), + SslProtocols.Tls12 => ("tls", "1.2"), + SslProtocols.Tls13 => ("tls", "1.3"), + _ => throw new Exception("unknown protocol") + }; +#pragma warning restore 0618, SYSLIB0039 + + Assert.Equal(ActivityKind.Internal, clientActivity.Kind); + Assert.True(clientActivity.Duration > TimeSpan.Zero); + Assert.Equal(ActivityName, clientActivity.OperationName); + Assert.Equal($"TLS client handshake {test.Name}", clientActivity.DisplayName); + ActivityAssert.HasTag(clientActivity, "server.address", test.Name); + ActivityAssert.HasTag(clientActivity, "tls.protocol.name", protocolName); + ActivityAssert.HasTag(clientActivity, "tls.protocol.version", protocolVersion); + ActivityAssert.HasNoTag(clientActivity, "error.type"); + + Assert.Equal(ActivityKind.Internal, serverActivity.Kind); + Assert.True(serverActivity.Duration > TimeSpan.Zero); + Assert.Equal(ActivityName, serverActivity.OperationName); + Assert.StartsWith($"TLS server handshake", serverActivity.DisplayName); + ActivityAssert.HasTag(serverActivity, "tls.protocol.name", protocolName); + ActivityAssert.HasTag(serverActivity, "tls.protocol.version", protocolVersion); + ActivityAssert.HasNoTag(serverActivity, "error.type"); + + }, synchronousApi.ToString()).DisposeAsync(); + } + + [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + public async Task FailingHandshake_ActivityRecorded() + { + await RemoteExecutor.Invoke(async () => + { + using ActivityRecorder recorder = new ActivityRecorder(ActivitySourceName, ActivityName); + + var test = new SslStreamStreamToStreamTest_Async(); + await test.SslStream_StreamToStream_Authentication_IncorrectServerName_Fail(); + + recorder.VerifyActivityRecorded(2); // client + server + + Activity clientActivity = recorder.FinishedActivities.Single(a => a.DisplayName.StartsWith("TLS client")); + Activity serverActivity = recorder.FinishedActivities.Single(a => a.DisplayName.StartsWith("TLS server")); + + Assert.Equal(ActivityKind.Internal, clientActivity.Kind); + Assert.Equal(ActivityStatusCode.Error, clientActivity.Status); + Assert.True(clientActivity.Duration > TimeSpan.Zero); + Assert.Equal(ActivityName, clientActivity.OperationName); + Assert.Equal($"TLS client handshake {test.Name}", clientActivity.DisplayName); + ActivityAssert.HasTag(clientActivity, "server.address", test.Name); + ActivityAssert.HasTag(clientActivity, "error.type", typeof(AuthenticationException).FullName); + + Assert.Equal(ActivityKind.Internal, serverActivity.Kind); + Assert.True(serverActivity.Duration > TimeSpan.Zero); + Assert.Equal(ActivityName, serverActivity.OperationName); + Assert.StartsWith($"TLS server handshake", serverActivity.DisplayName); + }).DisposeAsync(); + } + [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 diff --git a/src/libraries/System.Net.Sockets/src/System.Net.Sockets.csproj b/src/libraries/System.Net.Sockets/src/System.Net.Sockets.csproj index ced52a7f14f7e..5198e80906163 100644 --- a/src/libraries/System.Net.Sockets/src/System.Net.Sockets.csproj +++ b/src/libraries/System.Net.Sockets/src/System.Net.Sockets.csproj @@ -292,6 +292,7 @@ + diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs index c8df9f89c4a03..02edb8853f909 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs @@ -2782,7 +2782,7 @@ internal bool ConnectAsync(SocketAsyncEventArgs e, bool userSocket, bool saeaCan WildcardBindForConnectIfNecessary(endPointSnapshot.AddressFamily); - SocketsTelemetry.Log.ConnectStart(e._socketAddress!); + e.ConnectActivity = SocketsTelemetry.Log.ConnectStart(e._socketAddress!, _protocolType, endPointSnapshot, keepActivityCurrent: true); // Prepare for the native call. try @@ -2792,7 +2792,8 @@ internal bool ConnectAsync(SocketAsyncEventArgs e, bool userSocket, bool saeaCan } catch (Exception ex) { - SocketsTelemetry.Log.AfterConnect(SocketError.NotSocket, ex.Message); + SocketsTelemetry.Log.AfterConnect(SocketError.NotSocket, e.ConnectActivity, ex.Message); + e.ConnectActivity = null; throw; } @@ -2808,7 +2809,8 @@ internal bool ConnectAsync(SocketAsyncEventArgs e, bool userSocket, bool saeaCan } catch (Exception ex) { - SocketsTelemetry.Log.AfterConnect(SocketError.NotSocket, ex.Message); + SocketsTelemetry.Log.AfterConnect(SocketError.NotSocket, e.ConnectActivity, ex.Message); + e.ConnectActivity = null; _localEndPoint = null; @@ -3189,7 +3191,7 @@ private SocketAddress Serialize(ref EndPoint remoteEP) private void DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress) { - SocketsTelemetry.Log.ConnectStart(socketAddress); + Activity? activity = SocketsTelemetry.Log.ConnectStart(socketAddress, _protocolType, endPointSnapshot, keepActivityCurrent: false); SocketError errorCode; try { @@ -3197,7 +3199,7 @@ private void DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress) } catch (Exception ex) { - SocketsTelemetry.Log.AfterConnect(SocketError.NotSocket, ex.Message); + SocketsTelemetry.Log.AfterConnect(SocketError.NotSocket, activity, ex.Message); throw; } @@ -3210,12 +3212,12 @@ private void DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress) UpdateStatusAfterSocketError(socketException); if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(this, socketException); - SocketsTelemetry.Log.AfterConnect(errorCode); + SocketsTelemetry.Log.AfterConnect(errorCode, activity); throw socketException; } - SocketsTelemetry.Log.AfterConnect(SocketError.Success); + SocketsTelemetry.Log.AfterConnect(SocketError.Success, activity); if (NetEventSource.Log.IsEnabled()) NetEventSource.Info(this, $"connection to:{endPointSnapshot}"); diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs index 29e9aa094555b..158d56182aae2 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEventArgs.cs @@ -3,6 +3,7 @@ using System.Collections.Generic; using System.Diagnostics; +using System.Runtime.CompilerServices; using System.Runtime.InteropServices; using System.Threading; using System.Threading.Tasks; @@ -71,6 +72,7 @@ public partial class SocketAsyncEventArgs : EventArgs, IDisposable private readonly bool _flowExecutionContext; private ExecutionContext? _context; private static readonly ContextCallback s_executionCallback = ExecutionCallback; + private static ConditionalWeakTable? s_connectActivityTable; private Socket? _currentSocket; private bool _userSocket; // if false when performing Connect, _currentSocket should be disposed private bool _disposeCalled; @@ -224,7 +226,8 @@ private void AfterConnectAcceptTelemetry() break; case SocketAsyncOperation.Connect: - SocketsTelemetry.Log.AfterConnect(SocketError); + SocketsTelemetry.Log.AfterConnect(SocketError, ConnectActivity); + ConnectActivity = null; break; default: @@ -302,6 +305,26 @@ public object? UserToken set { _userToken = value; } } + internal Activity? ConnectActivity + { + // ConditionalWeakTable is used to avoid penalizing every SAEA with a new field in the the vast majority of the cases, + // when ConnectActivity is null. Accessors of this property should never race over the same SAEA instance. + // Telemetry logic ensures that getter calls are always preceded by a setter call. + get => s_connectActivityTable?.TryGetValue(this, out Activity? result) == true ? result : null; + set + { + if (value is not null) + { + LazyInitializer.EnsureInitialized(ref s_connectActivityTable, () => new ConditionalWeakTable()); + s_connectActivityTable.AddOrUpdate(this, value); + } + else + { + s_connectActivityTable?.Remove(this); + } + } + } + public void SetBuffer(int offset, int count) { StartConfiguring(); diff --git a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs index bea730b47b162..2a7abb81f60b8 100644 --- a/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs +++ b/src/libraries/System.Net.Sockets/src/System/Net/Sockets/SocketsTelemetry.cs @@ -10,6 +10,10 @@ namespace System.Net.Sockets [EventSource(Name = "System.Net.Sockets")] internal sealed class SocketsTelemetry : EventSource { + private const string ActivitySourceName = "Experimental.System.Net.Sockets"; + private const string ConnectActivityName = ActivitySourceName + ".Connect"; + private static readonly ActivitySource s_connectActivitySource = new ActivitySource(ActivitySourceName); + public static readonly SocketsTelemetry Log = new SocketsTelemetry(); private PollingCounter? _currentOutgoingConnectAttemptsCounter; @@ -77,7 +81,7 @@ private void AcceptFailed(SocketError error, string? exceptionMessage) } [NonEvent] - public void ConnectStart(SocketAddress address) + public Activity? ConnectStart(SocketAddress address, ProtocolType protocolType, EndPoint endPoint, bool keepActivityCurrent) { Interlocked.Increment(ref _currentOutgoingConnectAttempts); @@ -85,14 +89,75 @@ public void ConnectStart(SocketAddress address) { ConnectStart(address.ToString()); } + + Activity? activity = null; + if (s_connectActivitySource.HasListeners()) + { + Activity? activityToReset = keepActivityCurrent ? Activity.Current : null; + activity = s_connectActivitySource.StartActivity(ConnectActivityName); + if (keepActivityCurrent) + { + // Do not overwrite Activity.Current in the caller's ExecutionContext. + Activity.Current = activityToReset; + } + } + + if (activity is not null) + { + if (endPoint is IPEndPoint ipEndPoint) + { + int port = ipEndPoint.Port; + activity.DisplayName = $"socket connect {ipEndPoint.Address}:{port}"; + if (activity.IsAllDataRequested) + { + activity.SetTag("network.peer.address", ipEndPoint.Address.ToString()); + activity.SetTag("network.peer.port", port); + activity.SetTag("network.type", ipEndPoint.AddressFamily == AddressFamily.InterNetwork ? "ipv4" : "ipv6"); + if (protocolType is ProtocolType.Tcp) + { + SetNetworkTransport(activity, "tcp"); + } + else if (protocolType is ProtocolType.Udp) + { + SetNetworkTransport(activity, "udp"); + } + } + } + else if (endPoint is UnixDomainSocketEndPoint udsEndPoint) + { + string peerAddress = udsEndPoint.ToString(); + activity.DisplayName = $"socket connect {peerAddress}"; + + if (activity.IsAllDataRequested) + { + activity.SetTag("network.peer.address", peerAddress); + SetNetworkTransport(activity, "unix"); + } + } + } + + static void SetNetworkTransport(Activity activity, string transportType) => activity.SetTag("network.transport", transportType); + + return activity; } [NonEvent] - public void AfterConnect(SocketError error, string? exceptionMessage = null) + public void AfterConnect(SocketError error, Activity? activity, string? exceptionMessage = null) { long newCount = Interlocked.Decrement(ref _currentOutgoingConnectAttempts); Debug.Assert(newCount >= 0); + if (activity is not null) + { + if (error != SocketError.Success) + { + activity.SetStatus(ActivityStatusCode.Error); + activity.SetTag("error.type", GetErrorType(error)); + } + + activity.Stop(); + } + if (error == SocketError.Success) { Debug.Assert(exceptionMessage is null); @@ -166,6 +231,32 @@ public void DatagramSent() Interlocked.Increment(ref _datagramsSent); } + private static string GetErrorType(SocketError socketError) => socketError switch + { + // Common connect() errors expected to be seen: + // https://learn.microsoft.com/en-us/windows/win32/api/winsock2/nf-winsock2-connect#return-value + // https://man7.org/linux/man-pages/man2/connect.2.html + SocketError.NetworkDown => "network_down", + SocketError.AddressAlreadyInUse => "address_already_in_use", + SocketError.Interrupted => "interrupted", + SocketError.InProgress => "in_progress", + SocketError.AlreadyInProgress => "already_in_progress", + SocketError.AddressNotAvailable => "address_not_available", + SocketError.AddressFamilyNotSupported => "address_family_not_supported", + SocketError.ConnectionRefused => "connection_refused", + SocketError.Fault => "fault", + SocketError.InvalidArgument => "invalid_argument", + SocketError.IsConnected => "is_connected", + SocketError.NetworkUnreachable => "network_unreachable", + SocketError.HostUnreachable => "host_unreachable", + SocketError.NoBufferSpaceAvailable => "no_buffer_space_available", + SocketError.TimedOut => "timed_out", + SocketError.AccessDenied => "access_denied", + SocketError.ProtocolType => "protocol_type", + + _ => "_OTHER" + }; + protected override void OnEventCommand(EventCommandEventArgs command) { if (command.Command == EventCommand.Enable) diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/System.Net.Sockets.Tests.csproj b/src/libraries/System.Net.Sockets/tests/FunctionalTests/System.Net.Sockets.Tests.csproj index cc57803fa1c50..2b5c1cea632f0 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/System.Net.Sockets.Tests.csproj +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/System.Net.Sockets.Tests.csproj @@ -78,6 +78,8 @@ + > s_remoteServerIsReachable = new Lazy>(() => Task.Run(async () => { try @@ -71,8 +76,8 @@ from acceptMethod in SocketMethods_MemberData() public static IEnumerable SocketMethods_WithBools_MemberData() { return from connectMethod in SocketMethods_MemberData() - from useDnsEndPoint in new[] { true, false } - select new[] { connectMethod[0], useDnsEndPoint }; + from boolValue in new[] { true, false } + select new[] { connectMethod[0], boolValue }; } private static async Task GetRemoteEndPointAsync(string useDnsEndPointString, int port) @@ -104,6 +109,128 @@ private static SocketHelperBase GetHelperBase(string socketMethod) }; } + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [MemberData(nameof(SocketMethods_WithBools_MemberData))] + public async Task Connect_Success_ActivityRecorded(string connectMethod, bool ipv6) + { + if (ipv6 && !Socket.OSSupportsIPv6) return; + + await RemoteExecutor.Invoke(static async (connectMethod, ipv6Str) => + { + bool ipv6 = bool.Parse(ipv6Str); + using Socket server = new Socket(ipv6 ? AddressFamily.InterNetworkV6 : AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp); + server.BindToAnonymousPort(ipv6 ? IPAddress.IPv6Loopback : IPAddress.Loopback); + server.Listen(); + + Activity parent = new Activity("parent").Start(); + + using Socket client = new Socket(ipv6 ? AddressFamily.InterNetworkV6 : AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp); + + using ActivityRecorder recorder = new ActivityRecorder(ActivitySourceName, ActivityName) + { + ExpectedParent = parent + }; + + Task connectTask = GetHelperBase(connectMethod).ConnectAsync(client, server.LocalEndPoint); + await server.AcceptAsync(); + await connectTask; + + recorder.VerifyActivityRecorded(1); + Activity activity = recorder.LastFinishedActivity; + VerifyTcpConnectActivity(activity, (IPEndPoint)server.LocalEndPoint, ipv6); + + Assert.Same(parent, Activity.Current); + parent.Stop(); + }, connectMethod, ipv6.ToString()).DisposeAsync(); + } + + static void VerifyTcpConnectActivity(Activity activity, IPEndPoint remoteEndPoint, bool ipv6) + { + string address = remoteEndPoint.Address.ToString(); + int port = remoteEndPoint.Port; + Assert.Equal(ActivityKind.Internal, activity.Kind); + Assert.Equal(ActivityName, activity.OperationName); + Assert.Equal($"socket connect {address}:{port}", activity.DisplayName); + ActivityAssert.HasTag(activity, "network.peer.address", address); + ActivityAssert.HasTag(activity, "network.peer.port", port); + ActivityAssert.HasTag(activity, "network.type", ipv6 ? "ipv6" : "ipv4"); + ActivityAssert.HasTag(activity, "network.transport", "tcp"); + } + + [OuterLoop("Connection failure takes long on Windows.")] + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [MemberData(nameof(SocketMethods_WithBools_MemberData))] + public async Task Connect_Failure_ActivityRecorded(string connectMethod, bool ipv6) + { + await RemoteExecutor.Invoke(static async (connectMethod, ipv6Str) => + { + bool ipv6 = bool.Parse(ipv6Str); + using Socket notListening = new Socket(ipv6 ? AddressFamily.InterNetworkV6 : AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp); + notListening.BindToAnonymousPort(ipv6 ? IPAddress.IPv6Loopback : IPAddress.Loopback); + + Activity parent = new Activity("parent").Start(); + + using Socket client = new Socket(ipv6 ? AddressFamily.InterNetworkV6 : AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp); + + using ActivityRecorder recorder = new ActivityRecorder(ActivitySourceName, ActivityName) + { + ExpectedParent = parent + }; + + SocketException ex = await Assert.ThrowsAsync(() => GetHelperBase(connectMethod) + .ConnectAsync(client, notListening.LocalEndPoint)); + + recorder.VerifyActivityRecorded(1); + Activity activity = recorder.LastFinishedActivity; + VerifyTcpConnectActivity(activity, (IPEndPoint)notListening.LocalEndPoint, ipv6); + string expectedErrorType = ActivityAssert.CamelToSnake(ex.SocketErrorCode.ToString()); + ActivityAssert.HasTag(activity, "error.type", expectedErrorType); + Assert.Equal(ActivityStatusCode.Error, activity.Status); + + Assert.Same(parent, Activity.Current); + parent.Stop(); + }, connectMethod, ipv6.ToString()).DisposeAsync(); + } + + [ConditionalTheory(typeof(Socket), nameof(Socket.OSSupportsUnixDomainSockets))] + [SkipOnPlatform(TestPlatforms.LinuxBionic, "SElinux blocks UNIX sockets in our CI environment")] + [MemberData(nameof(SocketMethods_MemberData))] + public async Task Socket_UDS_Success_ActivityRecorded(string connectMethod) + { + await RemoteExecutor.Invoke(static async connectMethod => + { + Socket server = null; + UnixDomainSocketEndPoint endPoint = null; + + //Path selection is contingent on a successful Bind(). + //If it fails, the next iteration will try another path. + RetryHelper.Execute(() => + { + server = new Socket(AddressFamily.Unix, SocketType.Stream, ProtocolType.Unspecified); + endPoint = new UnixDomainSocketEndPoint(UnixDomainSocketTest.GetRandomNonExistingFilePath()); + server.Bind(endPoint); + server.Listen(); + }, retryWhen: e => e is SocketException); + + using Socket client = new Socket(AddressFamily.Unix, SocketType.Stream, ProtocolType.Unspecified); + + using ActivityRecorder recorder = new ActivityRecorder(ActivitySourceName, ActivityName); + + Task connectTask = GetHelperBase(connectMethod).ConnectAsync(client, endPoint); + await server.AcceptAsync(); + await connectTask; + + recorder.VerifyActivityRecorded(1); + Activity activity = recorder.LastFinishedActivity; + Assert.Equal(ActivityKind.Internal, activity.Kind); + Assert.Equal(ActivityName, activity.OperationName); + Assert.Equal($"socket connect {endPoint}", activity.DisplayName); + ActivityAssert.HasTag(activity, "network.peer.address", endPoint.ToString()); + ActivityAssert.HasTag(activity, "network.transport", "unix"); + + }, connectMethod).DisposeAsync(); + } + [OuterLoop] [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] [MemberData(nameof(SocketMethods_Matrix_MemberData))] diff --git a/src/libraries/System.Net.Sockets/tests/FunctionalTests/UnixDomainSocketTest.cs b/src/libraries/System.Net.Sockets/tests/FunctionalTests/UnixDomainSocketTest.cs index 58edc1ecffaa5..a49b8aa235a4e 100644 --- a/src/libraries/System.Net.Sockets/tests/FunctionalTests/UnixDomainSocketTest.cs +++ b/src/libraries/System.Net.Sockets/tests/FunctionalTests/UnixDomainSocketTest.cs @@ -636,7 +636,7 @@ public async Task UnixDomainSocket_Receive_GetsCanceledByDispose() } } - private static string GetRandomNonExistingFilePath() + internal static string GetRandomNonExistingFilePath() { string result; do