Skip to content

Commit

Permalink
Moved HTTP request telemetry to HttpClient.SendAsync (#41022)
Browse files Browse the repository at this point in the history 
* Moved HTTP request telemetry to HttpClient.SendAsync

* Added ResponseContent and helper methods events.

* Rework helper method activity nesting

* Expand Telemetry tests

* Also log RequestStart/Stop in HttpMessageInvoker

* Update RequestStart signature

* RequestAborted => RequestFailed rename

* ResponseContent Begin => Start/Stop

* Fix HttpMessageInvoker implementation

* Add Synchronous request Telemetry tests

* Check telemetryStarted before ResponseContentStart

Co-authored-by: MihaZupan <mihazupan.zupan1@gmail.com>
  • Loading branch information
@ManickaP @MihaZupan
ManickaP and MihaZupan authored Aug 31, 2020
1 parent 9f48dcd commit 05efa9b
Show file tree
Hide file tree
Showing 10 changed files with 529 additions and 265 deletions.
379 changes: 255 additions & 124 deletions src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs
View file

Large diffs are not rendered by default.

56 changes: 55 additions & 1 deletion src/libraries/System.Net.Http/src/System/Net/Http/HttpMessageInvoker.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,7 +41,28 @@ public virtual HttpResponseMessage Send(HttpRequestMessage request,
}
CheckDisposed();

return _handler.Send(request, cancellationToken);
if (HttpTelemetry.Log.IsEnabled() && !request.WasSentByHttpClient() && request.RequestUri != null)
{
HttpTelemetry.Log.RequestStart(request);

try
{
return _handler.Send(request, cancellationToken);
}
catch when (LogRequestFailed(telemetryStarted: true))
{
// Unreachable as LogRequestFailed will return false
throw;
}
finally
{
HttpTelemetry.Log.RequestStop();
}
}
else
{
return _handler.Send(request, cancellationToken);
}
}

public virtual Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
Expand All @@ -53,7 +74,40 @@ public virtual Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
}
CheckDisposed();

if (HttpTelemetry.Log.IsEnabled() && !request.WasSentByHttpClient() && request.RequestUri != null)
{
return SendAsyncWithTelemetry(_handler, request, cancellationToken);
}

return _handler.SendAsync(request, cancellationToken);

static async Task<HttpResponseMessage> SendAsyncWithTelemetry(HttpMessageHandler handler, HttpRequestMessage request, CancellationToken cancellationToken)
{
HttpTelemetry.Log.RequestStart(request);

try
{
return await handler.SendAsync(request, cancellationToken).ConfigureAwait(false);
}
catch when (LogRequestFailed(telemetryStarted: true))
{
// Unreachable as LogRequestFailed will return false
throw;
}
finally
{
HttpTelemetry.Log.RequestStop();
}
}
}

internal static bool LogRequestFailed(bool telemetryStarted)
{
if (HttpTelemetry.Log.IsEnabled() && telemetryStarted)
{
HttpTelemetry.Log.RequestFailed();
}
return false;
}

public void Dispose()
Expand Down
31 changes: 3 additions & 28 deletions src/libraries/System.Net.Http/src/System/Net/Http/HttpRequestMessage.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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

Expand All @@ -242,8 +219,6 @@ protected virtual void Dispose(bool disposing)
_content.Dispose();
}
}

OnStopped();
}

public void Dispose()
Expand Down
73 changes: 53 additions & 20 deletions src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -13,18 +13,18 @@ internal sealed class HttpTelemetry : EventSource
public static readonly HttpTelemetry Log = new HttpTelemetry();

private IncrementingPollingCounter? _startedRequestsPerSecondCounter;
private IncrementingPollingCounter? _abortedRequestsPerSecondCounter;
private IncrementingPollingCounter? _failedRequestsPerSecondCounter;
private PollingCounter? _startedRequestsCounter;
private PollingCounter? _currentRequestsCounter;
private PollingCounter? _abortedRequestsCounter;
private PollingCounter? _failedRequestsCounter;
private PollingCounter? _totalHttp11ConnectionsCounter;
private PollingCounter? _totalHttp20ConnectionsCounter;
private EventCounter? _http11RequestsQueueDurationCounter;
private EventCounter? _http20RequestsQueueDurationCounter;

private long _startedRequests;
private long _stoppedRequests;
private long _abortedRequests;
private long _failedRequests;

private long _openedHttp11Connections;
private long _openedHttp20Connections;
Expand All @@ -37,10 +37,25 @@ internal sealed class HttpTelemetry : EventSource
// - A stop event's event id must be next one after its start event.

[Event(1, Level = EventLevel.Informational)]
public void RequestStart(string scheme, string host, int port, string pathAndQuery, int versionMajor, int versionMinor)
private void RequestStart(string scheme, string host, int port, string pathAndQuery, byte versionMajor, byte versionMinor, HttpVersionPolicy versionPolicy)
{
Interlocked.Increment(ref _startedRequests);
WriteEvent(eventId: 1, scheme, host, port, pathAndQuery, versionMajor, versionMinor);
WriteEvent(eventId: 1, scheme, host, port, pathAndQuery, versionMajor, versionMinor, versionPolicy);
}

[NonEvent]
public void RequestStart(HttpRequestMessage request)
{
Debug.Assert(request.RequestUri != null);

RequestStart(
request.RequestUri.Scheme,
request.RequestUri.IdnHost,
request.RequestUri.Port,
request.RequestUri.PathAndQuery,
(byte)request.Version.Major,
(byte)request.Version.Minor,
request.VersionPolicy);
}

[Event(2, Level = EventLevel.Informational)]
Expand All @@ -51,9 +66,9 @@ public void RequestStop()
}

[Event(3, Level = EventLevel.Error)]
public void RequestAborted()
public void RequestFailed()
{
Interlocked.Increment(ref _abortedRequests);
Interlocked.Increment(ref _failedRequests);
WriteEvent(eventId: 3);
}

Expand Down Expand Up @@ -81,6 +96,18 @@ public void ResponseHeadersBegin()
WriteEvent(eventId: 7);
}

[Event(8, Level = EventLevel.Informational)]
public void ResponseContentStart()
{
WriteEvent(eventId: 8);
}

[Event(9, Level = EventLevel.Informational)]
public void ResponseContentStop()
{
WriteEvent(eventId: 9);
}

[NonEvent]
public void Http11ConnectionEstablished()
{
Expand Down Expand Up @@ -145,22 +172,23 @@ protected override void OnEventCommand(EventCommandEventArgs command)
DisplayRateTimeScale = TimeSpan.FromSeconds(1)
};

// The cumulative number of HTTP requests aborted since the process started.
// Aborted means that an exception occurred during the handler's Send(Async) call as a result of a
// connection related error, timeout, or explicitly cancelled.
_abortedRequestsCounter ??= new PollingCounter("requests-aborted", this, () => Interlocked.Read(ref _abortedRequests))
// The cumulative number of HTTP requests failed since the process started.
// Failed means that an exception occurred during the handler's Send(Async) call as a result of a connection related error, timeout, or explicitly cancelled.
// In case of using HttpClient's SendAsync(and friends) with buffering, this includes exceptions that occured while buffering the response content
// In case of using HttpClient's helper methods (GetString/ByteArray/Stream), this includes responses with non-success status codes
_failedRequestsCounter ??= new PollingCounter("requests-failed", this, () => Interlocked.Read(ref _failedRequests))
{
DisplayName = "Requests Aborted"
DisplayName = "Requests Failed"
};

// The number of HTTP requests aborted per second since the process started.
_abortedRequestsPerSecondCounter ??= new IncrementingPollingCounter("requests-aborted-rate", this, () => Interlocked.Read(ref _abortedRequests))
// The number of HTTP requests failed per second since the process started.
_failedRequestsPerSecondCounter ??= new IncrementingPollingCounter("requests-failed-rate", this, () => Interlocked.Read(ref _failedRequests))
{
DisplayName = "Requests Aborted Rate",
DisplayName = "Requests Failed Rate",
DisplayRateTimeScale = TimeSpan.FromSeconds(1)
};

// The current number of active HTTP requests that have started but not yet completed or aborted.
// The current number of active HTTP requests that have started but not yet completed or failed.
// Use (-_stoppedRequests + _startedRequests) to avoid returning a negative value if _stoppedRequests is
// incremented after reading _startedRequests due to race conditions with completing the HTTP request.
_currentRequestsCounter ??= new PollingCounter("current-requests", this, () => -Interlocked.Read(ref _stoppedRequests) + Interlocked.Read(ref _startedRequests))
Expand Down Expand Up @@ -193,7 +221,7 @@ protected override void OnEventCommand(EventCommandEventArgs command)
}

[NonEvent]
private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3, string? arg4, int arg5, int arg6)
private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3, string? arg4, byte arg5, byte arg6, HttpVersionPolicy arg7)
{
if (IsEnabled())
{
Expand All @@ -205,7 +233,7 @@ private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3
fixed (char* arg2Ptr = arg2)
fixed (char* arg4Ptr = arg4)
{
const int NumEventDatas = 6;
const int NumEventDatas = 7;
EventData* descrs = stackalloc EventData[NumEventDatas];

descrs[0] = new EventData
Expand All @@ -231,12 +259,17 @@ private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3
descrs[4] = new EventData
{
DataPointer = (IntPtr)(&arg5),
Size = sizeof(int)
Size = sizeof(byte)
};
descrs[5] = new EventData
{
DataPointer = (IntPtr)(&arg6),
Size = sizeof(int)
Size = sizeof(byte)
};
descrs[6] = new EventData
{
DataPointer = (IntPtr)(&arg7),
Size = sizeof(HttpVersionPolicy)
};

WriteEventCore(eventId, NumEventDatas, descrs);
Expand Down
12 changes: 0 additions & 12 deletions src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -1155,10 +1147,6 @@ private void CloseResponseBody()
{
Cancel();
}
else
{
_request.OnStopped();
}

_responseBuffer.Dispose();
}
Expand Down
4 changes: 0 additions & 4 deletions src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -120,8 +120,6 @@ protected void Dispose(bool disposing)

_pool.DecrementConnectionCount();

if (HttpTelemetry.Log.IsEnabled()) _currentRequest?.OnAborted();

if (disposing)
{
GC.SuppressFinalize(this);
Expand Down Expand Up @@ -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;

Expand Down
47 changes: 0 additions & 47 deletions ...aries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -358,53 +358,6 @@ public ValueTask<HttpResponseMessage> SendProxyConnectAsync(HttpRequestMessage r
}

public ValueTask<HttpResponseMessage> SendAsync(HttpRequestMessage request, bool async, bool doRequestAuth, CancellationToken cancellationToken)
{
if (HttpTelemetry.Log.IsEnabled())
{
// [ActiveIssue("https://github.com/dotnet/runtime/issues/40896")]
if (request.Version.Major < 3 && request.RequestUri != null)
{
return SendAsyncWithLogging(request, async, doRequestAuth, cancellationToken);
}
}

return SendAsyncHelper(request, async, doRequestAuth, cancellationToken);
}

private async ValueTask<HttpResponseMessage> SendAsyncWithLogging(HttpRequestMessage request, bool async, bool doRequestAuth, CancellationToken cancellationToken)
{
Debug.Assert(request.RequestUri != null);
HttpTelemetry.Log.RequestStart(
request.RequestUri.Scheme,
request.RequestUri.IdnHost,
request.RequestUri.Port,
request.RequestUri.PathAndQuery,
request.Version.Major,
request.Version.Minor);

request.MarkAsTrackedByTelemetry();

try
{
return await SendAsyncHelper(request, async, doRequestAuth, cancellationToken).ConfigureAwait(false);
}
catch when (LogException(request))
{
// This code should never run.
throw;
}

static bool LogException(HttpRequestMessage request)
{
request.OnAborted();

// Returning false means the catch handler isn't run.
// So the exception isn't considered to be caught so it will now propagate up the stack.
return false;
}
}

private ValueTask<HttpResponseMessage> SendAsyncHelper(HttpRequestMessage request, bool async, bool doRequestAuth, CancellationToken cancellationToken)
{
if (_proxy == null)
{
Expand Down
4 changes: 2 additions & 2 deletions src/libraries/System.Net.Http/tests/FunctionalTests/HttpClientTest.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -327,12 +327,12 @@ static void Verify(HttpResponseMessage message)
}

[Fact]
public void GetAsync_CustomException_Synchronous_ThrowsException()
public async Task GetAsync_CustomException_Synchronous_ThrowsException()
{
var e = new FormatException();
using (var client = new HttpClient(new CustomResponseHandler((r, c) => { throw e; })))
{
FormatException thrown = Assert.Throws<FormatException>(() => { client.GetAsync(CreateFakeUri()); });
FormatException thrown = await Assert.ThrowsAsync<FormatException>(() => client.GetAsync(CreateFakeUri()));
Assert.Same(e, thrown);
}
}
Expand Down
Loading

0 comments on commit 05efa9b

Please sign in to comment.