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 dc3172c8a8772..8e34a9f40bc14 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 @@ -163,51 +163,90 @@ public HttpClient(HttpMessageHandler handler, bool disposeHandler) public Task GetStringAsync(string? requestUri, CancellationToken cancellationToken) => GetStringAsync(CreateUri(requestUri), cancellationToken); - public Task GetStringAsync(Uri? requestUri, CancellationToken cancellationToken) => - GetStringAsyncCore(GetAsync(requestUri, HttpCompletionOption.ResponseHeadersRead, cancellationToken), cancellationToken); + public Task GetStringAsync(Uri? requestUri, CancellationToken cancellationToken) + { + HttpRequestMessage request = CreateRequestMessage(HttpMethod.Get, requestUri); + + // Called outside of async state machine to propagate certain exception even without awaiting the returned task. + CheckRequestBeforeSend(request); - private async Task GetStringAsyncCore(Task getTask, CancellationToken cancellationToken) + return GetStringAsyncCore(request, cancellationToken); + } + + private async Task GetStringAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken) { - // Wait for the response message. - using (HttpResponseMessage responseMessage = await getTask.ConfigureAwait(false)) + bool telemetryStarted = false, responseContentTelemetryStarted = false; + if (HttpTelemetry.Log.IsEnabled() && request.RequestUri != null) { - // Make sure it completed successfully. - responseMessage.EnsureSuccessStatusCode(); + HttpTelemetry.Log.RequestStart(request); + telemetryStarted = true; + } - // Get the response content. - HttpContent? c = responseMessage.Content; - if (c != null) + try + { + // Wait for the response message. + using (HttpResponseMessage responseMessage = await SendAsyncCore(request, HttpCompletionOption.ResponseHeadersRead, async: true, emitTelemetryStartStop: false, cancellationToken).ConfigureAwait(false)) { -#if NET46 - return await c.ReadAsStringAsync().ConfigureAwait(false); -#else - HttpContentHeaders headers = c.Headers; - - // Since the underlying byte[] will never be exposed, we use an ArrayPool-backed - // stream to which we copy all of the data from the response. - using (Stream responseStream = c.TryReadAsStream() ?? await c.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false)) - using (var buffer = new HttpContent.LimitArrayPoolWriteStream(_maxResponseContentBufferSize, (int)headers.ContentLength.GetValueOrDefault())) + // Make sure it completed successfully. + responseMessage.EnsureSuccessStatusCode(); + + // Get the response content. + HttpContent? c = responseMessage.Content; + if (c != null) { - try + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { - await responseStream.CopyToAsync(buffer, cancellationToken).ConfigureAwait(false); + HttpTelemetry.Log.ResponseContentStart(); + responseContentTelemetryStarted = true; } - catch (Exception e) when (HttpContent.StreamCopyExceptionNeedsWrapping(e)) + #if NET46 + return await c.ReadAsStringAsync().ConfigureAwait(false); + #else + HttpContentHeaders headers = c.Headers; + + // Since the underlying byte[] will never be exposed, we use an ArrayPool-backed + // stream to which we copy all of the data from the response. + using (Stream responseStream = c.TryReadAsStream() ?? await c.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false)) + using (var buffer = new HttpContent.LimitArrayPoolWriteStream(_maxResponseContentBufferSize, (int)headers.ContentLength.GetValueOrDefault())) { - throw HttpContent.WrapStreamCopyException(e); - } + try + { + await responseStream.CopyToAsync(buffer, cancellationToken).ConfigureAwait(false); + } + catch (Exception e) when (HttpContent.StreamCopyExceptionNeedsWrapping(e)) + { + throw HttpContent.WrapStreamCopyException(e); + } - if (buffer.Length > 0) - { - // Decode and return the data from the buffer. - return HttpContent.ReadBufferAsString(buffer.GetBuffer(), headers); + if (buffer.Length > 0) + { + // Decode and return the data from the buffer. + return HttpContent.ReadBufferAsString(buffer.GetBuffer(), headers); + } } + #endif } -#endif + + // No content to return. + return string.Empty; } + } + catch when (LogRequestFailed(telemetryStarted)) + { + // Unreachable as LogRequestFailed will return false + throw; + } + finally + { + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) + { + if (responseContentTelemetryStarted) + { + HttpTelemetry.Log.ResponseContentStop(); + } - // No content to return. - return string.Empty; + HttpTelemetry.Log.RequestStop(); + } } } @@ -220,60 +259,58 @@ private async Task GetStringAsyncCore(Task getTask, public Task GetByteArrayAsync(string? requestUri, CancellationToken cancellationToken) => GetByteArrayAsync(CreateUri(requestUri), cancellationToken); - public Task GetByteArrayAsync(Uri? requestUri, CancellationToken cancellationToken) => - GetByteArrayAsyncCore(GetAsync(requestUri, HttpCompletionOption.ResponseHeadersRead, cancellationToken), cancellationToken); + public Task GetByteArrayAsync(Uri? requestUri, CancellationToken cancellationToken) + { + HttpRequestMessage request = CreateRequestMessage(HttpMethod.Get, requestUri); + + // Called outside of async state machine to propagate certain exception even without awaiting the returned task. + CheckRequestBeforeSend(request); + + return GetByteArrayAsyncCore(request, cancellationToken); + } - private async Task GetByteArrayAsyncCore(Task getTask, CancellationToken cancellationToken) + private async Task GetByteArrayAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken) { - // Wait for the response message. - using (HttpResponseMessage responseMessage = await getTask.ConfigureAwait(false)) + bool telemetryStarted = false, responseContentTelemetryStarted = false; + if (HttpTelemetry.Log.IsEnabled() && request.RequestUri != null) { - // Make sure it completed successfully. - responseMessage.EnsureSuccessStatusCode(); + HttpTelemetry.Log.RequestStart(request); + telemetryStarted = true; + } - // Get the response content. - HttpContent? c = responseMessage.Content; - if (c != null) + try + { + // Wait for the response message. + using (HttpResponseMessage responseMessage = await SendAsyncCore(request, HttpCompletionOption.ResponseHeadersRead, async: true, emitTelemetryStartStop: false, cancellationToken).ConfigureAwait(false)) { -#if NET46 - return await c.ReadAsByteArrayAsync().ConfigureAwait(false); -#else - HttpContentHeaders headers = c.Headers; - using (Stream responseStream = c.TryReadAsStream() ?? await c.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false)) - { - long? contentLength = headers.ContentLength; - Stream buffer; // declared here to share the state machine field across both if/else branches + // Make sure it completed successfully. + responseMessage.EnsureSuccessStatusCode(); - if (contentLength.HasValue) + // Get the response content. + HttpContent? c = responseMessage.Content; + if (c != null) + { + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { - // If we got a content length, then we assume that it's correct and create a MemoryStream - // to which the content will be transferred. That way, assuming we actually get the exact - // amount we were expecting, we can simply return the MemoryStream's underlying buffer. - buffer = new HttpContent.LimitMemoryStream(_maxResponseContentBufferSize, (int)contentLength.GetValueOrDefault()); - - try - { - await responseStream.CopyToAsync(buffer, cancellationToken).ConfigureAwait(false); - } - catch (Exception e) when (HttpContent.StreamCopyExceptionNeedsWrapping(e)) - { - throw HttpContent.WrapStreamCopyException(e); - } - - if (buffer.Length > 0) - { - return ((HttpContent.LimitMemoryStream)buffer).GetSizedBuffer(); - } + HttpTelemetry.Log.ResponseContentStart(); + responseContentTelemetryStarted = true; } - else + #if NET46 + return await c.ReadAsByteArrayAsync().ConfigureAwait(false); + #else + HttpContentHeaders headers = c.Headers; + using (Stream responseStream = c.TryReadAsStream() ?? await c.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false)) { - // If we didn't get a content length, then we assume we're going to have to grow - // the buffer potentially several times and that it's unlikely the underlying buffer - // at the end will be the exact size needed, in which case it's more beneficial to use - // ArrayPool buffers and copy out to a new array at the end. - buffer = new HttpContent.LimitArrayPoolWriteStream(_maxResponseContentBufferSize); - try + long? contentLength = headers.ContentLength; + Stream buffer; // declared here to share the state machine field across both if/else branches + + if (contentLength.HasValue) { + // If we got a content length, then we assume that it's correct and create a MemoryStream + // to which the content will be transferred. That way, assuming we actually get the exact + // amount we were expecting, we can simply return the MemoryStream's underlying buffer. + buffer = new HttpContent.LimitMemoryStream(_maxResponseContentBufferSize, (int)contentLength.GetValueOrDefault()); + try { await responseStream.CopyToAsync(buffer, cancellationToken).ConfigureAwait(false); @@ -285,17 +322,58 @@ private async Task GetByteArrayAsyncCore(Task getTa if (buffer.Length > 0) { - return ((HttpContent.LimitArrayPoolWriteStream)buffer).ToArray(); + return ((HttpContent.LimitMemoryStream)buffer).GetSizedBuffer(); + } + } + else + { + // If we didn't get a content length, then we assume we're going to have to grow + // the buffer potentially several times and that it's unlikely the underlying buffer + // at the end will be the exact size needed, in which case it's more beneficial to use + // ArrayPool buffers and copy out to a new array at the end. + buffer = new HttpContent.LimitArrayPoolWriteStream(_maxResponseContentBufferSize); + try + { + try + { + await responseStream.CopyToAsync(buffer, cancellationToken).ConfigureAwait(false); + } + catch (Exception e) when (HttpContent.StreamCopyExceptionNeedsWrapping(e)) + { + throw HttpContent.WrapStreamCopyException(e); + } + + if (buffer.Length > 0) + { + return ((HttpContent.LimitArrayPoolWriteStream)buffer).ToArray(); + } } + finally { buffer.Dispose(); } } - finally { buffer.Dispose(); } } + #endif } -#endif + + // No content to return. + return Array.Empty(); } + } + catch when (LogRequestFailed(telemetryStarted)) + { + // Unreachable as LogRequestFailed will return false + throw; + } + finally + { + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) + { + if (responseContentTelemetryStarted) + { + HttpTelemetry.Log.ResponseContentStop(); + } - // No content to return. - return Array.Empty(); + HttpTelemetry.Log.RequestStop(); + } } } @@ -308,17 +386,59 @@ private async Task GetByteArrayAsyncCore(Task getTa public Task GetStreamAsync(Uri? requestUri) => GetStreamAsync(requestUri, CancellationToken.None); - public Task GetStreamAsync(Uri? requestUri, CancellationToken cancellationToken) => - FinishGetStreamAsync(GetAsync(requestUri, HttpCompletionOption.ResponseHeadersRead, cancellationToken), cancellationToken); + public Task GetStreamAsync(Uri? requestUri, CancellationToken cancellationToken) + { + HttpRequestMessage request = CreateRequestMessage(HttpMethod.Get, requestUri); + + // Called outside of async state machine to propagate certain exception even without awaiting the returned task. + CheckRequestBeforeSend(request); - private async Task FinishGetStreamAsync(Task getTask, CancellationToken cancellationToken) + return GetStreamAsyncCore(request, cancellationToken); + } + + private async Task GetStreamAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken) { - HttpResponseMessage response = await getTask.ConfigureAwait(false); - response.EnsureSuccessStatusCode(); - HttpContent? c = response.Content; - return c != null ? - (c.TryReadAsStream() ?? await c.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false)) : - Stream.Null; + bool telemetryStarted = false, responseContentTelemetryStarted = false; + if (HttpTelemetry.Log.IsEnabled() && request.RequestUri != null) + { + HttpTelemetry.Log.RequestStart(request); + telemetryStarted = true; + } + + try + { + HttpResponseMessage response = await SendAsyncCore(request, HttpCompletionOption.ResponseHeadersRead, async: true, emitTelemetryStartStop: false, cancellationToken).ConfigureAwait(false); + response.EnsureSuccessStatusCode(); + HttpContent? c = response.Content; + if (c != null) + { + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) + { + HttpTelemetry.Log.ResponseContentStart(); + responseContentTelemetryStarted = true; + } + + return c.TryReadAsStream() ?? await c.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false); + } + return Stream.Null; + } + catch when (LogRequestFailed(telemetryStarted)) + { + // Unreachable as LogRequestFailed will return false + throw; + } + finally + { + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) + { + if (responseContentTelemetryStarted) + { + HttpTelemetry.Log.ResponseContentStop(); + } + + HttpTelemetry.Log.RequestStop(); + } + } } #endregion Simple Get Overloads @@ -482,7 +602,10 @@ public HttpResponseMessage Send(HttpRequestMessage request, HttpCompletionOption public HttpResponseMessage Send(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationToken cancellationToken) { - ValueTask sendTask = SendAsyncCore(request, completionOption, async: false, cancellationToken); + // Called outside of async state machine to propagate certain exception even without awaiting the returned task. + CheckRequestBeforeSend(request); + + ValueTask sendTask = SendAsyncCore(request, completionOption, async: false, emitTelemetryStartStop: true, cancellationToken); Debug.Assert(sendTask.IsCompleted); return sendTask.GetAwaiter().GetResult(); } @@ -506,11 +629,13 @@ public Task SendAsync(HttpRequestMessage request, HttpCompl public Task SendAsync(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationToken cancellationToken) { - return SendAsyncCore(request, completionOption, async: true, cancellationToken).AsTask(); + // Called outside of async state machine to propagate certain exception even without awaiting the returned task. + CheckRequestBeforeSend(request); + + return SendAsyncCore(request, completionOption, async: true, emitTelemetryStartStop: true, cancellationToken).AsTask(); } - private ValueTask SendAsyncCore(HttpRequestMessage request, HttpCompletionOption completionOption, - bool async, CancellationToken cancellationToken) + private void CheckRequestBeforeSend(HttpRequestMessage request) { if (request == null) { @@ -520,49 +645,38 @@ public Task SendAsync(HttpRequestMessage request, HttpCompl CheckRequestMessage(request); SetOperationStarted(); - PrepareRequestMessage(request); + // PrepareRequestMessage will resolve the request address against the base address. + PrepareRequestMessage(request); + } + private async ValueTask SendAsyncCore(HttpRequestMessage request, HttpCompletionOption completionOption, + bool async, bool emitTelemetryStartStop, CancellationToken cancellationToken) + { // Combines given cancellationToken with the global one and the timeout. CancellationTokenSource cts = PrepareCancellationTokenSource(cancellationToken, out bool disposeCts, out long timeoutTime); - // Initiate the send. - ValueTask responseTask; - try - { - responseTask = async ? - new ValueTask(base.SendAsync(request, cts.Token)) : - new ValueTask(base.Send(request, cts.Token)); - } - catch (Exception e) - { - HandleFinishSendCleanup(cts, disposeCts); + bool buffered = completionOption == HttpCompletionOption.ResponseContentRead && + !string.Equals(request.Method.Method, "HEAD", StringComparison.OrdinalIgnoreCase); - if (e is OperationCanceledException operationException && TimeoutFired(cancellationToken, timeoutTime)) + bool telemetryStarted = false, responseContentTelemetryStarted = false; + if (HttpTelemetry.Log.IsEnabled()) + { + if (emitTelemetryStartStop && request.RequestUri != null) { - throw CreateTimeoutException(operationException); + HttpTelemetry.Log.RequestStart(request); + telemetryStarted = true; } - - throw; } - bool buffered = completionOption == HttpCompletionOption.ResponseContentRead && - !string.Equals(request.Method.Method, "HEAD", StringComparison.OrdinalIgnoreCase); - - return FinishSendAsync(responseTask, request, cts, disposeCts, buffered, async, cancellationToken, timeoutTime); - } - - private async ValueTask FinishSendAsync(ValueTask sendTask, HttpRequestMessage request, CancellationTokenSource cts, - bool disposeCts, bool buffered, bool async, CancellationToken callerToken, long timeoutTime) - { + // Initiate the send. HttpResponseMessage? response = null; try { - // In sync scenario the ValueTask must already contains the result. - Debug.Assert(async || sendTask.IsCompleted, "In synchronous scenario, the sendTask must be already completed."); - // Wait for the send request to complete, getting back the response. - response = await sendTask.ConfigureAwait(false); + response = async ? + await base.SendAsync(request, cts.Token).ConfigureAwait(false) : + base.Send(request, cts.Token); if (response == null) { throw new InvalidOperationException(SR.net_http_handler_noresponse); @@ -571,10 +685,15 @@ public Task SendAsync(HttpRequestMessage request, HttpCompl // Buffer the response content if we've been asked to and we have a Content to buffer. if (buffered && response.Content != null) { + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) + { + HttpTelemetry.Log.ResponseContentStart(); + responseContentTelemetryStarted = true; + } + if (async) { await response.Content.LoadIntoBufferAsync(_maxResponseContentBufferSize, cts.Token).ConfigureAwait(false); - } else { @@ -587,9 +706,11 @@ public Task SendAsync(HttpRequestMessage request, HttpCompl } catch (Exception e) { + LogRequestFailed(telemetryStarted); + response?.Dispose(); - if (e is OperationCanceledException operationException && TimeoutFired(callerToken, timeoutTime)) + if (e is OperationCanceledException operationException && TimeoutFired(cancellationToken, timeoutTime)) { HandleSendTimeout(operationException); throw CreateTimeoutException(operationException); @@ -600,6 +721,16 @@ public Task SendAsync(HttpRequestMessage request, HttpCompl } finally { + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) + { + if (responseContentTelemetryStarted) + { + HttpTelemetry.Log.ResponseContentStop(); + } + + HttpTelemetry.Log.RequestStop(); + } + HandleFinishSendCleanup(cts, disposeCts); } } 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 60e39a2098655..d4d98e2697496 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,7 +41,28 @@ public HttpMessageInvoker(HttpMessageHandler handler, bool disposeHandler) } 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 SendAsync(HttpRequestMessage request, @@ -53,7 +74,40 @@ public HttpMessageInvoker(HttpMessageHandler handler, bool disposeHandler) } CheckDisposed(); + if (HttpTelemetry.Log.IsEnabled() && !request.WasSentByHttpClient() && request.RequestUri != null) + { + return SendAsyncWithTelemetry(_handler, request, cancellationToken); + } + return _handler.SendAsync(request, cancellationToken); + + static async Task 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() diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/HttpRequestMessage.cs b/src/libraries/System.Net.Http/src/System/Net/Http/HttpRequestMessage.cs index 5f9d7b6dda6a7..388bf1b843155 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/HttpRequestMessage.cs +++ b/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() 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 957a96117182c..5879581504f45 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,17 +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? _requestsQueueDurationCounter; + private EventCounter? _http11RequestsQueueDurationCounter; + private EventCounter? _http20RequestsQueueDurationCounter; private long _startedRequests; private long _stoppedRequests; - private long _abortedRequests; + private long _failedRequests; private long _openedHttp11Connections; private long _openedHttp20Connections; @@ -36,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)] @@ -50,53 +66,120 @@ 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); } [Event(4, Level = EventLevel.Informational)] + private void ConnectionEstablished(byte versionMajor, byte versionMinor) + { + WriteEvent(eventId: 4, versionMajor, versionMinor); + } + + [Event(5, Level = EventLevel.Informational)] + private void ConnectionClosed(byte versionMajor, byte versionMinor) + { + WriteEvent(eventId: 5, versionMajor, versionMinor); + } + + [Event(6, Level = EventLevel.Informational)] + private void RequestLeftQueue(double timeOnQueueMilliseconds, byte versionMajor, byte versionMinor) + { + WriteEvent(eventId: 6, timeOnQueueMilliseconds, versionMajor, versionMinor); + } + + [Event(7, Level = EventLevel.Informational)] + public void RequestHeadersStart() + { + WriteEvent(eventId: 7); + } + + [Event(8, Level = EventLevel.Informational)] + public void RequestHeadersStop() + { + WriteEvent(eventId: 8); + } + + [Event(9, Level = EventLevel.Informational)] + public void RequestContentStart() + { + WriteEvent(eventId: 9); + } + + [Event(10, Level = EventLevel.Informational)] + public void RequestContentStop(long contentLength) + { + WriteEvent(eventId: 10, contentLength); + } + + [Event(11, Level = EventLevel.Informational)] + public void ResponseHeadersStart() + { + WriteEvent(eventId: 11); + } + + [Event(12, Level = EventLevel.Informational)] + public void ResponseHeadersStop() + { + WriteEvent(eventId: 12); + } + + [Event(13, Level = EventLevel.Informational)] + public void ResponseContentStart() + { + WriteEvent(eventId: 13); + } + + [Event(14, Level = EventLevel.Informational)] + public void ResponseContentStop() + { + WriteEvent(eventId: 14); + } + + [NonEvent] public void Http11ConnectionEstablished() { Interlocked.Increment(ref _openedHttp11Connections); - WriteEvent(eventId: 4); + ConnectionEstablished(versionMajor: 1, versionMinor: 1); } - [Event(5, Level = EventLevel.Informational)] + [NonEvent] public void Http11ConnectionClosed() { long count = Interlocked.Decrement(ref _openedHttp11Connections); Debug.Assert(count >= 0); - WriteEvent(eventId: 5); + ConnectionClosed(versionMajor: 1, versionMinor: 1); } - [Event(6, Level = EventLevel.Informational)] + [NonEvent] public void Http20ConnectionEstablished() { Interlocked.Increment(ref _openedHttp20Connections); - WriteEvent(eventId: 6); + ConnectionEstablished(versionMajor: 2, versionMinor: 0); } - [Event(7, Level = EventLevel.Informational)] + [NonEvent] public void Http20ConnectionClosed() { long count = Interlocked.Decrement(ref _openedHttp20Connections); Debug.Assert(count >= 0); - WriteEvent(eventId: 7); + ConnectionClosed(versionMajor: 2, versionMinor: 0); } - [Event(8, Level = EventLevel.Informational)] + [NonEvent] public void Http11RequestLeftQueue(double timeOnQueueMilliseconds) { - _requestsQueueDurationCounter!.WriteMetric(timeOnQueueMilliseconds); - WriteEvent(eventId: 8, timeOnQueueMilliseconds); + _http11RequestsQueueDurationCounter!.WriteMetric(timeOnQueueMilliseconds); + RequestLeftQueue(timeOnQueueMilliseconds, versionMajor: 1, versionMinor: 1); } - [Event(9, Level = EventLevel.Informational)] - public void ResponseHeadersBegin() + [NonEvent] + public void Http20RequestLeftQueue(double timeOnQueueMilliseconds) { - WriteEvent(eventId: 9); + _http20RequestsQueueDurationCounter!.WriteMetric(timeOnQueueMilliseconds); + RequestLeftQueue(timeOnQueueMilliseconds, versionMajor: 2, versionMinor: 0); } protected override void OnEventCommand(EventCommandEventArgs command) @@ -119,22 +202,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)) @@ -152,16 +236,22 @@ protected override void OnEventCommand(EventCommandEventArgs command) DisplayName = "Current Http 2.0 Connections" }; - _requestsQueueDurationCounter ??= new EventCounter("http11-requests-queue-duration", this) + _http11RequestsQueueDurationCounter ??= new EventCounter("http11-requests-queue-duration", this) { DisplayName = "HTTP 1.1 Requests Queue Duration", DisplayUnits = "ms" }; + + _http20RequestsQueueDurationCounter ??= new EventCounter("http20-requests-queue-duration", this) + { + DisplayName = "HTTP 2.0 Requests Queue Duration", + DisplayUnits = "ms" + }; } } [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()) { @@ -173,8 +263,8 @@ private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3 fixed (char* arg2Ptr = arg2) fixed (char* arg4Ptr = arg4) { - const int NumEventDatas = 6; - var descrs = stackalloc EventData[NumEventDatas]; + const int NumEventDatas = 7; + EventData* descrs = stackalloc EventData[NumEventDatas]; descrs[0] = new EventData { @@ -199,12 +289,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); @@ -213,17 +308,53 @@ private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3 } [NonEvent] - private unsafe void WriteEvent(int eventId, double arg1) + private unsafe void WriteEvent(int eventId, double arg1, byte arg2, byte arg3) { if (IsEnabled()) { - EventData descr = new EventData + const int NumEventDatas = 3; + EventData* descrs = stackalloc EventData[NumEventDatas]; + + descrs[0] = new EventData { DataPointer = (IntPtr)(&arg1), Size = sizeof(double) }; + descrs[1] = new EventData + { + DataPointer = (IntPtr)(&arg2), + Size = sizeof(byte) + }; + descrs[2] = new EventData + { + DataPointer = (IntPtr)(&arg3), + Size = sizeof(byte) + }; + + WriteEventCore(eventId, NumEventDatas, descrs); + } + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, byte arg1, byte arg2) + { + if (IsEnabled()) + { + const int NumEventDatas = 2; + EventData* descrs = stackalloc EventData[NumEventDatas]; + + descrs[0] = new EventData + { + DataPointer = (IntPtr)(&arg1), + Size = sizeof(byte) + }; + descrs[1] = new EventData + { + DataPointer = (IntPtr)(&arg2), + Size = sizeof(byte) + }; - WriteEventCore(eventId, eventDataCount: 1, &descr); + WriteEventCore(eventId, NumEventDatas, descrs); } } } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingWriteStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingWriteStream.cs index 4da5c7b2878b0..e66dbf095cef9 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingWriteStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingWriteStream.cs @@ -19,6 +19,8 @@ public ChunkedEncodingWriteStream(HttpConnection connection) : base(connection) public override void Write(ReadOnlySpan buffer) { + BytesWritten += buffer.Length; + HttpConnection connection = GetConnectionOrThrow(); Debug.Assert(connection._currentRequest != null); @@ -39,6 +41,8 @@ public override void Write(ReadOnlySpan buffer) public override ValueTask WriteAsync(ReadOnlyMemory buffer, CancellationToken ignored) { + BytesWritten += buffer.Length; + HttpConnection connection = GetConnectionOrThrow(); Debug.Assert(connection._currentRequest != null); diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthWriteStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthWriteStream.cs index 7867eac8dd6d8..e51c5e06cbe71 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthWriteStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthWriteStream.cs @@ -17,6 +17,8 @@ public ContentLengthWriteStream(HttpConnection connection) : base(connection) public override void Write(ReadOnlySpan buffer) { + BytesWritten += buffer.Length; + // Have the connection write the data, skipping the buffer. Importantly, this will // force a flush of anything already in the buffer, i.e. any remaining request headers // that are still buffered. @@ -27,6 +29,8 @@ public override void Write(ReadOnlySpan buffer) public override ValueTask WriteAsync(ReadOnlyMemory buffer, CancellationToken ignored) // token ignored as it comes from SendAsync { + BytesWritten += buffer.Length; + // Have the connection write the data, skipping the buffer. Importantly, this will // force a flush of anything already in the buffer, i.e. any remaining request headers // that are still buffered. diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs index b01878edf34f5..e4e717189ee10 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs @@ -16,6 +16,7 @@ using System.Threading; using System.Threading.Channels; using System.Threading.Tasks; +using Microsoft.Extensions.Internal; namespace System.Net.Http { @@ -1308,16 +1309,24 @@ private async ValueTask SendHeadersAsync(HttpRequestMessage request // in order to avoid consuming resources in potentially many requests waiting for access. try { - if (_pool.EnableMultipleHttp2Connections) + if (!_concurrentStreams.TryRequestCreditNoWait(1)) { - if (!_concurrentStreams.TryRequestCreditNoWait(1)) + if (_pool.EnableMultipleHttp2Connections) { throw new HttpRequestException(null, null, RequestRetryType.RetryOnNextConnection); } - } - else - { - await _concurrentStreams.RequestCreditAsync(1, cancellationToken).ConfigureAwait(false); + + if (HttpTelemetry.Log.IsEnabled()) + { + // Only log Http20RequestLeftQueue if we spent time waiting on the queue + ValueStopwatch stopwatch = ValueStopwatch.StartNew(); + await _concurrentStreams.RequestCreditAsync(1, cancellationToken).ConfigureAwait(false); + HttpTelemetry.Log.Http20RequestLeftQueue(stopwatch.GetElapsedTime().TotalMilliseconds); + } + else + { + await _concurrentStreams.RequestCreditAsync(1, cancellationToken).ConfigureAwait(false); + } } } catch (ObjectDisposedException) @@ -1345,6 +1354,8 @@ private async ValueTask SendHeadersAsync(HttpRequestMessage request ArrayBuffer headerBuffer = default; try { + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestHeadersStart(); + // Serialize headers to a temporary buffer, and do as much work to prepare to send the headers as we can // before taking the write lock. headerBuffer = new ArrayBuffer(InitialConnectionBufferSize, usePool: true); @@ -1425,6 +1436,9 @@ private async ValueTask SendHeadersAsync(HttpRequestMessage request return s.mustFlush || s.endStream; }, cancellationToken).ConfigureAwait(false); + + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestHeadersStop(); + return http2Stream; } catch 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 448c86b814c93..d1932068ab509 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 @@ -194,6 +194,8 @@ public async Task SendRequestBodyAsync(CancellationToken cancellationToken) { using var writeStream = new Http2WriteStream(this); + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestContentStart(); + ValueTask vt = _request.Content.InternalCopyToAsync(writeStream, context: null, _requestBodyCancellationSource.Token); if (vt.IsCompleted) { @@ -208,6 +210,8 @@ public async Task SendRequestBodyAsync(CancellationToken cancellationToken) await vt.ConfigureAwait(false); } + + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestContentStop(writeStream.BytesWritten); } if (NetEventSource.Log.IsEnabled()) Trace($"Finished sending request body."); @@ -351,12 +355,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 +389,6 @@ private void Cancel() { _waitSource.SetResult(true); } - - if (HttpTelemetry.Log.IsEnabled()) _request.OnAborted(); } // Returns whether the waiter should be signalled or not. @@ -576,8 +572,6 @@ public void OnHeader(ReadOnlySpan name, ReadOnlySpan value) public void OnHeadersStart() { - if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersBegin(); - Debug.Assert(!Monitor.IsEntered(SyncObject)); lock (SyncObject) { @@ -847,6 +841,8 @@ public async Task ReadResponseHeadersAsync(CancellationToken cancellationToken) bool emptyResponse; try { + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStart(); + // Wait for response headers to be read. bool wait; @@ -859,6 +855,8 @@ public async Task ReadResponseHeadersAsync(CancellationToken cancellationToken) (wait, emptyResponse) = TryEnsureHeaders(); Debug.Assert(!wait); } + + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop(); } catch { @@ -1155,10 +1153,6 @@ private void CloseResponseBody() { Cancel(); } - else - { - _request.OnStopped(); - } _responseBuffer.Dispose(); } @@ -1356,6 +1350,8 @@ private sealed class Http2WriteStream : HttpBaseStream { private Http2Stream? _http2Stream; + public long BytesWritten { get; private set; } + public Http2WriteStream(Http2Stream http2Stream) { Debug.Assert(http2Stream != null); @@ -1382,6 +1378,8 @@ protected override void Dispose(bool disposing) public override ValueTask WriteAsync(ReadOnlyMemory buffer, CancellationToken cancellationToken) { + BytesWritten += buffer.Length; + Http2Stream? http2Stream = _http2Stream; if (http2Stream == null) 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 54e38fd591737..f2bff590ca5cf 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 @@ -120,8 +120,6 @@ protected void Dispose(bool disposing) _pool.DecrementConnectionCount(); - if (HttpTelemetry.Log.IsEnabled()) _currentRequest?.OnAborted(); - if (disposing) { GC.SuppressFinalize(this); @@ -366,6 +364,8 @@ public async Task SendAsyncCore(HttpRequestMessage request, CancellationTokenRegistration cancellationRegistration = RegisterCancellation(cancellationToken); try { + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestHeadersStart(); + Debug.Assert(request.RequestUri != null); // Write request line await WriteStringAsync(normalizedMethod.Method, async).ConfigureAwait(false); @@ -459,6 +459,8 @@ public async Task SendAsyncCore(HttpRequestMessage request, // CRLF for end of headers. await WriteTwoBytesAsync((byte)'\r', (byte)'\n', async).ConfigureAwait(false); + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestHeadersStop(); + if (request.Content == null) { // We have nothing more to send, so flush out any headers we haven't yet sent. @@ -537,7 +539,7 @@ public async Task SendAsyncCore(HttpRequestMessage request, var response = new HttpResponseMessage() { RequestMessage = request, Content = new HttpConnectionResponseContent() }; ParseStatusLine(await ReadNextResponseHeaderLineAsync(async).ConfigureAwait(false), response); - if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersBegin(); + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStart(); // Multiple 1xx responses handling. // RFC 7231: A client MUST be able to parse one or more 1xx responses received prior to a final response, @@ -586,6 +588,8 @@ public async Task SendAsyncCore(HttpRequestMessage request, ParseHeaderNameValue(this, line, response); } + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.ResponseHeadersStop(); + if (allowExpect100ToContinue != null) { // If we sent an Expect: 100-continue header, and didn't receive a 100-continue. Handle the final response accordingly. @@ -819,6 +823,9 @@ private async ValueTask SendRequestContentAsync(HttpRequestMessage request, Http // Now that we're sending content, prohibit retries on this connection. _canRetry = false; + Debug.Assert(stream.BytesWritten == 0); + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestContentStart(); + // Copy all of the data to the server. if (async) { @@ -835,6 +842,8 @@ private async ValueTask SendRequestContentAsync(HttpRequestMessage request, Http // Flush any content that might still be buffered. await FlushAsync(async).ConfigureAwait(false); + if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestContentStop(stream.BytesWritten); + if (NetEventSource.Log.IsEnabled()) Trace("Finished sending request content."); } @@ -1872,8 +1881,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; diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs index 1b62119d17420..84ac7270df15c 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs @@ -358,53 +358,6 @@ public ValueTask SendProxyConnectAsync(HttpRequestMessage r } public ValueTask 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 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 SendAsyncHelper(HttpRequestMessage request, bool async, bool doRequestAuth, CancellationToken cancellationToken) { if (_proxy == null) { diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpContentWriteStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpContentWriteStream.cs index 0284562e6e971..2ae430c4a40f5 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpContentWriteStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpContentWriteStream.cs @@ -12,6 +12,8 @@ internal partial class HttpConnection : IDisposable { private abstract class HttpContentWriteStream : HttpContentStream { + public long BytesWritten { get; protected set; } + public HttpContentWriteStream(HttpConnection connection) : base(connection) => Debug.Assert(connection != null); diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/HttpClientTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/HttpClientTest.cs index 840dd74ad7023..03f57772a49d5 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/HttpClientTest.cs +++ b/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(() => { client.GetAsync(CreateFakeUri()); }); + FormatException thrown = await Assert.ThrowsAsync(() => client.GetAsync(CreateFakeUri())); Assert.Same(e, thrown); } } diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs index 351f1595da2df..782212211cb41 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs @@ -4,8 +4,10 @@ using System.Collections.Concurrent; using System.Collections.Generic; using System.Diagnostics.Tracing; +using System.IO; using System.Linq; using System.Net.Test.Common; +using System.Text; using System.Threading; using System.Threading.Tasks; using Microsoft.DotNet.RemoteExecutor; @@ -30,12 +32,34 @@ public static void EventSource_ExistsWithCorrectId() Assert.NotEmpty(EventSource.GenerateManifest(esType, esType.Assembly.Location)); } + public static IEnumerable TestMethods_MemberData() + { + yield return new object[] { "GetAsync" }; + yield return new object[] { "SendAsync" }; + yield return new object[] { "GetStringAsync" }; + yield return new object[] { "GetByteArrayAsync" }; + yield return new object[] { "GetStreamAsync" }; + yield return new object[] { "InvokerSendAsync" }; + + yield return new object[] { "Send" }; + yield return new object[] { "InvokerSend" }; + } + [OuterLoop] - [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - public void EventSource_SuccessfulRequest_LogsStartStop() + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [MemberData(nameof(TestMethods_MemberData))] + public void EventSource_SuccessfulRequest_LogsStartStop(string testMethod) { - RemoteExecutor.Invoke(async useVersionString => + if (UseVersion.Major != 1 && !testMethod.EndsWith("Async")) { + // Synchronous requests are only supported for HTTP/1.1 + return; + } + + RemoteExecutor.Invoke(async (useVersionString, testMethod) => + { + const int ResponseContentLength = 42; + Version version = Version.Parse(useVersionString); using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); @@ -45,8 +69,52 @@ public void EventSource_SuccessfulRequest_LogsStartStop() await GetFactoryForVersion(version).CreateClientAndServerAsync( async uri => { - using HttpClient client = CreateHttpClient(useVersionString); - await client.GetStringAsync(uri); + using HttpClientHandler handler = CreateHttpClientHandler(useVersionString); + using HttpClient client = CreateHttpClient(handler, useVersionString); + using var invoker = new HttpMessageInvoker(handler); + + var request = new HttpRequestMessage(HttpMethod.Get, uri) + { + Version = version + }; + + switch (testMethod) + { + case "GetAsync": + await client.GetAsync(uri); + break; + + case "Send": + await Task.Run(() => client.Send(request)); + break; + + case "SendAsync": + await client.SendAsync(request); + break; + + case "GetStringAsync": + await client.GetStringAsync(uri); + break; + + case "GetByteArrayAsync": + await client.GetByteArrayAsync(uri); + break; + + case "GetStreamAsync": + Stream responseStream = await client.GetStreamAsync(uri); + await responseStream.CopyToAsync(Stream.Null); + break; + + case "InvokerSend": + HttpResponseMessage syncResponse = await Task.Run(() => invoker.Send(request, cancellationToken: default)); + await syncResponse.Content.CopyToAsync(Stream.Null); + break; + + case "InvokerSendAsync": + HttpResponseMessage asyncResponse = await invoker.SendAsync(request, cancellationToken: default); + await asyncResponse.Content.CopyToAsync(Stream.Null); + break; + } }, async server => { @@ -54,7 +122,7 @@ public void EventSource_SuccessfulRequest_LogsStartStop() { await Task.Delay(300); await connection.ReadRequestDataAsync(); - await connection.SendResponseAsync(); + await connection.SendResponseAsync(content: new string('a', ResponseContentLength)); }); }); @@ -68,31 +136,34 @@ public void EventSource_SuccessfulRequest_LogsStartStop() EventWrittenEventArgs stop = Assert.Single(events, e => e.EventName == "RequestStop"); Assert.Empty(stop.Payload); - Assert.DoesNotContain(events, e => e.EventName == "RequestAborted"); + Assert.DoesNotContain(events, e => e.EventName == "RequestFailed"); - if (version.Major == 1) - { - Assert.Single(events, e => e.EventName == "Http11ConnectionEstablished"); - Assert.Single(events, e => e.EventName == "Http11ConnectionClosed"); - } - else - { - Assert.Single(events, e => e.EventName == "Http20ConnectionEstablished"); - Assert.Single(events, e => e.EventName == "Http20ConnectionClosed"); - } + ValidateConnectionEstablishedClosed(events, version); - Assert.Single(events, e => e.EventName == "ResponseHeadersBegin"); + ValidateRequestResponseStartStopEvents( + events, + requestContentLength: null, + responseContentLength: testMethod.StartsWith("InvokerSend") ? null : ResponseContentLength, + count: 1); VerifyEventCounters(events, requestCount: 1, shouldHaveFailures: false); - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), testMethod).Dispose(); } [OuterLoop] - [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - public void EventSource_UnsuccessfulRequest_LogsStartAbortedStop() + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [MemberData(nameof(TestMethods_MemberData))] + public void EventSource_UnsuccessfulRequest_LogsStartFailedStop(string testMethod) { - RemoteExecutor.Invoke(async useVersionString => + if (UseVersion.Major != 1 && !testMethod.EndsWith("Async")) { + // Synchronous requests are only supported for HTTP/1.1 + return; + } + + RemoteExecutor.Invoke(async (useVersionString, testMethod) => + { + Version version = Version.Parse(useVersionString); using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); var events = new ConcurrentQueue(); @@ -101,11 +172,53 @@ public void EventSource_UnsuccessfulRequest_LogsStartAbortedStop() var semaphore = new SemaphoreSlim(0, 1); var cts = new CancellationTokenSource(); - await GetFactoryForVersion(Version.Parse(useVersionString)).CreateClientAndServerAsync( + await GetFactoryForVersion(version).CreateClientAndServerAsync( async uri => { - using HttpClient client = CreateHttpClient(useVersionString); - await Assert.ThrowsAsync(async () => await client.GetStringAsync(uri, cts.Token)); + using HttpClientHandler handler = CreateHttpClientHandler(useVersionString); + using HttpClient client = CreateHttpClient(handler, useVersionString); + using var invoker = new HttpMessageInvoker(handler); + + var request = new HttpRequestMessage(HttpMethod.Get, uri) + { + Version = version + }; + + switch (testMethod) + { + case "GetAsync": + await Assert.ThrowsAsync(async () => await client.GetAsync(uri, cts.Token)); + break; + + case "Send": + await Assert.ThrowsAsync(async () => await Task.Run(() => client.Send(request, cts.Token))); + break; + + case "SendAsync": + await Assert.ThrowsAsync(async () => await client.SendAsync(request, cts.Token)); + break; + + case "GetStringAsync": + await Assert.ThrowsAsync(async () => await client.GetStringAsync(uri, cts.Token)); + break; + + case "GetByteArrayAsync": + await Assert.ThrowsAsync(async () => await client.GetByteArrayAsync(uri, cts.Token)); + break; + + case "GetStreamAsync": + await Assert.ThrowsAsync(async () => await client.GetStreamAsync(uri, cts.Token)); + break; + + case "InvokerSend": + await Assert.ThrowsAsync(async () => await Task.Run(() => invoker.Send(request, cts.Token))); + break; + + case "InvokerSendAsync": + await Assert.ThrowsAsync(async () => await invoker.SendAsync(request, cts.Token)); + break; + } + semaphore.Release(); }, async server => @@ -125,30 +238,200 @@ public void EventSource_UnsuccessfulRequest_LogsStartAbortedStop() EventWrittenEventArgs start = Assert.Single(events, e => e.EventName == "RequestStart"); ValidateStartEventPayload(start); - EventWrittenEventArgs abort = Assert.Single(events, e => e.EventName == "RequestAborted"); - Assert.Empty(abort.Payload); + EventWrittenEventArgs failure = Assert.Single(events, e => e.EventName == "RequestFailed"); + Assert.Empty(failure.Payload); EventWrittenEventArgs stop = Assert.Single(events, e => e.EventName == "RequestStop"); Assert.Empty(stop.Payload); + ValidateConnectionEstablishedClosed(events, version); + VerifyEventCounters(events, requestCount: 1, shouldHaveFailures: true); - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), testMethod).Dispose(); + } + + [OuterLoop] + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData("PostAsync")] + [InlineData("Send")] + [InlineData("SendAsync")] + [InlineData("SendChunkedAsync")] + [InlineData("InvokerSend")] + [InlineData("InvokerSendAsync")] + public void EventSource_SendingRequestContent_LogsRequestContentStartStop(string testMethod) + { + if (UseVersion.Major != 1 && !testMethod.EndsWith("Async")) + { + // Synchronous requests are only supported for HTTP/1.1 + return; + } + + RemoteExecutor.Invoke(async (useVersionString, testMethod) => + { + const int RequestContentLength = 42; + const int ResponseContentLength = 43; + + Version version = Version.Parse(useVersionString); + using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); + + var events = new ConcurrentQueue(); + await listener.RunWithCallbackAsync(events.Enqueue, async () => + { + await GetFactoryForVersion(version).CreateClientAndServerAsync( + async uri => + { + using HttpClientHandler handler = CreateHttpClientHandler(useVersionString); + using HttpClient client = CreateHttpClient(handler, useVersionString); + using var invoker = new HttpMessageInvoker(handler); + + var request = new HttpRequestMessage(HttpMethod.Get, uri) + { + Version = version + }; + + var content = new ByteArrayContent(Encoding.ASCII.GetBytes(new string('a', RequestContentLength))); + request.Content = content; + + switch (testMethod) + { + case "PostAsync": + await client.PostAsync(uri, content); + break; + + case "Send": + await Task.Run(() => client.Send(request)); + break; + + case "SendAsync": + await client.SendAsync(request); + break; + + case "SendChunkedAsync": + request.Headers.TransferEncodingChunked = true; + await client.SendAsync(request); + break; + + case "InvokerSend": + HttpResponseMessage syncResponse = await Task.Run(() => invoker.Send(request, cancellationToken: default)); + await syncResponse.Content.CopyToAsync(Stream.Null); + break; + + case "InvokerSendAsync": + HttpResponseMessage asyncResponse = await invoker.SendAsync(request, cancellationToken: default); + await asyncResponse.Content.CopyToAsync(Stream.Null); + break; + } + }, + async server => + { + await server.AcceptConnectionAsync(async connection => + { + await Task.Delay(300); + await connection.ReadRequestDataAsync(); + await connection.SendResponseAsync(content: new string('a', ResponseContentLength)); + }); + }); + + await Task.Delay(300); + }); + Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself + + EventWrittenEventArgs start = Assert.Single(events, e => e.EventName == "RequestStart"); + ValidateStartEventPayload(start); + + EventWrittenEventArgs stop = Assert.Single(events, e => e.EventName == "RequestStop"); + Assert.Empty(stop.Payload); + + Assert.DoesNotContain(events, e => e.EventName == "RequestFailed"); + + ValidateConnectionEstablishedClosed(events, version); + + ValidateRequestResponseStartStopEvents( + events, + RequestContentLength, + responseContentLength: testMethod.StartsWith("InvokerSend") ? null : ResponseContentLength, + count: 1); + + VerifyEventCounters(events, requestCount: 1, shouldHaveFailures: false); + }, UseVersion.ToString(), testMethod).Dispose(); } - protected static void ValidateStartEventPayload(EventWrittenEventArgs startEvent) + private static void ValidateStartEventPayload(EventWrittenEventArgs startEvent) { Assert.Equal("RequestStart", startEvent.EventName); - Assert.Equal(6, startEvent.Payload.Count); + Assert.Equal(7, startEvent.Payload.Count); Assert.StartsWith("http", (string)startEvent.Payload[0]); Assert.NotEmpty((string)startEvent.Payload[1]); // host Assert.True(startEvent.Payload[2] is int port && port >= 0 && port <= 65535); Assert.NotEmpty((string)startEvent.Payload[3]); // pathAndQuery - Assert.True(startEvent.Payload[4] is int versionMajor && (versionMajor == 1 || versionMajor == 2)); - Assert.True(startEvent.Payload[5] is int versionMinor && (versionMinor == 1 || versionMinor == 0)); + Assert.True(startEvent.Payload[4] is byte versionMajor && (versionMajor == 1 || versionMajor == 2)); + Assert.True(startEvent.Payload[5] is byte versionMinor && (versionMinor == 1 || versionMinor == 0)); + Assert.InRange((HttpVersionPolicy)startEvent.Payload[6], HttpVersionPolicy.RequestVersionOrLower, HttpVersionPolicy.RequestVersionExact); + } + + private static void ValidateConnectionEstablishedClosed(ConcurrentQueue events, Version version, int count = 1) + { + EventWrittenEventArgs[] connectionsEstablished = events.Where(e => e.EventName == "ConnectionEstablished").ToArray(); + Assert.Equal(count, connectionsEstablished.Length); + foreach (EventWrittenEventArgs connectionEstablished in connectionsEstablished) + { + Assert.Equal(2, connectionEstablished.Payload.Count); + Assert.Equal(version.Major, (byte)connectionEstablished.Payload[0]); + Assert.Equal(version.Minor, (byte)connectionEstablished.Payload[1]); + } + + EventWrittenEventArgs[] connectionsClosed = events.Where(e => e.EventName == "ConnectionClosed").ToArray(); + Assert.Equal(count, connectionsClosed.Length); + foreach (EventWrittenEventArgs connectionClosed in connectionsClosed) + { + Assert.Equal(2, connectionClosed.Payload.Count); + Assert.Equal(version.Major, (byte)connectionClosed.Payload[0]); + Assert.Equal(version.Minor, (byte)connectionClosed.Payload[1]); + } + } + + private static void ValidateRequestResponseStartStopEvents(ConcurrentQueue events, int? requestContentLength, int? responseContentLength, int count) + { + EventWrittenEventArgs[] requestHeadersStarts = events.Where(e => e.EventName == "RequestHeadersStart").ToArray(); + Assert.Equal(count, requestHeadersStarts.Length); + Assert.All(requestHeadersStarts, r => Assert.Empty(r.Payload)); + + EventWrittenEventArgs[] requestHeadersStops = events.Where(e => e.EventName == "RequestHeadersStop").ToArray(); + Assert.Equal(count, requestHeadersStops.Length); + Assert.All(requestHeadersStops, r => Assert.Empty(r.Payload)); + + EventWrittenEventArgs[] requestContentStarts = events.Where(e => e.EventName == "RequestContentStart").ToArray(); + Assert.Equal(requestContentLength.HasValue ? count : 0, requestContentStarts.Length); + Assert.All(requestContentStarts, r => Assert.Empty(r.Payload)); + + EventWrittenEventArgs[] requestContentStops = events.Where(e => e.EventName == "RequestContentStop").ToArray(); + Assert.Equal(requestContentLength.HasValue ? count : 0, requestContentStops.Length); + foreach (EventWrittenEventArgs requestContentStop in requestContentStops) + { + object payload = Assert.Single(requestContentStop.Payload); + Assert.True(payload is long); + Assert.Equal(requestContentLength.Value, (long)payload); + } + + EventWrittenEventArgs[] responseHeadersStarts = events.Where(e => e.EventName == "ResponseHeadersStart").ToArray(); + Assert.Equal(count, responseHeadersStarts.Length); + Assert.All(responseHeadersStarts, r => Assert.Empty(r.Payload)); + + EventWrittenEventArgs[] responseHeadersStops = events.Where(e => e.EventName == "ResponseHeadersStop").ToArray(); + Assert.Equal(count, responseHeadersStops.Length); + Assert.All(responseHeadersStops, r => Assert.Empty(r.Payload)); + + EventWrittenEventArgs[] responseContentStarts = events.Where(e => e.EventName == "ResponseContentStart").ToArray(); + Assert.Equal(responseContentLength.HasValue ? count : 0, responseContentStarts.Length); + Assert.All(responseContentStarts, r => Assert.Empty(r.Payload)); + + EventWrittenEventArgs[] responseContentStops = events.Where(e => e.EventName == "ResponseContentStop").ToArray(); + Assert.Equal(responseContentLength.HasValue ? count : 0, responseContentStops.Length); + Assert.All(responseContentStops, r => Assert.Empty(r.Payload)); } - protected static void VerifyEventCounters(ConcurrentQueue events, int requestCount, bool shouldHaveFailures, bool shouldHaveQueuedRequests = false) + private static void VerifyEventCounters(ConcurrentQueue events, int requestCount, bool shouldHaveFailures, int requestsLeftQueueVersion = -1) { Dictionary eventCounters = events .Where(e => e.EventName == "EventCounters") @@ -162,17 +445,17 @@ protected static void VerifyEventCounters(ConcurrentQueue Assert.True(eventCounters.TryGetValue("requests-started-rate", out double[] requestRate)); Assert.Contains(requestRate, r => r > 0); - Assert.True(eventCounters.TryGetValue("requests-aborted", out double[] requestsAborted)); - Assert.True(eventCounters.TryGetValue("requests-aborted-rate", out double[] requestsAbortedRate)); + Assert.True(eventCounters.TryGetValue("requests-failed", out double[] requestsFailures)); + Assert.True(eventCounters.TryGetValue("requests-failed-rate", out double[] requestsFailureRate)); if (shouldHaveFailures) { - Assert.Equal(1, requestsAborted[^1]); - Assert.Contains(requestsAbortedRate, r => r > 0); + Assert.Equal(1, requestsFailures[^1]); + Assert.Contains(requestsFailureRate, r => r > 0); } else { - Assert.All(requestsAborted, a => Assert.Equal(0, a)); - Assert.All(requestsAbortedRate, r => Assert.Equal(0, r)); + Assert.All(requestsFailures, a => Assert.Equal(0, a)); + Assert.All(requestsFailureRate, r => Assert.Equal(0, r)); } Assert.True(eventCounters.TryGetValue("current-requests", out double[] currentRequests)); @@ -187,30 +470,38 @@ protected static void VerifyEventCounters(ConcurrentQueue Assert.All(http20ConnectionsTotal, c => Assert.True(c >= 0)); Assert.Equal(0, http20ConnectionsTotal[^1]); - Assert.True(eventCounters.TryGetValue("http11-requests-queue-duration", out double[] requestQueueDurations)); - Assert.Equal(0, requestQueueDurations[^1]); - if (shouldHaveQueuedRequests) + Assert.True(eventCounters.TryGetValue("http11-requests-queue-duration", out double[] http11requestQueueDurations)); + Assert.Equal(0, http11requestQueueDurations[^1]); + if (requestsLeftQueueVersion == 1) { - Assert.Contains(requestQueueDurations, d => d > 0); - Assert.All(requestQueueDurations, d => Assert.True(d >= 0)); + Assert.Contains(http11requestQueueDurations, d => d > 0); + Assert.All(http11requestQueueDurations, d => Assert.True(d >= 0)); } else { - Assert.All(requestQueueDurations, d => Assert.True(d == 0)); + Assert.All(http11requestQueueDurations, d => Assert.True(d == 0)); } - } - } - public sealed class TelemetryTest_Http11 : TelemetryTest - { - public TelemetryTest_Http11(ITestOutputHelper output) : base(output) { } + Assert.True(eventCounters.TryGetValue("http20-requests-queue-duration", out double[] http20requestQueueDurations)); + Assert.Equal(0, http20requestQueueDurations[^1]); + if (requestsLeftQueueVersion == 2) + { + Assert.Contains(http20requestQueueDurations, d => d > 0); + Assert.All(http20requestQueueDurations, d => Assert.True(d >= 0)); + } + else + { + Assert.All(http20requestQueueDurations, d => Assert.True(d == 0)); + } + } [OuterLoop] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue() { - RemoteExecutor.Invoke(async () => + RemoteExecutor.Invoke(async useVersionString => { + Version version = Version.Parse(useVersionString); using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); var events = new ConcurrentQueue(); @@ -219,15 +510,17 @@ public void EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue() var firstRequestReceived = new SemaphoreSlim(0, 1); var secondRequestSent = new SemaphoreSlim(0, 1); - await LoopbackServer.CreateClientAndServerAsync( + await GetFactoryForVersion(version).CreateClientAndServerAsync( async uri => { - using var handler = new SocketsHttpHandler - { - MaxConnectionsPerServer = 1 - }; + using HttpClientHandler handler = CreateHttpClientHandler(useVersionString); + using HttpClient client = CreateHttpClient(handler, useVersionString); + + var socketsHttpHandler = GetUnderlyingSocketsHttpHandler(handler) as SocketsHttpHandler; + socketsHttpHandler.MaxConnectionsPerServer = 1; - using var client = new HttpClient(handler); + // Dummy request to ensure that the MaxConcurrentStreams setting has been acknowledged + await client.GetStringAsync(uri); Task firstRequest = client.GetStringAsync(uri); Assert.True(await firstRequestReceived.WaitAsync(TimeSpan.FromSeconds(10))); @@ -240,16 +533,34 @@ public void EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue() }, async server => { - await server.AcceptConnectionAsync(async connection => + GenericLoopbackConnection connection; + if (server is Http2LoopbackServer http2Server) + { + http2Server.AllowMultipleConnections = true; + connection = await http2Server.EstablishConnectionAsync(new SettingsEntry { SettingId = SettingId.MaxConcurrentStreams, Value = 1 }); + } + else + { + connection = await server.EstablishGenericConnectionAsync(); + } + + using (connection) { + // Dummy request to ensure that the MaxConcurrentStreams setting has been acknowledged + await connection.ReadRequestDataAsync(readBody: false); + await connection.SendResponseAsync(); + + // First request + await connection.ReadRequestDataAsync(readBody: false); firstRequestReceived.Release(); - await connection.ReadRequestDataAsync(); Assert.True(await secondRequestSent.WaitAsync(TimeSpan.FromSeconds(10))); await Task.Delay(100); await connection.SendResponseAsync(); - }); - await server.HandleRequestAsync(); + // Second request + await connection.ReadRequestDataAsync(readBody: false); + await connection.SendResponseAsync(); + }; }); await Task.Delay(300); @@ -257,36 +568,35 @@ public void EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue() Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself EventWrittenEventArgs[] starts = events.Where(e => e.EventName == "RequestStart").ToArray(); - Assert.Equal(2, starts.Length); + Assert.Equal(3, starts.Length); Assert.All(starts, s => ValidateStartEventPayload(s)); EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "RequestStop").ToArray(); - Assert.Equal(2, stops.Length); + Assert.Equal(3, stops.Length); Assert.All(stops, s => Assert.Empty(s.Payload)); - Assert.DoesNotContain(events, e => e.EventName == "RequestAborted"); - - EventWrittenEventArgs[] connectionsEstablished = events.Where(e => e.EventName == "Http11ConnectionEstablished").ToArray(); - Assert.Equal(2, connectionsEstablished.Length); - Assert.All(connectionsEstablished, c => Assert.Empty(c.Payload)); + Assert.DoesNotContain(events, e => e.EventName == "RequestFailed"); - EventWrittenEventArgs[] connectionsClosed = events.Where(e => e.EventName == "Http11ConnectionClosed").ToArray(); - Assert.Equal(2, connectionsClosed.Length); - Assert.All(connectionsClosed, c => Assert.Empty(c.Payload)); + ValidateConnectionEstablishedClosed(events, version); - EventWrittenEventArgs requestLeftQueue = Assert.Single(events, e => e.EventName == "Http11RequestLeftQueue"); - double duration = Assert.IsType(Assert.Single(requestLeftQueue.Payload)); - Assert.True(duration > 0); + EventWrittenEventArgs requestLeftQueue = Assert.Single(events, e => e.EventName == "RequestLeftQueue"); + Assert.Equal(3, requestLeftQueue.Payload.Count); + Assert.True((double)requestLeftQueue.Payload.Count > 0); // timeSpentOnQueue + Assert.Equal(version.Major, (byte)requestLeftQueue.Payload[1]); + Assert.Equal(version.Minor, (byte)requestLeftQueue.Payload[2]); - EventWrittenEventArgs[] responseHeadersBegin = events.Where(e => e.EventName == "ResponseHeadersBegin").ToArray(); - Assert.Equal(2, responseHeadersBegin.Length); - Assert.All(responseHeadersBegin, r => Assert.Empty(r.Payload)); + ValidateRequestResponseStartStopEvents(events, requestContentLength: null, responseContentLength: 0, count: 3); - VerifyEventCounters(events, requestCount: 2, shouldHaveFailures: false, shouldHaveQueuedRequests: true); - }).Dispose(); + VerifyEventCounters(events, requestCount: 3, shouldHaveFailures: false, requestsLeftQueueVersion: version.Major); + }, UseVersion.ToString()).Dispose(); } } + public sealed class TelemetryTest_Http11 : TelemetryTest + { + public TelemetryTest_Http11(ITestOutputHelper output) : base(output) { } + } + public sealed class TelemetryTest_Http20 : TelemetryTest { protected override Version UseVersion => HttpVersion.Version20; 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 e6ca98293ba61..5667687e632e2 100644 --- a/src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs +++ b/src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs @@ -9,8 +9,14 @@ public class HttpTelemetry public bool IsEnabled() => false; + public void RequestStart(HttpRequestMessage request) { } + public void RequestStop() { } - public void RequestAborted() { } + public void RequestFailed() { } + + public void ResponseContentStart() { } + + public void ResponseContentStop() { } } } diff --git a/src/libraries/System.Net.Security/src/System/Net/Security/NetSecurityTelemetry.cs b/src/libraries/System.Net.Security/src/System/Net/Security/NetSecurityTelemetry.cs index f283faf6ee46e..0c393405bfc4c 100644 --- a/src/libraries/System.Net.Security/src/System/Net/Security/NetSecurityTelemetry.cs +++ b/src/libraries/System.Net.Security/src/System/Net/Security/NetSecurityTelemetry.cs @@ -133,7 +133,7 @@ public void HandshakeStart(bool isServer, string targetHost) } [Event(2, Level = EventLevel.Informational)] - private void HandshakeStop(string protocol) + private void HandshakeStop(SslProtocols protocol) { if (IsEnabled(EventLevel.Informational, EventKeywords.None)) { @@ -159,7 +159,7 @@ public void HandshakeFailed(bool isServer, ValueStopwatch stopwatch, string exce HandshakeFailed(isServer, stopwatch.GetElapsedTime().TotalMilliseconds, exceptionMessage); } - HandshakeStop(protocol: string.Empty); + HandshakeStop(SslProtocols.None); } [NonEvent] @@ -206,10 +206,7 @@ public void HandshakeCompleted(SslProtocols protocol, ValueStopwatch stopwatch, handshakeDurationCounter?.WriteMetric(duration); _handshakeDurationCounter!.WriteMetric(duration); - if (IsEnabled(EventLevel.Informational, EventKeywords.None)) - { - HandshakeStop(protocol.ToString()); - } + HandshakeStop(protocol); } [NonEvent] @@ -271,6 +268,21 @@ private unsafe void WriteEvent(int eventId, bool arg1, string? arg2) } } + [NonEvent] + private unsafe void WriteEvent(int eventId, SslProtocols arg1) + { + if (IsEnabled()) + { + var data = new EventData + { + DataPointer = (IntPtr)(&arg1), + Size = sizeof(SslProtocols) + }; + + WriteEventCore(eventId, eventDataCount: 1, &data); + } + } + [NonEvent] private unsafe void WriteEvent(int eventId, bool arg1, double arg2, string? arg3) { diff --git a/src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs index 1ce02cf14a1c7..72b71d0463781 100644 --- a/src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs @@ -5,6 +5,7 @@ using System.Collections.Generic; using System.Diagnostics.Tracing; using System.Linq; +using System.Security.Authentication; using System.Threading.Tasks; using Microsoft.DotNet.RemoteExecutor; using Xunit; @@ -51,8 +52,7 @@ public static void EventSource_SuccessfulHandshake_LogsStartStop() EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "HandshakeStop").ToArray(); Assert.Equal(2, stops.Length); - Assert.All(stops, s => Assert.Equal(1, s.Payload.Count)); - Assert.All(stops, s => Assert.NotEmpty(s.Payload[0] as string)); + Assert.All(stops, s => ValidateHandshakeStopEventPayload(s, failure: false)); Assert.DoesNotContain(events, e => e.EventName == "HandshakeFailed"); @@ -92,13 +92,30 @@ public static void EventSource_UnsuccessfulHandshake_LogsStartFailureStop() EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "HandshakeStop").ToArray(); Assert.Equal(2, stops.Length); - Assert.All(stops, s => Assert.Equal(1, s.Payload.Count)); - Assert.All(stops, s => Assert.Empty(s.Payload[0] as string)); + Assert.All(stops, s => ValidateHandshakeStopEventPayload(s, failure: true)); VerifyEventCounters(events, shouldHaveFailures: true); }).Dispose(); } + private static void ValidateHandshakeStopEventPayload(EventWrittenEventArgs stopEvent, bool failure) + { + Assert.Equal("HandshakeStop", stopEvent.EventName); + Assert.Equal(1, stopEvent.Payload.Count); + + var protocol = (SslProtocols)stopEvent.Payload[0]; + Assert.True(Enum.IsDefined(protocol)); + + if (failure) + { + Assert.Equal(SslProtocols.None, protocol); + } + else + { + Assert.NotEqual(SslProtocols.None, protocol); + } + } + private static void VerifyEventCounters(ConcurrentQueue events, bool shouldHaveFailures) { Dictionary eventCounters = events