diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs b/src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs index 853c14d76942db..f00260f6ca9b53 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs @@ -227,7 +227,7 @@ private async Task GetStringAsyncCore(HttpRequestMessage request, Cancel } finally { - FinishSend(cts, disposeCts, telemetryStarted, responseContentTelemetryStarted); + FinishSend(response, cts, disposeCts, telemetryStarted, responseContentTelemetryStarted); } } @@ -306,7 +306,7 @@ private async Task GetByteArrayAsyncCore(HttpRequestMessage request, Can } finally { - FinishSend(cts, disposeCts, telemetryStarted, responseContentTelemetryStarted); + FinishSend(response, cts, disposeCts, telemetryStarted, responseContentTelemetryStarted); } } @@ -352,7 +352,7 @@ private async Task GetStreamAsyncCore(HttpRequestMessage request, Cancel } finally { - FinishSend(cts, disposeCts, telemetryStarted, responseContentTelemetryStarted: false); + FinishSend(response, cts, disposeCts, telemetryStarted, responseContentTelemetryStarted: false); } } @@ -496,7 +496,7 @@ public HttpResponseMessage Send(HttpRequestMessage request, HttpCompletionOption } finally { - FinishSend(cts, disposeCts, telemetryStarted, responseContentTelemetryStarted); + FinishSend(response, cts, disposeCts, telemetryStarted, responseContentTelemetryStarted); } } @@ -551,7 +551,7 @@ async Task Core( } finally { - FinishSend(cts, disposeCts, telemetryStarted, responseContentTelemetryStarted); + FinishSend(response, cts, disposeCts, telemetryStarted, responseContentTelemetryStarted); } } } @@ -583,8 +583,6 @@ private static bool ShouldBufferResponse(HttpCompletionOption completionOption, private void HandleFailure(Exception e, bool telemetryStarted, HttpResponseMessage? response, CancellationTokenSource cts, CancellationToken cancellationToken, CancellationTokenSource pendingRequestsCts) { - LogRequestFailed(telemetryStarted); - response?.Dispose(); Exception? toThrow = null; @@ -623,6 +621,8 @@ private void HandleFailure(Exception e, bool telemetryStarted, HttpResponseMessa e = toThrow = new OperationCanceledException(cancellationToken.IsCancellationRequested ? cancellationToken : cts.Token); } + LogRequestFailed(e, telemetryStarted); + if (NetEventSource.Log.IsEnabled()) NetEventSource.Error(this, e); if (toThrow != null) @@ -642,7 +642,7 @@ private static bool StartSend(HttpRequestMessage request) return false; } - private static void FinishSend(CancellationTokenSource cts, bool disposeCts, bool telemetryStarted, bool responseContentTelemetryStarted) + private static void FinishSend(HttpResponseMessage? response, CancellationTokenSource cts, bool disposeCts, bool telemetryStarted, bool responseContentTelemetryStarted) { // Log completion. if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) @@ -652,7 +652,7 @@ private static void FinishSend(CancellationTokenSource cts, bool disposeCts, boo HttpTelemetry.Log.ResponseContentStop(); } - HttpTelemetry.Log.RequestStop(); + HttpTelemetry.Log.RequestStop(response); } // Dispose of the CancellationTokenSource if it was created specially for this request diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/HttpMessageInvoker.cs b/src/libraries/System.Net.Http/src/System/Net/Http/HttpMessageInvoker.cs index a06da5b9ed5a27..ceb93c06a2aae2 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/HttpMessageInvoker.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/HttpMessageInvoker.cs @@ -41,18 +41,20 @@ public virtual HttpResponseMessage Send(HttpRequestMessage request, Cancellation { HttpTelemetry.Log.RequestStart(request); + HttpResponseMessage? response = null; try { - return _handler.Send(request, cancellationToken); + response = _handler.Send(request, cancellationToken); + return response; } - catch when (LogRequestFailed(telemetryStarted: true)) + catch (Exception ex) when (LogRequestFailed(ex, telemetryStarted: true)) { // Unreachable as LogRequestFailed will return false throw; } finally { - HttpTelemetry.Log.RequestStop(); + HttpTelemetry.Log.RequestStop(response); } } else @@ -78,18 +80,20 @@ static async Task SendAsyncWithTelemetry(HttpMessageHandler { HttpTelemetry.Log.RequestStart(request); + HttpResponseMessage? response = null; try { - return await handler.SendAsync(request, cancellationToken).ConfigureAwait(false); + response = await handler.SendAsync(request, cancellationToken).ConfigureAwait(false); + return response; } - catch when (LogRequestFailed(telemetryStarted: true)) + catch (Exception ex) when (LogRequestFailed(ex, telemetryStarted: true)) { // Unreachable as LogRequestFailed will return false throw; } finally { - HttpTelemetry.Log.RequestStop(); + HttpTelemetry.Log.RequestStop(response); } } } @@ -100,11 +104,11 @@ private static bool ShouldSendWithTelemetry(HttpRequestMessage request) => request.RequestUri is Uri requestUri && requestUri.IsAbsoluteUri; - internal static bool LogRequestFailed(bool telemetryStarted) + internal static bool LogRequestFailed(Exception exception, bool telemetryStarted) { if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { - HttpTelemetry.Log.RequestFailed(); + HttpTelemetry.Log.RequestFailed(exception); } return false; } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs b/src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs index 131748bddf5a8c..8126bda265a335 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs @@ -13,6 +13,11 @@ internal sealed partial class HttpTelemetry : EventSource { public static readonly HttpTelemetry Log = new HttpTelemetry(); + public static class Keywords + { + public const EventKeywords RequestFailedDetailed = (EventKeywords)1; + } + private long _startedRequests; private long _stoppedRequests; private long _failedRequests; @@ -50,18 +55,39 @@ public void RequestStart(HttpRequestMessage request) request.VersionPolicy); } - [Event(2, Level = EventLevel.Informational)] - public void RequestStop() + [NonEvent] + public void RequestStop(HttpResponseMessage? response) + { + RequestStop(response is null ? -1 : (int)response.StatusCode); + } + + [Event(2, Level = EventLevel.Informational, Version = 1)] + private void RequestStop(int statusCode) { Interlocked.Increment(ref _stoppedRequests); - WriteEvent(eventId: 2); + WriteEvent(eventId: 2, statusCode); } - [Event(3, Level = EventLevel.Error)] - public void RequestFailed() + [NonEvent] + public void RequestFailed(Exception exception) { Interlocked.Increment(ref _failedRequests); - WriteEvent(eventId: 3); + + if (IsEnabled(EventLevel.Error, EventKeywords.None)) + { + RequestFailed(exceptionMessage: exception.Message); + + if (IsEnabled(EventLevel.Error, Keywords.RequestFailedDetailed)) + { + RequestFailedDetailed(exception: exception.ToString()); + } + } + } + + [Event(3, Level = EventLevel.Error, Version = 1)] + private void RequestFailed(string exceptionMessage) + { + WriteEvent(eventId: 3, exceptionMessage); } [Event(4, Level = EventLevel.Informational)] @@ -112,10 +138,10 @@ public void ResponseHeadersStart() WriteEvent(eventId: 11); } - [Event(12, Level = EventLevel.Informational)] - public void ResponseHeadersStop() + [Event(12, Level = EventLevel.Informational, Version = 1)] + public void ResponseHeadersStop(int statusCode) { - WriteEvent(eventId: 12); + WriteEvent(eventId: 12, statusCode); } [Event(13, Level = EventLevel.Informational)] @@ -130,6 +156,12 @@ public void ResponseContentStop() WriteEvent(eventId: 14); } + [Event(15, Level = EventLevel.Error, Keywords = Keywords.RequestFailedDetailed)] + private void RequestFailedDetailed(string exception) + { + WriteEvent(eventId: 15, exception); + } + [NonEvent] public void Http11ConnectionEstablished() { diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs index d5199afc6deb50..81aeaa63a9e29f 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs @@ -1024,7 +1024,8 @@ public async Task ReadResponseHeadersAsync(CancellationToken cancellationToken) Debug.Assert(!wait); } - if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop(); + Debug.Assert(_response is not null); + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop((int)_response.StatusCode); } catch { diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs index 70b1690707ccb8..5bb3a2941cd6ff 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs @@ -352,7 +352,7 @@ private async Task ReadResponseAsync(CancellationToken cancellationToken) _headerState = HeaderState.TrailingHeaders; - if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop(); + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop((int)_response.StatusCode); } private async Task SendContentAsync(HttpContent content, CancellationToken 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 fbfa024a647cbd..ba3b895b65e239 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 @@ -696,7 +696,7 @@ public async Task SendAsync(HttpRequestMessage request, boo await FillForHeadersAsync(async).ConfigureAwait(false); } - if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop(); + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop((int)response.StatusCode); if (allowExpect100ToContinue != null) { diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs index b6bee89d36db76..9ac7d796600355 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs @@ -6,7 +6,6 @@ using System.Diagnostics.Tracing; using System.IO; using System.Linq; -using System.Net.Quic; using System.Net.Test.Common; using System.Text; using System.Threading; @@ -412,19 +411,40 @@ private static void ValidateStartFailedStopEvents(ConcurrentQueue<(EventWrittenE Assert.Equal(count, starts.Length); (EventWrittenEventArgs Event, Guid ActivityId)[] stops = events.Where(e => e.Event.EventName == "RequestStop").ToArray(); - Assert.All(stops, stopEvent => Assert.Empty(stopEvent.Event.Payload)); + foreach (EventWrittenEventArgs stopEvent in stops.Select(e => e.Event)) + { + object payload = Assert.Single(stopEvent.Payload); + int statusCode = Assert.IsType(payload); + Assert.Equal(shouldHaveFailures ? -1 : 200, statusCode); + } ValidateSameActivityIds(starts, stops); (EventWrittenEventArgs Event, Guid ActivityId)[] failures = events.Where(e => e.Event.EventName == "RequestFailed").ToArray(); - Assert.All(failures, failedEvent => Assert.Empty(failedEvent.Event.Payload)); + (EventWrittenEventArgs Event, Guid ActivityId)[] detailedFailures = events.Where(e => e.Event.EventName == "RequestFailedDetailed").ToArray(); if (shouldHaveFailures) { + foreach (EventWrittenEventArgs failedEvent in failures.Select(e => e.Event)) + { + object payload = Assert.Single(failedEvent.Payload); + string exceptionMessage = Assert.IsType(payload); + Assert.Equal(new OperationCanceledException().Message, exceptionMessage); + } + + foreach (EventWrittenEventArgs failedEvent in detailedFailures.Select(e => e.Event)) + { + object payload = Assert.Single(failedEvent.Payload); + string exception = Assert.IsType(payload); + Assert.StartsWith("System.Threading.Tasks.TaskCanceledException", exception); + } + ValidateSameActivityIds(starts, failures); + ValidateSameActivityIds(starts, detailedFailures); } else { Assert.Empty(failures); + Assert.Empty(detailedFailures); } } @@ -470,8 +490,8 @@ private static void ValidateRequestResponseStartStopEvents(ConcurrentQueue<(Even foreach (EventWrittenEventArgs requestContentStop in requestContentStops.Select(e => e.Event)) { object payload = Assert.Single(requestContentStop.Payload); - Assert.True(payload is long); - Assert.Equal(requestContentLength.Value, (long)payload); + long contentLength = Assert.IsType(payload); + Assert.Equal(requestContentLength.Value, contentLength); } ValidateSameActivityIds(requestContentStarts, requestContentStops); @@ -482,7 +502,12 @@ private static void ValidateRequestResponseStartStopEvents(ConcurrentQueue<(Even (EventWrittenEventArgs Event, Guid ActivityId)[] responseHeadersStops = events.Where(e => e.Event.EventName == "ResponseHeadersStop").ToArray(); Assert.Equal(count, responseHeadersStops.Length); - Assert.All(responseHeadersStops, r => Assert.Empty(r.Event.Payload)); + foreach (EventWrittenEventArgs responseHeadersStop in responseHeadersStops.Select(e => e.Event)) + { + object payload = Assert.Single(responseHeadersStop.Payload); + int statusCode = Assert.IsType(payload); + Assert.Equal(200, statusCode); + } ValidateSameActivityIds(responseHeadersStarts, responseHeadersStops); diff --git a/src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs b/src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs index 5667687e632e2f..26ac057e31bd8d 100644 --- a/src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs +++ b/src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs @@ -11,9 +11,9 @@ public class HttpTelemetry public void RequestStart(HttpRequestMessage request) { } - public void RequestStop() { } + public void RequestStop(HttpResponseMessage response) { } - public void RequestFailed() { } + public void RequestFailed(Exception exception) { } public void ResponseContentStart() { }