Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Connection Activities in SocketsHttpHandler #101814

Closed
wants to merge 10 commits into from
Closed

Connection Activities in SocketsHttpHandler #101814

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
10 commits
Select commit Hold shift + click to select a range
080ed80
implement Activity.AddLink
antonfirsov Apr 22, 2024
311adb6
.
antonfirsov Apr 24, 2024
d4daf03
Merge branch 'main' into connection-activities-01
antonfirsov Apr 30, 2024
7a40693
basic support for connection activities & events
antonfirsov May 1, 2024
6362c14
Merge branch 'main' into connection-activities-01
antonfirsov May 2, 2024
d9f41ac
Merge branch 'main' into connection-activities-01
antonfirsov May 9, 2024
6147532
Merge branch 'main' into connection-activities-01
antonfirsov May 16, 2024
927d3bf
Update src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsH…
antonfirsov May 16, 2024
3c7167e
apply suggestion
antonfirsov May 17, 2024
8cb8dbb
apply suggestions
antonfirsov May 17, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 8 additions & 8 deletions src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
private static readonly ActivitySource s_activitySource = new ActivitySource(DiagnosticsHandlerLoggingStrings.RequestNamespace);

private readonly HttpMessageHandler _innerHandler;
private readonly DistributedContextPropagator _propagator;
Expand Down Expand Up @@ -58,14 +58,14 @@ private static bool IsEnabled()
Activity? activity = null;
if (s_activitySource.HasListeners())
{
activity = s_activitySource.CreateActivity(DiagnosticsHandlerLoggingStrings.ActivityName, ActivityKind.Client);
activity = s_activitySource.CreateActivity(DiagnosticsHandlerLoggingStrings.RequestActivityName, ActivityKind.Client);
}

if (activity is null)
{
if (Activity.Current is not null || s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityName, requestMessage))
if (Activity.Current is not null || s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestActivityName, requestMessage))
{
activity = new Activity(DiagnosticsHandlerLoggingStrings.ActivityName);
activity = new Activity(DiagnosticsHandlerLoggingStrings.RequestActivityName);
}
}

Expand Down Expand Up @@ -117,9 +117,9 @@ private async ValueTask<HttpResponseMessage> SendAsyncCore(HttpRequestMessage re
activity.Start();

// 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));
}
}

Expand Down Expand Up @@ -177,9 +177,9 @@ await _innerHandler.SendAsync(request, cancellationToken).ConfigureAwait(false)
activity.SetEndTime(DateTime.UtcNow);

// 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();
Expand Down
17 changes: 10 additions & 7 deletions src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,12 +9,15 @@ 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 ConnectionNamespace = "System.Net.Http.Connections";
public const string ConnectionActivityName = ConnectionNamespace + ".HttpConnectionOut";
}
}
4 changes: 3 additions & 1 deletion src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectHelper.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -55,7 +55,7 @@ private static SslClientAuthenticationOptions SetUpRemoteCertificateValidationCa
return sslOptions;
}

public static async ValueTask<SslStream> EstablishSslConnectionAsync(SslClientAuthenticationOptions sslOptions, HttpRequestMessage request, bool async, Stream stream, CancellationToken cancellationToken)
public static async ValueTask<SslStream> EstablishSslConnectionAsync(SslClientAuthenticationOptions sslOptions, HttpRequestMessage request, bool async, Stream stream, Activity? activity, CancellationToken cancellationToken)
{
sslOptions = SetUpRemoteCertificateValidationCallback(sslOptions, request);

Expand All @@ -74,10 +74,12 @@ public static async ValueTask<SslStream> EstablishSslConnectionAsync(SslClientAu
sslStream.AuthenticateAsClient(sslOptions);
}
}
activity?.AddEvent(new ActivityEvent("Tls.Authenticated"));
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd prefer to use spans and avoid using span events at all costs:

  1. A child span for TLS handshake would have a duration and timestamp
  2. It won't be verbose since connections are long-lived (much longer than requests)
  3. It can live without HTTP instrumentation on
  4. It can be turned off (if coming from a different source) while HTTP is on
  5. Span events are likely to be deprecated in the future in favor of independent Event API similar to logging
  6. We'll have standard means to record errors/duration.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd prefer to use spans and avoid using span events at all costs:

That seems fine to me. I mentioned in another comment that there was a timing issue where one long activity for the entire connection wouldn't transmit the events until the connection closed. I suggested changing the events to log messages as one potential solution, but changing them to spans also solves that problem.

It won't be verbose since connections are long-lived (much longer than requests)

I assume at the limit we might have one connection per request, but I hope such scenarios are uncommon in any high throughput service. Worst case if connection activity overhead was too high the app developer can always sample them or turn them off.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like the advantages that come from implementing this with sub activities. Another big advantage is that it would also work if ConnectCallback is present, since we would implement them in downstream libraries. However, there are some challanges:

  • It increases the scope of the problem, since we would need to touch multiple System.Net.* libraries. We may need to pull in more reviewers from the networking team.
  • If we want to add attributes to those sub-activities, it increases the scope even further since we would need to make decisions on the characteristics of those attributes (eg. naming, possible values for attributes like error.type, etc). As I also noted in Connection Activities in SocketsHttpHandler #101814 (comment), my recommendation would be to track this in a separate issue.
  • If there is an Activity.Current to be used as a parent activity, and System.Net.Http.Connections.HttpConnectionOut is not enabled, the DNS/TCP/TLS activity would attach to the Http activity as parent which is somewhat unfortunate. We would need to document that users should avoid this.

Regardless, I agree sub-activities are better. If we have consensus, I will change this PR to add activities in downstream libs. @MihaZupan any concerns?

changing the events to log messages

Just to not exclude this option completely yet: @noahfalk do you mean a writing to DiagnosticListener by this or some other technique?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If there is an Activity.Current to be used as a parent activity, and System.Net.Http.Connections.HttpConnectionOut is not enabled, the DNS/TCP/TLS activity would attach to the Http activity as parent which is somewhat unfortunate. We would need to document that users should avoid this.

This is why when we originally talked I said not to use Activity.Current and be explicit about passing in the activity if you can.
If the DNS and/or TLS activities are invoked and the parent is not a connection (As the source isn't enabled) , then they can look at the activity and see if its a connection or not and therefore not parent themselves to it. You will still see them on the overall timeline.

The other hack would be to put all these activities in the same source, so they can only be enabled/disabled as a group. But as I think they would be useful for other scenarios beyond http connections, that really does seem like a hack.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was thinking about something that would ultimately be ILogger but later recalled that I don't think ILogger is easy to generate from the level of this code in the stack. Technically there are ways around that but I wouldn't worry about pursuing it any further. I think sub-activities are both easier and better.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But as I think they would be useful for other scenarios beyond http connections

This is why I would prefer to create the sub-activities in downlevel libs. System.Net.Sockets|NameResolution|Security would all have their own ActivitySource-s.

passing in the activity if you can.

It's not possible to pass it to downlevel libraries without significant (and IMO bloated) API additions, which we likely don't want.

}
catch (Exception e)
{
sslStream.Dispose();
activity?.Stop();

if (e is OperationCanceledException)
{
Expand Down
8 changes: 4 additions & 4 deletions ...et.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http1.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -259,14 +259,14 @@ private async Task InjectNewHttp11ConnectionAsync(RequestQueue<HttpConnection>.Q

internal async ValueTask<HttpConnection> 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<HttpConnection> ConstructHttp11ConnectionAsync(bool async, Stream stream, TransportContext? transportContext, HttpRequestMessage request, IPEndPoint? remoteEndPoint, CancellationToken cancellationToken)
private async ValueTask<HttpConnection> 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<HttpConnection>? requestWaiter, Exception e)
Expand Down
16 changes: 8 additions & 8 deletions ...et.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionPool/HttpConnectionPool.Http2.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -185,7 +185,7 @@ private async Task InjectNewHttp2ConnectionAsync(RequestQueue<Http2Connection?>.
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)
{
Expand All @@ -202,19 +202,19 @@ private async Task InjectNewHttp2ConnectionAsync(RequestQueue<Http2Connection?>.
}
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)
Expand Down Expand Up @@ -244,11 +244,11 @@ private async Task InjectNewHttp2ConnectionAsync(RequestQueue<Http2Connection?>.
}
}

private async ValueTask<Http2Connection> ConstructHttp2ConnectionAsync(Stream stream, HttpRequestMessage request, IPEndPoint? remoteEndPoint, CancellationToken cancellationToken)
private async ValueTask<Http2Connection> 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);
Expand Down Expand Up @@ -287,7 +287,7 @@ private void HandleHttp2ConnectionFailure(HttpConnectionWaiter<Http2Connection?>
}
}

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");

Expand Down Expand Up @@ -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)
{
Expand Down
Loading
Loading