Moved HTTP request telemetry to HttpClient.SendAsync

src/libraries/System.Net.Http/src/System/Net/Http/HttpMessageInvoker.cs

@@ -41,7 +41,28 @@ public virtual HttpResponseMessage Send(HttpRequestMessage request,
             }
             CheckDisposed();
 
-            return _handler.Send(request, cancellationToken);
+            if (HttpTelemetry.Log.IsEnabled() && !request.WasSentByHttpClient() && request.RequestUri != null)
+            {
+                HttpTelemetry.Log.RequestStart(request);
+
+                try
+                {
+                    return _handler.Send(request, cancellationToken);
+                }
+                catch when (LogRequestFailed(telemetryStarted: true))
+                {
+                    // Unreachable as LogRequestFailed will return false
+                    throw;
+                }
+                finally
+                {
+                    HttpTelemetry.Log.RequestStop();
+                }
+            }
+            else
+            {
+                return _handler.Send(request, cancellationToken);
+            }
         }
 
         public virtual Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
@@ -53,7 +74,40 @@ public virtual Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
             }
             CheckDisposed();
 
+            if (HttpTelemetry.Log.IsEnabled() && !request.WasSentByHttpClient() && request.RequestUri != null)
+            {
+                return SendAsyncWithTelemetry(_handler, request, cancellationToken);
+            }
+
             return _handler.SendAsync(request, cancellationToken);
+
+            static async Task<HttpResponseMessage> SendAsyncWithTelemetry(HttpMessageHandler handler, HttpRequestMessage request, CancellationToken cancellationToken)
+            {
+                HttpTelemetry.Log.RequestStart(request);
+
+                try
+                {
+                    return await handler.SendAsync(request, cancellationToken).ConfigureAwait(false);
+                }
+                catch when (LogRequestFailed(telemetryStarted: true))
+                {
+                    // Unreachable as LogRequestFailed will return false
+                    throw;
+                }
+                finally
+                {
+                    HttpTelemetry.Log.RequestStop();
+                }
+            }
+        }
+
+        internal static bool LogRequestFailed(bool telemetryStarted)
+        {
+            if (HttpTelemetry.Log.IsEnabled() && telemetryStarted)
+            {
+                HttpTelemetry.Log.RequestFailed();
+            }
+            return false;
         }
 
         public void Dispose()

src/libraries/System.Net.Http/src/System/Net/Http/HttpRequestMessage.cs

@@ -14,10 +14,9 @@ public class HttpRequestMessage : IDisposable
     {
         private const int MessageNotYetSent = 0;
         private const int MessageAlreadySent = 1;
-        private const int MessageAlreadySent_StopNotYetCalled = 2;
 
         // Track whether the message has been sent.
-        // The message should only be sent if this field is equal to MessageNotYetSent.
+        // The message shouldn't be sent again if this field is equal to MessageAlreadySent.
         private int _sendStatus = MessageNotYetSent;
 
         private HttpMethod _method;
@@ -201,32 +200,10 @@ private void InitializeValues(HttpMethod method, Uri? requestUri)
 
         internal bool MarkAsSent()
         {
-            return Interlocked.CompareExchange(ref _sendStatus, MessageAlreadySent, MessageNotYetSent) == MessageNotYetSent;
+            return Interlocked.Exchange(ref _sendStatus, MessageAlreadySent) == MessageNotYetSent;
         }
 
-        internal void MarkAsTrackedByTelemetry()
-        {
-            Debug.Assert(_sendStatus != MessageAlreadySent_StopNotYetCalled);
-            _sendStatus = MessageAlreadySent_StopNotYetCalled;
-        }
-
-        internal void OnAborted() => OnStopped(aborted: true);
-
-        internal void OnStopped(bool aborted = false)
-        {
-            if (HttpTelemetry.Log.IsEnabled())
-            {
-                if (Interlocked.Exchange(ref _sendStatus, MessageAlreadySent) == MessageAlreadySent_StopNotYetCalled)
-                {
-                    if (aborted)
-                    {
-                        HttpTelemetry.Log.RequestAborted();
-                    }
-
-                    HttpTelemetry.Log.RequestStop();
-                }
-            }
-        }
+        internal bool WasSentByHttpClient() => _sendStatus == MessageAlreadySent;
 
         #region IDisposable Members
 
@@ -242,8 +219,6 @@ protected virtual void Dispose(bool disposing)
                     _content.Dispose();
                 }
             }
-
-            OnStopped();
         }
 
         public void Dispose()

src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs

@@ -13,18 +13,18 @@ internal sealed class HttpTelemetry : EventSource
         public static readonly HttpTelemetry Log = new HttpTelemetry();
 
         private IncrementingPollingCounter? _startedRequestsPerSecondCounter;
-        private IncrementingPollingCounter? _abortedRequestsPerSecondCounter;
+        private IncrementingPollingCounter? _failedRequestsPerSecondCounter;
         private PollingCounter? _startedRequestsCounter;
         private PollingCounter? _currentRequestsCounter;
-        private PollingCounter? _abortedRequestsCounter;
+        private PollingCounter? _failedRequestsCounter;
         private PollingCounter? _totalHttp11ConnectionsCounter;
         private PollingCounter? _totalHttp20ConnectionsCounter;
         private EventCounter? _http11RequestsQueueDurationCounter;
         private EventCounter? _http20RequestsQueueDurationCounter;
 
         private long _startedRequests;
         private long _stoppedRequests;
-        private long _abortedRequests;
+        private long _failedRequests;
 
         private long _openedHttp11Connections;
         private long _openedHttp20Connections;
@@ -37,10 +37,25 @@ internal sealed class HttpTelemetry : EventSource
         // - A stop event's event id must be next one after its start event.
 
         [Event(1, Level = EventLevel.Informational)]
-        public void RequestStart(string scheme, string host, int port, string pathAndQuery, int versionMajor, int versionMinor)
+        private void RequestStart(string scheme, string host, int port, string pathAndQuery, byte versionMajor, byte versionMinor, HttpVersionPolicy versionPolicy)
         {
             Interlocked.Increment(ref _startedRequests);
-            WriteEvent(eventId: 1, scheme, host, port, pathAndQuery, versionMajor, versionMinor);
+            WriteEvent(eventId: 1, scheme, host, port, pathAndQuery, versionMajor, versionMinor, versionPolicy);
+        }
+
+        [NonEvent]
+        public void RequestStart(HttpRequestMessage request)
+        {
+            Debug.Assert(request.RequestUri != null);
+
+            RequestStart(
+                request.RequestUri.Scheme,
+                request.RequestUri.IdnHost,
+                request.RequestUri.Port,
+                request.RequestUri.PathAndQuery,
+                (byte)request.Version.Major,
+                (byte)request.Version.Minor,
+                request.VersionPolicy);
         }
 
         [Event(2, Level = EventLevel.Informational)]
@@ -51,9 +66,9 @@ public void RequestStop()
         }
 
         [Event(3, Level = EventLevel.Error)]
-        public void RequestAborted()
+        public void RequestFailed()
         {
-            Interlocked.Increment(ref _abortedRequests);
+            Interlocked.Increment(ref _failedRequests);
             WriteEvent(eventId: 3);
         }
 
@@ -81,6 +96,18 @@ public void ResponseHeadersBegin()
             WriteEvent(eventId: 7);
         }
 
+        [Event(8, Level = EventLevel.Informational)]
+        public void ResponseContentStart()
+        {
+            WriteEvent(eventId: 8);
+        }
+
+        [Event(9, Level = EventLevel.Informational)]
+        public void ResponseContentStop()
+        {
+            WriteEvent(eventId: 9);
+        }
+
         [NonEvent]
         public void Http11ConnectionEstablished()
         {
@@ -145,22 +172,23 @@ protected override void OnEventCommand(EventCommandEventArgs command)
                     DisplayRateTimeScale = TimeSpan.FromSeconds(1)
                 };
 
-                // The cumulative number of HTTP requests aborted since the process started.
-                // Aborted means that an exception occurred during the handler's Send(Async) call as a result of a
-                // connection related error, timeout, or explicitly cancelled.
-                _abortedRequestsCounter ??= new PollingCounter("requests-aborted", this, () => Interlocked.Read(ref _abortedRequests))
+                // The cumulative number of HTTP requests failed since the process started.
+                // Failed means that an exception occurred during the handler's Send(Async) call as a result of a connection related error, timeout, or explicitly cancelled.
+                // In case of using HttpClient's SendAsync(and friends) with buffering, this includes exceptions that occured while buffering the response content
+                // In case of using HttpClient's helper methods (GetString/ByteArray/Stream), this includes responses with non-success status codes
+                _failedRequestsCounter ??= new PollingCounter("requests-failed", this, () => Interlocked.Read(ref _failedRequests))
                 {
-                    DisplayName = "Requests Aborted"
+                    DisplayName = "Requests Failed"
                 };
 
-                // The number of HTTP requests aborted per second since the process started.
-                _abortedRequestsPerSecondCounter ??= new IncrementingPollingCounter("requests-aborted-rate", this, () => Interlocked.Read(ref _abortedRequests))
+                // The number of HTTP requests failed per second since the process started.
+                _failedRequestsPerSecondCounter ??= new IncrementingPollingCounter("requests-failed-rate", this, () => Interlocked.Read(ref _failedRequests))
                 {
-                    DisplayName = "Requests Aborted Rate",
+                    DisplayName = "Requests Failed Rate",
                     DisplayRateTimeScale = TimeSpan.FromSeconds(1)
                 };
 
-                // The current number of active HTTP requests that have started but not yet completed or aborted.
+                // The current number of active HTTP requests that have started but not yet completed or failed.
                 // Use (-_stoppedRequests + _startedRequests) to avoid returning a negative value if _stoppedRequests is
                 // incremented after reading _startedRequests due to race conditions with completing the HTTP request.
                 _currentRequestsCounter ??= new PollingCounter("current-requests", this, () => -Interlocked.Read(ref _stoppedRequests) + Interlocked.Read(ref _startedRequests))
@@ -193,7 +221,7 @@ protected override void OnEventCommand(EventCommandEventArgs command)
         }
 
         [NonEvent]
-        private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3, string? arg4, int arg5, int arg6)
+        private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3, string? arg4, byte arg5, byte arg6, HttpVersionPolicy arg7)
         {
             if (IsEnabled())
             {
@@ -205,7 +233,7 @@ private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3
                 fixed (char* arg2Ptr = arg2)
                 fixed (char* arg4Ptr = arg4)
                 {
-                    const int NumEventDatas = 6;
+                    const int NumEventDatas = 7;
                     EventData* descrs = stackalloc EventData[NumEventDatas];
 
                     descrs[0] = new EventData
@@ -231,12 +259,17 @@ private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3
                     descrs[4] = new EventData
                     {
                         DataPointer = (IntPtr)(&arg5),
-                        Size = sizeof(int)
+                        Size = sizeof(byte)
                     };
                     descrs[5] = new EventData
                     {
                         DataPointer = (IntPtr)(&arg6),
-                        Size = sizeof(int)
+                        Size = sizeof(byte)
+                    };
+                    descrs[6] = new EventData
+                    {
+                        DataPointer = (IntPtr)(&arg7),
+                        Size = sizeof(HttpVersionPolicy)
                     };
 
                     WriteEventCore(eventId, NumEventDatas, descrs);

src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs

@@ -351,12 +351,6 @@ private void Complete()
                     w.Dispose();
                     _creditWaiter = null;
                 }
-
-                if (HttpTelemetry.Log.IsEnabled())
-                {
-                    bool aborted = _requestCompletionState == StreamCompletionState.Failed || _responseCompletionState == StreamCompletionState.Failed;
-                    _request.OnStopped(aborted);
-                }
             }
 
             private void Cancel()
@@ -391,8 +385,6 @@ private void Cancel()
                 {
                     _waitSource.SetResult(true);
                 }
-
-                if (HttpTelemetry.Log.IsEnabled()) _request.OnAborted();
             }
 
             // Returns whether the waiter should be signalled or not.
@@ -1155,10 +1147,6 @@ private void CloseResponseBody()
                 {
                     Cancel();
                 }
-                else
-                {
-                    _request.OnStopped();
-                }
 
                 _responseBuffer.Dispose();
             }

src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs

@@ -120,8 +120,6 @@ protected void Dispose(bool disposing)
 
                 _pool.DecrementConnectionCount();
 
-                if (HttpTelemetry.Log.IsEnabled()) _currentRequest?.OnAborted();
-
                 if (disposing)
                 {
                     GC.SuppressFinalize(this);
@@ -1872,8 +1870,6 @@ private void CompleteResponse()
             Debug.Assert(_currentRequest != null, "Expected the connection to be associated with a request.");
             Debug.Assert(_writeOffset == 0, "Everything in write buffer should have been flushed.");
 
-            if (HttpTelemetry.Log.IsEnabled()) _currentRequest.OnStopped();
-
             // Disassociate the connection from a request.
             _currentRequest = null;
 

src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs

@@ -358,53 +358,6 @@ public ValueTask<HttpResponseMessage> SendProxyConnectAsync(HttpRequestMessage r
         }
 
         public ValueTask<HttpResponseMessage> SendAsync(HttpRequestMessage request, bool async, bool doRequestAuth, CancellationToken cancellationToken)
-        {
-            if (HttpTelemetry.Log.IsEnabled())
-            {
-                // [ActiveIssue("https://github.com/dotnet/runtime/issues/40896")]
-                if (request.Version.Major < 3 && request.RequestUri != null)
-                {
-                    return SendAsyncWithLogging(request, async, doRequestAuth, cancellationToken);
-                }
-            }
-
-            return SendAsyncHelper(request, async, doRequestAuth, cancellationToken);
-        }
-
-        private async ValueTask<HttpResponseMessage> SendAsyncWithLogging(HttpRequestMessage request, bool async, bool doRequestAuth, CancellationToken cancellationToken)
-        {
-            Debug.Assert(request.RequestUri != null);
-            HttpTelemetry.Log.RequestStart(
-                request.RequestUri.Scheme,
-                request.RequestUri.IdnHost,
-                request.RequestUri.Port,
-                request.RequestUri.PathAndQuery,
-                request.Version.Major,
-                request.Version.Minor);
-
-            request.MarkAsTrackedByTelemetry();
-
-            try
-            {
-                return await SendAsyncHelper(request, async, doRequestAuth, cancellationToken).ConfigureAwait(false);
-            }
-            catch when (LogException(request))
-            {
-                // This code should never run.
-                throw;
-            }
-
-            static bool LogException(HttpRequestMessage request)
-            {
-                request.OnAborted();
-
-                // Returning false means the catch handler isn't run.
-                // So the exception isn't considered to be caught so it will now propagate up the stack.
-                return false;
-            }
-        }
-
-        private ValueTask<HttpResponseMessage> SendAsyncHelper(HttpRequestMessage request, bool async, bool doRequestAuth, CancellationToken cancellationToken)
         {
             if (_proxy == null)
             {

src/libraries/System.Net.Http/tests/FunctionalTests/HttpClientTest.cs

@@ -327,12 +327,12 @@ static void Verify(HttpResponseMessage message)
         }
 
         [Fact]
-        public void GetAsync_CustomException_Synchronous_ThrowsException()
+        public async Task GetAsync_CustomException_Synchronous_ThrowsException()
         {
             var e = new FormatException();
             using (var client = new HttpClient(new CustomResponseHandler((r, c) => { throw e; })))
             {
-                FormatException thrown = Assert.Throws<FormatException>(() => { client.GetAsync(CreateFakeUri()); });
+                FormatException thrown = await Assert.ThrowsAsync<FormatException>(() => client.GetAsync(CreateFakeUri()));
                 Assert.Same(e, thrown);
             }
         }