From e94f4c5de74b73eb1bd8eb86464b0ccd414642a7 Mon Sep 17 00:00:00 2001
From: Natalia Kondratyeva <knatalia@microsoft.com>
Date: Thu, 17 Mar 2022 19:09:14 +0100
Subject: [PATCH] Add additional trace to HttpConnectionPool (#66605)

The additional trace should help troubleshoot hanged "pending" connection issues (i.e. the reasons why new connections were not created) in HttpConnectionPool.

The issue manifests as growing number of timeouted requests. It is not easy to link a timeouted request (esp. with a small timeout) to a connection that was created 3 minutes ago but still is not connected. There are no traces of the state of HttpConnectionPool, e.g. number of pending connections, so it is unclear from existing traces why the pool decided not to create a connection.

Related to #66297
---
 .../Http/SocketsHttpHandler/HttpConnectionPool.cs | 15 ++++++++++++---
 1 file changed, 12 insertions(+), 3 deletions(-)

diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs
index 09459f6616460..68671fb98549a 100644
--- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs
+++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs
@@ -477,6 +477,13 @@ private void CheckForHttp11ConnectionInjection()
                 return;
             }
 
+            if (NetEventSource.Log.IsEnabled())
+            {
+                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
@@ -865,8 +872,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;
@@ -1603,7 +1612,7 @@ private async ValueTask<Stream> EstablishSocksTunnel(HttpRequestMessage request,
 
         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;
@@ -1633,7 +1642,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;