From 3f00240900fa3561d6c68cfadfbe1ad5dbb7a4a3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marie=20P=C3=ADchov=C3=A1?= Date: Tue, 18 Aug 2020 18:18:40 +0200 Subject: [PATCH 01/11] Moved HTTP request telemetry to HttpClient.SendAsync --- .../src/System/Net/Http/HttpClient.cs | 75 +++++++++++-------- .../src/System/Net/Http/HttpRequestMessage.cs | 31 +------- .../Http/SocketsHttpHandler/Http2Stream.cs | 12 --- .../Http/SocketsHttpHandler/HttpConnection.cs | 4 - .../HttpConnectionPoolManager.cs | 47 ------------ 5 files changed, 45 insertions(+), 124 deletions(-) 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 dc3172c8a87728..17dc13a9a749d4 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 @@ -482,6 +482,9 @@ public override HttpResponseMessage Send(HttpRequestMessage request, public HttpResponseMessage Send(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationToken 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, cancellationToken); Debug.Assert(sendTask.IsCompleted); return sendTask.GetAwaiter().GetResult(); @@ -506,11 +509,13 @@ public Task SendAsync(HttpRequestMessage request, HttpCompl public Task SendAsync(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationToken cancellationToken) { + // Called outside of async state machine to propagate certain exception even without awaiting the returned task. + CheckRequestBeforeSend(request); + return SendAsyncCore(request, completionOption, async: true, cancellationToken).AsTask(); } - private ValueTask SendAsyncCore(HttpRequestMessage request, HttpCompletionOption completionOption, - bool async, CancellationToken cancellationToken) + private void CheckRequestBeforeSend(HttpRequestMessage request) { if (request == null) { @@ -520,49 +525,45 @@ private ValueTask SendAsyncCore(HttpRequestMessage request, 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, 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; + if (HttpTelemetry.Log.IsEnabled()) + { + // TODO https://github.com/dotnet/runtime/issues/40896: Enable tracing for HTTP/3. + if (request.Version.Major < 3 && request.RequestUri != null) { - throw CreateTimeoutException(operationException); + HttpTelemetry.Log.RequestStart( + request.RequestUri.Scheme, + request.RequestUri.IdnHost, + request.RequestUri.Port, + request.RequestUri.PathAndQuery, + request.Version.Major, + request.Version.Minor); + 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); @@ -587,9 +588,14 @@ private async ValueTask FinishSendAsync(ValueTask FinishSendAsync(ValueTask 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(); - } - } + return Interlocked.Exchange(ref _sendStatus, MessageAlreadySent) == MessageNotYetSent; } #region IDisposable Members @@ -242,8 +217,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/SocketsHttpHandler/Http2Stream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs index 448c86b814c932..788a68c286680b 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 @@ -351,12 +351,6 @@ private void Complete() w.Dispose(); _creditWaiter = null; } - - if (HttpTelemetry.Log.IsEnabled()) - { - bool aborted = _requestCompletionState == StreamCompletionState.Failed || _responseCompletionState == StreamCompletionState.Failed; - _request.OnStopped(aborted); - } } private void Cancel() @@ -391,8 +385,6 @@ private void Cancel() { _waitSource.SetResult(true); } - - if (HttpTelemetry.Log.IsEnabled()) _request.OnAborted(); } // Returns whether the waiter should be signalled or not. @@ -1155,10 +1147,6 @@ private void CloseResponseBody() { Cancel(); } - else - { - _request.OnStopped(); - } _responseBuffer.Dispose(); } 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 54e38fd5917379..9c3655b408d44f 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); @@ -1872,8 +1870,6 @@ private void CompleteResponse() Debug.Assert(_currentRequest != null, "Expected the connection to be associated with a request."); Debug.Assert(_writeOffset == 0, "Everything in write buffer should have been flushed."); - if (HttpTelemetry.Log.IsEnabled()) _currentRequest.OnStopped(); - // Disassociate the connection from a request. _currentRequest = null; 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 1b62119d174203..84ac7270df15cc 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) { From ec189d40575c689a87da63c786acd083d69ef524 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marie=20P=C3=ADchov=C3=A1?= Date: Fri, 21 Aug 2020 10:32:13 +0200 Subject: [PATCH 02/11] Added ResponseContent and helper methods events. --- .../src/System/Net/Http/HttpClient.cs | 300 ++++++++++++------ .../src/System/Net/Http/HttpTelemetry.cs | 24 ++ 2 files changed, 230 insertions(+), 94 deletions(-) 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 17dc13a9a749d4..58250c8a0e4fe2 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 @@ -164,50 +164,81 @@ public Task GetStringAsync(string? requestUri, CancellationToken cancell GetStringAsync(CreateUri(requestUri), cancellationToken); public Task GetStringAsync(Uri? requestUri, CancellationToken cancellationToken) => - GetStringAsyncCore(GetAsync(requestUri, HttpCompletionOption.ResponseHeadersRead, cancellationToken), cancellationToken); + GetStringAsyncCore(requestUri, cancellationToken); - private async Task GetStringAsyncCore(Task getTask, CancellationToken cancellationToken) + private async Task GetStringAsyncCore(Uri? requestUri, CancellationToken cancellationToken) { - // Wait for the response message. - using (HttpResponseMessage responseMessage = await getTask.ConfigureAwait(false)) + bool telemetryStarted = false; + bool responseTelemetryStarted = false; + + if (HttpTelemetry.Log.IsEnabled()) { - // Make sure it completed successfully. - responseMessage.EnsureSuccessStatusCode(); + HttpTelemetry.Log.GetHelperStart(nameof(GetStringAsync)); + telemetryStarted = true; + } - // Get the response content. - HttpContent? c = responseMessage.Content; - if (c != null) + try + { + // Wait for the response message. + using (HttpResponseMessage responseMessage = await GetAsync(requestUri, HttpCompletionOption.ResponseHeadersRead, 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()) { - await responseStream.CopyToAsync(buffer, cancellationToken).ConfigureAwait(false); + HttpTelemetry.Log.ResponseContentStart(); + responseTelemetryStarted = 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; + // No content to return. + return string.Empty; + } + } + finally + { + if (HttpTelemetry.Log.IsEnabled()) + { + if (responseTelemetryStarted) + { + HttpTelemetry.Log.ResponseContentStop(); + } + if (telemetryStarted) + { + HttpTelemetry.Log.GetHelperStop(); + } + } } } @@ -221,59 +252,52 @@ public Task GetByteArrayAsync(string? requestUri, CancellationToken canc GetByteArrayAsync(CreateUri(requestUri), cancellationToken); public Task GetByteArrayAsync(Uri? requestUri, CancellationToken cancellationToken) => - GetByteArrayAsyncCore(GetAsync(requestUri, HttpCompletionOption.ResponseHeadersRead, cancellationToken), cancellationToken); + GetByteArrayAsyncCore(requestUri, cancellationToken); - private async Task GetByteArrayAsyncCore(Task getTask, CancellationToken cancellationToken) + private async Task GetByteArrayAsyncCore(Uri? requestUri, CancellationToken cancellationToken) { - // Wait for the response message. - using (HttpResponseMessage responseMessage = await getTask.ConfigureAwait(false)) + bool telemetryStarted = false; + bool responseTelemetryStarted = false; + + if (HttpTelemetry.Log.IsEnabled()) { - // Make sure it completed successfully. - responseMessage.EnsureSuccessStatusCode(); + HttpTelemetry.Log.GetHelperStart(nameof(GetByteArrayAsync)); + telemetryStarted = true; + } - // Get the response content. - HttpContent? c = responseMessage.Content; - if (c != null) + try + { + // Wait for the response message. + using (HttpResponseMessage responseMessage = await GetAsync(requestUri, HttpCompletionOption.ResponseHeadersRead, 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()) { - // 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(); + responseTelemetryStarted = 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 +309,55 @@ 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(); + // No content to return. + return Array.Empty(); + } + } + finally + { + if (HttpTelemetry.Log.IsEnabled()) + { + if (responseTelemetryStarted) + { + HttpTelemetry.Log.ResponseContentStop(); + } + if (telemetryStarted) + { + HttpTelemetry.Log.GetHelperStop(); + } + } } } @@ -309,16 +371,50 @@ public Task GetStreamAsync(Uri? requestUri) => GetStreamAsync(requestUri, CancellationToken.None); public Task GetStreamAsync(Uri? requestUri, CancellationToken cancellationToken) => - FinishGetStreamAsync(GetAsync(requestUri, HttpCompletionOption.ResponseHeadersRead, cancellationToken), cancellationToken); + FinishGetStreamAsync(requestUri, cancellationToken); - private async Task FinishGetStreamAsync(Task getTask, CancellationToken cancellationToken) + private async Task FinishGetStreamAsync(Uri? requestUri, 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; + bool responseTelemetryStarted = false; + + if (HttpTelemetry.Log.IsEnabled()) + { + HttpTelemetry.Log.GetHelperStart(nameof(GetStreamAsync)); + telemetryStarted = true; + } + + try + { + HttpResponseMessage response = await GetAsync(requestUri, HttpCompletionOption.ResponseHeadersRead, cancellationToken).ConfigureAwait(false); + response.EnsureSuccessStatusCode(); + HttpContent? c = response.Content; + if (c != null) + { + if (HttpTelemetry.Log.IsEnabled()) + { + HttpTelemetry.Log.ResponseContentStart(); + responseTelemetryStarted = true; + } + + return c.TryReadAsStream() ?? await c.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false); + } + return Stream.Null; + } + finally + { + if (HttpTelemetry.Log.IsEnabled()) + { + if (responseTelemetryStarted) + { + HttpTelemetry.Log.ResponseContentStop(); + } + if (telemetryStarted) + { + HttpTelemetry.Log.GetHelperStop(); + } + } + } } #endregion Simple Get Overloads @@ -542,8 +638,7 @@ private async ValueTask SendAsyncCore(HttpRequestMessage re bool telemetryStarted = false; if (HttpTelemetry.Log.IsEnabled()) { - // TODO https://github.com/dotnet/runtime/issues/40896: Enable tracing for HTTP/3. - if (request.Version.Major < 3 && request.RequestUri != null) + if (request.RequestUri != null) { HttpTelemetry.Log.RequestStart( request.RequestUri.Scheme, @@ -572,14 +667,31 @@ await base.SendAsync(request, cts.Token).ConfigureAwait(false) : // Buffer the response content if we've been asked to and we have a Content to buffer. if (buffered && response.Content != null) { - if (async) + bool responseTelemetryStarted = false; + if (HttpTelemetry.Log.IsEnabled()) { - await response.Content.LoadIntoBufferAsync(_maxResponseContentBufferSize, cts.Token).ConfigureAwait(false); + HttpTelemetry.Log.ResponseContentStart(); + responseTelemetryStarted = true; + } + try + { + if (async) + { + await response.Content.LoadIntoBufferAsync(_maxResponseContentBufferSize, cts.Token).ConfigureAwait(false); + + } + else + { + response.Content.LoadIntoBuffer(_maxResponseContentBufferSize, cts.Token); + } } - else + finally { - response.Content.LoadIntoBuffer(_maxResponseContentBufferSize, cts.Token); + if (HttpTelemetry.Log.IsEnabled() && responseTelemetryStarted) + { + HttpTelemetry.Log.ResponseContentStop(); + } } } 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 957a96117182c8..8d942c5df284c4 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 @@ -99,6 +99,30 @@ public void ResponseHeadersBegin() WriteEvent(eventId: 9); } + [Event(10, Level = EventLevel.Informational)] + public void ResponseContentStart() + { + WriteEvent(eventId: 10); + } + + [Event(11, Level = EventLevel.Informational)] + public void ResponseContentStop() + { + WriteEvent(eventId: 11); + } + + [Event(12, Level = EventLevel.Informational)] + public void GetHelperStart(string methodName) + { + WriteEvent(eventId: 12, methodName); + } + + [Event(13, Level = EventLevel.Informational)] + public void GetHelperStop() + { + WriteEvent(eventId: 13); + } + protected override void OnEventCommand(EventCommandEventArgs command) { if (command.Command == EventCommand.Enable) From 1fe0f60c250d0f9e1d3faad6be3a8ad589055106 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Wed, 26 Aug 2020 18:27:51 +0200 Subject: [PATCH 03/11] Rework helper method activity nesting --- .../src/System/Net/Http/HttpClient.cs | 172 +++++++++--------- .../src/System/Net/Http/HttpTelemetry.cs | 36 ++-- .../tests/FunctionalTests/HttpClientTest.cs | 4 +- .../tests/FunctionalTests/TelemetryTest.cs | 29 ++- .../tests/UnitTests/Fakes/HttpTelemetry.cs | 4 + 5 files changed, 129 insertions(+), 116 deletions(-) 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 58250c8a0e4fe2..89a7146a9ab06d 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,24 +163,29 @@ public Task GetStringAsync(Uri? requestUri) => public Task GetStringAsync(string? requestUri, CancellationToken cancellationToken) => GetStringAsync(CreateUri(requestUri), cancellationToken); - public Task GetStringAsync(Uri? requestUri, CancellationToken cancellationToken) => - GetStringAsyncCore(requestUri, cancellationToken); + public Task GetStringAsync(Uri? requestUri, CancellationToken cancellationToken) + { + HttpRequestMessage request = CreateRequestMessage(HttpMethod.Get, requestUri); - private async Task GetStringAsyncCore(Uri? requestUri, CancellationToken cancellationToken) + // Called outside of async state machine to propagate certain exception even without awaiting the returned task. + CheckRequestBeforeSend(request); + + return GetStringAsyncCore(request, cancellationToken); + } + + private async Task GetStringAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken) { bool telemetryStarted = false; - bool responseTelemetryStarted = false; - - if (HttpTelemetry.Log.IsEnabled()) + if (HttpTelemetry.Log.IsEnabled() && request.RequestUri != null) { - HttpTelemetry.Log.GetHelperStart(nameof(GetStringAsync)); + HttpTelemetry.Log.RequestStart(request); telemetryStarted = true; } try { // Wait for the response message. - using (HttpResponseMessage responseMessage = await GetAsync(requestUri, HttpCompletionOption.ResponseHeadersRead, cancellationToken).ConfigureAwait(false)) + using (HttpResponseMessage responseMessage = await SendAsyncCore(request, HttpCompletionOption.ResponseHeadersRead, async: true, emitTelemetryStartStop: false, cancellationToken).ConfigureAwait(false)) { // Make sure it completed successfully. responseMessage.EnsureSuccessStatusCode(); @@ -191,8 +196,7 @@ private async Task GetStringAsyncCore(Uri? requestUri, CancellationToken { if (HttpTelemetry.Log.IsEnabled()) { - HttpTelemetry.Log.ResponseContentStart(); - responseTelemetryStarted = true; + HttpTelemetry.Log.ResponseContentBegin(); } #if NET46 return await c.ReadAsStringAsync().ConfigureAwait(false); @@ -226,18 +230,16 @@ private async Task GetStringAsyncCore(Uri? requestUri, CancellationToken return string.Empty; } } + catch when (LogRequestAborted(telemetryStarted)) + { + // Unreachable as LogRequestAborted will return false + throw; + } finally { - if (HttpTelemetry.Log.IsEnabled()) + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { - if (responseTelemetryStarted) - { - HttpTelemetry.Log.ResponseContentStop(); - } - if (telemetryStarted) - { - HttpTelemetry.Log.GetHelperStop(); - } + HttpTelemetry.Log.RequestStop(); } } } @@ -251,24 +253,29 @@ public Task GetByteArrayAsync(Uri? requestUri) => public Task GetByteArrayAsync(string? requestUri, CancellationToken cancellationToken) => GetByteArrayAsync(CreateUri(requestUri), cancellationToken); - public Task GetByteArrayAsync(Uri? requestUri, CancellationToken cancellationToken) => - GetByteArrayAsyncCore(requestUri, 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); - private async Task GetByteArrayAsyncCore(Uri? requestUri, CancellationToken cancellationToken) + return GetByteArrayAsyncCore(request, cancellationToken); + } + + private async Task GetByteArrayAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken) { bool telemetryStarted = false; - bool responseTelemetryStarted = false; - - if (HttpTelemetry.Log.IsEnabled()) + if (HttpTelemetry.Log.IsEnabled() && request.RequestUri != null) { - HttpTelemetry.Log.GetHelperStart(nameof(GetByteArrayAsync)); + HttpTelemetry.Log.RequestStart(request); telemetryStarted = true; } try { // Wait for the response message. - using (HttpResponseMessage responseMessage = await GetAsync(requestUri, HttpCompletionOption.ResponseHeadersRead, cancellationToken).ConfigureAwait(false)) + using (HttpResponseMessage responseMessage = await SendAsyncCore(request, HttpCompletionOption.ResponseHeadersRead, async: true, emitTelemetryStartStop: false, cancellationToken).ConfigureAwait(false)) { // Make sure it completed successfully. responseMessage.EnsureSuccessStatusCode(); @@ -279,8 +286,7 @@ private async Task GetByteArrayAsyncCore(Uri? requestUri, CancellationTo { if (HttpTelemetry.Log.IsEnabled()) { - HttpTelemetry.Log.ResponseContentStart(); - responseTelemetryStarted = true; + HttpTelemetry.Log.ResponseContentBegin(); } #if NET46 return await c.ReadAsByteArrayAsync().ConfigureAwait(false); @@ -345,18 +351,16 @@ private async Task GetByteArrayAsyncCore(Uri? requestUri, CancellationTo return Array.Empty(); } } + catch when (LogRequestAborted(telemetryStarted)) + { + // Unreachable as LogRequestAborted will return false + throw; + } finally { - if (HttpTelemetry.Log.IsEnabled()) + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { - if (responseTelemetryStarted) - { - HttpTelemetry.Log.ResponseContentStop(); - } - if (telemetryStarted) - { - HttpTelemetry.Log.GetHelperStop(); - } + HttpTelemetry.Log.RequestStop(); } } } @@ -370,53 +374,64 @@ public Task GetStreamAsync(string? requestUri, CancellationToken cancell public Task GetStreamAsync(Uri? requestUri) => GetStreamAsync(requestUri, CancellationToken.None); - public Task GetStreamAsync(Uri? requestUri, CancellationToken cancellationToken) => - FinishGetStreamAsync(requestUri, 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(Uri? requestUri, CancellationToken cancellationToken) + return GetStreamAsyncCore(request, cancellationToken); + } + + private async Task GetStreamAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken) { bool telemetryStarted = false; - bool responseTelemetryStarted = false; - - if (HttpTelemetry.Log.IsEnabled()) + if (HttpTelemetry.Log.IsEnabled() && request.RequestUri != null) { - HttpTelemetry.Log.GetHelperStart(nameof(GetStreamAsync)); + HttpTelemetry.Log.RequestStart(request); telemetryStarted = true; } try { - HttpResponseMessage response = await GetAsync(requestUri, HttpCompletionOption.ResponseHeadersRead, cancellationToken).ConfigureAwait(false); + 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()) { - HttpTelemetry.Log.ResponseContentStart(); - responseTelemetryStarted = true; + HttpTelemetry.Log.ResponseContentBegin(); } return c.TryReadAsStream() ?? await c.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false); } return Stream.Null; } + catch when (LogRequestAborted(telemetryStarted)) + { + // Unreachable as LogRequestAborted will return false + throw; + } finally { - if (HttpTelemetry.Log.IsEnabled()) + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { - if (responseTelemetryStarted) - { - HttpTelemetry.Log.ResponseContentStop(); - } - if (telemetryStarted) - { - HttpTelemetry.Log.GetHelperStop(); - } + HttpTelemetry.Log.RequestStop(); } } } + private static bool LogRequestAborted(bool telemetryStarted) + { + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) + { + HttpTelemetry.Log.RequestAborted(); + } + return false; + } + #endregion Simple Get Overloads #region REST Send Overloads @@ -581,7 +596,7 @@ public HttpResponseMessage Send(HttpRequestMessage request, HttpCompletionOption // 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, cancellationToken); + ValueTask sendTask = SendAsyncCore(request, completionOption, async: false, emitTelemetryStartStop: true, cancellationToken); Debug.Assert(sendTask.IsCompleted); return sendTask.GetAwaiter().GetResult(); } @@ -608,7 +623,7 @@ public Task SendAsync(HttpRequestMessage request, HttpCompl // Called outside of async state machine to propagate certain exception even without awaiting the returned task. CheckRequestBeforeSend(request); - return SendAsyncCore(request, completionOption, async: true, cancellationToken).AsTask(); + return SendAsyncCore(request, completionOption, async: true, emitTelemetryStartStop: true, cancellationToken).AsTask(); } private void CheckRequestBeforeSend(HttpRequestMessage request) @@ -627,7 +642,7 @@ private void CheckRequestBeforeSend(HttpRequestMessage request) } private async ValueTask SendAsyncCore(HttpRequestMessage request, HttpCompletionOption completionOption, - bool async, CancellationToken cancellationToken) + 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); @@ -638,15 +653,9 @@ private async ValueTask SendAsyncCore(HttpRequestMessage re bool telemetryStarted = false; if (HttpTelemetry.Log.IsEnabled()) { - if (request.RequestUri != null) + if (emitTelemetryStartStop && request.RequestUri != null) { - HttpTelemetry.Log.RequestStart( - request.RequestUri.Scheme, - request.RequestUri.IdnHost, - request.RequestUri.Port, - request.RequestUri.PathAndQuery, - request.Version.Major, - request.Version.Minor); + HttpTelemetry.Log.RequestStart(request); telemetryStarted = true; } } @@ -667,31 +676,19 @@ await base.SendAsync(request, cts.Token).ConfigureAwait(false) : // Buffer the response content if we've been asked to and we have a Content to buffer. if (buffered && response.Content != null) { - bool responseTelemetryStarted = false; if (HttpTelemetry.Log.IsEnabled()) { - HttpTelemetry.Log.ResponseContentStart(); - responseTelemetryStarted = true; + HttpTelemetry.Log.ResponseContentBegin(); } - try + if (async) { - if (async) - { - await response.Content.LoadIntoBufferAsync(_maxResponseContentBufferSize, cts.Token).ConfigureAwait(false); + await response.Content.LoadIntoBufferAsync(_maxResponseContentBufferSize, cts.Token).ConfigureAwait(false); - } - else - { - response.Content.LoadIntoBuffer(_maxResponseContentBufferSize, cts.Token); - } } - finally + else { - if (HttpTelemetry.Log.IsEnabled() && responseTelemetryStarted) - { - HttpTelemetry.Log.ResponseContentStop(); - } + response.Content.LoadIntoBuffer(_maxResponseContentBufferSize, cts.Token); } } @@ -700,10 +697,7 @@ await base.SendAsync(request, cts.Token).ConfigureAwait(false) : } catch (Exception e) { - if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) - { - HttpTelemetry.Log.RequestAborted(); - } + LogRequestAborted(telemetryStarted); response?.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 8d942c5df284c4..10ae81664708df 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 @@ -36,12 +36,26 @@ 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, int versionMajor, int versionMinor) { Interlocked.Increment(ref _startedRequests); WriteEvent(eventId: 1, scheme, host, port, pathAndQuery, versionMajor, versionMinor); } + [NonEvent] + public void RequestStart(HttpRequestMessage request) + { + Debug.Assert(request.RequestUri != null); + + RequestStart( + request.RequestUri.Scheme, + request.RequestUri.IdnHost, + request.RequestUri.Port, + request.RequestUri.PathAndQuery, + request.Version.Major, + request.Version.Minor); + } + [Event(2, Level = EventLevel.Informational)] public void RequestStop() { @@ -100,29 +114,11 @@ public void ResponseHeadersBegin() } [Event(10, Level = EventLevel.Informational)] - public void ResponseContentStart() + public void ResponseContentBegin() { WriteEvent(eventId: 10); } - [Event(11, Level = EventLevel.Informational)] - public void ResponseContentStop() - { - WriteEvent(eventId: 11); - } - - [Event(12, Level = EventLevel.Informational)] - public void GetHelperStart(string methodName) - { - WriteEvent(eventId: 12, methodName); - } - - [Event(13, Level = EventLevel.Informational)] - public void GetHelperStop() - { - WriteEvent(eventId: 13); - } - protected override void OnEventCommand(EventCommandEventArgs command) { if (command.Command == EventCommand.Enable) diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/HttpClientTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/HttpClientTest.cs index 840dd74ad7023e..03f57772a49d50 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 351f1595da2df4..bb852bab49372c 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs @@ -31,10 +31,13 @@ public static void EventSource_ExistsWithCorrectId() } [OuterLoop] - [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - public void EventSource_SuccessfulRequest_LogsStartStop() + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData("String")] + [InlineData("ByteArray")] + [InlineData("Stream")] + public void EventSource_SuccessfulRequest_LogsStartStop(string testMethod) { - RemoteExecutor.Invoke(async useVersionString => + RemoteExecutor.Invoke(async (useVersionString, testMethod) => { Version version = Version.Parse(useVersionString); using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); @@ -46,7 +49,21 @@ await GetFactoryForVersion(version).CreateClientAndServerAsync( async uri => { using HttpClient client = CreateHttpClient(useVersionString); - await client.GetStringAsync(uri); + + switch (testMethod) + { + case "String": + await client.GetStringAsync(uri); + break; + + case "ByteArray": + await client.GetByteArrayAsync(uri); + break; + + case "Stream": + await client.GetStreamAsync(uri); + break; + } }, async server => { @@ -83,8 +100,10 @@ await server.AcceptConnectionAsync(async connection => Assert.Single(events, e => e.EventName == "ResponseHeadersBegin"); + Assert.Single(events, e => e.EventName == "ResponseContentBegin"); + VerifyEventCounters(events, requestCount: 1, shouldHaveFailures: false); - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), testMethod).Dispose(); } [OuterLoop] 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 e6ca98293ba613..846b7233af454c 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,12 @@ public class HttpTelemetry public bool IsEnabled() => false; + public void RequestStart(HttpRequestMessage request) { } + public void RequestStop() { } public void RequestAborted() { } + + public void ResponseContentBegin() { } } } From 56190b5553960b684fb1eeb20580402cfa6fb728 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Wed, 26 Aug 2020 19:22:26 +0200 Subject: [PATCH 04/11] Expand Telemetry tests --- .../tests/FunctionalTests/TelemetryTest.cs | 38 ++++++++++++++++--- 1 file changed, 33 insertions(+), 5 deletions(-) diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs index bb852bab49372c..83dabd89f214b3 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs @@ -32,6 +32,7 @@ public static void EventSource_ExistsWithCorrectId() [OuterLoop] [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData("Get")] [InlineData("String")] [InlineData("ByteArray")] [InlineData("Stream")] @@ -52,6 +53,10 @@ await GetFactoryForVersion(version).CreateClientAndServerAsync( switch (testMethod) { + case "Get": + await client.GetAsync(uri); + break; + case "String": await client.GetStringAsync(uri); break; @@ -107,10 +112,14 @@ await server.AcceptConnectionAsync(async connection => } [OuterLoop] - [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - public void EventSource_UnsuccessfulRequest_LogsStartAbortedStop() + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData("Get")] + [InlineData("String")] + [InlineData("ByteArray")] + [InlineData("Stream")] + public void EventSource_UnsuccessfulRequest_LogsStartAbortedStop(string testMethod) { - RemoteExecutor.Invoke(async useVersionString => + RemoteExecutor.Invoke(async (useVersionString, testMethod) => { using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); @@ -124,7 +133,26 @@ await GetFactoryForVersion(Version.Parse(useVersionString)).CreateClientAndServe async uri => { using HttpClient client = CreateHttpClient(useVersionString); - await Assert.ThrowsAsync(async () => await client.GetStringAsync(uri, cts.Token)); + + switch (testMethod) + { + case "Get": + await Assert.ThrowsAsync(async () => await client.GetAsync(uri, cts.Token)); + break; + + case "String": + await Assert.ThrowsAsync(async () => await client.GetStringAsync(uri, cts.Token)); + break; + + case "ByteArray": + await Assert.ThrowsAsync(async () => await client.GetByteArrayAsync(uri, cts.Token)); + break; + + case "Stream": + await Assert.ThrowsAsync(async () => await client.GetStreamAsync(uri, cts.Token)); + break; + } + semaphore.Release(); }, async server => @@ -151,7 +179,7 @@ await server.AcceptConnectionAsync(async connection => Assert.Empty(stop.Payload); VerifyEventCounters(events, requestCount: 1, shouldHaveFailures: true); - }, UseVersion.ToString()).Dispose(); + }, UseVersion.ToString(), testMethod).Dispose(); } protected static void ValidateStartEventPayload(EventWrittenEventArgs startEvent) From 7cba4cfde375640a018b794a33f95bede505aa2a Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Thu, 27 Aug 2020 17:20:16 +0200 Subject: [PATCH 05/11] Also log RequestStart/Stop in HttpMessageInvoker --- .../src/System/Net/Http/HttpClient.cs | 10 ---- .../src/System/Net/Http/HttpMessageInvoker.cs | 54 +++++++++++++++++- .../src/System/Net/Http/HttpRequestMessage.cs | 2 + .../tests/FunctionalTests/TelemetryTest.cs | 55 +++++++++++++++---- 4 files changed, 98 insertions(+), 23 deletions(-) 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 89a7146a9ab06d..e3f26a4b2e7138 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 @@ -423,15 +423,6 @@ private async Task GetStreamAsyncCore(HttpRequestMessage request, Cancel } } - private static bool LogRequestAborted(bool telemetryStarted) - { - if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) - { - HttpTelemetry.Log.RequestAborted(); - } - return false; - } - #endregion Simple Get Overloads #region REST Send Overloads @@ -684,7 +675,6 @@ await base.SendAsync(request, cts.Token).ConfigureAwait(false) : if (async) { await response.Content.LoadIntoBufferAsync(_maxResponseContentBufferSize, cts.Token).ConfigureAwait(false); - } else { 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 60e39a20986553..3400230ccc1302 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,26 @@ public virtual HttpResponseMessage Send(HttpRequestMessage request, } CheckDisposed(); - return _handler.Send(request, cancellationToken); + if (HttpTelemetry.Log.IsEnabled() && !request.WasSentByHttpClient()) + { + try + { + return _handler.Send(request, cancellationToken); + } + catch when (LogRequestAborted(telemetryStarted: true)) + { + // Unreachable as LogRequestAborted will return false + throw; + } + finally + { + HttpTelemetry.Log.RequestStop(); + } + } + else + { + return _handler.Send(request, cancellationToken); + } } public virtual Task SendAsync(HttpRequestMessage request, @@ -53,7 +72,40 @@ public virtual Task SendAsync(HttpRequestMessage request, } CheckDisposed(); + if (HttpTelemetry.Log.IsEnabled() && !request.WasSentByHttpClient()) + { + 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 (LogRequestAborted(telemetryStarted: true)) + { + // Unreachable as LogRequestAborted will return false + throw; + } + finally + { + HttpTelemetry.Log.RequestStop(); + } + } + } + + internal static bool LogRequestAborted(bool telemetryStarted) + { + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) + { + HttpTelemetry.Log.RequestAborted(); + } + 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 d92a4808ce1f40..388bf1b8431552 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 @@ -203,6 +203,8 @@ internal bool MarkAsSent() return Interlocked.Exchange(ref _sendStatus, MessageAlreadySent) == MessageNotYetSent; } + internal bool WasSentByHttpClient() => _sendStatus == MessageAlreadySent; + #region IDisposable Members protected virtual void Dispose(bool disposing) diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs index 83dabd89f214b3..c901966d7a403f 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs @@ -30,12 +30,18 @@ public static void EventSource_ExistsWithCorrectId() Assert.NotEmpty(EventSource.GenerateManifest(esType, esType.Assembly.Location)); } + public static IEnumerable TestMethods_MemberData() + { + yield return new object[] { "Get" }; + yield return new object[] { "String" }; + yield return new object[] { "ByteArray" }; + yield return new object[] { "Stream" }; + yield return new object[] { "Invoker" }; + } + [OuterLoop] [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - [InlineData("Get")] - [InlineData("String")] - [InlineData("ByteArray")] - [InlineData("Stream")] + [MemberData(nameof(TestMethods_MemberData))] public void EventSource_SuccessfulRequest_LogsStartStop(string testMethod) { RemoteExecutor.Invoke(async (useVersionString, testMethod) => @@ -49,7 +55,8 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => await GetFactoryForVersion(version).CreateClientAndServerAsync( async uri => { - using HttpClient client = CreateHttpClient(useVersionString); + using HttpClientHandler handler = CreateHttpClientHandler(useVersionString); + using HttpClient client = CreateHttpClient(handler, useVersionString); switch (testMethod) { @@ -68,6 +75,17 @@ await GetFactoryForVersion(version).CreateClientAndServerAsync( case "Stream": await client.GetStreamAsync(uri); break; + + case "Invoker": + using (var invoker = new HttpMessageInvoker(handler)) + { + var request = new HttpRequestMessage(HttpMethod.Get, uri) + { + Version = version + }; + await invoker.SendAsync(request, cancellationToken: default); + } + break; } }, async server => @@ -105,7 +123,10 @@ await server.AcceptConnectionAsync(async connection => Assert.Single(events, e => e.EventName == "ResponseHeadersBegin"); - Assert.Single(events, e => e.EventName == "ResponseContentBegin"); + if (testMethod != "Invoker") + { + Assert.Single(events, e => e.EventName == "ResponseContentBegin"); + } VerifyEventCounters(events, requestCount: 1, shouldHaveFailures: false); }, UseVersion.ToString(), testMethod).Dispose(); @@ -113,14 +134,12 @@ await server.AcceptConnectionAsync(async connection => [OuterLoop] [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - [InlineData("Get")] - [InlineData("String")] - [InlineData("ByteArray")] - [InlineData("Stream")] + [MemberData(nameof(TestMethods_MemberData))] public void EventSource_UnsuccessfulRequest_LogsStartAbortedStop(string testMethod) { 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(); @@ -129,10 +148,11 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => 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); + using HttpClientHandler handler = CreateHttpClientHandler(useVersionString); + using HttpClient client = CreateHttpClient(handler, useVersionString); switch (testMethod) { @@ -151,6 +171,17 @@ await GetFactoryForVersion(Version.Parse(useVersionString)).CreateClientAndServe case "Stream": await Assert.ThrowsAsync(async () => await client.GetStreamAsync(uri, cts.Token)); break; + + case "Invoker": + using (var invoker = new HttpMessageInvoker(handler)) + { + var request = new HttpRequestMessage(HttpMethod.Get, uri) + { + Version = version + }; + await Assert.ThrowsAsync(async () => await invoker.SendAsync(request, cts.Token)); + } + break; } semaphore.Release(); From d1ad906724d314e5af1c2d3d11eb75888d581aa7 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Fri, 28 Aug 2020 14:16:34 +0200 Subject: [PATCH 06/11] Update RequestStart signature --- .../src/System/Net/Http/HttpTelemetry.cs | 22 ++++++++++++------- .../tests/FunctionalTests/TelemetryTest.cs | 7 +++--- 2 files changed, 18 insertions(+), 11 deletions(-) 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 10ae81664708df..8464fe7cab87a2 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 @@ -36,10 +36,10 @@ internal sealed class HttpTelemetry : EventSource // - A stop event's event id must be next one after its start event. [Event(1, Level = EventLevel.Informational)] - private 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] @@ -52,8 +52,9 @@ public void RequestStart(HttpRequestMessage request) request.RequestUri.IdnHost, request.RequestUri.Port, request.RequestUri.PathAndQuery, - request.Version.Major, - request.Version.Minor); + (byte)request.Version.Major, + (byte)request.Version.Minor, + request.VersionPolicy); } [Event(2, Level = EventLevel.Informational)] @@ -181,7 +182,7 @@ protected override void OnEventCommand(EventCommandEventArgs command) } [NonEvent] - private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3, string? arg4, int arg5, int arg6) + private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3, string? arg4, byte arg5, byte arg6, HttpVersionPolicy arg7) { if (IsEnabled()) { @@ -193,7 +194,7 @@ private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3 fixed (char* arg2Ptr = arg2) fixed (char* arg4Ptr = arg4) { - const int NumEventDatas = 6; + const int NumEventDatas = 7; var descrs = stackalloc EventData[NumEventDatas]; descrs[0] = new EventData @@ -219,12 +220,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); diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs index c901966d7a403f..93db81c61241d1 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs @@ -216,14 +216,15 @@ await server.AcceptConnectionAsync(async connection => protected 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); } protected static void VerifyEventCounters(ConcurrentQueue events, int requestCount, bool shouldHaveFailures, bool shouldHaveQueuedRequests = false) From 75751725a136d5e731ea252dc4030ead5870891f Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Fri, 28 Aug 2020 14:36:27 +0200 Subject: [PATCH 07/11] RequestAborted => RequestFailed rename --- .../src/System/Net/Http/HttpClient.cs | 14 ++++----- .../src/System/Net/Http/HttpMessageInvoker.cs | 12 ++++---- .../src/System/Net/Http/HttpTelemetry.cs | 29 ++++++++++--------- .../tests/FunctionalTests/TelemetryTest.cs | 22 +++++++------- .../tests/UnitTests/Fakes/HttpTelemetry.cs | 2 +- 5 files changed, 40 insertions(+), 39 deletions(-) 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 e3f26a4b2e7138..e843104699e53e 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 @@ -230,9 +230,9 @@ private async Task GetStringAsyncCore(HttpRequestMessage request, Cancel return string.Empty; } } - catch when (LogRequestAborted(telemetryStarted)) + catch when (LogRequestFailed(telemetryStarted)) { - // Unreachable as LogRequestAborted will return false + // Unreachable as LogRequestFailed will return false throw; } finally @@ -351,9 +351,9 @@ private async Task GetByteArrayAsyncCore(HttpRequestMessage request, Can return Array.Empty(); } } - catch when (LogRequestAborted(telemetryStarted)) + catch when (LogRequestFailed(telemetryStarted)) { - // Unreachable as LogRequestAborted will return false + // Unreachable as LogRequestFailed will return false throw; } finally @@ -409,9 +409,9 @@ private async Task GetStreamAsyncCore(HttpRequestMessage request, Cancel } return Stream.Null; } - catch when (LogRequestAborted(telemetryStarted)) + catch when (LogRequestFailed(telemetryStarted)) { - // Unreachable as LogRequestAborted will return false + // Unreachable as LogRequestFailed will return false throw; } finally @@ -687,7 +687,7 @@ await base.SendAsync(request, cts.Token).ConfigureAwait(false) : } catch (Exception e) { - LogRequestAborted(telemetryStarted); + LogRequestFailed(telemetryStarted); response?.Dispose(); 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 3400230ccc1302..eceeccaa3dca42 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 @@ -47,9 +47,9 @@ public virtual HttpResponseMessage Send(HttpRequestMessage request, { return _handler.Send(request, cancellationToken); } - catch when (LogRequestAborted(telemetryStarted: true)) + catch when (LogRequestFailed(telemetryStarted: true)) { - // Unreachable as LogRequestAborted will return false + // Unreachable as LogRequestFailed will return false throw; } finally @@ -87,9 +87,9 @@ static async Task SendAsyncWithTelemetry(HttpMessageHandler { return await handler.SendAsync(request, cancellationToken).ConfigureAwait(false); } - catch when (LogRequestAborted(telemetryStarted: true)) + catch when (LogRequestFailed(telemetryStarted: true)) { - // Unreachable as LogRequestAborted will return false + // Unreachable as LogRequestFailed will return false throw; } finally @@ -99,11 +99,11 @@ static async Task SendAsyncWithTelemetry(HttpMessageHandler } } - internal static bool LogRequestAborted(bool telemetryStarted) + internal static bool LogRequestFailed(bool telemetryStarted) { if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { - HttpTelemetry.Log.RequestAborted(); + HttpTelemetry.Log.RequestFailed(); } 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 8464fe7cab87a2..cbab6d64b6b11a 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,17 @@ 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 long _startedRequests; private long _stoppedRequests; - private long _abortedRequests; + private long _failedRequests; private long _openedHttp11Connections; private long _openedHttp20Connections; @@ -65,9 +65,9 @@ public void RequestStop() } [Event(3, Level = EventLevel.Error)] - public void RequestAborted() + public void RequestFailed() { - Interlocked.Increment(ref _abortedRequests); + Interlocked.Increment(ref _failedRequests); WriteEvent(eventId: 3); } @@ -140,22 +140,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)) diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs index 93db81c61241d1..ee049e11082d59 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs @@ -108,7 +108,7 @@ await server.AcceptConnectionAsync(async connection => 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) { @@ -135,7 +135,7 @@ await server.AcceptConnectionAsync(async connection => [OuterLoop] [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] [MemberData(nameof(TestMethods_MemberData))] - public void EventSource_UnsuccessfulRequest_LogsStartAbortedStop(string testMethod) + public void EventSource_UnsuccessfulRequest_LogsStartFailedStop(string testMethod) { RemoteExecutor.Invoke(async (useVersionString, testMethod) => { @@ -203,8 +203,8 @@ await server.AcceptConnectionAsync(async connection => 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); @@ -241,17 +241,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)); @@ -343,7 +343,7 @@ await server.AcceptConnectionAsync(async connection => Assert.Equal(2, stops.Length); Assert.All(stops, s => Assert.Empty(s.Payload)); - Assert.DoesNotContain(events, e => e.EventName == "RequestAborted"); + Assert.DoesNotContain(events, e => e.EventName == "RequestFailed"); EventWrittenEventArgs[] connectionsEstablished = events.Where(e => e.EventName == "Http11ConnectionEstablished").ToArray(); Assert.Equal(2, connectionsEstablished.Length); 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 846b7233af454c..5a89f76617069b 100644 --- a/src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs +++ b/src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs @@ -13,7 +13,7 @@ public void RequestStart(HttpRequestMessage request) { } public void RequestStop() { } - public void RequestAborted() { } + public void RequestFailed() { } public void ResponseContentBegin() { } } From 72e2f42a5b8c6e57e5f596dcebc097c7d29f128c Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Fri, 28 Aug 2020 14:54:20 +0200 Subject: [PATCH 08/11] ResponseContent Begin => Start/Stop --- .../src/System/Net/Http/HttpClient.cs | 40 +++++++++++++++---- .../src/System/Net/Http/HttpTelemetry.cs | 8 +++- .../tests/FunctionalTests/TelemetryTest.cs | 3 +- .../tests/UnitTests/Fakes/HttpTelemetry.cs | 4 +- 4 files changed, 44 insertions(+), 11 deletions(-) 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 e843104699e53e..487c4ad9741cf1 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 @@ -175,7 +175,7 @@ public Task GetStringAsync(Uri? requestUri, CancellationToken cancellati private async Task GetStringAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken) { - bool telemetryStarted = false; + bool telemetryStarted = false, responseContentTelemetryStarted = false; if (HttpTelemetry.Log.IsEnabled() && request.RequestUri != null) { HttpTelemetry.Log.RequestStart(request); @@ -196,7 +196,8 @@ private async Task GetStringAsyncCore(HttpRequestMessage request, Cancel { if (HttpTelemetry.Log.IsEnabled()) { - HttpTelemetry.Log.ResponseContentBegin(); + HttpTelemetry.Log.ResponseContentStart(); + responseContentTelemetryStarted = true; } #if NET46 return await c.ReadAsStringAsync().ConfigureAwait(false); @@ -239,6 +240,11 @@ private async Task GetStringAsyncCore(HttpRequestMessage request, Cancel { if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { + if (responseContentTelemetryStarted) + { + HttpTelemetry.Log.ResponseContentStop(); + } + HttpTelemetry.Log.RequestStop(); } } @@ -265,7 +271,7 @@ public Task GetByteArrayAsync(Uri? requestUri, CancellationToken cancell private async Task GetByteArrayAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken) { - bool telemetryStarted = false; + bool telemetryStarted = false, responseContentTelemetryStarted = false; if (HttpTelemetry.Log.IsEnabled() && request.RequestUri != null) { HttpTelemetry.Log.RequestStart(request); @@ -286,7 +292,8 @@ private async Task GetByteArrayAsyncCore(HttpRequestMessage request, Can { if (HttpTelemetry.Log.IsEnabled()) { - HttpTelemetry.Log.ResponseContentBegin(); + HttpTelemetry.Log.ResponseContentStart(); + responseContentTelemetryStarted = true; } #if NET46 return await c.ReadAsByteArrayAsync().ConfigureAwait(false); @@ -360,6 +367,11 @@ private async Task GetByteArrayAsyncCore(HttpRequestMessage request, Can { if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { + if (responseContentTelemetryStarted) + { + HttpTelemetry.Log.ResponseContentStop(); + } + HttpTelemetry.Log.RequestStop(); } } @@ -386,7 +398,7 @@ public Task GetStreamAsync(Uri? requestUri, CancellationToken cancellati private async Task GetStreamAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken) { - bool telemetryStarted = false; + bool telemetryStarted = false, responseContentTelemetryStarted = false; if (HttpTelemetry.Log.IsEnabled() && request.RequestUri != null) { HttpTelemetry.Log.RequestStart(request); @@ -402,7 +414,8 @@ private async Task GetStreamAsyncCore(HttpRequestMessage request, Cancel { if (HttpTelemetry.Log.IsEnabled()) { - HttpTelemetry.Log.ResponseContentBegin(); + HttpTelemetry.Log.ResponseContentStart(); + responseContentTelemetryStarted = true; } return c.TryReadAsStream() ?? await c.ReadAsStreamAsync(cancellationToken).ConfigureAwait(false); @@ -418,6 +431,11 @@ private async Task GetStreamAsyncCore(HttpRequestMessage request, Cancel { if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { + if (responseContentTelemetryStarted) + { + HttpTelemetry.Log.ResponseContentStop(); + } + HttpTelemetry.Log.RequestStop(); } } @@ -641,7 +659,7 @@ private async ValueTask SendAsyncCore(HttpRequestMessage re bool buffered = completionOption == HttpCompletionOption.ResponseContentRead && !string.Equals(request.Method.Method, "HEAD", StringComparison.OrdinalIgnoreCase); - bool telemetryStarted = false; + bool telemetryStarted = false, responseContentTelemetryStarted = false; if (HttpTelemetry.Log.IsEnabled()) { if (emitTelemetryStartStop && request.RequestUri != null) @@ -669,7 +687,8 @@ await base.SendAsync(request, cts.Token).ConfigureAwait(false) : { if (HttpTelemetry.Log.IsEnabled()) { - HttpTelemetry.Log.ResponseContentBegin(); + HttpTelemetry.Log.ResponseContentStart(); + responseContentTelemetryStarted = true; } if (async) @@ -704,6 +723,11 @@ await base.SendAsync(request, cts.Token).ConfigureAwait(false) : { if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { + if (responseContentTelemetryStarted) + { + HttpTelemetry.Log.ResponseContentStop(); + } + HttpTelemetry.Log.RequestStop(); } 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 cbab6d64b6b11a..969288c76e4de3 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 @@ -115,11 +115,17 @@ public void ResponseHeadersBegin() } [Event(10, Level = EventLevel.Informational)] - public void ResponseContentBegin() + public void ResponseContentStart() { WriteEvent(eventId: 10); } + [Event(11, Level = EventLevel.Informational)] + public void ResponseContentStop() + { + WriteEvent(eventId: 11); + } + protected override void OnEventCommand(EventCommandEventArgs command) { if (command.Command == EventCommand.Enable) diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs index ee049e11082d59..955cfb98d6b95d 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs @@ -125,7 +125,8 @@ await server.AcceptConnectionAsync(async connection => if (testMethod != "Invoker") { - Assert.Single(events, e => e.EventName == "ResponseContentBegin"); + Assert.Single(events, e => e.EventName == "ResponseContentStart"); + Assert.Single(events, e => e.EventName == "ResponseContentStop"); } VerifyEventCounters(events, requestCount: 1, shouldHaveFailures: false); 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 5a89f76617069b..5667687e632e2f 100644 --- a/src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs +++ b/src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs @@ -15,6 +15,8 @@ public void RequestStop() { } public void RequestFailed() { } - public void ResponseContentBegin() { } + public void ResponseContentStart() { } + + public void ResponseContentStop() { } } } From 726cac7819edcc6a030c912aec4613da504b8cf4 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Fri, 28 Aug 2020 15:19:03 +0200 Subject: [PATCH 09/11] Fix HttpMessageInvoker implementation --- .../src/System/Net/Http/HttpMessageInvoker.cs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) 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 eceeccaa3dca42..d4d98e26974963 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,8 +41,10 @@ public virtual HttpResponseMessage Send(HttpRequestMessage request, } CheckDisposed(); - if (HttpTelemetry.Log.IsEnabled() && !request.WasSentByHttpClient()) + if (HttpTelemetry.Log.IsEnabled() && !request.WasSentByHttpClient() && request.RequestUri != null) { + HttpTelemetry.Log.RequestStart(request); + try { return _handler.Send(request, cancellationToken); @@ -72,7 +74,7 @@ public virtual Task SendAsync(HttpRequestMessage request, } CheckDisposed(); - if (HttpTelemetry.Log.IsEnabled() && !request.WasSentByHttpClient()) + if (HttpTelemetry.Log.IsEnabled() && !request.WasSentByHttpClient() && request.RequestUri != null) { return SendAsyncWithTelemetry(_handler, request, cancellationToken); } From 0a82deb0fee3fb0e5a71578bc46b00284d687dd0 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Fri, 28 Aug 2020 15:50:23 +0200 Subject: [PATCH 10/11] Add Synchronous request Telemetry tests --- .../tests/FunctionalTests/TelemetryTest.cs | 96 ++++++++++++++----- 1 file changed, 72 insertions(+), 24 deletions(-) diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs index 955cfb98d6b95d..ebeab9546874ab 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs @@ -32,11 +32,15 @@ public static void EventSource_ExistsWithCorrectId() public static IEnumerable TestMethods_MemberData() { - yield return new object[] { "Get" }; - yield return new object[] { "String" }; - yield return new object[] { "ByteArray" }; - yield return new object[] { "Stream" }; - yield return new object[] { "Invoker" }; + 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] @@ -44,6 +48,12 @@ public static IEnumerable TestMethods_MemberData() [MemberData(nameof(TestMethods_MemberData))] public void EventSource_SuccessfulRequest_LogsStartStop(string testMethod) { + 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); @@ -58,31 +68,47 @@ await GetFactoryForVersion(version).CreateClientAndServerAsync( using HttpClientHandler handler = CreateHttpClientHandler(useVersionString); using HttpClient client = CreateHttpClient(handler, useVersionString); + var request = new HttpRequestMessage(HttpMethod.Get, uri) + { + Version = version + }; + switch (testMethod) { - case "Get": + case "GetAsync": await client.GetAsync(uri); break; - case "String": + case "Send": + await Task.Run(() => client.Send(request)); + break; + + case "SendAsync": + await client.SendAsync(request); + break; + + case "GetStringAsync": await client.GetStringAsync(uri); break; - case "ByteArray": + case "GetByteArrayAsync": await client.GetByteArrayAsync(uri); break; - case "Stream": + case "GetStreamAsync": await client.GetStreamAsync(uri); break; - case "Invoker": + case "InvokerSend": + using (var invoker = new HttpMessageInvoker(handler)) + { + await Task.Run(() => invoker.Send(request, cancellationToken: default)); + } + break; + + case "InvokerSendAsync": using (var invoker = new HttpMessageInvoker(handler)) { - var request = new HttpRequestMessage(HttpMethod.Get, uri) - { - Version = version - }; await invoker.SendAsync(request, cancellationToken: default); } break; @@ -123,7 +149,7 @@ await server.AcceptConnectionAsync(async connection => Assert.Single(events, e => e.EventName == "ResponseHeadersBegin"); - if (testMethod != "Invoker") + if (!testMethod.StartsWith("InvokerSend")) { Assert.Single(events, e => e.EventName == "ResponseContentStart"); Assert.Single(events, e => e.EventName == "ResponseContentStop"); @@ -138,6 +164,12 @@ await server.AcceptConnectionAsync(async connection => [MemberData(nameof(TestMethods_MemberData))] public void EventSource_UnsuccessfulRequest_LogsStartFailedStop(string testMethod) { + 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); @@ -155,31 +187,47 @@ await GetFactoryForVersion(version).CreateClientAndServerAsync( using HttpClientHandler handler = CreateHttpClientHandler(useVersionString); using HttpClient client = CreateHttpClient(handler, useVersionString); + var request = new HttpRequestMessage(HttpMethod.Get, uri) + { + Version = version + }; + switch (testMethod) { - case "Get": + case "GetAsync": await Assert.ThrowsAsync(async () => await client.GetAsync(uri, cts.Token)); break; - case "String": + 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 "ByteArray": + case "GetByteArrayAsync": await Assert.ThrowsAsync(async () => await client.GetByteArrayAsync(uri, cts.Token)); break; - case "Stream": + case "GetStreamAsync": await Assert.ThrowsAsync(async () => await client.GetStreamAsync(uri, cts.Token)); break; - case "Invoker": + case "InvokerSend": + using (var invoker = new HttpMessageInvoker(handler)) + { + await Assert.ThrowsAsync(async () => await Task.Run(() => invoker.Send(request, cts.Token))); + } + break; + + case "InvokerSendAsync": using (var invoker = new HttpMessageInvoker(handler)) { - var request = new HttpRequestMessage(HttpMethod.Get, uri) - { - Version = version - }; await Assert.ThrowsAsync(async () => await invoker.SendAsync(request, cts.Token)); } break; From dffda18231b563bae9e524657ee680fda67a9b79 Mon Sep 17 00:00:00 2001 From: MihaZupan Date: Fri, 28 Aug 2020 19:06:44 +0200 Subject: [PATCH 11/11] Check telemetryStarted before ResponseContentStart --- .../System.Net.Http/src/System/Net/Http/HttpClient.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) 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 487c4ad9741cf1..8e34a9f40bc141 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 @@ -194,7 +194,7 @@ private async Task GetStringAsyncCore(HttpRequestMessage request, Cancel HttpContent? c = responseMessage.Content; if (c != null) { - if (HttpTelemetry.Log.IsEnabled()) + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { HttpTelemetry.Log.ResponseContentStart(); responseContentTelemetryStarted = true; @@ -290,7 +290,7 @@ private async Task GetByteArrayAsyncCore(HttpRequestMessage request, Can HttpContent? c = responseMessage.Content; if (c != null) { - if (HttpTelemetry.Log.IsEnabled()) + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { HttpTelemetry.Log.ResponseContentStart(); responseContentTelemetryStarted = true; @@ -412,7 +412,7 @@ private async Task GetStreamAsyncCore(HttpRequestMessage request, Cancel HttpContent? c = response.Content; if (c != null) { - if (HttpTelemetry.Log.IsEnabled()) + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { HttpTelemetry.Log.ResponseContentStart(); responseContentTelemetryStarted = true; @@ -685,7 +685,7 @@ await base.SendAsync(request, cts.Token).ConfigureAwait(false) : // 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()) + if (HttpTelemetry.Log.IsEnabled() && telemetryStarted) { HttpTelemetry.Log.ResponseContentStart(); responseContentTelemetryStarted = true;