Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

Add additional trace to HttpConnectionPool #66605

Merged
merged 3 commits into from
Mar 17, 2022
Merged

Add additional trace to HttpConnectionPool #66605

Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
68af49d
Add additional trace to HttpConnectionPool
CarnaViire Mar 14, 2022
a8b2d4f
Add exception to trace in case of failed connect
CarnaViire Mar 15, 2022
a956ca7
Fix build
CarnaViire Mar 16, 2022
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
15 changes: 12 additions & 3 deletions src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -478,6 +478,13 @@ private void CheckForHttp11ConnectionInjection()
return;
}

if (NetEventSource.Log.IsEnabled())
Copy link
Member

@ManickaP ManickaP Mar 14, 2022 •
edited
Loading

Choose a reason for hiding this comment

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

Would it be possible to add some telemetry counters? So that you wouldn't need to turn on the whole debugging logs to diagnose it.
cc @MihaZupan

Copy link
Member

Choose a reason for hiding this comment

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

What kind of counters did you have in mind?
We could expose many things, but they may not be too useful in diagnosing an issue like this since they are all aggregated for the process.

I see System.Net.Sockets doesn't have a "current" connection attempt counter - I don't see a reason not to add that. We have "current" counters on all the other sources.
Something like PendingHttp11ConnectionCount on Http would then be sort of redundant.

Copy link
Member

Choose a reason for hiding this comment

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

What I was trying to point out is that in order to get this diagnostics log, you need to turn on the internal logging. It's very verbose and chaotic and not designed to be used in production. I see it mostly as our internal logging helping us diagnose issues. In general, we don't recommend customers to turn this on. And there were even attempts to get completely rid of this.
So the question is whether this trace should help us or the customer diagnose the issue? If it's for customers, shouldn't it be part of the official HTTP telemetry?

Copy link
Member

Choose a reason for hiding this comment

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

EventSource does have the LogLevel for a reason, so we could certainly expose a lot more info under debug/trace.

The "official" telemetry surface is an API we effectively promise not to break.
As such, these logs shouldn't be unique events with a bunch of parameters since they are likely to change/break in the future.

We can, however, have something like

ConnectionPoolDebug(long poolId, string message);

Where you can still easily collect and aggregate all the information around the pool behavior, it just wouldn't be ideal for automatic processing.

Alternatively, we can start using the Keywords feature of EventSource (filtering by topic). Or the connection pool can have its own EventSource System.Net.Http.ConnectionPool.

{
Trace($"Available HTTP/1.1 connections: {_availableHttp11Connections.Count}, Requests in the queue: {_http11RequestQueue.Count}, " +
$"Pending HTTP/1.1 connections: {_pendingHttp11ConnectionCount}, Total associated HTTP/1.1 connections: {_associatedHttp11ConnectionCount}, " +
$"Max HTTP/1.1 connection limit: {_maxHttp11Connections}.");
}

// Determine if we can and should add a new connection to the pool.
if (_availableHttp11Connections.Count == 0 && // No available connections
_http11RequestQueue.Count > _pendingHttp11ConnectionCount && // More requests queued than pending connections
Expand Down Expand Up @@ -866,8 +873,10 @@ private async ValueTask<Http3Connection> GetHttp3ConnectionAsync(HttpRequestMess
{
quicConnection = await ConnectHelper.ConnectQuicAsync(request, Settings._quicImplementationProvider ?? QuicImplementationProviders.Default, new DnsEndPoint(authority.IdnHost, authority.Port), _sslOptionsHttp3!, cancellationToken).ConfigureAwait(false);
}
catch
catch (Exception e)
{
if (NetEventSource.Log.IsEnabled()) Trace($"QUIC connection failed: {e}");

// Disables HTTP/3 until server announces it can handle it via Alt-Svc.
BlocklistAuthority(authority);
throw;
Expand Down Expand Up @@ -1612,7 +1621,7 @@ private async ValueTask<Stream> EstablishProxyTunnelAsync(bool async, HttpReques

private void HandleHttp11ConnectionFailure(HttpRequestMessage request, Exception e)
{
if (NetEventSource.Log.IsEnabled()) Trace("HTTP/1.1 connection failed");
if (NetEventSource.Log.IsEnabled()) Trace($"HTTP/1.1 connection failed: {e}");

bool failRequest;
TaskCompletionSourceWithCancellation<HttpConnection>? waiter;
Expand Down Expand Up @@ -1642,7 +1651,7 @@ private void HandleHttp11ConnectionFailure(HttpRequestMessage request, Exception

private void HandleHttp2ConnectionFailure(HttpRequestMessage request, Exception e)
{
if (NetEventSource.Log.IsEnabled()) Trace("HTTP2 connection failed");
if (NetEventSource.Log.IsEnabled()) Trace($"HTTP2 connection failed: {e}");

bool failRequest;
TaskCompletionSourceWithCancellation<Http2Connection?>? waiter;
Expand Down